Bug #71706 for IO-Async: tests fail on Cygwin

Sat Oct 15 14:46:16 2011 rkitover [...] cpan.org - Ticket created

Subject:	tests fail on Cygwin
Date:	Sat, 15 Oct 2011 14:45:42 -0400
To:	bug-IO-Async [...] rt.cpan.org
From:	Rafael Kitover <rkitover [...] cpan.org>

here's the output of make test: /usr/bin/perl.exe Build --makefile_env_macros 1 test t/00use.t .................... ok t/01timequeue.t .............. ok t/02loop-magic.t ............. ok t/03loop-osabstract.t ........ ok t/04notifier.t ............... ok t/05notifier-child.t ......... ok t/06notifier-mixin.t ......... ok t/10loop-poll-io.t ........... ok # Failed test 'exceptional socket invokes on_read_ready' # at /c/Users/rkitover/.cpan/build/IO-Async-0.44-gjq9KX/blib/lib/IO/Async/LoopTests.pm line 342. # got: '0' # expected: '1' # Looks like you failed 1 test of 20. t/10loop-select-io.t ......... Dubious, test returned 1 (wstat 256, 0x100) Failed 1/20 subtests (less 3 skipped subtests: 16 okay) # Failed test 'Other timers still fire after self-cancelling one' # at /c/Users/rkitover/.cpan/build/IO-Async-0.44-gjq9KX/blib/lib/IO/Async/LoopTests.pm line 458. # got: undef # expected: '1' # Looks like you failed 1 test of 15. t/11loop-poll-timer.t ........ Dubious, test returned 1 (wstat 256, 0x100) Failed 1/15 subtests # Failed test 'Other timers still fire after self-cancelling one' # at /c/Users/rkitover/.cpan/build/IO-Async-0.44-gjq9KX/blib/lib/IO/Async/LoopTests.pm line 458. # got: undef # expected: '1' # Looks like you failed 1 test of 15. t/11loop-select-timer.t ...... Dubious, test returned 1 (wstat 256, 0x100) Failed 1/15 subtests t/12loop-poll-signal.t ....... ok t/12loop-select-signal.t ..... ok t/13loop-poll-idle.t ......... ok t/13loop-select-idle.t ....... ok t/14loop-poll-child.t ........ ok t/14loop-select-child.t ...... ok t/15loop-poll-control.t ...... ok t/15loop-select-control.t .... ok t/18loop-poll-legacy.t ....... ok t/18loop-select-legacy.t ..... ok t/19test.t ................... ok # Failed test 'syswrite into EOF read handle' # at t/20handle.t line 273. # got: '5' # expected: undef # Looks like you failed 1 test of 72. t/20handle.t ................. Dubious, test returned 1 (wstat 256, 0x100) Failed 1/72 subtests Can't locate object method "binmode" via package "IO::Handle" at t/21stream-1read.t line 383. # Looks like you planned 54 tests but ran 53. # Looks like your test exited with 104 just after 53. t/21stream-1read.t ........... Dubious, test returned 104 (wstat 26624, 0x6800) Failed 1/54 subtests t/21stream-2write.t .......... ok Can't locate object method "binmode" via package "IO::Handle" at t/21stream-3split.t line 179. # Looks like you planned 21 tests but ran 19. # Looks like your test exited with 9 just after 19. t/21stream-3split.t .......... Dubious, test returned 9 (wstat 2304, 0x900) Failed 2/21 subtests t/21stream-4encoding.t ....... ok t/22timer-absolute.t ......... ok t/22timer-countdown.t ........ ok t/22timer-periodic.t ......... ok t/23signal.t ................. ok t/24listener.t ............... ok t/25socket.t ................. ok t/26pid.t .................... ok t/27filestream.t ............. ok t/30loop-fork.t .............. ok t/31loop-spawnchild.t ........ ok t/32loop-spawnchild-setup.t .. ok t/33process.t ................ ok t/34process-handles.t ........ ok t/35loop-openchild.t ......... ok t/36loop-runchild.t .......... ok t/37loop-child-root.t ........ skipped: not root SIGCHLD handler "DEFAULT" not defined. t/41detachedcode-call.t ...... ok t/41function.t ............... ok t/50resolver.t ............... ok # Failed test '$failerr is 'Connection refused'' # at t/51loop-connect.t line 192. # got: 'Operation not permitted' # expected: 'Connection refused' # Failed test '$error[1] is 'Connection refused'' # at t/51loop-connect.t line 195. # got: 'Operation not permitted' # expected: 'Connection refused' # Looks like you failed 2 tests of 16. t/51loop-connect.t ........... Dubious, test returned 2 (wstat 512, 0x200) Failed 2/16 subtests t/52loop-listen.t ............ ok t/53loop-extend.t ............ ok t/60protocol.t ............... ok t/60sequencer-client.t ....... ok t/60sequencer-server.t ....... ok t/61protocol-stream.t ........ ok t/62protocol-linestream.t .... ok t/99pod.t .................... ok Test Summary Report ------------------- t/10loop-select-io.t (Wstat: 256 Tests: 20 Failed: 1) Failed test: 17 Non-zero exit status: 1 t/11loop-poll-timer.t (Wstat: 256 Tests: 15 Failed: 1) Failed test: 14 Non-zero exit status: 1 t/11loop-select-timer.t (Wstat: 256 Tests: 15 Failed: 1) Failed test: 14 Non-zero exit status: 1 t/20handle.t (Wstat: 256 Tests: 72 Failed: 1) Failed test: 52 Non-zero exit status: 1 t/21stream-1read.t (Wstat: 26624 Tests: 53 Failed: 0) Non-zero exit status: 104 Parse errors: Bad plan. You planned 54 tests but ran 53. t/21stream-3split.t (Wstat: 2304 Tests: 19 Failed: 0) Non-zero exit status: 9 Parse errors: Bad plan. You planned 21 tests but ran 19. t/51loop-connect.t (Wstat: 512 Tests: 16 Failed: 2) Failed tests: 14, 16 Non-zero exit status: 2 Files=55, Tests=1361, 168 wallclock secs ( 1.67 usr 1.04 sys + 39.34 cusr 39.17 csys = 81.22 CPU) Result: FAIL Failed 7/55 test programs. 6/1361 subtests failed. make: *** [test] Error 255

