Bug #82402 for IO-Async: IO-Async-0.53 test stuck on Windows

Fri Jan 04 07:10:58 2013 gabor [...] szabgab.com - Ticket created

Subject:	IO-Async-0.53 test stuck on Windows
Date:	Fri, 4 Jan 2013 14:10:47 +0200
To:	bug-IO-Async [...] rt.cpan.org
From:	Gabor Szabo <gabor [...] szabgab.com>

Starwberry Perl 5.12.3 (32 bit) On 5.16.2 I could not even get to that point as Future-0.07.tar.gz failed to install. (Report sent to CPANTESTERS.) Checksum for C:\strawberry\cpan\sources\authors\id\P\PE\PEVANS\IO-Async-0.53.tar.gz ok CPAN.pm: Building P/PE/PEVANS/IO-Async-0.53.tar.gz Created MYMETA.yml and MYMETA.json Creating new 'Build' script for 'IO-Async' version '0.53' (C:\strawberry\perl\bin\perl.exe Build.PL exited with 0) CPAN::Reporter: Build.PL result is 'pass', No errors. Building IO-Async (C:\strawberry\perl\bin\perl.exe ./Build exited with 0) CPAN::Reporter: Build result is 'pass', No errors. PEVANS/IO-Async-0.53.tar.gz C:\strawberry\perl\bin\perl.exe ./Build -- OK Running Build test t\00use.t .................... ok t\01timequeue.t .............. ok t\02os.t ..................... ok t\03loop-magic.t ............. ok t\04notifier.t ............... ok t\05notifier-child.t ......... ok t\06notifier-mixin.t ......... ok # Failed test '$readready after pipe HUP' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 267. # got: '0' # expected: '1' # Failed test 'regular file is readready' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 380. # got: '0' # expected: '1' # Failed test 'regular file is writeready' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 381. # got: '0' # expected: '1' # Looks like you failed 3 tests of 21. t\10loop-poll-io.t ........... Dubious, test returned 3 (wstat 768, 0x300) Failed 3/21 subtests (less 2 skipped subtests: 16 okay) # Failed test '$readready before pipe HUP' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 260. # got: '1' # expected: '0' # Looks like you failed 1 test of 21. t\10loop-select-io.t ......... Dubious, test returned 1 (wstat 256, 0x100) Failed 1/21 subtests (less 2 skipped subtests: 18 okay) # Failed test 'One ->loop_once(1) sufficient for a single 0.01 second timer' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 505. # got: '2' # expected: '1' # Failed test 'One ->loop_once(1) sufficient for a single 0.1 second timer' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 505. # got: '2' # expected: '1' # Looks like you failed 2 tests of 25. t\11loop-poll-timer.t ........ Dubious, test returned 2 (wstat 512, 0x200) Failed 2/25 subtests # Failed test 'One ->loop_once(1) sufficient for a single 0.01 second timer' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 505. # got: '2' # expected: '1' # Failed test 'One ->loop_once(1) sufficient for a single 0.1 second timer' # at C:\strawberry\cpan\build\IO-Async-0.53-a69fW_\blib\lib/IO/Async/LoopTests.pm line 505. # got: '2' # expected: '1' # Looks like you failed 2 tests of 25. t\11loop-select-timer.t ...... Dubious, test returned 2 (wstat 512, 0x200) Failed 2/25 subtests Terminating on signal SIGBREAK(21) t\12loop-poll-signal.t ....... Dubious, test returned 21 (wstat 5376, 0x1500) Failed 13/18 subtests

Fri Apr 05 11:20:47 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added

On Fri Jan 04 07:10:58 2013, gabor@szabgab.com wrote: Show quoted text

> Starwberry Perl 5.12.3 (32 bit) > On 5.16.2 I could not even get to that point as Future-0.07.tar.gz > failed to install. (Report sent to CPANTESTERS.)

Newest Future (0.12) appears to work fine on Windows now. Show quoted text

