{"thread":{"id":"44349","subject":"Prove \"Tests out of sequence\" Error","startedAt":"2016-10-21T04:14:58Z","lastAt":"2021-03-22T13:47:42Z","messageCount":47,"participants":["Lars Schneider","Stefan Beller","Jeff King","Jacob Keller","Junio C Hamano","Ævar Arnfjörð Bjarmason","SZEDER Gábor","Chris Torek","Johannes Schindelin"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"304556","messageId":"D9C1E13F-88A2-483E-A549-1C2294EACFEB@gmail.com","threadId":"44349","inReplyTo":null,"subject":"Prove \"Tests out of sequence\" Error","fromName":"Lars Schneider","fromEmail":"larsxschneider@gmail.com","sentAt":"2016-10-21T04:14:48Z","receivedAt":"2016-10-21T04:14:58Z","isPatch":false,"sender":{"key":"larsxschneider@gmail.com","avatar":"https://avatars.githubusercontent.com/u/477434?v=4"},"body":"Hi,\n\non TravisCI I see these weird \"Tests out of sequence\" errors with prove\nand they seem to not go away. I assume the reason that they not go away\nis that the \".prove\" file is carried over from on build to another (but I can't \nlook into this file on TravisCI).\n\nHas anyone an idea where these errors might come from?\n\n------------------------------------------------------------------------\nt5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)\n Parse errors: Tests out of sequence. Found (2) but expected (3)\n Tests out of sequence. Found (3) but expected (4)\n Tests out of sequence. Found (4) but expected (5)\n Bad plan. You planned 4 tests but ran 5.\nFiles=760, Tests=15109, 679 wallclock secs (21.91 usr 1.78 sys + 320.79 cusr 529.13 csys = 873.61 CPU)\nResult: FAIL\nmake[1]: *** [prove] Error 1\nmake: *** [test] Error 2\n------------------------------------------------------------------------\n\nExample:\nhttps://s3.amazonaws.com/archive.travis-ci.org/jobs/169385219/log.txt\n\nThanks,\nLars"},{"id":"304558","messageId":"CAGZ79kZo3LdcRmrjQTAvgx=H6U2tdjASK3qv5A2K5J2HQ2NvSw@mail.gmail.com","threadId":"44349","inReplyTo":"D9C1E13F-88A2-483E-A549-1C2294EACFEB@gmail.com","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2016-10-21T06:10:39Z","receivedAt":"2016-10-21T06:10:45Z","isPatch":false,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Thu, Oct 20, 2016 at 9:14 PM, Lars Schneider\n wrote:\n> Hi,\n>\n> on TravisCI I see these weird \"Tests out of sequence\" errors with prove\n> and they seem to not go away. I assume the reason that they not go away\n> is that the \".prove\" file is carried over from on build to another (but I can't\n> look into this file on TravisCI).\n>\n> Has anyone an idea where these errors might come from?\n>\n> ------------------------------------------------------------------------\n> t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)\n\npush quarantine is a new thing made by Jeff 2 weeks ago, IIRC.\n\n> Parse errors: Tests out of sequence. Found (2) but expected (3)\n> Tests out of sequence. Found (3) but expected (4)\n> Tests out of sequence. Found (4) but expected (5)\n> Bad plan. You planned 4 tests but ran 5.\n> Files=760, Tests=15109, 679 wallclock secs (21.91 usr 1.78 sys + 320.79 cusr 529.13 csys = 873.61 CPU)\n> Result: FAIL\n> make[1]: *** [prove] Error 1\n> make: *** [test] Error 2\n> ------------------------------------------------------------------------\n>\n> Example:\n> https://s3.amazonaws.com/archive.travis-ci.org/jobs/169385219/log.txt\n>\n> Thanks,\n> Lars\n"},{"id":"304560","messageId":"20161021082035.xad6wfny5i6wtshh@sigill.intra.peff.net","threadId":"44349","inReplyTo":"CAGZ79kZo3LdcRmrjQTAvgx=H6U2tdjASK3qv5A2K5J2HQ2NvSw@mail.gmail.com","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T08:20:35Z","receivedAt":"2016-10-21T08:20:45Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 20, 2016 at 11:10:39PM -0700, Stefan Beller wrote:\n\n> > on TravisCI I see these weird \"Tests out of sequence\" errors with prove\n> > and they seem to not go away. I assume the reason that they not go away\n> > is that the \".prove\" file is carried over from on build to another (but I can't\n> > look into this file on TravisCI).\n> >\n> > Has anyone an idea where these errors might come from?\n> >\n> > ------------------------------------------------------------------------\n> > t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)\n> \n> push quarantine is a new thing made by Jeff 2 weeks ago, IIRC.\n\nYes, but I do not see how it can trigger this:\n\n> > Parse errors: Tests out of sequence. Found (2) but expected (3)\n> > Tests out of sequence. Found (3) but expected (4)\n> > Tests out of sequence. Found (4) but expected (5)\n> > Bad plan. You planned 4 tests but ran 5.\n\nThe TAP output from one of our tests should look something like:\n\n ok 1 - subject one\n ok 2 - subject two\n ok 3 - subject three\n ok 4 - subject four\n # passed all 4 test(s)\n 1..4\n\nthe \"plan\" is the bit at the end. That looks like $test_count\naccidentally got incremented by one and we generated something like:\n\n ok 1 - subject one\n ok 3 - subject two\n ok 4 - subject three\n ok 5 - subject four\n 1..4\n\nwhich would explain the \"out of sequence\" errors as well as the \"planned\n4 but ran 5\".\n\nBut I do not see how the test script could screw that up. The counting\nis handled entirely by the harness in test-lib.sh.\n\nNor do I see how a stale .prove file could matter. It does not store\ninformation about the test plan at all. E.g., here is the entry from\nmine for t5547:\n\n t5547-push-quarantine.sh:\n elapsed: 0.0762169361114502\n gen: 1\n last_pass_time: 1477037708.741\n last_result: 0\n last_run_time: 1477037708.741\n last_todo: 0\n seq: 437\n total_passes: 1\n\nPuzzling.\n\n-Peff\n"},{"id":"304562","messageId":"20161021084348.dp4jfpfownodl7nz@sigill.intra.peff.net","threadId":"44349","inReplyTo":"20161021082035.xad6wfny5i6wtshh@sigill.intra.peff.net","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T08:43:48Z","receivedAt":"2016-10-21T08:43:55Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 04:20:35AM -0400, Jeff King wrote:\n\n> Yes, but I do not see how it can trigger this:\n> \n> > > Parse errors: Tests out of sequence. Found (2) but expected (3)\n> > > Tests out of sequence. Found (3) but expected (4)\n> > > Tests out of sequence. Found (4) but expected (5)\n> > > Bad plan. You planned 4 tests but ran 5.\n> \n> The TAP output from one of our tests should look something like:\n> \n> ok 1 - subject one\n> ok 2 - subject two\n> ok 3 - subject three\n> ok 4 - subject four\n> # passed all 4 test(s)\n> 1..4\n> \n> the \"plan\" is the bit at the end. That looks like $test_count\n> accidentally got incremented by one and we generated something like:\n> \n> ok 1 - subject one\n> ok 3 - subject two\n> ok 4 - subject three\n> ok 5 - subject four\n> 1..4\n> \n> which would explain the \"out of sequence\" errors as well as the \"planned\n> 4 but ran 5\".\n\nHmm, actually the numbering problem is the other way around. It finds 2\nbut expects 3, so it is more like:\n\n ok 1 - subject one\n ok 2 - something else stuck in here!\n ok 2 - subject two\n ...\n\nwhich gives us a clue. And thanks to TAP auto-numbering, you can also\ntrigger this like:\n\n ok 1 - subject one\n ok\n ok 2 - subject two\n\nThe \"ok\" by itself is taken to mean \"ok 2\". And now I have enough to\ngenerate this locally. t5547 does:\n\n test_commit ok &&\n ...\n git cat-file commit $commit\n\nwhich will print a line with just \"ok\" on it. Normally this is not sent\nto stdout at all; test output goes to /dev/null unless \"--verbose\" is\ngiven. When \"--verbose\" is used, we get all manner of random program\noutput intermingled with our TAP output, which is an accident waiting to\nhappen. Usually nobody cares, because they only use \"--verbose\" when\ndebugging a test individually (and nothing is parsing the TAP output).\nBut I can trigger the problem with:\n\n prove t5547-push-quarantine.sh :: -v\n\nThe Travis tests do exactly this (along with --tee to actually save the\noutput). It seems like a minor miracle that this is the first test\noutput that has actually triggered as TAP input. I'd suggest that the\nproblem is not in the test, though, but that our \"--verbose\" option is\nunsuitable for using with a TAP harness.\n\nThe obvious fix would be to send \"--verbose\" output to stderr, but I\nsuspect that would end up annoying for people who do:\n\n ./t5547-push-quarantine.sh -v | less\n\nto read long output. Probably we need some option like \"--log\" which\nlogs in the same way that \"--tee\" does, but _without_ sending the data\nto stdout. Naively, that just means replacing the \"tee\" invocation with\n\"cat\", but I suspect it will be a lot more complicated than that,\nbecause we still need to let the TAP output go to stdout.\n\n-Peff\n"},{"id":"304566","messageId":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","threadId":"44349","inReplyTo":"20161021084348.dp4jfpfownodl7nz@sigill.intra.peff.net","subject":"[PATCH 0/3] fix travis TAP/--verbose conflict","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T10:41:07Z","receivedAt":"2016-10-21T10:41:15Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:\n\n> The obvious fix would be to send \"--verbose\" output to stderr, but I\n> suspect that would end up annoying for people who do:\n> \n> ./t5547-push-quarantine.sh -v | less\n> \n> to read long output. Probably we need some option like \"--log\" which\n> logs in the same way that \"--tee\" does, but _without_ sending the data\n> to stdout. Naively, that just means replacing the \"tee\" invocation with\n> \"cat\", but I suspect it will be a lot more complicated than that,\n> because we still need to let the TAP output go to stdout.\n\nYeah, it was definitely a lot more complicated. This patch series fixes\nit.\n\n [1/3]: test-lib: handle TEST_OUTPUT_DIRECTORY with spaces\n [2/3]: test-lib: add --verbose-log option\n [3/3]: travis: use --verbose-log test option\n\n .travis.yml | 2 +-\n t/README | 6 ++++++\n t/test-lib.sh | 24 ++++++++++++++++++++----\n 3 files changed, 27 insertions(+), 5 deletions(-)\n\n-Peff\n"},{"id":"304567","messageId":"20161021104210.lvmet65avogogiqo@sigill.intra.peff.net","threadId":"44349","inReplyTo":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","subject":"[PATCH 1/3] test-lib: handle TEST_OUTPUT_DIRECTORY with spaces","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T10:42:10Z","receivedAt":"2016-10-21T10:42:17Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"We are careful in test_done to handle a results directory\nwith a space in it, but the \"--tee\" code path does not.\nDoing:\n\n export TEST_OUTPUT_DIRECTORY='/tmp/path with spaces'\n ./t000-init.sh --tee\n\nresults in errors. Let's consistently double-quote our path\nvariables so that this works.\n\nSigned-off-by: Jeff King \n---\nI imagine nobody cares much about this, but I just happened to notice it\nwhile writing the rest of the patches (and it's obviously quite easy to\nfix).\n\n t/test-lib.sh | 4 ++--\n 1 file changed, 2 insertions(+), 2 deletions(-)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 11562bde10..33cbbb7806 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -58,8 +58,8 @@ done,*)\n \tmkdir -p \"$TEST_OUTPUT_DIRECTORY/test-results\"\n \tBASE=\"$TEST_OUTPUT_DIRECTORY/test-results/$(basename \"$0\" .sh)\"\n \t(GIT_TEST_TEE_STARTED=done ${SHELL_PATH} \"$0\" \"$@\" 2>&1;\n-\t echo $? > $BASE.exit) | tee $BASE.out\n-\ttest \"$(cat $BASE.exit)\" = 0\n+\t echo $? >\"$BASE.exit\") | tee \"$BASE.out\"\n+\ttest \"$(cat \"$BASE.exit\")\" = 0\n \texit\n \t;;\n esac\n-- \n2.10.1.776.ge0e381e\n\n"},{"id":"304568","messageId":"20161021104759.hx6q7u66r3ll7l44@sigill.intra.peff.net","threadId":"44349","inReplyTo":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","subject":"[PATCH 2/3] test-lib: add --verbose-log option","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T10:48:00Z","receivedAt":"2016-10-21T10:48:07Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"The \"--verbose\" option redirects output from arbitrary\ntest commands to stdout. This is useful for examining the\noutput manually, like:\n\n ./t5547-push-quarantine.sh -v | less\n\nBut it also means that the output is intermingled with the\nTAP directives, which can confuse a TAP parser like \"prove\".\nThis has always been a potential problem, but became an\nissue recently when one test happened to output the word\n\"ok\" on a line by itself, which prove interprets as a test\nsuccess:\n\n $ prove t5547-push-quarantine.sh :: -v\n t5547-push-quarantine.sh .. 1/? To dest.git\n * [new branch] HEAD -> master\n To dest.git\n ! [remote rejected] reject -> reject (pre-receive hook declined)\n error: failed to push some refs to 'dest.git'\n fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file\n t5547-push-quarantine.sh .. Failed -1/4 subtests\n\n Test Summary Report\n -------------------\n t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)\n Parse errors: Tests out of sequence. Found (2) but expected (3)\n Tests out of sequence. Found (3) but expected (4)\n Tests out of sequence. Found (4) but expected (5)\n Bad plan. You planned 4 tests but ran 5.\n Files=1, Tests=5, 0 wallclock secs ( 0.01 usr + 0.01 sys = 0.02 CPU)\n Result: FAIL\n\nOne answer is \"if it hurts, don't do it\", but that's not\nquite the whole story. The Travis tests use \"--verbose\n--tee\" so that they can get the benefit of prove's parallel\noptions, along with a verbose log in case there is a\nfailure. We just need the verbose output to go to the log,\nbut keep stdout clean.\n\nGetting this right turns out to be surprisingly difficult.\nHere's the progression of alternatives I considered:\n\n 1. Add an option to write verbose output to stderr. This is\n hard to capture, though, because we want each test to\n have its own log (because they're all run in parallel\n and the jumbled output would be useless).\n\n 2. Add an option to write verbose output to a file in\n test-results. This works, but the log is missing all of\n the non-verbose output, which gives context.\n\n 3. Like (2), but teach say_color() to additionally output\n to the log. This mostly works, but misses any output\n that happens outside of the say() functions (which isn't\n a lot, but is a potential maintenance headache).\n\n 4. Like (2), but make the log file the same as the \"--tee\"\n file. That almost works, but now we have two processes\n opening the same file. That gives us two separate\n descriptors, each with their own idea of the current\n position. They'll each start writing at offset 0, and\n overwrite each other's data.\n\n 5. Like (4), but in each case open the file for appending.\n That atomically positions each write at the end of the\n file.\n\n It's possible we may still get sheared writes between\n the two processes, but this is already the case when\n writing to stdout. It's not a problem in practice\n because the test harness generally waits for snippets to\n finish before writing the TAP output.\n\n We can ignore buffering issues with tee, because POSIX\n mandates that it does not buffer. Likewise, POSIX\n specifies \"tee -a\", so it should be available\n everywhere.\n\nThis patch implements option (5), which seems to work well\nin practice.\n\nSigned-off-by: Jeff King \n---\nArguably we don't need a new option for this, and could just do it\nautomatically. I wasn't sure when, though:\n\n - if \"--tee --verbose\" triggers it, then somebody running that outside\n of \"prove\" who _wants_ the verbose output on stdout (because they're\n looking at it, but also want to save a copy to the log) would be\n regressed\n\n - possibly \"--tee\" could just always write verbose output to the\n logfile (but not stdout). That's kind of weirdly magical, and we'd\n have to update the travis invocation anyway.\n\nSo I went with a new option which implies the other ones. No chance of\nregression, and it's easy to explain.\n\n t/README | 6 ++++++\n t/test-lib.sh | 22 +++++++++++++++++++---\n 2 files changed, 25 insertions(+), 3 deletions(-)\n\ndiff --git a/t/README b/t/README\nindex 0f764c0aef..4982d1c521 100644\n--- a/t/README\n+++ b/t/README\n@@ -153,6 +153,12 @@ appropriately before running \"make\".\n \tAs the names depend on the tests' file names, it is safe to\n \trun the tests with this option in parallel.\n \n+--verbose-log::\n+\tWrite verbose output to the same logfile as `--tee`, but do\n+\t_not_ write it to stdout. Unlike `--tee --verbose`, this option\n+\tis safe to use when stdout is being consumed by a TAP parser\n+\tlike `prove`. Implies `--tee` and `--verbose`.\n+\n --with-dashes::\n \tBy default tests are run without dashed forms of\n \tcommands (like git-commit) in the PATH (it only uses\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 33cbbb7806..85946ec40d 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -54,11 +54,21 @@ case \"$GIT_TEST_TEE_STARTED, $* \" in\n done,*)\n \t# do not redirect again\n \t;;\n-*' --tee '*|*' --va'*)\n+*' --tee '*|*' --va'*|*' --verbose-log '*)\n \tmkdir -p \"$TEST_OUTPUT_DIRECTORY/test-results\"\n \tBASE=\"$TEST_OUTPUT_DIRECTORY/test-results/$(basename \"$0\" .sh)\"\n+\n+\t# Make this filename available to the sub-process in case it is using\n+\t# --verbose-log.\n+\tGIT_TEST_TEE_OUTPUT_FILE=$BASE.out\n+\texport GIT_TEST_TEE_OUTPUT_FILE\n+\n+\t# Truncate before calling \"tee -a\" to get rid of the results\n+\t# from any previous runs.\n+\t>\"$GIT_TEST_TEE_OUTPUT_FILE\"\n+\n \t(GIT_TEST_TEE_STARTED=done ${SHELL_PATH} \"$0\" \"$@\" 2>&1;\n-\t echo $? >\"$BASE.exit\") | tee \"$BASE.out\"\n+\t echo $? >\"$BASE.exit\") | tee -a \"$GIT_TEST_TEE_OUTPUT_FILE\"\n \ttest \"$(cat \"$BASE.exit\")\" = 0\n \texit\n \t;;\n@@ -246,6 +256,9 @@ do\n \t\ttrace=t\n \t\tverbose=t\n \t\tshift ;;\n+\t--verbose-log)\n+\t\tverbose_log=t\n+\t\tshift ;;\n \t*)\n \t\techo \"error: unknown test option '$1'\" >&2; exit 1 ;;\n \tesac\n@@ -319,7 +332,10 @@ fi\n \n exec 5>&1\n exec 6<&0\n-if test \"$verbose\" = \"t\"\n+if test \"$verbose_log\" = \"t\"\n+then\n+\texec 3>>\"$GIT_TEST_TEE_OUTPUT_FILE\" 4>&3\n+elif test \"$verbose\" = \"t\"\n then\n \texec 4>&2 3>&1\n else\n-- \n2.10.1.776.ge0e381e\n\n"},{"id":"304569","messageId":"20161021104812.b5mk2s3ve2iotv3j@sigill.intra.peff.net","threadId":"44349","inReplyTo":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","subject":"[PATCH 3/3] travis: use --verbose-log test option","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T10:48:12Z","receivedAt":"2016-10-21T10:48:18Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"Because we run the tests via \"prove\", the output from\n\"--verbose\" may interfere with our TAP output. Using\n\"--verbose-log\" solves this while letting us retain our\non-disk log.\n\nSigned-off-by: Jeff King \n---\n .travis.yml | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/.travis.yml b/.travis.yml\nindex 37a1e1fb6d..9a65514d82 100644\n--- a/.travis.yml\n+++ b/.travis.yml\n@@ -31,7 +31,7 @@ env:\n - LINUX_GIT_LFS_VERSION=\"1.2.0\"\n - DEFAULT_TEST_TARGET=prove\n - GIT_PROVE_OPTS=\"--timer --jobs 3 --state=failed,slow,save\"\n- - GIT_TEST_OPTS=\"--verbose --tee\"\n+ - GIT_TEST_OPTS=\"--verbose-log\"\n - GIT_TEST_HTTPD=true\n - GIT_TEST_CLONE_2GB=YesPlease\n # t9810 occasionally fails on Travis CI OS X\n-- \n2.10.1.776.ge0e381e\n"},{"id":"304611","messageId":"CA+P7+xozpk2-WZUYtaKmCazG3Owzpa3bsDejyUuGj0YEQnJWJg@mail.gmail.com","threadId":"44349","inReplyTo":"20161021084348.dp4jfpfownodl7nz@sigill.intra.peff.net","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jacob Keller","fromEmail":"jacob.keller@gmail.com","sentAt":"2016-10-21T15:29:49Z","receivedAt":"2016-10-21T15:30:17Z","isPatch":false,"sender":{"key":"jacob.keller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/874719?v=4"},"body":"On Fri, Oct 21, 2016 at 1:43 AM, Jeff King wrote:\n> prove t5547-push-quarantine.sh :: -v\n>\n> The Travis tests do exactly this (along with --tee to actually save the\n> output). It seems like a minor miracle that this is the first test\n> output that has actually triggered as TAP input. I'd suggest that the\n> problem is not in the test, though, but that our \"--verbose\" option is\n> unsuitable for using with a TAP harness.\n>\n> The obvious fix would be to send \"--verbose\" output to stderr, but I\n> suspect that would end up annoying for people who do:\n>\n> ./t5547-push-quarantine.sh -v | less\n>\n> to read long output. Probably we need some option like \"--log\" which\n> logs in the same way that \"--tee\" does, but _without_ sending the data\n> to stdout. Naively, that just means replacing the \"tee\" invocation with\n> \"cat\", but I suspect it will be a lot more complicated than that,\n> because we still need to let the TAP output go to stdout.\n>\n> -Peff\n\nCan we determine that we're running with something monitoring the TAP\noutput? Because then we could make verbose go to stderr instead\ndynamically?\n\nThanks,\nJake\n"},{"id":"304612","messageId":"20161021153534.mjed3sqhxjelxzwx@sigill.intra.peff.net","threadId":"44349","inReplyTo":"CA+P7+xozpk2-WZUYtaKmCazG3Owzpa3bsDejyUuGj0YEQnJWJg@mail.gmail.com","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T15:35:34Z","receivedAt":"2016-10-21T15:35:41Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 08:29:49AM -0700, Jacob Keller wrote:\n\n> > The Travis tests do exactly this (along with --tee to actually save the\n> > output). It seems like a minor miracle that this is the first test\n> > output that has actually triggered as TAP input. I'd suggest that the\n> > problem is not in the test, though, but that our \"--verbose\" option is\n> > unsuitable for using with a TAP harness.\n> >\n> > The obvious fix would be to send \"--verbose\" output to stderr, but I\n> > suspect that would end up annoying for people who do:\n> >\n> > ./t5547-push-quarantine.sh -v | less\n> >\n> > to read long output. Probably we need some option like \"--log\" which\n> > logs in the same way that \"--tee\" does, but _without_ sending the data\n> > to stdout. Naively, that just means replacing the \"tee\" invocation with\n> > \"cat\", but I suspect it will be a lot more complicated than that,\n> > because we still need to let the TAP output go to stdout.\n> \n> Can we determine that we're running with something monitoring the TAP\n> output? Because then we could make verbose go to stderr instead\n> dynamically?\n\nI think $HARNESS_ACTIVE could tell us that. But the hard part isn't\nactivating it; it's directing the verbose output to the log without\nsending it to stdout.\n\nSee the patch I posted later in the thread, and my musings on\nauto-activating it. I guess we could do so safely when we see\n$HARNESS_ACTIVE along with \"--tee\" and \"--verbose\", though I don't know\nif it's worth the trouble.\n\nFor $HARNESS_ACTIVE with _just_ \"--verbose\", I don't think it would be a\ngood idea to activate it. We should either silently ignore --verbose\nthen, or complain and die.\n\n-Peff\n"},{"id":"304614","messageId":"CA+P7+xrix3UZDEE1swG_=jBLwWHA04KoYikWBBMNx7aa=Hevmw@mail.gmail.com","threadId":"44349","inReplyTo":"20161021153534.mjed3sqhxjelxzwx@sigill.intra.peff.net","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jacob Keller","fromEmail":"jacob.keller@gmail.com","sentAt":"2016-10-21T15:42:58Z","receivedAt":"2016-10-21T15:43:26Z","isPatch":false,"sender":{"key":"jacob.keller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/874719?v=4"},"body":"On Fri, Oct 21, 2016 at 8:35 AM, Jeff King wrote:\n> On Fri, Oct 21, 2016 at 08:29:49AM -0700, Jacob Keller wrote:\n>\n>> > The Travis tests do exactly this (along with --tee to actually save the\n>> > output). It seems like a minor miracle that this is the first test\n>> > output that has actually triggered as TAP input. I'd suggest that the\n>> > problem is not in the test, though, but that our \"--verbose\" option is\n>> > unsuitable for using with a TAP harness.\n>> >\n>> > The obvious fix would be to send \"--verbose\" output to stderr, but I\n>> > suspect that would end up annoying for people who do:\n>> >\n>> > ./t5547-push-quarantine.sh -v | less\n>> >\n>> > to read long output. Probably we need some option like \"--log\" which\n>> > logs in the same way that \"--tee\" does, but _without_ sending the data\n>> > to stdout. Naively, that just means replacing the \"tee\" invocation with\n>> > \"cat\", but I suspect it will be a lot more complicated than that,\n>> > because we still need to let the TAP output go to stdout.\n>>\n>> Can we determine that we're running with something monitoring the TAP\n>> output? Because then we could make verbose go to stderr instead\n>> dynamically?\n>\n> I think $HARNESS_ACTIVE could tell us that. But the hard part isn't\n> activating it; it's directing the verbose output to the log without\n> sending it to stdout.\n>\n> See the patch I posted later in the thread, and my musings on\n> auto-activating it. I guess we could do so safely when we see\n> $HARNESS_ACTIVE along with \"--tee\" and \"--verbose\", though I don't know\n> if it's worth the trouble.\n>\n> For $HARNESS_ACTIVE with _just_ \"--verbose\", I don't think it would be a\n> good idea to activate it. We should either silently ignore --verbose\n> then, or complain and die.\n>\n\nWe should probably do that to make sure people realize what might\nhappen. I read your series and it has a good explanation of the\npossible alternatives. I like the approach you chose.\n\nThanks,\nJake\n\n> -Peff\n"},{"id":"304615","messageId":"20161021154840.pdmb5c3gjharsrxe@sigill.intra.peff.net","threadId":"44349","inReplyTo":"CA+P7+xrix3UZDEE1swG_=jBLwWHA04KoYikWBBMNx7aa=Hevmw@mail.gmail.com","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T15:48:40Z","receivedAt":"2016-10-21T15:48:50Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 08:42:58AM -0700, Jacob Keller wrote:\n\n> > For $HARNESS_ACTIVE with _just_ \"--verbose\", I don't think it would be a\n> > good idea to activate it. We should either silently ignore --verbose\n> > then, or complain and die.\n> \n> We should probably do that to make sure people realize what might\n> happen. I read your series and it has a good explanation of the\n> possible alternatives. I like the approach you chose.\n\nThanks. Do you want to make a patch on top of my series?\n\n-Peff\n"},{"id":"304618","messageId":"CA+P7+xp8TDL59tQgCpmMDJ-BspA1CF6YsnuGMXas1bx_X0qJoA@mail.gmail.com","threadId":"44349","inReplyTo":"20161021154840.pdmb5c3gjharsrxe@sigill.intra.peff.net","subject":"Re: Prove \"Tests out of sequence\" Error","fromName":"Jacob Keller","fromEmail":"jacob.keller@gmail.com","sentAt":"2016-10-21T16:15:28Z","receivedAt":"2016-10-21T16:15:55Z","isPatch":false,"sender":{"key":"jacob.keller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/874719?v=4"},"body":"On Fri, Oct 21, 2016 at 8:48 AM, Jeff King wrote:\n> On Fri, Oct 21, 2016 at 08:42:58AM -0700, Jacob Keller wrote:\n>\n>> > For $HARNESS_ACTIVE with _just_ \"--verbose\", I don't think it would be a\n>> > good idea to activate it. We should either silently ignore --verbose\n>> > then, or complain and die.\n>>\n>> We should probably do that to make sure people realize what might\n>> happen. I read your series and it has a good explanation of the\n>> possible alternatives. I like the approach you chose.\n>\n> Thanks. Do you want to make a patch on top of my series?\n>\n> -Peff\n\nI am not sure I will find time to do it today, so it wouldn't be for a\nfew more days.\n\nThanks,\nJake\n"},{"id":"304622","messageId":"xmqq7f91d3tb.fsf@gitster.mtv.corp.google.com","threadId":"44349","inReplyTo":"20161021104759.hx6q7u66r3ll7l44@sigill.intra.peff.net","subject":"Re: [PATCH 2/3] test-lib: add --verbose-log option","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-10-21T17:12:16Z","receivedAt":"2016-10-21T17:12:25Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> This patch implements option (5), which seems to work well\n> in practice.\n\nYour journey to reach this final design and implementation may have\nbeen painful---I really like the end result. This was an accident\nwaiting to happen.\n\nThanks for fixing it.\n\n> @@ -319,7 +332,10 @@ fi\n> \n> exec 5>&1\n> exec 6<&0\n> -if test \"$verbose\" = \"t\"\n> +if test \"$verbose_log\" = \"t\"\n> +then\n> +\texec 3>>\"$GIT_TEST_TEE_OUTPUT_FILE\" 4>&3\n> +elif test \"$verbose\" = \"t\"\n> then\n> \texec 4>&2 3>&1\n> else\n\nOK, unlike \"verbose\" case where we give 3 (saved stdout) to 1 and 4\n(saved stderr) to 2, we send 3 to the output file and 4 to the same.\n\nMakes sense.\n"},{"id":"304623","messageId":"CAGZ79kaPAHdRsTXFUqjB843kSq7jVzy7zf4r7hT4YtyxeCPRdg@mail.gmail.com","threadId":"44349","inReplyTo":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","subject":"Re: [PATCH 0/3] fix travis TAP/--verbose conflict","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2016-10-21T17:19:02Z","receivedAt":"2016-10-21T17:19:07Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Fri, Oct 21, 2016 at 3:41 AM, Jeff King wrote:\n> On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:\n>\n>> The obvious fix would be to send \"--verbose\" output to stderr, but I\n>> suspect that would end up annoying for people who do:\n>>\n>> ./t5547-push-quarantine.sh -v | less\n>>\n>> to read long output. Probably we need some option like \"--log\" which\n>> logs in the same way that \"--tee\" does, but _without_ sending the data\n>> to stdout. Naively, that just means replacing the \"tee\" invocation with\n>> \"cat\", but I suspect it will be a lot more complicated than that,\n>> because we still need to let the TAP output go to stdout.\n>\n> Yeah, it was definitely a lot more complicated. This patch series fixes\n> it.\n>\n> [1/3]: test-lib: handle TEST_OUTPUT_DIRECTORY with spaces\n> [2/3]: test-lib: add --verbose-log option\n> [3/3]: travis: use --verbose-log test option\n\nAll patches look good to me\n(1&3 are obvious, and 2 is very well described).\n\nThanks,\nStefan\n"},{"id":"304647","messageId":"20161021214622.csroal7hws3cnszg@sigill.intra.peff.net","threadId":"44349","inReplyTo":"xmqq7f91d3tb.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 2/3] test-lib: add --verbose-log option","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-21T21:46:23Z","receivedAt":"2016-10-21T21:46:32Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 10:12:16AM -0700, Junio C Hamano wrote:\n\n> > -if test \"$verbose\" = \"t\"\n> > +if test \"$verbose_log\" = \"t\"\n> > +then\n> > +\texec 3>>\"$GIT_TEST_TEE_OUTPUT_FILE\" 4>&3\n> > +elif test \"$verbose\" = \"t\"\n> > then\n> > \texec 4>&2 3>&1\n> > else\n> \n> OK, unlike \"verbose\" case where we give 3 (saved stdout) to 1 and 4\n> (saved stderr) to 2, we send 3 to the output file and 4 to the same.\n\nYour comment made me double-check whether we ought to be separating the\ntwo in any way. Because my statement earlier in the thread that the\n--verbose output goes to stdout is not _entirely_ true. It goes to\nstdout and stderr, as written by the various programs in the tests.\n\nSo:\n\n ./t0000-whatever.sh -v | less\n\nisn't quite sufficient. You really do want \"2>&1\" in there to catch\neverything.\n\nBut for the case of \"--tee\", we already do so, in order to make sure it\nall goes to the logfile. And since this option always implies \"--tee\",\nit is correct here to send \"3\" and \"4\" to the same place.\n\nSo the patch is correct. But when I said earlier that people might be\nannoyed if we just sent --verbose output to stderr, that probably isn't\ntrue. We could perhaps make:\n\n prove t0000-whatever.sh :: -v\n\n\"just work\" by sending all of the verbose output to stderr. I don't\nthink it really matters, though. Nobody is doing that, because it's\npointless without \"--tee\".\n\n-Peff\n"},{"id":"304667","messageId":"20161022044506.vba6g2q25yxa2air@sigill.intra.peff.net","threadId":"44349","inReplyTo":"CA+P7+xp8TDL59tQgCpmMDJ-BspA1CF6YsnuGMXas1bx_X0qJoA@mail.gmail.com","subject":"[PATCH 4/3] test-lib: bail out when \"-v\" used under \"prove\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-10-22T04:45:06Z","receivedAt":"2016-10-22T04:45:16Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Oct 21, 2016 at 09:15:28AM -0700, Jacob Keller wrote:\n\n> >> > For $HARNESS_ACTIVE with _just_ \"--verbose\", I don't think it would be a\n> >> > good idea to activate it. We should either silently ignore --verbose\n> >> > then, or complain and die.\n> >>\n> >> We should probably do that to make sure people realize what might\n> >> happen. I read your series and it has a good explanation of the\n> >> possible alternatives. I like the approach you chose.\n> >\n> > Thanks. Do you want to make a patch on top of my series?\n> \n> I am not sure I will find time to do it today, so it wouldn't be for a\n> few more days.\n\nI thought I'd just knock this out in 5 minutes before I forgot about it.\nBut as with so many things, getting it right proved slightly harder than\nI thought. But I did learn about TAP's \"Bail out!\" directive. And\napparently you can pass it back arbitrary YAML (!). And the \"--verbose\"\noutput really is violating the spec, and they claim that Test::Harness\nwill eventually be tightened to complain (though that was in 2007, and\nit still hasn't happened, so...).\n\nAnyway. Here is the patch I came up with (on top of the others).\n\n-- >8 --\nSubject: test-lib: bail out when \"-v\" used under \"prove\"\n\nWhen there is a TAP harness consuming the output of our test\nscripts, the \"--verbose\" breaks the output by mingling\ntest command output with TAP. Because the TAP::Harness\nmodule used by \"prove\" is fairly lenient, this _usually_\nworks, but it violates the spec, and things get very\nconfusing if the commands happen to output a line that looks\nlike TAP (e.g., the word \"ok\" on its own line).\n\nLet's detect this situation and complain. Just calling\nerror() isn't great, though; prove will tell us that the\nscript failed, but the message doesn't make it through to\nthe user. Instead, we can use the special TAP signal \"Bail\nout!\". This not only shows the message to the user, but\ninstructs the harness to stop running the tests entirely.\nThis is exactly what we want here, as the problem is in the\ncommand-line options, and every test script would produce\nthe same error.\n\nThe result looks like this (the first \"Bailout called\" line\nis in red if prove uses color on your terminal):\n\n $ make GIT_TEST_OPTS='--verbose --tee'\n rm -f -r 'test-results'\n *** prove ***\n Bailout called. Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log\n FAILED--Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log\n Makefile:39: recipe for target 'prove' failed\n make: *** [prove] Error 255\n\nSigned-off-by: Jeff King \n---\n t/test-lib.sh | 10 ++++++++++\n 1 file changed, 10 insertions(+)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 85946ec40d..b859db61ac 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -321,6 +321,16 @@ say () {\n \tsay_color info \"$*\"\n }\n \n+if test -n \"$HARNESS_ACTIVE\"\n+then\n+\tif test \"$verbose\" = t || test -n \"$verbose_only\"\n+\tthen\n+\t\tprintf 'Bail out! %s\\n' \\\n+\t\t 'verbose mode forbidden under TAP harness; try --verbose-log'\n+\t\texit 1\n+\tfi\n+fi\n+\n test \"${test_description}\" != \"\" ||\n error \"Test script did not set test_description.\"\n \n-- \n2.10.1.776.ge0e381e\n\n"},{"id":"304670","messageId":"CA+P7+xqwLiwSWAwsreW=nCMU5QiNq4AUGPMawzLofB3vyAqYYw@mail.gmail.com","threadId":"44349","inReplyTo":"20161022044506.vba6g2q25yxa2air@sigill.intra.peff.net","subject":"Re: [PATCH 4/3] test-lib: bail out when \"-v\" used under \"prove\"","fromName":"Jacob Keller","fromEmail":"jacob.keller@gmail.com","sentAt":"2016-10-22T05:25:42Z","receivedAt":"2016-10-22T05:26:08Z","isPatch":true,"sender":{"key":"jacob.keller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/874719?v=4"},"body":"On Fri, Oct 21, 2016 at 9:45 PM, Jeff King wrote:\n> I thought I'd just knock this out in 5 minutes before I forgot about it.\n> But as with so many things, getting it right proved slightly harder than\n> I thought.\n\nAlways seems to be that way, doesn't it?\n\n> But I did learn about TAP's \"Bail out!\" directive. And\n> apparently you can pass it back arbitrary YAML (!). And the \"--verbose\"\n> output really is violating the spec, and they claim that Test::Harness\n> will eventually be tightened to complain (though that was in 2007, and\n> it still hasn't happened, so...).\n>\n> Anyway. Here is the patch I came up with (on top of the others).\n>\n\nNice.\n\n> -- >8 --\n> Subject: test-lib: bail out when \"-v\" used under \"prove\"\n>\n> When there is a TAP harness consuming the output of our test\n> scripts, the \"--verbose\" breaks the output by mingling\n> test command output with TAP. Because the TAP::Harness\n> module used by \"prove\" is fairly lenient, this _usually_\n> works, but it violates the spec, and things get very\n> confusing if the commands happen to output a line that looks\n> like TAP (e.g., the word \"ok\" on its own line).\n>\n> Let's detect this situation and complain. Just calling\n> error() isn't great, though; prove will tell us that the\n> script failed, but the message doesn't make it through to\n> the user. Instead, we can use the special TAP signal \"Bail\n> out!\". This not only shows the message to the user, but\n> instructs the harness to stop running the tests entirely.\n> This is exactly what we want here, as the problem is in the\n> command-line options, and every test script would produce\n> the same error.\n>\n> The result looks like this (the first \"Bailout called\" line\n> is in red if prove uses color on your terminal):\n>\n> $ make GIT_TEST_OPTS='--verbose --tee'\n> rm -f -r 'test-results'\n> *** prove ***\n> Bailout called. Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log\n> FAILED--Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log\n> Makefile:39: recipe for target 'prove' failed\n> make: *** [prove] Error 255\n>\n\nNice that makes sense.\n\n> Signed-off-by: Jeff King \n> ---\n> t/test-lib.sh | 10 ++++++++++\n> 1 file changed, 10 insertions(+)\n>\n> diff --git a/t/test-lib.sh b/t/test-lib.sh\n> index 85946ec40d..b859db61ac 100644\n> --- a/t/test-lib.sh\n> +++ b/t/test-lib.sh\n> @@ -321,6 +321,16 @@ say () {\n> say_color info \"$*\"\n> }\n>\n> +if test -n \"$HARNESS_ACTIVE\"\n> +then\n> + if test \"$verbose\" = t || test -n \"$verbose_only\"\n> + then\n> + printf 'Bail out! %s\\n' \\\n> + 'verbose mode forbidden under TAP harness; try --verbose-log'\n> + exit 1\n> + fi\n> +fi\n> +\n\nNot too much code, so that's good. I like it.\n\nThanks,\nJake\n\n> test \"${test_description}\" != \"\" ||\n> error \"Test script did not set test_description.\"\n>\n> --\n> 2.10.1.776.ge0e381e\n>\n"},{"id":"304786","messageId":"96985FB6-67D9-4146-BDBA-E22699061885@gmail.com","threadId":"44349","inReplyTo":"20161021104107.vh3bjx6x6pd6izat@sigill.intra.peff.net","subject":"Re: [PATCH 0/3] fix travis TAP/--verbose conflict","fromName":"Lars Schneider","fromEmail":"larsxschneider@gmail.com","sentAt":"2016-10-24T18:06:10Z","receivedAt":"2016-10-24T18:11:31Z","isPatch":true,"sender":{"key":"larsxschneider@gmail.com","avatar":"https://avatars.githubusercontent.com/u/477434?v=4"},"body":"\n> On 21 Oct 2016, at 12:41, Jeff King wrote:\n> \n> On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:\n> \n>> The obvious fix would be to send \"--verbose\" output to stderr, but I\n>> suspect that would end up annoying for people who do:\n>> \n>> ./t5547-push-quarantine.sh -v | less\n>> \n>> to read long output. Probably we need some option like \"--log\" which\n>> logs in the same way that \"--tee\" does, but _without_ sending the data\n>> to stdout. Naively, that just means replacing the \"tee\" invocation with\n>> \"cat\", but I suspect it will be a lot more complicated than that,\n>> because we still need to let the TAP output go to stdout.\n> \n> Yeah, it was definitely a lot more complicated. This patch series fixes\n> it.\n\nThanks a lot for this detailed and quick fix :-)\n\nCheers,\nLars\n\n"},{"id":"417998","messageId":"87tupwj5y5.fsf@evledraar.gmail.com","threadId":"44349","inReplyTo":"20161021104759.hx6q7u66r3ll7l44@sigill.intra.peff.net","subject":"[PATCH/RFC] test-lib: make --verbose work under prove","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-02-28T20:25:06Z","receivedAt":"2021-02-28T20:26:06Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nAs explained in 452320f1f5 (test-lib: add --verbose-log option,\n2016-10-21) combining the \"--verbose\" option with the TAP-parsing\n\"prove\" utility would result in broken tests.\n\nThis is because \"prove\" expects valid TAP on stdout, and if there's a\nstray line starting with \"ok\", or other invalid TAP syntax it will\nerror on the test.\n\nIn 452320f1f5 numerous potential methods are discussed for dealing\nwith this problem, but not the one implemented here, which I think is\na much simpler approach.\n\nWhen we detect that we're running under \"prove\" we prefix all\nlegitimate TAP directives with \"GIT_TEST_TEE_STARTED\":\n\n $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh\n GIT_TEST_TEE_STARTED ok 1 - create picky dest repo\n GIT_TEST_TEE_STARTED ok 2 - accepted objects work\n [...]\n GIT_TEST_TEE_STARTED 1..6\n\nThen, instead of piping the output to \"tee -a\" we pipe it to a helper\nwhich first converts \"ok\" and other TAP syntax to e.g. \"\\ok\", and then\nstrips that \"GIT_TEST_TEE_STARTED \" prefix from the start of the line.\n\nThe end result is that we're guaranteed to have valid TAP syntax on\nstdout. We can thus get rid of the --verbose-log special-case. Since\nthat option was meant to get around the TAP issue let's simply make it\nan alias for \"--verbose --tee\".\n\nWe can also revert relevant parts of 88c6e9d31c (test-lib: --valgrind\nshould not override --verbose-log, 2017-09-05) and\nf5ba2de6bc (test-lib: make \"-x\" work with \"--verbose-log\",\n2017-12-08), which were follow-up changes to work around the previous\n--verbose-log implementation.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason \n---\n\nOn Fri, Oct 21 2016, Jeff King wrote:\n\n> The \"--verbose\" option redirects output from arbitrary\n> test commands to stdout. This is useful for examining the\n> output manually, like:\n>\n> ./t5547-push-quarantine.sh -v | less\n>\n> But it also means that the output is intermingled with the\n> TAP directives, which can confuse a TAP parser like \"prove\".\n> This has always been a potential problem, but became an\n> issue recently when one test happened to output the word\n> \"ok\" on a line by itself, which prove interprets as a test\n> success:\n>\n> $ prove t5547-push-quarantine.sh :: -v\n> t5547-push-quarantine.sh .. 1/? To dest.git\n> * [new branch] HEAD -> master\n> To dest.git\n> ! [remote rejected] reject -> reject (pre-receive hook declined)\n> error: failed to push some refs to 'dest.git'\n> fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file\n> t5547-push-quarantine.sh .. Failed -1/4 subtests\n>\n> Test Summary Report\n> -------------------\n> t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)\n> Parse errors: Tests out of sequence. Found (2) but expected (3)\n> Tests out of sequence. Found (3) but expected (4)\n> Tests out of sequence. Found (4) but expected (5)\n> Bad plan. You planned 4 tests but ran 5.\n> Files=1, Tests=5, 0 wallclock secs ( 0.01 usr + 0.01 sys = 0.02 CPU)\n> Result: FAIL\n>\n> One answer is \"if it hurts, don't do it\", but that's not\n> quite the whole story. The Travis tests use \"--verbose\n> --tee\" so that they can get the benefit of prove's parallel\n> options, along with a verbose log in case there is a\n> failure. We just need the verbose output to go to the log,\n> but keep stdout clean.\n>\n> Getting this right turns out to be surprisingly difficult.\n> Here's the progression of alternatives I considered:\n>\n> 1. Add an option to write verbose output to stderr. This is\n> hard to capture, though, because we want each test to\n> have its own log (because they're all run in parallel\n> and the jumbled output would be useless).\n>\n> 2. Add an option to write verbose output to a file in\n> test-results. This works, but the log is missing all of\n> the non-verbose output, which gives context.\n>\n> 3. Like (2), but teach say_color() to additionally output\n> to the log. This mostly works, but misses any output\n> that happens outside of the say() functions (which isn't\n> a lot, but is a potential maintenance headache).\n>\n> 4. Like (2), but make the log file the same as the \"--tee\"\n> file. That almost works, but now we have two processes\n> opening the same file. That gives us two separate\n> descriptors, each with their own idea of the current\n> position. They'll each start writing at offset 0, and\n> overwrite each other's data.\n>\n> 5. Like (4), but in each case open the file for appending.\n> That atomically positions each write at the end of the\n> file.\n>\n> It's possible we may still get sheared writes between\n> the two processes, but this is already the case when\n> writing to stdout. It's not a problem in practice\n> because the test harness generally waits for snippets to\n> finish before writing the TAP output.\n>\n> We can ignore buffering issues with tee, because POSIX\n> mandates that it does not buffer. Likewise, POSIX\n> specifies \"tee -a\", so it should be available\n> everywhere.\n>\n> This patch implements option (5), which seems to work well\n> in practice.\n> \n> Signed-off-by: Jeff King \n> ---\n> Arguably we don't need a new option for this, and could just do it\n> automatically. I wasn't sure when, though:\n>\n> - if \"--tee --verbose\" triggers it, then somebody running that outside\n> of \"prove\" who _wants_ the verbose output on stdout (because they're\n> looking at it, but also want to save a copy to the log) would be\n> regressed\n>\n> - possibly \"--tee\" could just always write verbose output to the\n> logfile (but not stdout). That's kind of weirdly magical, and we'd\n> have to update the travis invocation anyway.\n>\n> So I went with a new option which implies the other ones. No chance of\n> regression, and it's easy to explain.\n\nI came up with a #6 for this which I found much simpler: We control the\nTAP output, so instead of emitting \"ok\" and having it be corrupted,\nlet's emit \" ok\", and then have our own \"tee -a\" and\nsearch-replace it back & forth.\n\nThe above RFC is in the middle of a topic branch I have locally, so it\ndoesn't apply cleanly to anything.\n\nI just thought I'd send it as an RFC to see if anyone had issues with\nthe approach, and to simply make --verbose-log a synonym for --verbose\n--tee with this fix. Having the verbose output under \"prove\" doesn't\nmatter, it will only report on the TAP, so quieting the output had no UI\nimpact.\n\nThe t/lib-test/* changes of calling \"sed\" once per-line under --tee are\nrelatively inefficient. But it would be rather trivial to convert this\nto a our own \"tee -a\"-alike t/helper/* using strbuf_getline() and wrote\nto stdout and a file if anyone saw a practical issue with that part of\nthe implementation (e.g. maybe it's very slow on Windows or something).\n\n t/README | 9 ++++++---\n t/lib-test/tapify-tee-a.sh | 10 ++++++++++\n t/lib-test/tapify.sh | 5 +++++\n t/t0000-basic.sh | 8 ++++++++\n t/test-lib.sh | 40 +++++++++++++++++---------------------\n 5 files changed, 47 insertions(+), 25 deletions(-)\n create mode 100644 t/lib-test/tapify-tee-a.sh\n create mode 100644 t/lib-test/tapify.sh\n\ndiff --git a/t/README b/t/README\nindex 593d4a4e27..bf1f3313ac 100644\n--- a/t/README\n+++ b/t/README\n@@ -157,10 +157,13 @@ appropriately before running \"make\". Short options can be bundled, i.e.\n \n -V::\n --verbose-log::\n-\tWrite verbose output to the same logfile as `--tee`, but do\n-\t_not_ write it to stdout. Unlike `--tee --verbose`, this option\n+\tAn alias for `--verbose --tee`. This option\n \tis safe to use when stdout is being consumed by a TAP parser\n-\tlike `prove`. Implies `--tee` and `--verbose`.\n+\tlike `prove`.\n+\tHistorically this option was different from `--verbose --tee`\n+\tand would not write any verbose output to stdout to ensure the\n+\tTAP-correctness of the output. The TAP-correctness of the\n+\toutput is now sanity checked by the test library,\n \n --with-dashes::\n \tBy default tests are run without dashed forms of\ndiff --git a/t/lib-test/tapify-tee-a.sh b/t/lib-test/tapify-tee-a.sh\nnew file mode 100644\nindex 0000000000..f90f9a89c2\n--- /dev/null\n+++ b/t/lib-test/tapify-tee-a.sh\n@@ -0,0 +1,10 @@\n+#!/bin/sh\n+\n+# A 'tee -a'-alike that protects the sanity of the TAP output, for\n+# test-lib.sh's --tee option\n+\n+while read -r line\n+do\n+ printf \"%s\\n\" \"$line\"\n+ printf \"%s\\n\" \"$line\" | sed 's/^GIT_TEST_TEE_STARTED //' >>\"$1\"\n+done | $TEST_SHELL_PATH \"$TEST_DIRECTORY/lib-test/tapify.sh\"\ndiff --git a/t/lib-test/tapify.sh b/t/lib-test/tapify.sh\nnew file mode 100644\nindex 0000000000..bfa66d33b4\n--- /dev/null\n+++ b/t/lib-test/tapify.sh\n@@ -0,0 +1,5 @@\n+#!/bin/sh\n+\n+sed \\\n+ -e 's/^\\(ok\\|not ok\\|1\\.\\.\\)/\\\\\\1/' \\\n+ -e 's/^GIT_TEST_TEE_STARTED //'\ndiff --git a/t/t0000-basic.sh b/t/t0000-basic.sh\nindex 705d62cc27..2a95a612fb 100755\n--- a/t/t0000-basic.sh\n+++ b/t/t0000-basic.sh\n@@ -76,6 +76,14 @@ _run_sub_test_lib_test_common () {\n \t\t# this variable, so we need a stable setting under which to run\n \t\t# the sub-test.\n \t\tsane_unset HARNESS_ACTIVE &&\n+\n+\t\t# When under --tee pretend we're not as far as\n+\t\t# emitting the \"GIT_TEST_TEE_STARTED \" TAP sanity\n+\t\t# prefix goes. This means we promise not to emit\n+\t\t# invalid TAP, least this test fails under --tee under\n+\t\t# prove(1).\n+\t\tsane_unset GIT_TEST_TEE_STARTED &&\n+\n \t\tcd \"$name\" &&\n \t\twrite_script \"$name.sh\" \"$TEST_SHELL_PATH\" <<-EOF &&\n \t\ttest_description='$descr (run in sub test-lib)\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex af7a16fddd..f533cc02e9 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -146,9 +146,11 @@ parse_option () {\n \t--no-chain-lint)\n \t\tGIT_TEST_CHAIN_LINT=0 ;;\n \t-x)\n-\t\ttrace=t ;;\n+\t\ttrace=t\n+\t\tverbose=t\n+\t\t;;\n \t-V|--verbose-log)\n-\t\tverbose_log=t\n+\t\tverbose=t\n \t\ttee=t\n \t\t;;\n \t--write-junit-xml)\n@@ -233,7 +235,7 @@ then\n \ttest -z \"$verbose\" && verbose_only=\"$valgrind_only\"\n elif test -n \"$valgrind\"\n then\n-\ttest -z \"$verbose_log\" && verbose=t\n+\tverbose=t\n fi\n \n if test -n \"$stress\"\n@@ -364,9 +366,19 @@ then\n \t(\n \t\tGIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} \"$0\" \"$@\" 2>&1\n \t\techo $? >\"$TEST_RESULTS_BASE.exit\"\n-\t) | tee -a \"$GIT_TEST_TEE_OUTPUT_FILE\"\n+\t) | $TEST_SHELL_PATH \\\n+\t\t\"$TEST_DIRECTORY/lib-test/tapify-tee-a.sh\" \\\n+\t\t\"$GIT_TEST_TEE_OUTPUT_FILE\"\n \ttest \"$(cat \"$TEST_RESULTS_BASE.exit\")\" = 0\n \texit\n+elif test -n \"$verbose\" -a -n \"$HARNESS_ACTIVE\"\n+then\n+\tret=\n+\t(\n+\t\tGIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} \"$0\" \"$@\" 2>&1\n+\t\tret=$?\n+\t) | $TEST_SHELL_PATH \"$TEST_DIRECTORY/lib-test/tapify.sh\"\n+\texit $ret\n fi\n \n if test -n \"$trace\" && test -n \"$test_untraceable\"\n@@ -392,10 +404,6 @@ then\n \t\ttrace=\n \tfi\n fi\n-if test -n \"$trace\" && test -z \"$verbose_log\"\n-then\n-\tverbose=t\n-fi\n \n # For repeatability, reset the environment to known value.\n # TERM is sanitized below, after saving color control sequences.\n@@ -569,7 +577,7 @@ say_color_tap() {\n \ttest \"$#\" = 2 ||\n \tBUG \"not 2 parameters to say_color_tap\"\n \n-\tsay_color \"$1\" \"$2\"\n+\tsay_color \"$1\" \"${GIT_TEST_TEE_STARTED:+GIT_TEST_TEE_STARTED }$2\"\n }\n \n TERM=dumb\n@@ -590,16 +598,6 @@ say () {\n \tsay_color info \"$*\"\n }\n \n-if test -n \"$HARNESS_ACTIVE\"\n-then\n-\tif test \"$verbose\" = t || test -n \"$verbose_only\"\n-\tthen\n-\t\tprintf 'Bail out! %s\\n' \\\n-\t\t 'verbose mode forbidden under TAP harness; try --verbose-log'\n-\t\texit 1\n-\tfi\n-fi\n-\n test \"${test_description}\" != \"\" ||\n error \"Test script did not set test_description.\"\n \n@@ -889,9 +887,7 @@ maybe_setup_valgrind () {\n \n trace_level_=0\n want_trace () {\n-\ttest \"$trace\" = t && {\n-\t\ttest \"$verbose\" = t || test \"$verbose_log\" = t\n-\t}\n+\ttest \"$trace\" = t && test \"$verbose\" = t\n }\n \n # This is a separate function because some tests use\n-- \n2.31.0.rc0.126.g04f22c5b82\n"},{"id":"418023","messageId":"YDy5LDsnF1THmvUw@coredump.intra.peff.net","threadId":"44349","inReplyTo":"87tupwj5y5.fsf@evledraar.gmail.com","subject":"Re: [PATCH/RFC] test-lib: make --verbose work under prove","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-03-01T09:51:40Z","receivedAt":"2021-03-01T09:53:57Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Feb 28, 2021 at 09:25:06PM +0100, Ævar Arnfjörð Bjarmason wrote:\n\n> As explained in 452320f1f5 (test-lib: add --verbose-log option,\n> 2016-10-21) combining the \"--verbose\" option with the TAP-parsing\n> \"prove\" utility would result in broken tests.\n> \n> This is because \"prove\" expects valid TAP on stdout, and if there's a\n> stray line starting with \"ok\", or other invalid TAP syntax it will\n> error on the test.\n> \n> In 452320f1f5 numerous potential methods are discussed for dealing\n> with this problem, but not the one implemented here, which I think is\n> a much simpler approach.\n\nI guess I don't really have an objection to this method existing, but I\ndon't see the point of it now. The original problem has been solved, and\nI don't find this any simpler than --verbose-log (on the contrary, I\nfind it much more complicated). So I don't know why I would want to use\nthis instead.\n\n-Peff\n"},{"id":"418035","messageId":"87r1kzj7xi.fsf@evledraar.gmail.com","threadId":"44349","inReplyTo":"YDy5LDsnF1THmvUw@coredump.intra.peff.net","subject":"Re: [PATCH/RFC] test-lib: make --verbose work under prove","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-01T13:54:33Z","receivedAt":"2021-03-01T13:55:38Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Mon, Mar 01 2021, Jeff King wrote:\n\n> On Sun, Feb 28, 2021 at 09:25:06PM +0100, Ævar Arnfjörð Bjarmason wrote:\n>\n>> As explained in 452320f1f5 (test-lib: add --verbose-log option,\n>> 2016-10-21) combining the \"--verbose\" option with the TAP-parsing\n>> \"prove\" utility would result in broken tests.\n>> \n>> This is because \"prove\" expects valid TAP on stdout, and if there's a\n>> stray line starting with \"ok\", or other invalid TAP syntax it will\n>> error on the test.\n>> \n>> In 452320f1f5 numerous potential methods are discussed for dealing\n>> with this problem, but not the one implemented here, which I think is\n>> a much simpler approach.\n>\n> I guess I don't really have an objection to this method existing, but I\n> don't see the point of it now. The original problem has been solved, and\n> I don't find this any simpler than --verbose-log (on the contrary, I\n> find it much more complicated). So I don't know why I would want to use\n> this instead.\n\nI guess that's the problem with picking something from the middle of a\nlocal WIP series I have, I forgot to state the end goal of the whole\nthing.\n\nThe point is to be able to run \"prove -v :: --verbose\" and see\nthe verbose output. See the commit message for when TAP was added for\nexamples: 5099b99d25 (test-lib: Adjust output to be valid TAP format,\n2010-06-24)[1].\n\nBecause it's valid TAP with this patch you can easily parse the output:\n\n HARNESS_ACTIVE=t ./t5547-push-quarantine.sh --verbose -x >t5547-push-quarantine.sh.tap\n perl -MTAP::Parser -MYAML::XS -wE '\n my $parser = TAP::Parser->new( { source => \"t5547-push-quarantine.sh.tap\" } );\n my @lines;\n while ( my $result = $parser->next ) {\n push @lines => $result;\n };\n say Dump \\@lines\n ' >t5547-push-quarantine.sh.tap.parsed\n\nGives you a stream like:\n\n [...]\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: + chmod +x dest.git/hooks/pre-receive\n type: unknown\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: ''\n type: unknown\n - !!perl/hash:TAP::Parser::Result::Test\n description: '- create picky dest repo'\n directive: ''\n explanation: ''\n ok: ok\n raw: ok 1 - create picky dest repo\n test_num: 1\n type: test\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: ''\n type: unknown\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: 'expecting success of 5547.2 ''accepted objects work'': '\n type: unknown\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: \"\\ttest_commit ok &&\"\n type: unknown\n - !!perl/hash:TAP::Parser::Result::Unknown\n raw: \"\\tgit push dest.git HEAD &&\"\n [...]\n\nThe eventual goal was to make ci/print-test-failures.sh and the code\nthat cares about t/test-results/* capable of working with output like\nthat.\n\nSo e.g. you could optionally get summarized output about just the\nspecific tests that failed, not all the output for failing tests, as\nci/print-test-failures.sh is spewing out now.\n\nI also wanted to have something similar to Documentation/doc-diff but\nfor smart test diffing. E.g. now we have an rc0 out, and the set of\ntests broken on various test boxes I have access to is different than in\nthe last release.\n\nBut it's a pain to summarize that output currently (or at least I've\nalways written one-off tools for it).\n\nBy being able to parse the tap it's easier to massage that output and\ne.g. spew it into a database, or into two text files friendly to \"git\ndiff --no-index\".\n\nBut yes, the implementation isn't any simpler, it's more complex than\njust a \"tee -a\", but I think it's worth it for machine-readable verbose\ntest output.\n\n1. As an aside this is a bit tricker/broken in the prove utility than\n when I wrote that code initially, sometimes it won't show you verbose\n output:\n https://github.com/Perl-Toolchain-Gang/Test-Harness/issues/105\n"},{"id":"418605","messageId":"20210309160219.13779-1-avarab@gmail.com","threadId":"44349","inReplyTo":"87r1kzj7xi.fsf@evledraar.gmail.com","subject":"[PATCH 0/6 + 1] test-lib: make --verbose output valid TAP","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-09T16:02:12Z","receivedAt":"2021-03-09T16:03:19Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"This makes the --verbose valid TAP.\n\nThis is a non-RFC version of an RFC patch I sent in\nhttps://lore.kernel.org/git/87tupwj5y5.fsf@evledraar.gmail.com/\n\nThere's a 7/7 patch that's an RFC at the end. It works for me, but\nsince I haven't used the JUnit output it's likely subtly broken in\nsome way (e.g. the new output doesn't include a timestamp attribute),\nbut it shows how easy it is to add new output targets.\n\nThe eventual goal not included in this series is to have multiple\noutput targets, and e.g. convert ci/print-test-failures.sh to use a\nTAP parser.\n\nMachine-readable \"TAP --verbose -x\" output can bring us a lot of nice\nthings down the line, I have some local WIP code that's a smarter\nversion of ci/print-test-failures.sh that knows how to spew out only\nthe output relevant to the failing test(s).\n\nFuture improvements based on that could be showing what specific line\nin a &&-chain failed, as well as e.g. running a debug version of a\nfailing \"grep\" if we detect that the failing line line was 'grep \n'.\n\nÆvar Arnfjörð Bjarmason (7):\n test-lib: remove test_external\n test-lib: add say_color_tap helper to emit TAP format\n test-lib: color \"ok\" TAP directives green under --verbose (or -x)\n test-lib: add tee with TAP support to test-tool\n test-lib: indent and format GIT_TEST_TEE_OUTPUT_FILE code\n test-lib: make --verbose output valid TAP\n test-lib: generate JUnit output via TAP\n\n Makefile | 2 +-\n .../netrc/t-git-credential-netrc.sh | 7 +-\n t/README | 35 +--\n t/helper/test-date.c | 12 -\n t/helper/test-path-utils.c | 21 --\n t/helper/test-tee.c | 85 +++++++\n t/helper/test-tool.c | 2 +-\n t/helper/test-tool.h | 2 +-\n t/helper/test-xml-encode.c | 80 -------\n t/t0000-basic.sh | 8 +\n t/t0202-gettext-perl.sh | 10 +-\n t/t9700-perl-git.sh | 10 +-\n t/test-lib-functions.sh | 89 +------\n t/test-lib.sh | 226 +++++-------------\n 14 files changed, 177 insertions(+), 412 deletions(-)\n create mode 100644 t/helper/test-tee.c\n delete mode 100644 t/helper/test-xml-encode.c\n\n-- \n2.31.0.rc1.210.g0f8085a843c\n\n"},{"id":"418606","messageId":"20210309160219.13779-4-avarab@gmail.com","threadId":"44349","inReplyTo":"87r1kzj7xi.fsf@evledraar.gmail.com","subject":"[PATCH 3/7] test-lib: color \"ok\" TAP directives green under --verbose (or -x)","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-09T16:02:15Z","receivedAt":"2021-03-09T16:03:19Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Change the color of \"ok\" lines to be green when we run under --verbose\nor -x.\n\nWhen a test fails we color the \"not ok\" line red, but the \"ok\" lines\nare not colored.\n\nI think that's the right thing to do in the default output, which is\ne.g.:\n\n $ ./t0000-basic.sh\n ok 1 - verify that the running shell supports \"local\"\n ok 2 - .git/objects should be empty after git init in an empty repo\n ok 3 - .git/objects should have 3 subdirectories\n [...]\n\nHaving almost every line colored green in that output would be\ndistracting.\n\nHowever, under --verbose we'll typically might emit 10-20 lines of\nnon-colored stderr and \"info\" colored output describing the test\nitself.\n\nWhen paging through that output always having the boundaries between\ntests highlighted makes the output more readable.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason \n---\n t/test-lib.sh | 3 ++-\n 1 file changed, 2 insertions(+), 1 deletion(-)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 9a3a3d8d16d..8562b11b817 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -545,6 +545,7 @@ then\n \tsay_color_skip=$(tput setaf 4) # blue\n \tsay_color_warn=$(tput setaf 3) # brown/yellow\n \tsay_color_pass=$(tput setaf 2) # green\n+\tsay_color_pass_all=$(tput bold; tput setaf 2) # bold green\n \tsay_color_info=$(tput setaf 6) # cyan\n \tsay_color_reset=$(tput sgr0)\n \tsay_color_=\"\" # no formatting for normal text\n@@ -673,7 +674,7 @@ test_ok_ () {\n \t\twrite_junit_xml_testcase \"$*\"\n \tfi\n \ttest_success=$(($test_success + 1))\n-\tsay_color_tap \"\" \"ok $test_count - $@\"\n+\tsay_color_tap \"${verbose:+pass}\" \"ok $test_count - $@\"\n }\n \n test_failure_ () {\n-- \n2.31.0.rc1.210.g0f8085a843c\n\n"},{"id":"418607","messageId":"20210309160219.13779-5-avarab@gmail.com","threadId":"44349","inReplyTo":"87r1kzj7xi.fsf@evledraar.gmail.com","subject":"[PATCH 4/7] test-lib: add tee with TAP support to test-tool","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-09T16:02:16Z","receivedAt":"2021-03-09T16:03:20Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Add a 'test-tool tee' that behaves similarly to 'tee(1)', except that\nit supports sanitizing the TAP emitted on stdout.\n\nThis is done by assuming that the TAP is emitted by a friendly library\nthat promises to prefix valid TAP directives with what we're going to\nstrip with --strip-prefix=\"\".\n\nSigned-off-by: Ævar Arnfjörð Bjarmason \n---\n Makefile | 1 +\n t/helper/test-tee.c | 85 ++++++++++++++++++++++++++++++++++++++++++++\n t/helper/test-tool.c | 1 +\n t/helper/test-tool.h | 1 +\n 4 files changed, 88 insertions(+)\n create mode 100644 t/helper/test-tee.c\n\ndiff --git a/Makefile b/Makefile\nindex dfb0f1000fa..d26b9d62ee9 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -742,6 +742,7 @@ TEST_BUILTINS_OBJS += test-string-list.o\n TEST_BUILTINS_OBJS += test-submodule-config.o\n TEST_BUILTINS_OBJS += test-submodule-nested-repo-config.o\n TEST_BUILTINS_OBJS += test-subprocess.o\n+TEST_BUILTINS_OBJS += test-tee.o\n TEST_BUILTINS_OBJS += test-trace2.o\n TEST_BUILTINS_OBJS += test-urlmatch-normalization.o\n TEST_BUILTINS_OBJS += test-wildmatch.o\ndiff --git a/t/helper/test-tee.c b/t/helper/test-tee.c\nnew file mode 100644\nindex 00000000000..4ed34e9db93\n--- /dev/null\n+++ b/t/helper/test-tee.c\n@@ -0,0 +1,85 @@\n+#include \"test-tool.h\"\n+#include \"parse-options.h\"\n+#include \"strbuf.h\"\n+\n+static int line_has_tap(struct strbuf *line)\n+{\n+\t/*\n+\t * This is a less permissive version of\n+\t * https://metacpan.org/release/Test-Harness/source/lib/TAP/Parser/Grammar.pm\n+\t */\n+\tif (starts_with(line->buf, \"ok\") ||\n+\t starts_with(line->buf, \"not ok\") ||\n+\t starts_with(line->buf, \"1..\") ||\n+\t starts_with(line->buf, \"Bail out!\") ||\n+\t starts_with(line->buf, \"TAP version\") ||\n+\t starts_with(line->buf, \"pragma\"))\n+\t\treturn 1;\n+\tif (starts_with(line->buf, \"#\"))\n+\t\t/*\n+\t\t * We're ignoring comments from now, but might treat them\n+\t\t * specially in the future for sanctioned messaging from the\n+\t\t * test-lib.sh.\n+\t\t */\n+\t\treturn 0;\n+\treturn 0;\n+}\n+\n+int cmd__tee(int argc, const char **argv)\n+{\n+\tint tap = 0;\n+\tint escape_stdout = 0, escape_file = 0;\n+\tchar *prefix = NULL;\n+\tsize_t prefix_len = 0;\n+\tconst char *tee_usage[] = {\n+\t\t\"test-tool tee [] \",\n+\t\tNULL\n+\t};\n+\tstruct option options[] = {\n+\t\tOPT_BOOL(0, \"escape-stdout\", &escape_stdout,\n+\t\t\t \"escape output on stdout\"),\n+\t\tOPT_BOOL(0, \"escape-file\", &escape_file,\n+\t\t\t \"escape output written to file\"),\n+\t\tOPT_BOOL(0, \"tap\", &tap,\n+\t\t\t \"output is TAP\"),\n+\t\tOPT_STRING(0, \"prefix\", &prefix, \"str\",\n+\t\t\t \"prefix to strip from the output\"),\n+\t\tOPT_END()\n+\t};\n+\tstruct strbuf line = STRBUF_INIT;\n+\tFILE *logfp = NULL;\n+\n+\targc = parse_options(argc, argv, NULL, options,\n+\t\t\t tee_usage, PARSE_OPT_STOP_AT_NON_OPTION);\n+\tif (argc > 1) {\n+\t\tfprintf(stderr, \"got bad option: %s\\n\", argv[0]);\n+\t\tusage_with_options(tee_usage, options);\n+\t}\n+\tif (prefix)\n+\t\tprefix_len = strlen(prefix);\n+\n+\tif (argc)\n+\t\tlogfp = xfopen(argv[0], \"w\");\n+\n+\twhile (strbuf_getline(&line, stdin) != EOF) {\n+\t\tsize_t offs = 0;\n+\t\tif (prefix && starts_with(line.buf, prefix))\n+\t\t\toffs = prefix_len;\n+\n+\t\tif (!offs && tap && line_has_tap(&line)) {\n+\t\t\tif (escape_stdout)\n+\t\t\t\tfprintf(stdout, \"\\\\\");\n+\t\t\tif (logfp && escape_file)\n+\t\t\t\tfprintf(logfp, \"\\\\\");\n+\t\t}\n+\n+\t\tfprintf(stdout, \"%s\\n\", line.buf + offs);\n+\t\tif (logfp)\n+\t\t\tfprintf(logfp, \"%s\\n\", line.buf + offs);\n+\t}\n+\tstrbuf_release(&line);\n+\tif (logfp)\n+\t\tfclose(logfp);\n+\n+\treturn 0;\n+}\ndiff --git a/t/helper/test-tool.c b/t/helper/test-tool.c\nindex f97cd9f48a6..1876bad8f42 100644\n--- a/t/helper/test-tool.c\n+++ b/t/helper/test-tool.c\n@@ -70,6 +70,7 @@ static struct test_cmd cmds[] = {\n \t{ \"submodule-config\", cmd__submodule_config },\n \t{ \"submodule-nested-repo-config\", cmd__submodule_nested_repo_config },\n \t{ \"subprocess\", cmd__subprocess },\n+\t{ \"tee\", cmd__tee },\n \t{ \"trace2\", cmd__trace2 },\n \t{ \"urlmatch-normalization\", cmd__urlmatch_normalization },\n \t{ \"xml-encode\", cmd__xml_encode },\ndiff --git a/t/helper/test-tool.h b/t/helper/test-tool.h\nindex 28072c0ad5a..9b3c1f75267 100644\n--- a/t/helper/test-tool.h\n+++ b/t/helper/test-tool.h\n@@ -60,6 +60,7 @@ int cmd__string_list(int argc, const char **argv);\n int cmd__submodule_config(int argc, const char **argv);\n int cmd__submodule_nested_repo_config(int argc, const char **argv);\n int cmd__subprocess(int argc, const char **argv);\n+int cmd__tee(int argc, const char **argv);\n int cmd__trace2(int argc, const char **argv);\n int cmd__urlmatch_normalization(int argc, const char **argv);\n int cmd__xml_encode(int argc, const char **argv);\n-- \n2.31.0.rc1.210.g0f8085a843c\n\n"},{"id":"418608","messageId":"20210309160219.13779-3-avarab@gmail.com","threadId":"44349","inReplyTo":"87r1kzj7xi.fsf@evledraar.gmail.com","subject":"[PATCH 2/7] test-lib: add say_color_tap helper to emit TAP format","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-09T16:02:14Z","receivedAt":"2021-03-09T16:03:20Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Follow-up 5099b99d25 (test-lib: Adjust output to be valid TAP format,\n2010-06-24) and make it easy to distinguishing when we're emitting TAP\ndirectives (with the new \"say_color_tap\"), and when we just want to\nsay something with colored text \"say_color\".\n\nThis also makes it easier to do any follow-up changes where we'd like\nto do something special with the TAP directives, as they're what\ndrives the test when we run under the prove(1) utility.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason \n---\n t/test-lib.sh | 21 ++++++++++++++-------\n 1 file changed, 14 insertions(+), 7 deletions(-)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex b0a8bc42510..9a3a3d8d16d 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -562,6 +562,13 @@ else\n \t}\n fi\n \n+say_color_tap() {\n+\ttest \"$#\" = 2 ||\n+\tBUG \"not 2 parameters to say_color_tap\"\n+\n+\tsay_color \"$1\" \"$2\"\n+}\n+\n TERM=dumb\n export TERM\n \n@@ -666,7 +673,7 @@ test_ok_ () {\n \t\twrite_junit_xml_testcase \"$*\"\n \tfi\n \ttest_success=$(($test_success + 1))\n-\tsay_color \"\" \"ok $test_count - $@\"\n+\tsay_color_tap \"\" \"ok $test_count - $@\"\n }\n \n test_failure_ () {\n@@ -691,7 +698,7 @@ test_failure_ () {\n \t\twrite_junit_xml_testcase \"$1\" \" $junit_insert\"\n \tfi\n \ttest_failure=$(($test_failure + 1))\n-\tsay_color error \"not ok $test_count - $1\"\n+\tsay_color_tap error \"not ok $test_count - $1\"\n \tshift\n \tprintf '%s\\n' \"$*\" | sed -e 's/^/#\t/'\n \ttest \"$immediate\" = \"\" || { finalize_junit_xml; GIT_EXIT_OK=t; exit 1; }\n@@ -712,7 +719,7 @@ test_known_broken_failure_ () {\n \t\twrite_junit_xml_testcase \"$* (known breakage)\"\n \tfi\n \ttest_broken=$(($test_broken+1))\n-\tsay_color warn \"not ok $test_count - $@ # TODO known breakage\"\n+\tsay_color_tap warn \"not ok $test_count - $@ # TODO known breakage\"\n }\n \n test_debug () {\n@@ -1027,7 +1034,7 @@ test_skip () {\n \t\t\t\t\" \"\n \t\tfi\n \n-\t\tsay_color skip \"ok $test_count # skip $1 ($skipped_reason)\"\n+\t\tsay_color_tap skip \"ok $test_count # skip $1 ($skipped_reason)\"\n \t\t: true\n \t\t;;\n \t*)\n@@ -1153,12 +1160,12 @@ test_done () {\n \t\ttest -z \"$skip_all\" || skip_all=\"# SKIP $skip_all\"\n \t\tcase \"$test_count\" in\n \t\t0)\n-\t\t\tsay \"1..$test_count${skip_all:+ $skip_all}\"\n+\t\t\tsay_color_tap \"\" \"1..$test_count${skip_all:+ $skip_all}\"\n \t\t\t;;\n \t\t*)\n \t\t\ttest -z \"$skip_all\" ||\n \t\t\tsay_color warn \"$skip_all\"\n-\t\t\tsay \"1..$test_count\"\n+\t\t\tsay_color_tap \"\" \"1..$test_count\"\n \t\t\t;;\n \t\tesac\n \n@@ -1181,7 +1188,7 @@ test_done () {\n \n \t*)\n \t\tsay_color error \"# failed $test_failure among $msg\"\n-\t\tsay \"1..$test_count\"\n+\t\tsay_color_tap \"\" \"1..$test_count\"\n \n \t\texit 1 ;;\n \n-- \n2.31.0.rc1.210.g0f8085a843c\n\n"},{"id":"418609","messageId":"20210309160219.13779-2-avarab@gmail.com","threadId":"44349","inReplyTo":"87r1kzj7xi.fsf@evledraar.gmail.com","subject":"[PATCH 1/7] test-lib: remove test_external","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-03-09T16:02:13Z","receivedAt":"2021-03-09T16:03:20Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"Remove the test_external function(s) in favor of running the Perl\ntests with a test_expect_success.\n\nThe only advantage of this wrapper added in\nfb32c410087 (t/test-lib.sh: add test_external and\ntest_external_without_stderr, 2008-06-19) was that we got the\nTest::More output as-is from the two wrapped scripts.\n\nNow we'll instead hang until the script is finished, and report on its\nexit code. The Test::More framework ensures that we exit with non-zero\nexit code on failure.\n\nMy motivation for this is to eliminate a special case where things\nthat aren't test-lib.sh are going to produce TAP, for reasons that'll\nbe clear in subsequent commits.\n\nThis also eliminates special cases I added in d998bd4ab67 (test-lib:\nMake the test_external_* functions TAP-aware, 2010-06-24) from\ntest-lib.sh itself.\n\nSigned-off-by: Ævar Arnfjörð Bjarmason \n---\n .../netrc/t-git-credential-netrc.sh | 7 +-\n t/README | 26 ------\n t/t0202-gettext-perl.sh | 10 +--\n t/t9700-perl-git.sh | 10 +--\n t/test-lib-functions.sh | 89 +------------------\n t/test-lib.sh | 42 ++++-----\n 6 files changed, 28 insertions(+), 156 deletions(-)\n\ndiff --git a/contrib/credential/netrc/t-git-credential-netrc.sh b/contrib/credential/netrc/t-git-credential-netrc.sh\nindex 07227d02287..28118a9e194 100755\n--- a/contrib/credential/netrc/t-git-credential-netrc.sh\n+++ b/contrib/credential/netrc/t-git-credential-netrc.sh\n@@ -20,13 +20,10 @@\n \t\t'set up test repository' \\\n \t\t'git config --add gpg.program test.git-config-gpg'\n \n-\t# The external test will outputs its own plan\n-\ttest_external_has_tap=1\n-\n \texport PERL5LIB=\"$GITPERLLIB\"\n-\ttest_external \\\n-\t\t'git-credential-netrc' \\\n+\ttest_expect_success 'git-credential-netrc' '\n \t\tperl \"$GIT_BUILD_DIR\"/contrib/credential/netrc/test.pl\n+\t'\n \n \ttest_done\n )\ndiff --git a/t/README b/t/README\nindex 593d4a4e270..2cc8cbc7185 100644\n--- a/t/README\n+++ b/t/README\n@@ -844,32 +844,6 @@ library for your script to use.\n \t test_done\n \tfi\n \n- - test_external []