Skip Menu |

This queue is for tickets about the WWW-Mechanize-Chrome CPAN distribution.

Report information
The Basics
Id: 122768
Status: resolved
Priority: 0/
Queue: WWW-Mechanize-Chrome

People
Owner: Nobody in particular
Requestors: ANDK [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: (no value)
Broken in: 0.06
Fixed in: 0.37



Subject: Future.pm complains under PERL_FUTURE_DEBUG=1
Something seems to be wrong with the treatment of futures. When I run the test t/50-form2.t with the environment variable PERL_FUTURE_DEBUG=1, then I get eleven complaints of the form AnyEvent::Future=HASH(0xxxxxxxx) was constructed at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol/Transport/AnyEvent.pm line 90 and was lost near /home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm line 2050 before it was ready. That is with the current master at commit 1a1a165. Any insights or guidance how to tackle these would be welcome. Background: I tried to fix the form elements select and textarea but ran into the same future problems there. So I come to the conclusion that the future problem needs to be fixed first.
Subject: Re: [rt.cpan.org #122768] Future.pm complains under PERL_FUTURE_DEBUG=1
Date: Fri, 11 Aug 2017 15:58:30 +0200
To: bug-WWW-Mechanize-Chrome [...] rt.cpan.org,Andreas Koenig via RT <bug-WWW-Mechanize-Chrome [...] rt.cpan.org>
From: Max Maischein <webmaster [...] corion.net>
Hello Andreas! Thanks for teaching me about PERL_FUTURE_DEBUG! I've tracked that message to some old leftover code that I killed with 996c24d , but that doesn't fix the hag in t/forms2.t For debugging that, I currently stare at the output with the log turned up to $TRACE, but that's not pleasant... -max Am 11. August 2017 11:04:45 MESZ schrieb Andreas Koenig via RT <bug-WWW-Mechanize-Chrome@rt.cpan.org>: Show quoted text
>Fri Aug 11 05:04:44 2017: Request 122768 was acted upon. >Transaction: Ticket created by ANDK > Queue: WWW-Mechanize-Chrome > Subject: Future.pm complains under PERL_FUTURE_DEBUG=1 > Broken in: 0.06 > Severity: (no value) > Owner: Nobody > Requestors: ANDK@cpan.org > Status: new > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122768 > > > >Something seems to be wrong with the treatment of futures. When I run >the test t/50-form2.t with the environment variable >PERL_FUTURE_DEBUG=1, then I get eleven complaints of the form > >AnyEvent::Future=HASH(0xxxxxxxx) was constructed at >/home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol/Transport/AnyEvent.pm >line 90 and was lost near >/home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm >line 2050 before it was ready. > >That is with the current master at commit 1a1a165. > >Any insights or guidance how to tackle these would be welcome. > >Background: I tried to fix the form elements select and textarea but >ran into the same future problems there. So I come to the conclusion >that the future problem needs to be fixed first.
-- Diese Nachricht wurde von meinem Android-Mobiltelefon mit K-9 Mail gesendet.
How about trying this: sub future { my $f = AnyEvent::Future->new; Carp::cluck("producing new anyevent future $f"); return $f; } The trick here is that the message coming from Future's debugging message contains the physical address of the $future and so does the stack trace written by the cluck above. It helped me a lot to get a bit familiar with the code. Not enough yet, but maybe it helps you too:) Here is the biography of one of the lost futures: producing new anyevent future AnyEvent::Future=HASH(0x3964798) at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol/Transport/AnyEvent.pm line 91, <$server> line 1. Chrome::DevToolsProtocol::Transport::AnyEvent::future(Chrome::DevToolsProtocol::Transport::AnyEvent=HASH(0x384bed8)) called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol.pm line 226 Chrome::DevToolsProtocol::one_shot(Chrome::DevToolsProtocol=HASH(0x1a60168), "DOM.setChildNodes") called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm line 2058 WWW::Mechanize::Chrome::__ANON__(HASH(0x2605928)) called at /usr/share/perl5/Future.pm line 436 eval {...} called at /usr/share/perl5/Future.pm line 436 Future::_mark_ready(AnyEvent::Future=HASH(0x2610b98), "done") called at /usr/share/perl5/Future.pm line 508 Future::done(AnyEvent::Future=HASH(0x2610b98), HASH(0x2605928)) called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol.pm line 305 Chrome::DevToolsProtocol::on_response(Chrome::DevToolsProtocol=HASH(0x1a60168), AnyEvent::WebSocket::Connection=HASH(0x3843540), "{\"id\":7,\"result\":{\"searchId\":\"17531.23\",\"resultCount\":1}}") called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/Chrome/DevToolsProtocol/Transport/AnyEvent.pm line 67 Chrome::DevToolsProtocol::Transport::AnyEvent::__ANON__(AnyEvent::WebSocket::Connection=HASH(0x3843540), AnyEvent::WebSocket::Message=HASH(0x39645e8)) called at /home/andk/perl5/lib/perl5/AnyEvent/WebSocket/Connection.pm line 170 AnyEvent::WebSocket::Connection::_process_message(AnyEvent::WebSocket::Connection=HASH(0x3843540), AnyEvent::WebSocket::Message=HASH(0x39645e8)) called at /home/andk/perl5/lib/perl5/AnyEvent/WebSocket/Connection.pm line 104 eval {...} called at /home/andk/perl5/lib/perl5/AnyEvent/WebSocket/Connection.pm line 95 AnyEvent::WebSocket::Connection::__ANON__(AnyEvent::Handle=HASH(0x26056d0)) called at /home/andk/perl5/lib/perl5/x86_64-linux-gnu-thread-multi/AnyEvent/Handle.pm line 1327 AnyEvent::Handle::_drain_rbuf(AnyEvent::Handle=HASH(0x26056d0)) called at /home/andk/perl5/lib/perl5/x86_64-linux-gnu-thread-multi/AnyEvent/Handle.pm line 2015 AnyEvent::Handle::__ANON__(EV::IO=SCALAR(0x3890828), 1) called at /home/andk/perl5/lib/perl5/x86_64-linux-gnu-thread-multi/AnyEvent/Impl/EV.pm line 88 eval {...} called at /home/andk/perl5/lib/perl5/x86_64-linux-gnu-thread-multi/AnyEvent/Impl/EV.pm line 88 AnyEvent::CondVar::Base::_wait(AnyEvent::CondVar=HASH(0x25c1448)) called at /home/andk/perl5/lib/perl5/x86_64-linux-gnu-thread-multi/AnyEvent.pm line 2023 AnyEvent::CondVar::Base::recv(AnyEvent::CondVar=HASH(0x25c1448)) called at /home/andk/perl5/lib/perl5/AnyEvent/Future.pm line 178 AnyEvent::Future::await(AnyEvent::Future=HASH(0x3967b20)) called at /usr/share/perl5/Future.pm line 774 Future::get(AnyEvent::Future=HASH(0x3967b20)) called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm line 2205 WWW::Mechanize::Chrome::xpath(WWW::Mechanize::Chrome=HASH(0x1b9c2e0), "(//form)[1]", "user_info", "form number 1", "single", 1) called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm line 2599 WWW::Mechanize::Chrome::form_number(WWW::Mechanize::Chrome=HASH(0x1b9c2e0), 1) called at /home/andk/src/WWW-Mechanize-Chrome/blib/lib/WWW/Mechanize/Chrome.pm line 2487 WWW::Mechanize::Chrome::current_form(WWW::Mechanize::Chrome=HASH(0x1b9c2e0)) called at t/50-form2.t line 41 main::__ANON__("/usr/bin/google-chrome-stable", WWW::Mechanize::Chrome=HASH(0x1b9c2e0)) called at t/helper.pm line 106 t::helper::run_across_instances(ARRAY(0xe6d110), 9222, CODE(0x22d3488), 13, CODE(0x22d3638)) called at t/50-form2.t line 78
Hey, your fix works for me. If I run all tests with PERL_FUTURE_DEBUG=1, then I only get warnings with these three tests: t/50-follow-link.t t/50-popup.t t/51-mech-submit.t This seesm to be a huge progress, thanks Max!
Kinda fixed the rest of the warnings with two patches. The second is quite bogus, because it resorts to sleep to avoid a race condition. Maybe you have a better approach? This one is trivial: --- a/lib/WWW/Mechanize/Chrome.pm +++ b/lib/WWW/Mechanize/Chrome.pm @@ -827,11 +827,11 @@ sub _mightNavigate( $self, $get_navigation_future, %options ) { # Handle all the events, by turning them into a ->response again my $res = $self->httpMessageFromEvents( $self->frameId, \@events ); $self->update_response( $res ); - undef $scheduled; } else { $self->log('trace', "No navigation occurred, not collecting events"); - undef $scheduled; }; + $scheduled->cancel; + undef $scheduled; # Store our frame id so we know what events to listen for in the future! $self->{frameId} ||= $nav->{frameId}; It halfs the number of remaining warnings from Future.pm with PERL_FUTURE_DEBUG=1. The rest goes away with the second, but it surely is not a fix, just an indication where to look: --- a/lib/WWW/Mechanize/Chrome.pm +++ b/lib/WWW/Mechanize/Chrome.pm @@ -820,6 +820,7 @@ sub _mightNavigate( $self, $get_navigation_future, %options ) { # Kick off the navigation ourselves my $nav = $get_navigation_future->()->get; + $self->sleep(1); # WRONG! Kinda avert race condition above in $navigated my @events; if( $navigated or $options{ navigates }) { @@ -828,6 +829,7 @@ sub _mightNavigate( $self, $get_navigation_future, %options ) { my $res = $self->httpMessageFromEvents( $self->frameId, \@events ); $self->update_response( $res ); } else { + $does_navigation->cancel; $self->log('trace', "No navigation occurred, not collecting events"); }; $scheduled->cancel; Looking forward to your feedback. I'll probably go back now to investigating into select and textarea. Let me know what you think!
Subject: Re: [rt.cpan.org #122768] Future.pm complains under PERL_FUTURE_DEBUG=1
Date: Mon, 14 Aug 2017 11:42:23 +0200
To: bug-WWW-Mechanize-Chrome [...] rt.cpan.org
From: Max Maischein <webmaster [...] corion.net>
Hello Andreas Thanks for your investigation! The cancelling seems sensible, and the ->sleep call is something that I've also found. Chrome seems to be sending things in different orders so I need to think about how to better detect/find what to wait for. Hopefully I can do a more thorough investigation this week... -max Am 14. August 2017 10:45:44 MESZ schrieb Andreas Koenig via RT <bug-WWW-Mechanize-Chrome@rt.cpan.org>: Show quoted text
> Queue: WWW-Mechanize-Chrome > Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=122768 > > >Kinda fixed the rest of the warnings with two patches. The second is >quite bogus, because it resorts to sleep to avoid a race condition. >Maybe you have a better approach? > >This one is trivial: > >--- a/lib/WWW/Mechanize/Chrome.pm >+++ b/lib/WWW/Mechanize/Chrome.pm >@@ -827,11 +827,11 @@ sub _mightNavigate( $self, >$get_navigation_future, %options ) { > # Handle all the events, by turning them into a ->response again > my $res = $self->httpMessageFromEvents( $self->frameId, \@events ); > $self->update_response( $res ); >- undef $scheduled; > } else { > $self->log('trace', "No navigation occurred, not collecting events"); >- undef $scheduled; > }; >+ $scheduled->cancel; >+ undef $scheduled; > ># Store our frame id so we know what events to listen for in the >future! > $self->{frameId} ||= $nav->{frameId}; > > >It halfs the number of remaining warnings from Future.pm with >PERL_FUTURE_DEBUG=1. > >The rest goes away with the second, but it surely is not a fix, just an >indication where to look: > >--- a/lib/WWW/Mechanize/Chrome.pm >+++ b/lib/WWW/Mechanize/Chrome.pm >@@ -820,6 +820,7 @@ sub _mightNavigate( $self, $get_navigation_future, >%options ) { > > # Kick off the navigation ourselves > my $nav = $get_navigation_future->()->get; >+ $self->sleep(1); # WRONG! Kinda avert race condition above in >$navigated > > my @events; > if( $navigated or $options{ navigates }) { >@@ -828,6 +829,7 @@ sub _mightNavigate( $self, $get_navigation_future, >%options ) { > my $res = $self->httpMessageFromEvents( $self->frameId, \@events ); > $self->update_response( $res ); > } else { >+ $does_navigation->cancel; > $self->log('trace', "No navigation occurred, not collecting events"); > }; > $scheduled->cancel; > > >Looking forward to your feedback. I'll probably go back now to >investigating into select and textarea. Let me know what you think!
-- Diese Nachricht wurde von meinem Android-Mobiltelefon mit K-9 Mail gesendet.
Cool, thanks for the reassurance.
This has been fixed in between version but a new leak occurred with 0.37. This new leak/loss of Futures is fixed in the repository and will be released as 0.38. The test suite now always runs with PERL_FUTURE_DEBUG=1