Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Mojo::UserAgent: Can't call method "_write" on an undefined value #1472

Closed
olegwtf opened this issue Feb 14, 2020 · 23 comments
Closed

Mojo::UserAgent: Can't call method "_write" on an undefined value #1472

olegwtf opened this issue Feb 14, 2020 · 23 comments

Comments

@olegwtf
Copy link
Contributor

olegwtf commented Feb 14, 2020

  • Mojolicious version: 8.32
  • Perl version: 5.28.1
  • Operating system: linux

I am using Mojo::UserAgent in non-blocking way. Nothing special: about 100 parallel get requests with unstable socks proxy. Each request uses own Mojo::UserAgent object. In the log I can see such rare warnings:

 Mojo::Reactor::Poll: I/O watcher failed: Can't call method "_write" on an undefined value at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 351.

Code on this line is:

$c->{ioloop}->stream($id)->write($chunk => sub { $self->_write($id) });

Looks like internal Mojo::UserAgent issue. I don't think that some mistake in my code may produce this.

@kraih
Copy link
Member

kraih commented Feb 14, 2020

We need code to replicate the problem.

@olegwtf
Copy link
Contributor Author

olegwtf commented Feb 14, 2020

I think it is not easy to make reproducable test script. Can you imagine why this callback called after object destruction? If you mean code which causes problem, this is it (simplified):

for (1..$threads) {
    check_next_url();
}

Mojo::IOLoop->start();

sub check_next_url {
    my $period = int(rand($cfg->{max_check_period} - $cfg->{min_check_period} + 1 ) + $cfg->{min_check_period});
    # is it time to check this URL?
    my $time_left = $period - ( clock_gettime(CLOCK_MONOTONIC) - $urls[0]{time} );
    if ($time_left > 0) {
        Mojo::IOLoop->timer($time_left => \&check_next_url);
        return;
    }
    
    my $url = shift @urls;
    my $ua = Mojo::UserAgent->new();
    $ua->max_redirects(0);
    $ua->request_timeout(URL_CHECK_TIMEOUT);
    my $proxy = $proxy[rand @proxy];
    $ua->proxy->http($proxy)->https($proxy);
    
    get_with_retry($ua, $url->{url}, sub {
        my ($tx) = @_;
        
        my $error = $tx->error;
        # ...
        
        $url->{time} = clock_gettime(CLOCK_MONOTONIC);
        push @urls, $url;
        
        undef $ua;
        check_next_url();
    });
}

sub get_with_retry {
    my ($ua, $url, $cb, $cur_retry) = @_;
    
    $ua->get($url, sub {
        my ($ua, $tx) = @_;
        
        my $error = $tx->error;

        if (!$error || $error->{code} || ++$cur_retry > GET_RETRY_COUNT) {
            return $cb->($tx);
        }

        get_with_retry($ua, $url, $cb, $cur_retry);
    });
}

@jhthorsen
Copy link
Member

Doesn't the $ua go out of scope in the code above?

I think you should use one of our support channels for this instead: https://mojolicious.org/perldoc/Mojolicious/Guides/Contributing#SUPPORT

@olegwtf
Copy link
Contributor Author

olegwtf commented Feb 15, 2020

We are loosing last reference to $ua at the end of callback: undef $ua.

@EvanCarroll
Copy link

@olegwtf I've had this problem before. I patched it in our fork of Mojo. However. I forget what exactly it was. If you allow me to shoot in the dark though, can you edit your copy of Mojo::Util's monkey_patch to read this,

*{"${class}::$k"} = Sub::Util::set_prototype(
  Sub::Util::prototype( $patch{$k} ),
  Sub::Util::set_subname(
    "${class}::$k",
    sub {
      my $cr = Sub::Util::set_subname("${class}::$k", $patch{$k});
      goto $cr;
    }
  )
);

@olegwtf
Copy link
Contributor Author

olegwtf commented Feb 20, 2020

I got some stacktrace with Carp::Always:

