Hang on Win32 during make test? [rt.cpan.org #41811]

[toddr]

Migrated from rt.cpan.org#41811 (status was 'open')

Requestors:

• pshangov@yahoo.com

From pshangov@yahoo.com on 2008-12-18 16:29:32:

IPC::Run seems to hang during make test at t/run on Win32

Here is after I manually killed it after 10 minutes of running or so:

C:\temp\IPC-Run-0.82>dmake test
C:\strawberry\perl\bin\perl.exe "-MExtUtils::Command::MM" "-e"
"test_harness(0,
'blib\lib', 'blib\arch')" t/*.t
t/adopt............skipped: adopt not implemented yet
t/binmode..........ok
t/bogus............ok
t/filter...........ok
t/harness..........ok
t/io...............ok
t/kill_kill........skipped: Temporarily ignoring test failure on Win32
t/parallel.........ok
t/pty..............skipped: IO::Pty not installed
t/pump.............ok
t/run..............91/266 Terminating on signal SIGINT(2)

#   Failed test at t/run.t line 502.
t/run..............111/266
#   Failed test at t/run.t line 503.
Terminating on signal SIGINT(2)
Terminating on signal SIGINT(2)
Caught SIGINT. Trying to quit ...

Here is after I manually killed it after 30 minutes of running or so:

C:\temp\IPC-Run-0.82>dmake test
C:\strawberry\perl\bin\perl.exe "-MExtUtils::Command::MM" "-e"
"test_harness(0,
'blib\lib', 'blib\arch')" t/*.t
t/adopt............skipped: adopt not implemented yet
t/binmode..........ok
t/bogus............ok
t/filter...........ok
t/harness..........ok
t/io...............ok
t/kill_kill........skipped: Temporarily ignoring test failure on Win32
t/parallel.........ok
t/pty..............skipped: IO::Pty not installed
t/pump.............ok
t/run..............51/266 Terminating on signal SIGINT(2)
Terminating on signal SIGINT(2)
Terminating on signal SIGINT(2)
Terminating on signal SIGINT(2)
Caught SIGINT. Trying to quit ...
Bad file descriptor at t/run.t line 416.
Terminating on signal SIGINT(2)

Please contact me if I can provide further information.

From @schwern mschwern@cpan.org on 2009-07-06 21:45:55:

Same issue with 5.10.0.4 and 5.10.0.5 on WinXP 32 bit. It hangs in
run.t... sometimes. When it does its after test 207. That's this code:

##
## harness, pump, run
##
   $in  = 'SHOULD BE UNCHANGED';
   $out = 'REPLACE ME';
   $err = 'REPLACE ME';
   $? = 99;
   $fd_map = _map_fds;
   $h = start(
      [ @perl, '-pe', 'BEGIN { $| = 1 } print STDERR uc($_)' ],
      \$in, \$out, \$err,
   );

I've also had it hang after test 67 which I believe is this:

##
## Long output run through twice
##
## Adapted from a stress test by Aaron Elkiss <aelkiss@wam.umd.edu>
##

   $h = start [$perl, qw( -pe BEGIN{$|=1}1 )], \$in, \$out;
   $in = "\n";
   $out = "";
   pump $h until length $out;

[PhilterPaper]

This may be related. I have not been able to "upgrade" (via cpan subsystem) IPC::Run since 0.96. This is Windows 10, Strawberry Perl 5.26:

cpan> upgrade IPC::Run

Package namespace         installed    latest  in CPAN file
IPC::Run                       0.96 20180523.0  TODDR/IPC-Run-20180523.0.tar.gz
Running install for module 'IPC::Run'
Checksum for C:\STRAWB~1\cpan\sources\authors\id\T\TO\TODDR\IPC-Run-20180523.0.tar.gz ok
Configuring T/TO/TODDR/IPC-Run-20180523.0.tar.gz with Makefile.PL
Checking if your kit is complete...
Looks good
Generating a gmake-style Makefile
Writing Makefile for IPC::Run
Writing MYMETA.yml and MYMETA.json
  TODDR/IPC-Run-20180523.0.tar.gz
  C:\Strawberry\perl\bin\perl.exe Makefile.PL -- OK
Running make for T/TO/TODDR/IPC-Run-20180523.0.tar.gz
---- Unsatisfied dependencies detected during ----
----      TODDR/IPC-Run-20180523.0.tar.gz     ----
    IO::Pty [requires,optional]