> # Failed test '$readready after pipe HUP' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 267. > # got: '0' > # expected: '1'

I've been looking into this one from a number of reports. I'm coming to the conclusion that pipe + IO::Poll simply Does Not Work on MSWin32. At all. When the pipe hits an EOF condition, the underlying poll() implementation does not set any revents bits at all on it. This makes it impossible to handle. I really think this is an upstream bug. Show quoted text

> # Failed test 'regular file is readready' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 380. > # got: '0' > # expected: '1' > > # Failed test 'regular file is writeready' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 381. > # got: '0' > # expected: '1' > # Looks like you failed 3 tests of 21.

Oops; bug in my use of S_ISREG and stat(). Attached is a patch to fix this. Show quoted text

> t\10loop-poll-io.t ........... > Dubious, test returned 3 (wstat 768, 0x300) > Failed 3/21 subtests > (less 2 skipped subtests: 16 okay) > > # Failed test '$readready before pipe HUP' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 260. > # got: '1' > # expected: '0' > # Looks like you failed 1 test of 21. > t\10loop-select-io.t .........

Hrm. Readable -before- the HUP. That feels odd. Show quoted text

> Dubious, test returned 1 (wstat 256, 0x100) > Failed 1/21 subtests > (less 2 skipped subtests: 18 okay) > > # Failed test 'One ->loop_once(1) sufficient for a single 0.01 > second timer' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 505. > # got: '2' > # expected: '1' > > # Failed test 'One ->loop_once(1) sufficient for a single 0.1 second > timer' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 505. > # got: '2' > # expected: '1' > # Looks like you failed 2 tests of 25. > t\11loop-poll-timer.t ........ > Dubious, test returned 2 (wstat 512, 0x200) > Failed 2/25 subtests > > # Failed test 'One ->loop_once(1) sufficient for a single 0.01 > second timer' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 505. > # got: '2' > # expected: '1' > > # Failed test 'One ->loop_once(1) sufficient for a single 0.1 second > timer' > # at C:\strawberry\cpan\build\IO-Async-0.53- > a69fW_\blib\lib/IO/Async/LoopTests.pm > line 505. > # got: '2' > # expected: '1' > # Looks like you failed 2 tests of 25. > t\11loop-select-timer.t ...... > Dubious, test returned 2 (wstat 512, 0x200) > Failed 2/25 subtests > Terminating on signal SIGBREAK(21) > t\12loop-poll-signal.t ....... > Dubious, test returned 21 (wstat 5376, 0x1500) > Failed 13/18 subtests

These timer tests have now been revoked as they're way too sensitive. -- Paul Evans

Subject:

rt82402-stat.patch