Mojo::IOLoop::__ANON__(Mojo::Reactor::Poll=HASH(0x5624b4cfe378), "I/O watcher failed: Can't call method \"_write\" on an undefine"...) called at /usr/local/share/perl/5.28.1/Mojo/EventEmitter.pm line 15
Mojo::EventEmitter::emit(Mojo::Reactor::Poll=HASH(0x5624b4cfe378), "error", "I/O watcher failed: Can't call method \"_write\" on an undefine"...) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 145
Mojo::Reactor::Poll::_try(Mojo::Reactor::Poll=HASH(0x5624b4cfe378), "I/O watcher", CODE(0x5624b5a99388), 1) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 61
Mojo::Reactor::Poll::one_tick(Mojo::Reactor::Poll=HASH(0x5624b4cfe378)) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 101
Mojo::Reactor::Poll::start(Mojo::Reactor::Poll=HASH(0x5624b4cfe378)) called at /usr/local/share/perl/5.28.1/Mojo/IOLoop.pm line 134
Mojo::IOLoop::start("Mojo::IOLoop") called at /tmp/t.pl line 97

Will try with EV backend.

@olegwtf
Copy link
Contributor Author

olegwtf commented Feb 20, 2020

@EvanCarroll You mean to replace monkey_patch sub body with your code? Why may this help?

@olegwtf
Copy link
Contributor Author

olegwtf commented Feb 21, 2020

I have no errors with EV backend.

@kraih
Copy link
Member

kraih commented May 2, 2020

Yes, i don't see any connection to whatever @EvanCarroll proposed there. But the example code above is also not enough to investigate. Unless there is new information i don't see this issue going anywhere.

@stale
Copy link

stale bot commented Aug 30, 2020

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the wontfix label Aug 30, 2020
@olegwtf
Copy link
Contributor Author

olegwtf commented Sep 7, 2020

This now also occured with EV (after I changed proxy type to HTTP).

Mojo::Reactor::EV: I/O watcher failed: Can't call method "_write" on an undefined value at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 348.
$c->{ioloop}->stream($id)->write($chunk => sub { $self->_write($id) });
Mojo::Reactor::EV: I/O watcher failed: Can't call method "_write" on an undefined value at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 348.
        Mojo::UserAgent::__ANON__(Mojo::IOLoop::Stream=HASH(0x5590d2a3f448)) called at /usr/local/share/perl/5.28.1/Mojo/EventEmitter.pm line 35
        Mojo::EventEmitter::__ANON__(Mojo::IOLoop::Stream=HASH(0x5590d2a3f448)) called at /usr/local/share/perl/5.28.1/Mojo/EventEmitter.pm line 15
        Mojo::EventEmitter::emit(Mojo::IOLoop::Stream=HASH(0x5590d2a3f448), "drain") called at /usr/local/share/perl/5.28.1/Mojo/IOLoop/Stream.pm line 131
        Mojo::IOLoop::Stream::_write(Mojo::IOLoop::Stream=HASH(0x5590d2a3f448)) called at /usr/local/share/perl/5.28.1/Mojo/IOLoop/Stream.pm line 57
        Mojo::IOLoop::Stream::__ANON__(Mojo::Reactor::EV=HASH(0x5590d15288b8)) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 146
        eval {...} called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 146
        Mojo::Reactor::Poll::_try(Mojo::Reactor::EV=HASH(0x5590d15288b8), "I/O watcher", CODE(0x5590d2c92190), 1) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 55
        Mojo::Reactor::EV::__ANON__(EV::IO=SCALAR(0x5590d20acca8), 2) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 24
        eval {...} called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 24
        Mojo::Reactor::EV::one_tick(Mojo::Reactor::EV=HASH(0x5590d15288b8)) called at /usr/local/share/perl/5.28.1/Mojo/IOLoop.pm line 84
        Mojo::IOLoop::one_tick(Mojo::IOLoop=HASH(0x5590d1507c88)) called at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 323
        Mojo::UserAgent::_start(Mojo::UserAgent=HASH(0x5590d1edf138), Mojo::IOLoop=HASH(0x5590d1507c88), Mojo::Transaction::HTTP=HASH(0x5590d23575a0), CODE(0x5590d1fbb530)) called at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 59
        Mojo::UserAgent::start(Mojo::UserAgent=HASH(0x5590d1edf138), Mojo::Transaction::HTTP=HASH(0x5590d23575a0), CODE(0x5590d1fbb530)) called at /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm line 37
        Mojo::UserAgent::get(Mojo::UserAgent=HASH(0x5590d1edf138), "https://www.ettis-project.eu/en/bitcoin-circuit-review/") called at ./redirects-tracker-daemon.pl line 218

