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

[olegwtf]

• 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]

We need code to replicate the problem.

[olegwtf]

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]

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]

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

[EvanCarroll]

@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]

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]

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

[olegwtf]

I have no errors with EV backend.

[kraih]

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[bot]]

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.

[olegwtf]

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

[kraih]

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

[olegwtf]

I'll try to make it this time

[olegwtf]

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]

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]

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]

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

[kraih]

Maybe try triggering it in a GitHub action?

[kiwiroy]

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]

@olegwtf's test worked for me.

[stale[bot]]

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.

[kraih]

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

[kraih]

Should be resolved.