Skip Menu |
 

This queue is for tickets about the Net-Async-HTTP CPAN distribution.

Report information
The Basics
Id: 99142
Status: resolved
Priority: 0/
Queue: Net-Async-HTTP

People
Owner: Nobody in particular
Requestors: leonerd-cpan [...] leonerd.org.uk
Cc:
AdminCc:

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



Subject: Future double-completion error
Download (untitled) / with headers
text/plain 289b
IO::Async::Future=HASH(0x4907ebd0) is already done and cannot be ->fail'ed at /home/matrix/lib/perl5/Net/Async/HTTP.pm line 410. That was observed from the Matrix-IRCBridge bot. I don't have a clear sense yet of what it was doing at the time or how to recreate it though. -- Paul Evans
Download (untitled) / with headers
text/plain 497b
On Thu Sep 25 13:26:14 2014, PEVANS wrote: Show quoted text
> IO::Async::Future=HASH(0x4907ebd0) is already done and cannot be > ->fail'ed at /home/matrix/lib/perl5/Net/Async/HTTP.pm line 410. > > That was observed from the Matrix-IRCBridge bot. I don't have a clear > sense yet of what it was doing at the time or how to recreate it > though.
This keeps happening sufficiently often, I'm going to attempt more debugging: $ PERL_FUTURE_DEBUG=1 perl -MDevel::MAT::Dumper=-dump_at_DIE bot.pl ... -- Paul Evans
Download (untitled) / with headers
text/plain 240b
I've caught it in action, though the .pmat file is too big for this bug and probably contains sensitive information so I won't upload it. I'll do some graph analysis sometime soon though and see if I can work anything out. -- Paul Evans
Download (untitled) / with headers
text/plain 746b
More detail: IO::Async::Future=HASH(...) ("[connect matrix.org:443]") is already done at .../Net/Async/HTTP/Connection.pm line 116 and cannot be ->fail'ed at .../Net/Async/HTTP.pm line 422. Against NaHTTP 0.36_001. The ->done line is in the 'should_pipeline' branch of 'sub ready', and the ->fail line is within the 'on_error' callback of the call to 'connect_connection' at the end of 'sub get_connection'. This combination suggests that the failure is because of a (SSL?) failure to connect, despite that the Ready Future has already been completed due to an earlier finishing of a request on a different connection causing it to bubble up to the head of the pipeline queue. This at least suggests a way to unit-test it. -- Paul Evans
Download (untitled) / with headers
text/plain 145b
On Mon Dec 01 11:23:40 2014, PEVANS wrote: Show quoted text
> This at least suggests a way to unit-test it.
I think I've got it. Patch attached. -- Paul Evans
Subject: rt99142.patch
Download rt99142.patch
text/x-diff 3.9k
=== modified file 'lib/Net/Async/HTTP.pm' --- lib/Net/Async/HTTP.pm 2014-11-28 17:27:58 +0000 +++ lib/Net/Async/HTTP.pm 2014-12-01 17:35:30 +0000 @@ -389,8 +389,6 @@ return $f; } - $ready->connecting++; - my $conn = Net::Async::HTTP::Connection->new( notifier_name => "$host:$port,connecting", ready_queue => $ready_queue, @@ -414,7 +412,7 @@ $self->add_child( $conn ); push @$conns, $conn; - $self->connect_connection( %args, + $ready->connecting = $self->connect_connection( %args, conn => $conn, on_error => sub { my $conn = shift; === modified file 'lib/Net/Async/HTTP/Connection.pm' --- lib/Net/Async/HTTP/Connection.pm 2014-11-25 13:19:38 +0000 +++ lib/Net/Async/HTTP/Connection.pm 2014-12-01 17:35:30 +0000 @@ -110,18 +110,24 @@ if( $self->should_pipeline ) { $self->debug_printf( "READY pipelined" ); while( @$queue && $self->should_pipeline ) { - my $f = ( shift @$queue )->future; + my $ready = shift @$queue; + my $f = $ready->future; next if $f->is_cancelled; + $ready->connecting and $ready->connecting->cancel; + $f->done( $self ); } } elsif( @$queue and $self->is_idle ) { $self->debug_printf( "READY non-pipelined" ); while( @$queue ) { - my $f = ( shift @$queue )->future; + my $ready = shift @$queue; + my $f = $ready->future; next if $f->is_cancelled; + $ready->connecting and $ready->connecting->cancel; + $f->done( $self ); last; } === added file 't/90rt99142.t' --- t/90rt99142.t 1970-01-01 00:00:00 +0000 +++ t/90rt99142.t 2014-12-01 17:35:30 +0000 @@ -0,0 +1,85 @@ +#!/usr/bin/perl + +use strict; +use warnings; + +use Test::More; + +use IO::Async::Test; +use IO::Async::Loop; + +use Net::Async::HTTP; + +my $CRLF = "\x0d\x0a"; # because \r\n isn't portable + +my $loop = IO::Async::Loop->new(); +testing_loop( $loop ); + +my $http = Net::Async::HTTP->new( + user_agent => "", # Don't put one in request headers + max_connections_per_host => 2, +); + +$loop->add( $http ); + +{ + my @pending; + no warnings 'redefine'; + *IO::Async::Handle::connect = sub { + my $self = shift; + my %args = @_; + $args{host} eq "localhost" or die "Cannot fake connect - expected host 'localhost'"; + $args{service} eq "5000" or die "Cannot fake connect - expected service '5000'"; + + push @pending, [ $self, my $f = $loop->new_future ]; + return $f; + }; + + sub await_connection + { + wait_for { scalar @pending }; + + return @{ shift @pending }; + } +} + +# Make a first connection +my $req_f1 = $http->GET( "http://localhost:5000/1" ); +my $peersock; +{ + my ( $conn, $conn_f ) = await_connection; + + ( my $selfsock, $peersock ) = IO::Async::OS->socketpair() or die "Cannot create socket pair - $!"; + $conn->set_handle( $selfsock ); + + $conn_f->done( $conn ); +} + +# Before the first is ready, make a second one +my $req_f2 = $http->GET( "http://localhost:5000/2" ); +my ( $conn2, $conn_f2 ) = await_connection; +ok( $conn_f2, 'Second connection request is pending' ); + +my $request_stream = ""; +wait_for_stream { $request_stream =~ m/$CRLF$CRLF/ } $peersock => $request_stream; + +like( $request_stream, qr(^GET /1), 'First request written' ); +$request_stream = ""; + +# Respond with HTTP/1.1 so client knows it can pipeline +$peersock->syswrite( "HTTP/1.1 200 OK$CRLF" . + "Content-Length: 0$CRLF" . + $CRLF ); + +wait_for { $req_f1->is_ready }; +ok( $req_f1->is_done, '$req_f1 is done after first response' ); + +# At this point, req 2 should already be made down the socket +wait_for_stream { $request_stream =~ m/$CRLF$CRLF/ } $peersock => $request_stream; + +like( $request_stream, qr(^GET /2), 'Second request written down first socket' ); + +# And $conn_f2 should already be cancelled +ok( $conn_f2->is_cancelled, '$conn_f2 now cancelled' ); + +done_testing;
This was fixed in 0.37 -- Paul Evans


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

Please report any issues with rt.cpan.org to rt-cpan-admin@bestpractical.com.