Thu Feb 02 15:29:36 2012 RURBAN [...] cpan.org - Correspondence added

Not repro with a recent cygwin snapshot which improved poll and select. CYGWIN_NT-5.1 winxp 1.7.10s(0.259/5/3) 20120122 07:28:45 i686 Cygwin I got: # Failed test 'syswrite into EOF read handle' # at t/20handle.t line 273. # got: '5' # expected: undef # Looks like you failed 1 test of 72. t/20handle.t ................. Dubious, test returned 1 (wstat 256, 0x100) Failed 1/72 subtests Test died early - connect error connect # Looks like you planned 16 tests but ran 5. # Looks like your test exited with 118 just after 5. t/51loop-connect.t ........... Dubious, test returned 118 (wstat 30208, 0x7600) Failed 11/16 subtests t/20handle.t (Wstat: 256 Tests: 72 Failed: 1) Failed test: 52 Non-zero exit status: 1 t/51loop-connect.t (Wstat: 30208 Tests: 5 Failed: 0) Non-zero exit status: 118 Parse errors: Bad plan. You planned 16 tests but ran 5. -- Reini Urban

Thu Feb 02 15:29:37 2012 The RT System itself - Status changed from 'new' to 'open'

Tue Mar 13 04:19:29 2012 leonerd-cpan [...] leonerd.org.uk - Correspondence added

On Thu Feb 02 15:29:36 2012, RURBAN wrote: Show quoted text

> Not repro with a recent cygwin snapshot which improved poll and

select. Show quoted text

> CYGWIN_NT-5.1 winxp 1.7.10s(0.259/5/3) 20120122 07:28:45 i686 Cygwin > > I got: > # Failed test 'syswrite into EOF read handle' > # at t/20handle.t line 273. > # got: '5' > # expected: undef > # Looks like you failed 1 test of 72. > t/20handle.t ................. > Dubious, test returned 1 (wstat 256, 0x100) > Failed 1/72 subtests > > Test died early - connect error connect > # Looks like you planned 16 tests but ran 5. > # Looks like your test exited with 118 just after 5. > t/51loop-connect.t ........... > Dubious, test returned 118 (wstat 30208, 0x7600) > Failed 11/16 subtests > > > t/20handle.t (Wstat: 256 Tests: 72 Failed: 1) > Failed test: 52 > Non-zero exit status: 1 > t/51loop-connect.t (Wstat: 30208 Tests: 5 Failed: 0) > Non-zero exit status: 118 > Parse errors: Bad plan. You planned 16 tests but ran 5.

Try now with 0.46_001; I've had a go at fixing both of these. -- Paul Evans

Wed Mar 27 16:54:17 2013 CHORNY [...] cpan.org - Correspondence added