=== modified file 'lib/IO/Async/Loop/Poll.pm' --- lib/IO/Async/Loop/Poll.pm 2013-03-10 22:56:38 +0000 +++ lib/IO/Async/Loop/Poll.pm 2013-04-05 15:19:16 +0000 @@ -255,7 +255,7 @@ $params{on_write_ready} and $mask |= POLLOUT; $params{on_hangup} and $mask |= POLLHUP; - if( FAKE_ISREG_READY and S_ISREG(stat $handle) ) { + if( FAKE_ISREG_READY and S_ISREG +(stat $handle)[2] ) { $self->{fake_isreg}{$handle->fileno} = [ $handle, $mask ]; } @@ -281,7 +281,7 @@ $params{on_write_ready} and $mask &= ~POLLOUT; $params{on_hangup} and $mask &= ~POLLHUP; - if( FAKE_ISREG_READY and S_ISREG(stat $handle) ) { + if( FAKE_ISREG_READY and S_ISREG +(stat $handle)[2] ) { if( $mask ) { $self->{fake_isreg}{$handle->fileno} = [ $handle, $mask ]; } === modified file 'lib/IO/Async/Loop/Select.pm' --- lib/IO/Async/Loop/Select.pm 2013-04-05 13:01:27 +0000 +++ lib/IO/Async/Loop/Select.pm 2013-04-05 15:19:16 +0000 @@ -253,7 +253,7 @@ # but it does indicate exceptional vec( $self->{evec}, $fileno, 1 ) = 1 if SELECT_CONNECT_EVEC and $params{on_write_ready}; - vec( $self->{avec}, $fileno, 1 ) = 1 if FAKE_ISREG_READY and S_ISREG(stat $params{handle}); + vec( $self->{avec}, $fileno, 1 ) = 1 if FAKE_ISREG_READY and S_ISREG +(stat $params{handle})[2]; } sub unwatch_io @@ -270,7 +270,7 @@ vec( $self->{evec}, $fileno, 1 ) = 0 if SELECT_CONNECT_EVEC and $params{on_write_ready}; - vec( $self->{avec}, $fileno, 1 ) = 0 if FAKE_ISREG_READY and S_ISREG(stat $params{handle}); + vec( $self->{avec}, $fileno, 1 ) = 0 if FAKE_ISREG_READY and S_ISREG +(stat $params{handle})[2]; # vec will grow a bit vector as needed, but never shrink it. We'll trim # trailing null bytes

Fri Apr 05 11:20:56 2013 The RT System itself - Status changed from 'new' to 'open'

Fri Oct 11 08:50:59 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added

I've recently been working on some MSWin32 fixes, so hopefully things are now working as of the latest devel release: http://matrix.cpantesters.org/?dist=IO-Async%200.60_004;os=mswin32;reports=1 Please give that a go, and once I have a few more smoke test results for it, I think I'll call it 0.61. -- Paul Evans

Fri Oct 11 10:59:56 2013 gabor [...] szabgab.com - Correspondence added

Subject:	Re: [rt.cpan.org #82402] IO-Async-0.53 test stuck on Windows
Date:	Fri, 11 Oct 2013 16:59:39 +0200
To:	bug-IO-Async [...] rt.cpan.org
From:	Gabor Szabo <gabor [...] szabgab.com>

On Fri, Oct 11, 2013 at 3:51 PM, Paul Evans via RT <bug-IO-Async@rt.cpan.org> wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=82402 > > > I've recently been working on some MSWin32 fixes, so hopefully things are now working as of the latest devel release: > > http://matrix.cpantesters.org/?dist=IO-Async%200.60_004;os=mswin32;reports=1 > > Please give that a go, and once I have a few more smoke test results for it, I think I'll call it 0.61. >

Thanks for working on it and updating the ticket! I sent in a failing report to CPANTESTERS, but for faster turn-around the output was pasted here as well: CPAN::Reporter: Build result is 'pass', No errors. PEVANS/IO-Async-0.60.tar.gz C:\strawberry_5_16_2_1\perl\bin\perl.exe ./Build -- OK Running Build test t\00use.t .................... ok t\01timequeue.t .............. ok t\02os.t ..................... ok t\03loop-magic.t ............. ok t\04notifier.t ............... ok t\05notifier-child.t ......... ok t\06notifier-mixin.t ......... ok t\10loop-poll-io.t ........... ok t\10loop-select-io.t ......... ok t\11loop-poll-timer.t ........ ok t\11loop-select-timer.t ...... ok Terminating on signal SIGBREAK(21) t\12loop-poll-signal.t ....... Dubious, test returned 21 (wstat 5376, 0x1500) Failed 12/18 subtests Terminating on signal SIGBREAK(21) t\12loop-select-signal.t ..... Dubious, test returned 21 (wstat 5376, 0x1500) Failed 12/18 subtests t\13loop-poll-idle.t ......... ok t\13loop-select-idle.t ....... ok Nothing was ready after 10 second wait; called at C:\strawberry_5_16_2_1\cpan\build\IO-Async-0.60-2hMkq9\blib\lib/IO/Async/LoopTests.pm line 127 # Looks like you planned 12 tests but ran 5. # Looks like your test exited with 3 just after 5. t\14loop-poll-child.t ........ Dubious, test returned 3 (wstat 768, 0x300) Failed 7/12 subtests Nothing was ready after 10 second wait; called at C:\strawberry_5_16_2_1\cpan\build\IO-Async-0.60-2hMkq9\blib\lib/IO/Async/LoopTests.pm line 127 # Looks like you planned 12 tests but ran 5. # Looks like your test exited with 3 just after 5. t\14loop-select-child.t ...... Dubious, test returned 3 (wstat 768, 0x300) Failed 7/12 subtests 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\19loop-future.t ............ ok t\19test.t ................... ok t\20handle.t ................. ok t\21stream-1read.t ........... ok Nothing was ready after 10 second wait; called at t\21stream-2write.t line 267 # Tests were run but no plan was declared and done_testing() was not seen. t\21stream-2write.t .......... Dubious, test returned 9 (wstat 2304, 0x900) All 31 subtests passed t\21stream-3split.t .......... ok t\21stream-4encoding.t ....... ok t\22timer-absolute.t ......... ok t\22timer-countdown.t ........ ok t\22timer-periodic.t ......... ok Terminating on signal SIGBREAK(21) t\23signal.t ................. Dubious, test returned 21 (wstat 5376, 0x1500) All 6 subtests passed t\24listener.t ............... ok Nothing was ready after 10 second wait; called at t\25socket.t line 127 # Tests were run but no plan was declared and done_testing() was not seen. t\25socket.t ................. Dubious, test returned 255 (wstat 65280, 0xff00) All 11 subtests passed Nothing was ready after 10 second wait; called at t\26pid.t line 50 # Tests were run but no plan was declared and done_testing() was not seen. t\26pid.t .................... Dubious, test returned 3 (wstat 768, 0x300) All 6 subtests passed t\27file.t ................... ok t\28filestream.t ............. ok t\30loop-fork.t .............. Dubious, test returned 5 (wstat 1280, 0x500) No subtests run t\31loop-spawnchild.t ........ Dubious, test returned 42 (wstat 10752, 0x2a00) All 3 subtests passed t\32loop-spawnchild-setup.t .. Dubious, test returned 1 (wstat 256, 0x100) All 2 subtests passed t\33process.t ................ All 8 subtests passed t\34process-handles.t ........ All 2 subtests passed t\35loop-openchild.t ......... No subtests run t\36loop-runchild.t .......... No subtests run t\37loop-child-root.t ........ Dubious, test returned 255 (wstat 65280, 0xff00) All 1 subtests passed t\40channel.t ................ ok t\41routine.t ................ Dubious, test returned 255 (wstat 65280, 0xff00) All 3 subtests passed t\42function.t ............... Dubious, test returned 255 (wstat 65280, 0xff00) All 3 subtests passed t\50resolver.t ............... Dubious, test returned 255 (wstat 65280, 0xff00) All 6 subtests passed (less 5 skipped subtests: 1 okay) t\51loop-connect.t ........... ok t\52loop-listen.t ............ Dubious, test returned 255 (wstat 65280, 0xff00) All 4 subtests passed t\53loop-extend.t ............ ok t\60protocol.t ............... ok t\61protocol-stream.t ........ ok t\62protocol-linestream.t .... ok t\63handle-connect.t ......... ok t\99pod.t .................... ok Test Summary Report ------------------- t\12loop-poll-signal.t (Wstat: 5376 Tests: 6 Failed: 0) Non-zero exit status: 21 Parse errors: Bad plan. You planned 18 tests but ran 6. t\12loop-select-signal.t (Wstat: 5376 Tests: 6 Failed: 0) Non-zero exit status: 21 Parse errors: Bad plan. You planned 18 tests but ran 6. t\14loop-poll-child.t (Wstat: 768 Tests: 5 Failed: 0) Non-zero exit status: 3 Parse errors: Bad plan. You planned 12 tests but ran 5. t\14loop-select-child.t (Wstat: 768 Tests: 5 Failed: 0) Non-zero exit status: 3 Parse errors: Bad plan. You planned 12 tests but ran 5. t\21stream-2write.t (Wstat: 2304 Tests: 31 Failed: 0) Non-zero exit status: 9 Parse errors: No plan found in TAP output t\23signal.t (Wstat: 5376 Tests: 6 Failed: 0) Non-zero exit status: 21 Parse errors: No plan found in TAP output t\25socket.t (Wstat: 65280 Tests: 11 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output t\26pid.t (Wstat: 768 Tests: 6 Failed: 0) Non-zero exit status: 3 Parse errors: No plan found in TAP output t\30loop-fork.t (Wstat: 1280 Tests: 0 Failed: 0) Non-zero exit status: 5 Parse errors: No plan found in TAP output t\31loop-spawnchild.t (Wstat: 10752 Tests: 3 Failed: 0) Non-zero exit status: 42 Parse errors: No plan found in TAP output t\32loop-spawnchild-setup.t (Wstat: 256 Tests: 2 Failed: 0) Non-zero exit status: 1 Parse errors: No plan found in TAP output t\33process.t (Wstat: 0 Tests: 8 Failed: 0) Parse errors: No plan found in TAP output t\34process-handles.t (Wstat: 0 Tests: 2 Failed: 0) Parse errors: No plan found in TAP output t\35loop-openchild.t (Wstat: 0 Tests: 0 Failed: 0) Parse errors: No plan found in TAP output t\36loop-runchild.t (Wstat: 0 Tests: 0 Failed: 0) Parse errors: No plan found in TAP output t\37loop-child-root.t (Wstat: 65280 Tests: 1 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output t\41routine.t (Wstat: 65280 Tests: 3 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output t\42function.t (Wstat: 65280 Tests: 3 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output t\50resolver.t (Wstat: 65280 Tests: 6 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output t\52loop-listen.t (Wstat: 65280 Tests: 4 Failed: 0) Non-zero exit status: 255 Parse errors: No plan found in TAP output Files=57, Tests=1020, 199 wallclock secs ( 0.11 usr + 0.43 sys = 0.54 CPU) Result: FAIL Failed 20/57 test programs. 0/1020 subtests failed.

Fri Oct 11 11:13:35 2013 leonerd-cpan [...] leonerd.org.uk - Correspondence added

On Fri Oct 11 10:59:56 2013, gabor@szabgab.com wrote: Show quoted text

> CPAN::Reporter: Build result is 'pass', No errors. > PEVANS/IO-Async-0.60.tar.gz > C:\strawberry_5_16_2_1\perl\bin\perl.exe ./Build -- OK

This is the latest /stable/ version, 0.60. You'll want to test the /devel/ version, which is later, at 0.60_004: Show quoted text

cpan> test PEVANS/IO-Async-0.60_004.tar.gz

-- Paul Evans

Fri Oct 11 12:05:10 2013 gabor [...] szabgab.com - Correspondence added

Subject:	Re: [rt.cpan.org #82402] IO-Async-0.53 test stuck on Windows
Date:	Fri, 11 Oct 2013 18:04:54 +0200
To:	bug-IO-Async [...] rt.cpan.org
From:	Gabor Szabo <gabor [...] szabgab.com>

Show quoted text

> This is the latest /stable/ version, 0.60. > > You'll want to test the /devel/ version, which is later, at 0.60_004: >

> cpan> test PEVANS/IO-Async-0.60_004.tar.gz

Oh, great! Everything passes! Report sent to CPANTESTERS. thank you!

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

Finally all working at 0.61 \o/ -- Paul Evans

Wed Jan 08 20:01:40 2014 leonerd-cpan [...] leonerd.org.uk - Status changed from 'open' to 'resolved'

Wed Jan 08 20:01:40 2014 leonerd-cpan [...] leonerd.org.uk - Fixed in 0.61 added