@stale stale bot removed the stale label Sep 7, 2020
@kraih
Copy link
Member

kraih commented Sep 7, 2020

I bet this would have already been fixed if there was test code we could actually run.

@olegwtf
Copy link
Contributor Author

olegwtf commented Sep 7, 2020

I'll try to make it this time

@olegwtf
Copy link
Contributor Author

olegwtf commented Sep 8, 2020

Just added this debug info to Mojo::UserAgent

--- /usr/local/share/perl/5.28.1/Mojo/UserAgent.pm      2020-08-10 15:12:08.000000000 +0000
+++ lib/Mojo/UserAgent.pm       2020-09-08 05:24:08.070736482 +0000
@@ -345,7 +345,8 @@
   return unless length $chunk;
 
   weaken $self;
-  $c->{ioloop}->stream($id)->write($chunk => sub { $self->_write($id) });
+  my $self_string = "$self";
+  $c->{ioloop}->stream($id)->write($chunk => sub { eval { $self->_write($id); 1 } or do { die "$self_string: $@" } });
 }
 
 1;

Now in the trace I can see that $self_string contains Mojo::UserAgent not the same, as in the get() call, but one that was used before and already destroyed (I added logging before undef $ua; in my example above).

Mojo::IOLoop::__ANON__(Mojo::Reactor::EV=HASH(0x55a09aede768), "I/O watcher failed: Mojo::UserAgent=HASH(0x55a09b86cdb0): Can"...) called at /usr/local/share/perl/5.28.1/Mojo/EventEmitter.pm line 15
        Mojo::EventEmitter::emit(Mojo::Reactor::EV=HASH(0x55a09aede768), "error", "I/O watcher failed: Mojo::UserAgent=HASH(0x55a09b86cdb0): Can"...) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/Poll.pm line 146
        Mojo::Reactor::Poll::_try(Mojo::Reactor::EV=HASH(0x55a09aede768), "I/O watcher", CODE(0x55a09c92e958), 1) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 55
        Mojo::Reactor::EV::__ANON__(EV::IO=SCALAR(0x55a09bd194e8), 2) called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 24
        eval {...} called at /usr/local/share/perl/5.28.1/Mojo/Reactor/EV.pm line 24
        Mojo::Reactor::EV::one_tick(Mojo::Reactor::EV=HASH(0x55a09aede768)) called at /usr/local/share/perl/5.28.1/Mojo/IOLoop.pm line 84
        Mojo::IOLoop::one_tick(Mojo::IOLoop=HASH(0x55a09aea0230)) called at lib/Mojo/UserAgent.pm line 323
        Mojo::UserAgent::_start(Mojo::UserAgent=HASH(0x55a09b868490), Mojo::IOLoop=HASH(0x55a09aea0230), Mojo::Transaction::HTTP=HASH(0x55a09b98cf48), CODE(0x55a09cbb2908)) called at lib/Mojo/UserAgent.pm line 166
        Mojo::UserAgent::_connect_proxy(Mojo::UserAgent=HASH(0x55a09b868490), Mojo::IOLoop=HASH(0x55a09aea0230), Mojo::Transaction::HTTP=HASH(0x55a09c53b488), CODE(0x55a09baed970)) called at lib/Mojo/UserAgent.pm line 184
        Mojo::UserAgent::_connection(Mojo::UserAgent=HASH(0x55a09b868490), Mojo::IOLoop=HASH(0x55a09aea0230), Mojo::Transaction::HTTP=HASH(0x55a09c53b488), CODE(0x55a09baed970)) called at lib/Mojo/UserAgent.pm line 324
        Mojo::UserAgent::_start(Mojo::UserAgent=HASH(0x55a09b868490), Mojo::IOLoop=HASH(0x55a09aea0230), Mojo::Transaction::HTTP=HASH(0x55a09c53b488), CODE(0x55a09baed970)) called at lib/Mojo/UserAgent.pm line 59
        Mojo::UserAgent::start(Mojo::UserAgent=HASH(0x55a09b868490), Mojo::Transaction::HTTP=HASH(0x55a09c53b488), CODE(0x55a09baed970)) called at lib/Mojo/UserAgent.pm line 37
        Mojo::UserAgent::get(Mojo::UserAgent=HASH(0x55a09b868490), "https://opfer-gegen-gewalt.de/en/bitcoin-profit-review/") called at redirects-tracker-daemon.pl line 181