IO::Async 0.55 CYGWIN_NT-5.1 1.7.17 perl 5, version 14, subversion 2 (v5.14.2) built for cygwin-thread-multi-64int t/42function.t ............... 15/? Nothing was ready after 10 second wait; called at t/42function.t line 261 # Tests were run but no plan was declared and done_testing() was not seen. t/42function.t ............... Dubious, test returned 255 (wstat 65280, 0xff00) All 24 subtests passed t/50resolver.t ............... ok t/51loop-connect.t ........... 1/? Nothing was ready after 10 second wait; called at t/51loop-connect.t line 267 # Tests were run but no plan was declared and done_testing() was not seen. t/51loop-connect.t ........... Dubious, test returned 119 (wstat 30464, 0x7700) All 24 subtests passed (less 1 skipped subtest: 23 okay) t/52loop-listen.t ............ ok -- Alexandr Ciornii, http://chorny.net

Wed Apr 03 17:27:32 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added

So these would be.... On Wed Mar 27 16:54:17 2013, CHORNY wrote: Show quoted text

> t/42function.t ............... 15/? Nothing was ready after 10 second > wait; called at t/42function.t line 261 > # Tests were run but no plan was declared and done_testing() was not > seen. > t/42function.t ............... Dubious, test returned 255 (wstat > 65280, 0xff00) > All 24 subtests passed

Line 261 puts it in this test: 243 # restart after exit 244 { 245 my $function = IO::Async::Function->new( 246 min_workers => 0, 247 max_workers => 1, 248 code => sub { $_[0] ? exit shift : return 0 }, 249 ); 250 251 $loop->add( $function ); 252 253 my $err; 254 255 $function->call( 256 args => [ 16 ], 257 on_return => sub { $err = "" }, 258 on_error => sub { $err = [ @_ ] }, 259 ); 260 261 wait_for { defined $err }; Which means it got neither on_return nor on_error. I wonder if that's because it never noticed the child process's exit condition. In normal return cases from the IO::Async::Routine, the channels are gracefully closed: 168 my $ret = $code->(); 169 170 foreach ( @channels_in, @channels_out ) { 171 my ( $ch ) = @$_; 172 $ch->close; 173 } 174 175 return $ret; On a UNIX machine, a forced exit() here would just forcably close the channels anyway, but I wonder if the fake-fork used on Windows has a side-effect of not actually handling that here. :/ I wonder if an END {} block with code pushed into it might help matters here. Try applying the attached patch which moves it there, and see if that helps this one. Show quoted text

> t/51loop-connect.t ........... 1/? Nothing was ready after 10 second > wait; called at t/51loop-connect.t line 267 > # Tests were run but no plan was declared and done_testing() was not > seen. > t/51loop-connect.t ........... Dubious, test returned 119 (wstat > 30464, 0x7700) > All 24 subtests passed > (less 1 skipped subtest: 23 okay)

This one is the "test errors to connect": 252 SKIP: { 253 skip "Cannot find an un-connect(2)able socket on 127.0.0.1", 2 unless defined $po 254 255 my $failop; 256 my $failerr; 257 258 my @error; 259 260 $loop->connect( 261 addr => { family => "inet", socktype => "stream", port => $port, ip => "127.0.0.1" }, 262 on_connected => sub { die "Test died early - connect succeeded\n"; }, 263 on_fail => sub { $failop = shift @_; $failerr = pop @_; }, 264 on_connect_error => sub { @error = @_; }, 265 ); 266 267 wait_for { @error }; Failure here possibly means the Poll loop isn't correctly checking for connect() failure. I would love to see the poll() calls being made here but I understand Win32 lacks an strace-alike which might make that difficult. Perhaps some more debugging printing in Loop/Poll.pm could help with this one? Can you add some STDERR prints in strategic points of sub loop_once and sub post_poll and we'll see if that gives more detail..? -- Paul Evans

Subject:

rt71706-close-channels-in-END.patch

=== modified file 'lib/IO/Async/Routine.pm' --- lib/IO/Async/Routine.pm 2013-03-10 22:56:38 +0000 +++ lib/IO/Async/Routine.pm 2013-04-03 21:26:13 +0000 @@ -120,6 +120,11 @@ $self->SUPER::configure( %params ); } +my @cleanup; +END { + $_->() for @cleanup; +} + sub _add_to_loop { my $self = shift; @@ -165,14 +170,14 @@ $ch->setup_sync_mode( $wr ); } - my $ret = $code->(); - - foreach ( @channels_in, @channels_out ) { - my ( $ch ) = @$_; - $ch->close; - } - - return $ret; + push @cleanup, sub { + foreach ( @channels_in, @channels_out ) { + my ( $ch ) = @$_; + $ch->close; + } + }; + + return $code->(); }, );

Wed Jan 08 20:02:30 2014 leonerd-cpan [...] leonerd.org.uk - Correspondence added

Have you tried this more recently; specifically on 0.61? That release had a lot of rewrite for MSWin32, but I expect at least some of it may also help cygwin too. -- Paul Evans