cp lib/IPC/Run/Win32IO.pm blib\lib\IPC\Run\Win32IO.pm
cp lib/IPC/Run.pm blib\lib\IPC\Run.pm
cp lib/IPC/Run/Win32Pump.pm blib\lib\IPC\Run\Win32Pump.pm
cp lib/IPC/Run/Timer.pm blib\lib\IPC\Run\Timer.pm
cp lib/IPC/Run/Win32Helper.pm blib\lib\IPC\Run\Win32Helper.pm
cp lib/IPC/Run/Debug.pm blib\lib\IPC\Run\Debug.pm
cp lib/IPC/Run/IO.pm blib\lib\IPC\Run\IO.pm
  TODDR/IPC-Run-20180523.0.tar.gz
  C:\STRAWB~1\c\bin\gmake.exe -- OK
Running make test for TODDR/IPC-Run-20180523.0.tar.gz
"C:\Strawberry\perl\bin\perl.exe" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(0, 'blib\lib', 'blib\arch')" t/*.t
t/97_meta.t .......................... skipped: Author tests not required for installation
t/98_pod.t ........................... skipped: Author tests not required for installation
t/98_pod_coverage.t .................. skipped: Author tests not required for installation
t/99_perl_minimum_version.t .......... skipped: Author tests not required for installation
t/adopt.t ............................ skipped: adopt not implemented yet
t/autoflush.t ........................ ok
t/binmode.t .......................... ok
t/bogus.t ............................ ok
t/eintr.t ............................ No such signal: SIGUSR1 at t/eintr.t line 27.
t/eintr.t ............................ skipped: can't deliver a signal on this platform
t/filter.t ........................... ok
t/harness.t .......................... ok
t/io.t ............................... ok
t/kill_kill.t ........................ skipped: Temporarily ignoring test failure on Win32
t/parallel.t ......................... skipped: Parallel tests are dangerous on MSWin32
t/pty.t .............................. skipped: IO::Pty not installed
t/pump.t ............................. ok
t/readonly.t ......................... ok
t/run.t .............................. ok
t/run_stdin-callback-return-array.t .. ok
t/signal.t ........................... skipped: Skipping on Win32
t/timeout.t .......................... 9/26 Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminate batch job (Y/N)? Terminate batch job (Y/N)? y
y

Anyway, cpan crashes in a ball of fire, and has to be cleaned up on running cpan again. Is the test harness giving the SIGBREAK? If so, perhaps that test should be skipped on Windows. My point of entry was replying 'y' twice to "Terminate batch job (Y/N)?"

Seeing the warning about IO::Pty, I tried manually installing it:

cpan> install IO::Pty
Running install for module 'IO::Pty'
Fetching with LWP:
http://cpan.strawberryperl.com/authors/id/T/TO/TODDR/IO-Tty-1.12.tar.gz
Checksum for C:\STRAWB~1\cpan\sources\authors\id\T\TO\TODDR\IO-Tty-1.12.tar.gz ok
Scanning cache C:\STRAWB~1\cpan\build for sizes
............................................................................DONE
Configuring T/TO/TODDR/IO-Tty-1.12.tar.gz with Makefile.PL
This module requires a POSIX compliant system to work. Try cygwin if you need this module on windows
OS unsupported at Makefile.PL line 6.
Warning: No success on command[C:\Strawberry\perl\bin\perl.exe Makefile.PL]
  TODDR/IO-Tty-1.12.tar.gz
  C:\Strawberry\perl\bin\perl.exe Makefile.PL -- NOT OK
Stopping: 'install' failed for 'IO::Pty'.
Failed during this command:
 TODDR/IO-Tty-1.12.tar.gz                     : writemakefile NO 'C:\Strawberry\perl\bin\perl.exe Makefile.PL' returned status 65280

Could the lack of IO::Pty (both required and optional?) have something to do with it?

[nmisch]