root@oleg-seo-monitor:~/redirects-tracker# grep 0x55a09b86cdb0 redirects-tracker-daemon.log                                                                                                                                                                                    
[Tue Sep  8 05:26:35 2020] Mojo::UserAgent=HASH(0x55a09b86cdb0) created                                                                                                                                                                                                        
[Tue Sep  8 05:26:52 2020] Mojo::UserAgent=HASH(0x55a09b86cdb0) destroying
root@oleg-seo-monitor:~/redirects-tracker# grep 0x55a09b868490 redirects-tracker-daemon.log                                                                                                                                                                      
[Tue Sep  8 05:26:41 2020] Mojo::UserAgent=HASH(0x55a09b868490) created

Is there some incorrect $ua reusing in Mojo::UserAgent?

@olegwtf
Copy link
Contributor Author

olegwtf commented Sep 8, 2020

The best test case I can provide is this:

use strict;
use warnings;
use Mojo::UserAgent;
use Mojo::Util 'trim';

my @proxy = map { trim $_ } <DATA>;

for (1..300) {
    get_next();
}

sub get_next {
    my $ua = Mojo::UserAgent->new;
    $ua->proxy->http('http://' . $proxy[rand @proxy]);
    $ua->connect_timeout(10);
    $ua->request_timeout(10);
    $ua->get('http://oleghere.xyz/', sub {
        undef $ua;
        get_next();
    });
}

Mojo::IOLoop->start();

__DATA__
megaproxy.rotating.proxyrack.net:10000
megaproxy.rotating.proxyrack.net:10001
megaproxy.rotating.proxyrack.net:10002
megaproxy.rotating.proxyrack.net:10003
megaproxy.rotating.proxyrack.net:10004
megaproxy.rotating.proxyrack.net:10005

It starts to fail after 1-10 minutes of running. This proxy requires whitelist your IP. @kraih if u can provide your IP I can add it to whitelist. Here or to oleg@cpan.org

@olegwtf
Copy link
Contributor Author

olegwtf commented Sep 9, 2020

Finally I found out, that I can replicate this problem even without proxy enabled:

use strict;
use warnings;
BEGIN {
    # looks like more chance to get this error with non-blocking resolving disabled
    $ENV{MOJO_NO_NNR} = 1;
}
use Mojo::UserAgent;

for (1..300) {
    get_next();
}

sub get_next {
    my $ua = Mojo::UserAgent->new;
    $ua->connect_timeout(10);
    $ua->request_timeout(10);
    $ua->get('http://oleghere.xyz/', sub {
        undef $ua;
        get_next();
    });
}

Mojo::IOLoop->start();

@kraih
Copy link
Member

kraih commented Sep 13, 2020

I still cannot replicate the problem with any of the test cases provided so far.

@kraih
Copy link
Member

kraih commented Sep 13, 2020

Maybe try triggering it in a GitHub action?

@kiwiroy
Copy link
Contributor

kiwiroy commented Sep 16, 2020

I've managed to trigger in an action and locally in docker container log

edit This was/is a red herring. 1024 bits isn't enough on buster leading to an error.

@EvanCarroll
Copy link

@olegwtf's test worked for me.

@stale
Copy link

stale bot commented Oct 23, 2020

This issue has been automatically marked as stale because it has not had recent activity. It may be closed if no further activity occurs. This is not a judgment on the merits of the issue, but an indication that more information may be needed to determine the appropriate course of action, if any. Thank you for your contributions.

@stale stale bot added the stale label Oct 23, 2020
@kraih kraih removed the stale label Nov 5, 2020
@kraih
Copy link
Member

kraih commented Feb 10, 2021

Still no way to replicate this. Afraid if there's no new information i'll have to call this a WONTFIX.

@kraih
Copy link
Member

kraih commented Mar 11, 2021

Should be resolved.

@kraih kraih closed this as completed Mar 11, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants