{"thread":{"id":"26453","subject":"t7006 sometimes hangs in cronjobs on OS X","startedAt":"2011-02-09T14:38:46Z","lastAt":"2011-02-17T12:38:52Z","messageCount":12,"participants":["Thomas Rast","Jeff King","Ben Walton","Jonathan Nieder"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"160766","messageId":"201102091538.46594.trast@student.ethz.ch","threadId":"26453","inReplyTo":null,"subject":"t7006 sometimes hangs in cronjobs on OS X","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2011-02-09T14:38:46Z","receivedAt":"2011-02-09T14:38:46Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Hi *,\n\nI have been running a nightly next&pu smoke tester each on RHEL5 and\nOS X.  For quite some time (at least a month), t7006 gets stuck\nrandomly (i.e., not every night).  [This has been a bit of a problem\nbecause it keeps a lot of processes stuck on the machine and eats into\nmy ulimit, but that's the case with any stuck process; I'll have to\nthink about a good solution to that.]\n\nThe relevant part of 'ps xwww' is\n\n  65211   ??  SN     0:00.03 /bin/sh t7006-pager.sh\n  65798   ??  SN     0:00.04 /usr/bin/perl /Users/trast/git-smoke/t/test-terminal.perl git --no-pager log\n  65846   ??  ZN     0:00.00 (git)\n  65847   ??  ZN     0:00.00 (perl5.10.0)\n\nEverything runs from a cronjob, so it does not have a terminal.  If I\nSIGTERM the first perl process, the script continues and I eventually\nget the normal results (upload to smoke.nix.git.is and emailed\nreport).\n\nThe Cc list is a bit of a random guess based on who worked on this;\nfrom the 'git --no-pager log' you can see that the test got stuck in\nthe 'no pager with --no-pager' test, but that was introduced 10 months\nago.  It may very well have been broken all the time, or also for\nother commands.\n\nSo if you have any idea what the problem could be or what I should be\nlooking for, help would be much appreciated...\n\n\nSome files that may be relevant:\n\nCrontab entry:\n0 5 * * * cd ~ && . .bashrc && ./do-the-smoke.sh\n\n---- 8< ---- ~/do-the-smoke.sh ---- 8< ----\n#!/bin/bash\n\ncd ~/git-smoke\ngit fetch -q\n\ndoit () {\n    branch=\"$1\"\n    git checkout origin/\"$branch\" || exit 1\n\n    make -j12 || exit 1\n    cd t\n    make clean\n    TEST_JOBS=6 nice make smoke\n    TEST_JOBS=6 nice make smoke_report SMOKE_COMMENT=\"Darwin 10.5 $branch\" SMOKE_TAGS=\"$branch, Darwin 10.5, NO_SVN_TESTS, NO_EXPAT\"\n}\n\n( doit next )\n( doit pu )\n---- >8 ---- >8 ----\n\n---- 8< ---- ~/git-smoke/config.mak ---- 8< ----\nCFLAGS = -Wall -O3 -g\nTHREADED_DELTA_SEARCH = 1\nNO_SVN_TESTS = 1\nASCIIDOC8 = 1\nASCIIDOC_NO_ROFF = 1\nGNU_ROFF = 1\nBLK_SHA1 = 1\nprefix = /home/thomas/.local\nNO_EXPAT = 1\nNO_GETTEXT = 1\nSMOKE_USERNAME = trast\nSMOKE_PASSWORD = I'm not telling you :-)\nSMOKE_COMMENT = RHEL5.5\n---- >8 ---- >8 ----\n\n(I just noticed that the above 'prefix' makes no sense because $HOME\nis /Users/trast, but I'm not installing it anyway...)\n\n-- \nThomas Rast\ntrast@{inf,student}.ethz.ch\n"},{"id":"160780","messageId":"1297276090-sup-7829@pinkfloyd.chass.utoronto.ca","threadId":"26453","inReplyTo":"201102091538.46594.trast@student.ethz.ch","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Ben Walton","fromEmail":"bwalton@artsci.utoronto.ca","sentAt":"2011-02-09T18:30:37Z","receivedAt":"2011-02-09T18:30:37Z","isPatch":false,"sender":{"key":"bdwalton@gmail.com","avatar":"https://avatars.githubusercontent.com/u/396061?v=4"},"body":"Excerpts from Thomas Rast's message of Wed Feb 09 09:38:46 -0500 2011:\n\n> I have been running a nightly next&pu smoke tester each on RHEL5 and\n> OS X.  For quite some time (at least a month), t7006 gets stuck\n> randomly (i.e., not every night).  [This has been a bit of a problem\n> because it keeps a lot of processes stuck on the machine and eats\n> into my ulimit, but that's the case with any stuck process; I'll\n> have to think about a good solution to that.]\n\nI'm also seeing this test fail when runing the packaging tools for\nOpenCSW.  I haven't had a chance to investigate yet, but manual tests\nof the script have run without errors so far.  It's only during the\nautomated build that it fails.  The automated build is initiated\nmanually but is run through a Makefile wrapper that will drastically\nalter the environment.  Beyond this, I have no further input.  I'm\nhoping to spend some time on it in the next few days.\n\nThanks\n-Ben\n--\nBen Walton\nSystems Programmer - CHASS\nUniversity of Toronto\nC:416.407.5610 | W:416.978.4302\n"},{"id":"160777","messageId":"20110209190900.GA8314@sigill.intra.peff.net","threadId":"26453","inReplyTo":"201102091538.46594.trast@student.ethz.ch","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2011-02-09T19:09:00Z","receivedAt":"2011-02-09T19:09:00Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Feb 09, 2011 at 03:38:46PM +0100, Thomas Rast wrote:\n\n> I have been running a nightly next&pu smoke tester each on RHEL5 and\n> OS X.  For quite some time (at least a month), t7006 gets stuck\n> randomly (i.e., not every night).  [This has been a bit of a problem\n> because it keeps a lot of processes stuck on the machine and eats into\n> my ulimit, but that's the case with any stuck process; I'll have to\n> think about a good solution to that.]\n> \n> The relevant part of 'ps xwww' is\n> \n>   65211   ??  SN     0:00.03 /bin/sh t7006-pager.sh\n>   65798   ??  SN     0:00.04 /usr/bin/perl /Users/trast/git-smoke/t/test-terminal.perl git --no-pager log\n>   65846   ??  ZN     0:00.00 (git)\n>   65847   ??  ZN     0:00.00 (perl5.10.0)\n\nHmm. The zombie git process implies to me that git has exited, but for\nsome reason we are still stuck in the copy-to-terminal loop and haven't\nreaped it. But the zombie perl process confuses me.  We fork a second\ntime so that one process copies stderr and the other one copies stdout.\nIs the second perl process the stderr copier, and we are still blocking\non copying stdout for some reason? But then why is the command name\ndifferent? Is /usr/bin/perl a wrapper script on your platform?\n\nHave you tried running strace on the surviving perl process to see what\nit's doing? Presumably it's just hung on a read() syscall.\n\nOr maybe try stracing the whole thing from the start, which may be more\ninformative, like:\n\ndiff --git a/t/lib-terminal.sh b/t/lib-terminal.sh\nindex c383b57..f7e6b7f 100644\n--- a/t/lib-terminal.sh\n+++ b/t/lib-terminal.sh\n@@ -13,7 +13,7 @@ test_expect_success 'set up terminal for tests' '\n \t\t\t\techo >&4 \"test_terminal: need to declare TTY prerequisite\"\n \t\t\t\treturn 127\n \t\t\tfi\n-\t\t\t\"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \"$@\"\n+\t\t\tstrace -f \"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \"$@\"\n \t\t}\n \tfi\n '\n\nand giving us the stderr dump (or perhaps redirecting strace output to a\nfile and saving it)?\n\n>     TEST_JOBS=6 nice make smoke\n\nIf you use TEST_JOBS=1, does it still happen? I can't imagine what race\ncondition would cause this, but there are other tests use\nlib-terminal.sh, so perhaps there is some interference there.\n\n-Peff\n"},{"id":"160778","messageId":"201102092016.55078.trast@student.ethz.ch","threadId":"26453","inReplyTo":"20110209190900.GA8314@sigill.intra.peff.net","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2011-02-09T19:16:54Z","receivedAt":"2011-02-09T19:16:54Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Jeff King wrote:\n> On Wed, Feb 09, 2011 at 03:38:46PM +0100, Thomas Rast wrote:\n> \n> > I have been running a nightly next&pu smoke tester each on RHEL5 and\n> > OS X.  For quite some time (at least a month), t7006 gets stuck\n> > randomly (i.e., not every night).\n\nBTW, I just noticed when re-reading this that it's a bit confusing.\nIt never hangs on RHEL (i.e. Linux), only on OS X.  (And I only\nreported it now because I only just noticed that I had a month's worth\nof zombies hanging around. :-)\n\n> >   65211   ??  SN     0:00.03 /bin/sh t7006-pager.sh\n> >   65798   ??  SN     0:00.04 /usr/bin/perl /Users/trast/git-smoke/t/test-terminal.perl git --no-pager log\n> >   65846   ??  ZN     0:00.00 (git)\n> >   65847   ??  ZN     0:00.00 (perl5.10.0)\n> \n> Hmm. The zombie git process implies to me that git has exited, but for\n> some reason we are still stuck in the copy-to-terminal loop and haven't\n> reaped it. But the zombie perl process confuses me.  We fork a second\n> time so that one process copies stderr and the other one copies stdout.\n> Is the second perl process the stderr copier, and we are still blocking\n> on copying stdout for some reason?\n\nHow do I find out?\n\n> But then why is the command name\n> different? Is /usr/bin/perl a wrapper script on your platform?\n\nNo, it's your average OS X binary (i.e., 'file' says it has an image\nfor every platform etc.).\n\nThe command name apparently just changes when it becomes a zombie:\nwhen I run perl -e 'if (fork) {sleep 10;} else {sleep 5;}' they first\nshare the command line, but as soon as the child's sleep expires its\ncommand line changes to '(perl5.10.0)'.\n\nI'll have to put off the more involved experimentation somewhat :-(\n\n-- \nThomas Rast\ntrast@{inf,student}.ethz.ch\n"},{"id":"160781","messageId":"201102092122.19178.trast@student.ethz.ch","threadId":"26453","inReplyTo":"201102092016.55078.trast@student.ethz.ch","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2011-02-09T20:22:19Z","receivedAt":"2011-02-09T20:22:19Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Thomas Rast wrote:\n> I'll have to put off the more involved experimentation somewhat :-(\n\nOr not.\n\nAnyway, I managed to load the relevant parts of t7006 in an\ninteractive shell, and used\n\n  i=0\n  while test_terminal git --no-pager log >out.$i 2>&1; do\n    i=$(($i+1))\n    echo $i\n  done\n\nto trigger the race.  With\n\n  test_terminal () {\n    sudo \"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \"$@\"\n  }\n\nwhich is the closest to dtruss I can get without actually using it, I\nhit the race very quickly, usually in ~5 runs.  But using either one\nof\n\n  test_terminal () {\n    sudo dtruss \"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \"$@\"\n  }\n\n  test_terminal () {\n    sudo dtruss -f \"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \"$@\"\n  }\n\nslows down things so much that it did not hit the race in useful time\n(about 100 runs).  I also tried running 'dtruss -n perl' in another\nterminal and hoping it will hit a wall eventually, which does run a\nbit faster but also got nowhere in about 350 runs.\n\nRunning 'dtruss -n git' instead did hit the issue, and I have the\noutput saved away, but I'm not sure what I'd be looking for.  After\nall, the git process becomes a zombie:\n\n  47606 s006  S+     0:00.13 /usr/bin/perl /Users/trast/git/t/test-terminal.perl git --no-pager log\n  47607 s006  Z+     0:00.00 (git)\n  47608 s006  Z+     0:00.00 (perl5.10.0)\n\nThe output for pid 47607 ends in:\n\n  47607/0x1f7fec5:  write_nocancel(0x1, \"Author: A U Thor <author@example.com>\\n\\0\", 0x26)                 = 38 0\n  47607/0x1f7fec5:  write_nocancel(0x1, \"Date:   Thu Apr 7 15:13:13 2005 -0700\\n\\0\", 0x26)                 = 38 0\n  47607/0x1f7fec5:  write_nocancel(0x1, \"\\n\\0\", 0x1)               = 1 0\n  47607/0x1f7fec5:  write_nocancel(0x1, \"    initial\\n\\0\", 0xC)            = 12 0\n  47607/0x1f7fec5:  fstat64(0x1, 0x7FFF5FBFE8A0, 0x0)              = 0 0\n  47607/0x1f7fec5:  fstat64(0x1, 0x7FFF5FBFEF60, 0x0)              = 0 0\n  47607/0x1f7fec5:  close_nocancel(0x1)            = 0 0\n\nWhich seems rather unsurprising really :-(\n\nFinally, attaching dtruss after hitting the race gives no output when\nI finally kill it.\n\n-- \nThomas Rast\ntrast@{inf,student}.ethz.ch\n"},{"id":"160782","messageId":"20110209205056.GA2083@sigill.intra.peff.net","threadId":"26453","inReplyTo":"201102092122.19178.trast@student.ethz.ch","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2011-02-09T20:50:57Z","receivedAt":"2011-02-09T20:50:57Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Feb 09, 2011 at 09:22:19PM +0100, Thomas Rast wrote:\n\n> Thomas Rast wrote:\n> > I'll have to put off the more involved experimentation somewhat :-(\n> \n> Or not.\n> \n> Anyway, I managed to load the relevant parts of t7006 in an\n> interactive shell, and used\n> \n>   i=0\n>   while test_terminal git --no-pager log >out.$i 2>&1; do\n>     i=$(($i+1))\n>     echo $i\n>   done\n\nGreat, that is a much smaller bit to work with. I of course can't\nreplicate it on my Linux boxes, though. :(\n\n> Running 'dtruss -n git' instead did hit the issue, and I have the\n> output saved away, but I'm not sure what I'd be looking for.  After\n> all, the git process becomes a zombie:\n> \n>   47606 s006  S+     0:00.13 /usr/bin/perl /Users/trast/git/t/test-terminal.perl git --no-pager log\n>   47607 s006  Z+     0:00.00 (git)\n>   47608 s006  Z+     0:00.00 (perl5.10.0)\n\nYeah, I think the problem is going to be in the perl process, but...\n\n> The output for pid 47607 ends in:\n> \n>   47607/0x1f7fec5:  write_nocancel(0x1, \"Author: A U Thor <author@example.com>\\n\\0\", 0x26)                 = 38 0\n>   47607/0x1f7fec5:  write_nocancel(0x1, \"Date:   Thu Apr 7 15:13:13 2005 -0700\\n\\0\", 0x26)                 = 38 0\n>   47607/0x1f7fec5:  write_nocancel(0x1, \"\\n\\0\", 0x1)               = 1 0\n>   47607/0x1f7fec5:  write_nocancel(0x1, \"    initial\\n\\0\", 0xC)            = 12 0\n>   47607/0x1f7fec5:  fstat64(0x1, 0x7FFF5FBFE8A0, 0x0)              = 0 0\n>   47607/0x1f7fec5:  fstat64(0x1, 0x7FFF5FBFEF60, 0x0)              = 0 0\n>   47607/0x1f7fec5:  close_nocancel(0x1)            = 0 0\n> \n> Which seems rather unsurprising really :-(\n\nIt doesn't close(2) also? That could be the problem. I would expect it\nalso to exit().\n\n> Finally, attaching dtruss after hitting the race gives no output when\n> I finally kill it.\n\nYeah, it is probably stuck in some syscall. You could try instrumenting\nyour test-terminal.perl like:\n\ndiff --git a/t/test-terminal.perl b/t/test-terminal.perl\nindex ee01eb9..1755017 100755\n--- a/t/test-terminal.perl\n+++ b/t/test-terminal.perl\n@@ -55,11 +55,15 @@ sub copy_stdio {\n \tdefined $pid or die \"fork failed: $!\";\n \tif (!$pid) {\n \t\tclose($out);\n+\t\tprint STDERR \"child: pumping stderr\\n\";\n \t\txsendfile(\\*STDERR, $err);\n+\t\tprint STDERR \"child: done pumping stderr\\n\";\n \t\texit 0;\n \t}\n \tclose($err);\n+\tprint STDERR \"parent: pumping stdout\\n\";\n \txsendfile(\\*STDOUT, $out);\n+\tprint STDERR \"parent: done pumping stdout\\n\";\n \tfinish_child($pid) == 0\n \t\tor exit 1;\n }\n\nand see which of those messages actually gets printed on the stuck case.\nMy suspicion is that one of the processes is getting stuck in xsendfile.\nIt may be the fault of File::Copy::copy, which I have seen be flaky\nbefore on non-regular files. We should arguably be using non-buffered\nI/O here anyway, so maybe try this:\n\ndiff --git a/t/test-terminal.perl b/t/test-terminal.perl\nindex ee01eb9..0d33da1 100755\n--- a/t/test-terminal.perl\n+++ b/t/test-terminal.perl\n@@ -3,7 +3,6 @@ use 5.008;\n use strict;\n use warnings;\n use IO::Pty;\n-use File::Copy;\n \n # Run @$argv in the background with stdio redirected to $out and $err.\n sub start_child {\n@@ -46,7 +45,13 @@ sub xsendfile {\n \t# from a disconnected terminal will return\n \t# EIO (as in AIX 4.x, IRIX, and Linux) or\n \t# end-of-file.  Either is fine.\n-\tcopy($in, $out, 4096) or $!{EIO} or die \"cannot copy from child: $!\";\n+\twhile (1) {\n+\t\tmy $r = sysread($in, my $buf, 4096);\n+\t\tlast if $r == 0;\n+\t\tlast if !defined $r and $!{EIO};\n+\t\tdie \"cannot copy from child: $!\" unless defined $r;\n+\t\tsyswrite($out, $buf);\n+\t}\n }\n \n sub copy_stdio {\n"},{"id":"160927","messageId":"20110212020321.GA24629@elie","threadId":"26453","inReplyTo":"20110209205056.GA2083@sigill.intra.peff.net","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2011-02-12T02:03:21Z","receivedAt":"2011-02-12T02:03:21Z","isPatch":false,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Jeff King wrote:\n\n> Yeah, it is probably stuck in some syscall. You could try instrumenting\n> your test-terminal.perl like:\n>\n> diff --git a/t/test-terminal.perl b/t/test-terminal.perl\n> index ee01eb9..1755017 100755\n> --- a/t/test-terminal.perl\n> +++ b/t/test-terminal.perl\n> @@ -55,11 +55,15 @@ sub copy_stdio {\n>  \tdefined $pid or die \"fork failed: $!\";\n>  \tif (!$pid) {\n>  \t\tclose($out);\n> +\t\tprint STDERR \"child: pumping stderr\\n\";\n[...]\n\nNice, I can reproduce this (kernel = Darwin 10.5.0, using Apple's perl\n5.10.0).  With\n\n\twhile ./test-terminal.perl echo hi >out.$i 2>&1\n\tdo\n\t\ti=$(($i + 1))\n\t\techo $i\n\tdone\n\nI get:\n\n\t$ cat out.28 \n\tchild: pumping stdout\n\tchild: pumping stderr\n\thi\n\tchild: done pumping stdout\n\nInstrumenting Copy.pm, I can see that we are stuck in sysread.\n\n\t31984: child: pumping stdout\n\t31984: enter copy loop.\n\t31984: time to read 4096...\n\t31986: child: pumping stderr\n\t31984: read returns with 4\n\t31984: about to write \"hi\n\t\"\n\t31984: pump 4 - 0, result = 4\n\t31984: time to read 4096...\n\t31986: enter copy loop.\n\t31986: time to read 4096...\n\t31986: read returns with 0\n\t31986: about to write \"\"\n\t31986: done!\n\t31986: successful return.\n\t31986: copy returns with 1 errno=\n\t31986: child: done pumping stderr\n\nRedirecting stderr by using 'xsendfile(\"elsewhere\", $err);' avoids\ntrouble.  Asking stderr and stdout to go to different places, like so:\n\n\t./test-terminal.perl echo hi >out.$i 2>err.$i\n\ndoes not avoid trouble.  Sometimes output includes some streams of\nnull bytes, which makes me suspect something awry in the kernel.\n"},{"id":"160928","messageId":"20110212020513.GB24629@elie","threadId":"26453","inReplyTo":"20110212020321.GA24629@elie","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2011-02-12T02:05:13Z","receivedAt":"2011-02-12T02:05:13Z","isPatch":false,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Jonathan Nieder wrote:\n\n> Sometimes output includes some streams of\n> null bytes, which makes me suspect something awry in the kernel.\n\n(or maybe that last part is a consequence of using stderr both for\nstandard, unbuffered output and our debugging output) :)\n"},{"id":"160930","messageId":"20110212051239.GA31606@sigill.intra.peff.net","threadId":"26453","inReplyTo":"20110212020321.GA24629@elie","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2011-02-12T05:12:39Z","receivedAt":"2011-02-12T05:12:39Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Feb 11, 2011 at 08:03:21PM -0600, Jonathan Nieder wrote:\n\n> Nice, I can reproduce this (kernel = Darwin 10.5.0, using Apple's perl\n> 5.10.0).  With\n> \n> \twhile ./test-terminal.perl echo hi >out.$i 2>&1\n> \tdo\n> \t\ti=$(($i + 1))\n> \t\techo $i\n> \tdone\n\nCool, more narrowing it down is nice. I'm not surprised it's a\ntest-terminal problem, not a git problem, but it's nice to see\nconfirmation.\n\n> I get:\n> \n> \t$ cat out.28 \n> \tchild: pumping stdout\n> \tchild: pumping stderr\n> \thi\n> \tchild: done pumping stdout\n\nHmm. So here, the stderr process hangs...\n\n> Instrumenting Copy.pm, I can see that we are stuck in sysread.\n> \n> \t31984: child: pumping stdout\n> \t31984: enter copy loop.\n> \t31984: time to read 4096...\n> \t31986: child: pumping stderr\n> \t31984: read returns with 4\n> \t31984: about to write \"hi\n> \t\"\n> \t31984: pump 4 - 0, result = 4\n> \t31984: time to read 4096...\n> \t31986: enter copy loop.\n> \t31986: time to read 4096...\n> \t31986: read returns with 0\n> \t31986: about to write \"\"\n> \t31986: done!\n> \t31986: successful return.\n> \t31986: copy returns with 1 errno=\n> \t31986: child: done pumping stderr\n\n...but here, the stdout process hangs. Weird.\n\nSo I'm not even sure our perl is bad. It's just that for some reason the\npty allocated by IO::Pty doesn't give us EOF sometimes. Hmm. Two curious\nthings I notice:\n\n  1. In your Copy.pm log above, it says read gives it 4 characters. But\n     \"hi\\n\" has only 3. CRLF or some other hidden character?\n\n  2. In test-terminal.perl, start_child clones the $out and $err handles\n     (which are the IO::Pty slaves). Then it closes $out, but not $err.\n     Why not? It shouldn't matter, since the child process ends up\n     dying, which should close all descriptors. And if that were the\n     problem, I would expect it to always hang on stderr, but your\n     examples show the hang on both descriptors.\n\n     Also, should the child be closing the pty masters? Again, it\n     shouldn't make a difference, both because the masters should be\n     waiting for the slaves to close to get EOF, and because the child\n     process dying should close all descriptors.\n\n     But the first could be explained by some differing bsd pty\n     semantics that Linux doesn't have. But for the second, I dunno.\n\nI would first try this patch:\n\ndiff --git a/t/test-terminal.perl b/t/test-terminal.perl\nindex ee01eb9..bfec680 100755\n--- a/t/test-terminal.perl\n+++ b/t/test-terminal.perl\n@@ -15,6 +15,7 @@ sub start_child {\n \t\topen STDOUT, \">&\", $out;\n \t\topen STDERR, \">&\", $err;\n \t\tclose $out;\n+\t\tclose $err;\n \t\texec(@$argv) or die \"cannot exec '$argv->[0]': $!\"\n \t}\n \treturn $pid;\n\nand then try this more drastic one:\n\ndiff --git a/t/test-terminal.perl b/t/test-terminal.perl\nindex ee01eb9..cce7de0 100755\n--- a/t/test-terminal.perl\n+++ b/t/test-terminal.perl\n@@ -12,9 +12,12 @@ sub start_child {\n \tif (not defined $pid) {\n \t\tdie \"fork failed: $!\"\n \t} elsif ($pid == 0) {\n-\t\topen STDOUT, \">&\", $out;\n-\t\topen STDERR, \">&\", $err;\n+\t\topen STDOUT, \">&\", $out->slave;\n+\t\topen STDERR, \">&\", $err->slave;\n+\t\tclose $out->slave;\n \t\tclose $out;\n+\t\tclose $err->slave;\n+\t\tclose $err;\n \t\texec(@$argv) or die \"cannot exec '$argv->[0]': $!\"\n \t}\n \treturn $pid;\n@@ -69,7 +72,7 @@ if ($#ARGV < 1) {\n }\n my $master_out = new IO::Pty;\n my $master_err = new IO::Pty;\n-my $pid = start_child(\\@ARGV, $master_out->slave, $master_err->slave);\n+my $pid = start_child(\\@ARGV, $master_out, $master_err);\n close $master_out->slave;\n close $master_err->slave;\n copy_stdio($master_out, $master_err);\n\nAlso, I don't know what kind of support you have for stuff like lsof,\nbut in theory we should be able to get a hung process, find the open\ndescriptor for the pty using lsof, match that descriptor with the other\nend of the pty, and then see which processes have that pty still open.\n\n> Redirecting stderr by using 'xsendfile(\"elsewhere\", $err);' avoids\n> trouble.\n\nThat seems doubly weird, since you are changing the _output_, not the\ninput. But the input is what is causing the hang.\n\n> Sometimes output includes some streams of null bytes, which makes me\n> suspect something awry in the kernel.\n\nYuck.\n\n-Peff\n"},{"id":"160940","messageId":"20110212083731.GB5182@elie","threadId":"26453","inReplyTo":"20110212051239.GA31606@sigill.intra.peff.net","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2011-02-12T08:37:44Z","receivedAt":"2011-02-12T08:37:44Z","isPatch":false,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Jeff King wrote:\n\n>   1. In your Copy.pm log above, it says read gives it 4 characters. But\n>      \"hi\\n\" has only 3.\n\nYes, it's \"hi\\r\\n\".\n\n> I would first try this patch:\n[...]\n> +++ b/t/test-terminal.perl\n> @@ -15,6 +15,7 @@ sub start_child {\n>  \t\topen STDOUT, \">&\", $out;\n>  \t\topen STDERR, \">&\", $err;\n>  \t\tclose $out;\n> +\t\tclose $err;\n>  \t\texec(@$argv) or die \"cannot exec '$argv->[0]': $!\"\n\nGood idea.  No change, alas (and likewise with the change to close\nthe pty master in the child).  It seems I have some reading to do.\n\nJonathan\n\n> and then try this more drastic one:\n[...]\n> --- a/t/test-terminal.perl\n> +++ b/t/test-terminal.perl\n> @@ -12,9 +12,12 @@ sub start_child {\n[...]\n> @@ -69,7 +72,7 @@ if ($#ARGV < 1) {\n>  }\n>  my $master_out = new IO::Pty;\n>  my $master_err = new IO::Pty;\n> -my $pid = start_child(\\@ARGV, $master_out->slave, $master_err->slave);\n> +my $pid = start_child(\\@ARGV, $master_out, $master_err);\n\nRuns through ~1000 iterations instead of 100 before hanging.\n\n> Also, I don't know what kind of support you have for stuff like lsof,\n> but in theory we should be able to get a hung process, find the open\n> descriptor for the pty using lsof, match that descriptor with the other\n> end of the pty, and then see which processes have that pty still open.\n\nTrial 1\n~~~~~~~\n PID 49145 (which has successfully pumped stdout):\n\n  0\t/dev/ttys001\n  1 write-only\tout.1707\n  2 write-only\tout.1707\n  3\t/dev/ptmx\t@ offset 4\n  5 write-only\tdebug.log\n\n PID 49147 (which is stuck in sysread trying to read stderr):\n\n  0\t/dev/ttys001\n  1 write-only\tout.1707\n  2 write-only\tout.1707\n  5 write-only\tdebug.log\n  6\t/dev/ptmx\t@ offset 0\n\nTrial 2\n~~~~~~~\n PID 51091 (which is stuck in sysread trying to read stdout):\n\n  0\t/dev/ttys001\n  1 write-only\tout.2017\n  2 write-only\tout.2017\n  3\t/dev/ptmx\t@ offset 4\n  5 write-only\tdebug.log\n\n PID 591093 (which successfully pumped stderr) is a zombie\n\n(echo was a zombie in both cases.)\n\n>> Redirecting stderr by using 'xsendfile(\"elsewhere\", $err);' avoids\n>> trouble.\n>\n> That seems doubly weird, since you are changing the _output_, not the\n> input. But the input is what is causing the hang.\n\nFalse alarm --- after about 2500 iterations it hangs.  Probably just\nchanged the timing.\n\n>> Sometimes output includes some streams of null bytes, which makes me\n>> suspect something awry in the kernel.\n>\n> Yuck.\n\nWas my mistake --- apparently I was writing files with holes.  Now I\nsend debug output to a separate file with O_APPEND and it hasn't\nhappened again.\n"},{"id":"160976","messageId":"20110213053159.GB15887@elie","threadId":"26453","inReplyTo":"201102091538.46594.trast@student.ethz.ch","subject":"Re: t7006 sometimes hangs in cronjobs on OS X","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2011-02-13T05:31:59Z","receivedAt":"2011-02-13T05:31:59Z","isPatch":false,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Thomas Rast wrote:\n\n> So if you have any idea what the problem could be or what I should be\n> looking for, help would be much appreciated...\n\nStill no idea, but I've passed the report on.\n\nhttps://rt.cpan.org/Ticket/Display.html?id=65692\n\nThanks, both.\n"},{"id":"161414","messageId":"20110217123852.GD7740@elie","threadId":"26453","inReplyTo":"201102091538.46594.trast@student.ethz.ch","subject":"[PATCH] tests: skip terminal output tests on OS X","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2011-02-17T12:38:52Z","receivedAt":"2011-02-17T12:38:52Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"On Mac OS X 10.5.0, test_terminal gets stuck reading from the pty\nmaster every once in a while.  To reproduce the problem:\n\n perl -MIO::Pty -MFile::Copy -e '\n\tfor (my $i = 0;; $i++) {\n\t\tmy $master = new IO::Pty;\n\t\tmy $slave = $master->slave;\n\t\tif (fork == 0) {\n\t\t\tclose $master or die \"close: $!\";\n\t\t\topen STDOUT, \">&\", $slave or die \"dup2: $!\";\n\t\t\tclose $slave or die \"close: $!\";\n\t\t\texec(\"echo\", \"hi\", $i) or die \"exec: $!\";\n\t\t}\n\t\tclose $slave or die \"close: $!\";\n\t\tcopy($master, \\*STDOUT) or die \"copy: $!\";\n\t\tclose $master or die \"close: $!\";\n\t\twait;\n\t}\n '\n\nIt blocks after 7000 iterations or so in sysread().  The relevant\nsysread() call is the second call by the parent, which presumably\nexecutes before the child dies but after the parent has read all\noutput from there.\n\nSince this is an intermitent problem, the quick check of terminal\nsupport in lib-terminal doesn't catch it.  Skip these tests on the Mac\nfor now.\n\nNoticed-by: Thomas Rast <trast@student.ethz.ch>\nSigned-off-by: Jonathan Nieder <jrnieder@gmail.com>\n---\nThanks for a reminder.\n\nI'd be interested to hear whether this happens on other BSDs, too.\nIt's possible that test_terminal should be using a select() loop\nto wait for input to be ready or the child to die instead of\nwaiting on one while the other happens.\n\n t/lib-terminal.sh |   22 +++++++++++++++++++---\n 1 files changed, 19 insertions(+), 3 deletions(-)\n\ndiff --git a/t/lib-terminal.sh b/t/lib-terminal.sh\nindex c383b57..58d911d 100644\n--- a/t/lib-terminal.sh\n+++ b/t/lib-terminal.sh\n@@ -1,8 +1,24 @@\n #!/bin/sh\n \n-test_expect_success 'set up terminal for tests' '\n-\tif\n-\t\ttest_have_prereq PERL &&\n+test_expect_success PERL 'set up terminal for tests' '\n+\t# Reading from the pty master seems to get stuck _sometimes_\n+\t# on Mac OS X 10.5.0, using Perl 5.10.0 or 5.8.9.\n+\t#\n+\t# Reproduction recipe: run\n+\t#\n+\t#\ti=0\n+\t#\twhile ./test-terminal.perl echo hi $i\n+\t#\tdo\n+\t#\t\t: $((i = $i + 1))\n+\t#\tdone\n+\t#\n+\t# After 2000 iterations or so it hangs.\n+\t# https://rt.cpan.org/Ticket/Display.html?id=65692\n+\t#\n+\tif test \"$(uname -s)\" = Darwin\n+\tthen\n+\t\t:\n+\telif\n \t\t\"$PERL_PATH\" \"$TEST_DIRECTORY\"/test-terminal.perl \\\n \t\t\tsh -c \"test -t 1 && test -t 2\"\n \tthen\n-- \n1.7.4.1\n"}]}