In the checks for commit 26f687e (merge of pull request #148), t/run.t hanged.
nmisch/IPC-Run@4b12ccf reproduces this by enforcing a timeout and looping over
the troubled tests. It finds trouble with the same command reported above.
The troubled test varied; here are IPCRUNDEBUG=details for the two patterns
of hang I've observed:

2022-07-10T20:36:36.0295095Z IPC::Run 0006 012345678-0-2345 [#65(6484)]: cmd line: "C:\Strawberry\perl\bin\perl.EXE" "-pe" "BEGIN { $| = 1 } print STDERR uc($_)"
2022-07-10T20:36:36.0295613Z IPC::Run 0006 012345678-0-2345 [#65(6484)]: disabling inheritance of 10
2022-07-10T20:36:36.0296005Z IPC::Run 0006 01234567890-2345 [#65(6484)]: dup( 0 ) = 9
2022-07-10T20:36:36.0296415Z IPC::Run 0006 01234567890-2345 [#65(6484)]: disabling inheritance of 9
2022-07-10T20:36:36.0296849Z IPC::Run 0006 01234567890-2345 [#65(6484)]: disabling inheritance of 9
2022-07-10T20:36:36.0297265Z IPC::Run 0006 01234567890-2345 [#65(6484)]: moving 4 to kid's 0
2022-07-10T20:36:36.0297651Z IPC::Run 0006 01234567890-2345 [#65(6484)]: dup2( 4, 0 ) = 0
2022-07-10T20:36:36.0298067Z IPC::Run 0006 01234567890-2345 [#65(6484)]: disabling inheritance of 4
2022-07-10T20:36:36.0298509Z IPC::Run 0006 01234567890-2345 [#65(6484)]: disabling inheritance of 12
2022-07-10T20:36:36.0298850Z IPC::Run 0006 0123456789012345 [#65(6484)]: dup( 1 ) = 11
2022-07-10T20:36:36.0299178Z IPC::Run 0007 0123456789012345 [#65(6484)]: disabling inheritance of 11
2022-07-10T20:36:36.0299589Z IPC::Run 0007 0123456789012345 [#65(6484)]: disabling inheritance of 11
2022-07-10T20:36:36.0300002Z IPC::Run 0007 0123456789012345 [#65(6484)]: moving 13 to kid's 1
2022-07-10T20:36:36.0300327Z IPC::Run 0007 0123456789012345 [#65(6484)]: dup2( 13, 1 ) = 1
2022-07-10T20:36:36.0300977Z IPC::Run 0007 0123456789012345 [#65(6484)]: disabling inheritance of 13
2022-07-10T20:36:36.0301348Z IPC::Run 0007 0123456789012345 [#65(6484)]: disabling inheritance of 14
2022-07-10T20:36:36.0301687Z IPC::Run 0007 01234567890123456 [#65(6484)]: dup( 2 ) = 16
2022-07-10T20:36:36.0302030Z IPC::Run 0007 01234567890123456 [#65(6484)]: disabling inheritance of 16
2022-07-10T20:36:36.0302496Z IPC::Run 0007 01234567890123456 [#65(6484)]: disabling inheritance of 16
2022-07-10T20:36:36.0302974Z IPC::Run 0007 01234567890123456 [#65(6484)]: moving 15 to kid's 2
2022-07-10T20:36:36.0303300Z IPC::Run 0007 01234567890123456 [#65(6484)]: dup2( 15, 2 ) = 2
2022-07-10T20:36:36.0303641Z IPC::Run 0007 01234567890123456 [#65(6484)]: disabling inheritance of 15
2022-07-10T20:36:36.0304024Z Use of uninitialized value in concatenation (.) or string at (eval 6) line 119.
2022-07-10T20:36:36.0304603Z IPC::Run 0007 0123-------- [#(1296) 13>pump>12]: Entered
2022-07-10T20:36:36.0304929Z IPC::Run 0007 01234567890123456 [#65(6484)]: dup2( 9, 0 ) = 0
2022-07-10T20:36:36.0305324Z IPC::Run 0007 012345678-0123456 [#65(6484)]: close( 9 ) = 0
2022-07-10T20:36:36.0735551Z Use of uninitialized value in concatenation (.) or string at (eval 6) line 119.
2022-07-10T20:36:36.0738452Z IPC::Run 0007 0123-------- [#(1120) 15>pump>14]: Entered
2022-07-10T20:39:22.2297380Z IPC::Run 0007 012345678-0123456 [#65(6484)]: dup2( 11, 1 ) = 1
2022-07-10T20:39:22.2331500Z IPC::Run 0173 012345678-0-23456 [#65(6484)]: close( 11 ) = 0
2022-07-10T20:39:22.2350323Z IPC::Run 0173 012345678-0-23456 [#65(6484)]: dup2( 16, 2 ) = 2
2022-07-10T20:39:22.2352868Z IPC::Run 0173 012345678-0-2345 [#65(6484)]: close( 16 ) = 0
2022-07-10T20:39:22.2375661Z IPC::Run 0173 012345678-0-2345 [#65(6484)]: spawn() = 920
2022-07-10T20:39:22.2378424Z IPC::Run 0173 0123-5678-0-2345 [#65(6484)]: close( 4 ) = 0
2022-07-10T20:39:22.2380414Z Use of uninitialized value in concatenation (.) or string at (eval 6) line 119.
2022-07-10T20:39:22.2380953Z IPC::Run 0173 0123-5678-0-2-45 [#65(6484)]: close( 13 ) = 0
2022-07-10T20:39:22.2489920Z IPC::Run 0173 0123-------- [#(1296) 13>pump>12]: Exiting, transferred 0 chars
2022-07-10T20:39:22.2490311Z [20:39:22] t/run.t .............................. 
2022-07-10T20:39:22.2505208Z Use of uninitialized value in concatenation (.) or string at (eval 6) line 119.
2022-07-10T20:39:22.2505552Z Dubious, test returned 14 (wstat 3584, 0xe00)
2022-07-10T20:39:22.2578750Z IPC::Run 0173 0123-------- [#(1120) 15>pump>14]: Exiting, transferred 0 chars
2022-07-10T20:39:22.2579073Z Failed 55/288 subtests 

2022-07-10T21:28:04.1533455Z IPC::Run 0013 0123456789012 [#47(6120)]: cmd line: "C:\Strawberry\perl\bin\perl.EXE" "-lane" "print STDERR qq{2:$_}; print $F[0], q{ },lc($F[1])"
2022-07-10T21:28:04.1533877Z IPC::Run 0013 01234567890123 [#47(6120)]: dup( 0 ) = 13
2022-07-10T21:28:04.1534381Z IPC::Run 0013 01234567890123 [#47(6120)]: disabling inheritance of 13
2022-07-10T21:28:04.1534724Z IPC::Run 0013 01234567890123 [#47(6120)]: disabling inheritance of 13
2022-07-10T21:28:04.1535189Z IPC::Run 0013 01234567890123 [#47(6120)]: moving 4 to kid's 0
2022-07-10T21:28:04.1535493Z IPC::Run 0013 01234567890123 [#47(6120)]: dup2( 4, 0 ) = 0
2022-07-10T21:28:04.1535795Z IPC::Run 0013 01234567890123 [#47(6120)]: disabling inheritance of 4
2022-07-10T21:28:04.1536117Z IPC::Run 0013 012345678901234 [#47(6120)]: dup( 1 ) = 14
2022-07-10T21:28:04.1536432Z IPC::Run 0013 012345678901234 [#47(6120)]: disabling inheritance of 14
2022-07-10T21:28:04.1536762Z IPC::Run 0013 012345678901234 [#47(6120)]: disabling inheritance of 14
2022-07-10T21:28:04.1537212Z IPC::Run 0013 012345678901234 [#47(6120)]: moving 11 to kid's 1
2022-07-10T21:28:04.1537519Z IPC::Run 0013 012345678901234 [#47(6120)]: dup2( 11, 1 ) = 1
2022-07-10T21:28:04.1537910Z IPC::Run 0013 012345678901234 [#47(6120)]: disabling inheritance of 11
2022-07-10T21:28:04.1538209Z IPC::Run 0013 0123456789012345 [#47(6120)]: dup( 2 ) = 15
2022-07-10T21:28:04.1538525Z IPC::Run 0013 0123456789012345 [#47(6120)]: disabling inheritance of 15
2022-07-10T21:28:04.1538867Z IPC::Run 0013 0123456789012345 [#47(6120)]: disabling inheritance of 15
2022-07-10T21:28:04.1539296Z IPC::Run 0013 0123456789012345 [#47(6120)]: moving 12 to kid's 2
2022-07-10T21:28:04.1539607Z IPC::Run 0013 0123456789012345 [#47(6120)]: dup2( 12, 2 ) = 2
2022-07-10T21:28:04.2730697Z IPC::Run 0013 0123456789012345 [#47(6120)]: disabling inheritance of 12
2022-07-10T21:28:04.3706072Z IPC::Run 0013 0123456789012345 [#47(6120)]: dup2( 13, 0 ) = 0
2022-07-10T21:30:40.4673583Z IPC::Run 0013 0123456789012-45 [#47(6120)]: close( 13 ) = 0

When the timestamp jumps, that's a timeout signal ending the hang. I will
continue investigating.

[PhilterPaper]

I'm looking forward for this package to show up on CPAN so I can test the fixed install image on Windows. Thanks!

Add: as mentioned in #138, still not working, although it's not hanging (different failure).