{"thread":{"id":"51580","subject":"[PATCH] test-lib-functions: show the test name at the start of verbose output","startedAt":"2019-08-03T08:01:34Z","lastAt":"2019-08-08T22:09:04Z","messageCount":9,"participants":["SZEDER Gábor","Johannes Schindelin","Junio C Hamano"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"379876","messageId":"20190803080126.29488-1-szeder.dev@gmail.com","threadId":"51580","inReplyTo":null,"subject":"[PATCH] test-lib-functions: show the test name at the start of verbose output","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-03T08:01:26Z","receivedAt":"2019-08-03T08:01:34Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The verbose output of every test looks something like this:\n\n  expecting success:\n          echo content >file &&\n          git add file &&\n          git commit -m \"add file\"\n\n  [master (root-commit) d1fbfbd] add file\n   Author: A U Thor <author@example.com>\n   1 file changed, 1 insertion(+)\n   create mode 100644 file\n  ok 1 - commit works\n\ni.e. first an \"expecting success\" (or \"checking known breakage\") line\nfollowed by the commands to be executed, then the output of those\ncomamnds, and finally an \"ok\"/\"not ok\" line containing the test name.\nNote that the test's name is only shown at the very end.\n\nWith '-x' tracing enabled and/or in longer tests the verbose output\nmight be several screenfulls long, making it harder than necessary to\nfind where the output of the test with a given name starts (especially\nwhen the outputs to different file descriptors are racing, and the\n\"expecting success\"/command block arrives earlier than the \"ok\" line\nof the previous test).\n\nPrint the test name at the start of the test's verbose output, i.e. at\nthe end of the \"expecting success\" and \"checking known breakage\"\nlines, to make the start of a particular test a bit easier to\nrecognize.\n\nSo the dummy test above would start like this:\n\n  expecting success of 'commit works':\n          echo content >file &&\n  [...]\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n\nI remember being annoyed by this every once in a while for years, and\nhttps://public-inbox.org/git/20190802100956.GV20404@szeder.dev/\nreminded me again to finally do something about it.\n\n t/t0000-basic.sh        | 8 ++++----\n t/test-lib-functions.sh | 4 ++--\n 2 files changed, 6 insertions(+), 6 deletions(-)\n\ndiff --git a/t/t0000-basic.sh b/t/t0000-basic.sh\nindex e89438e619..6bd21aacab 100755\n--- a/t/t0000-basic.sh\n+++ b/t/t0000-basic.sh\n@@ -285,14 +285,14 @@ test_expect_success C_LOCALE_OUTPUT 'test --verbose' '\n \tmv test-verbose/out test-verbose/out+ &&\n \tgrep -v \"^Initialized empty\" test-verbose/out+ >test-verbose/out &&\n \tcheck_sub_test_lib_test test-verbose <<-\\EOF\n-\t> expecting success: true\n+\t> expecting success of '\\''passing test'\\'': true\n \t> ok 1 - passing test\n \t> Z\n-\t> expecting success: echo foo\n+\t> expecting success of '\\''test with output'\\'': echo foo\n \t> foo\n \t> ok 2 - test with output\n \t> Z\n-\t> expecting success: false\n+\t> expecting success of '\\''failing test'\\'': false\n \t> not ok 3 - failing test\n \t> #\tfalse\n \t> Z\n@@ -313,7 +313,7 @@ test_expect_success 'test --verbose-only' '\n \tcheck_sub_test_lib_test test-verbose-only-2 <<-\\EOF\n \t> ok 1 - passing test\n \t> Z\n-\t> expecting success: echo foo\n+\t> expecting success of '\\''test with output'\\'': echo foo\n \t> foo\n \t> ok 2 - test with output\n \t> Z\ndiff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh\nindex d4f199391f..165e1e51c7 100644\n--- a/t/test-lib-functions.sh\n+++ b/t/test-lib-functions.sh\n@@ -580,7 +580,7 @@ test_expect_failure () {\n \texport test_prereq\n \tif ! test_skip \"$@\"\n \tthen\n-\t\tsay >&3 \"checking known breakage: $2\"\n+\t\tsay >&3 \"checking known breakage of '$1': $2\"\n \t\tif test_run_ \"$2\" expecting_failure\n \t\tthen\n \t\t\ttest_known_broken_ok_ \"$1\"\n@@ -600,7 +600,7 @@ test_expect_success () {\n \texport test_prereq\n \tif ! test_skip \"$@\"\n \tthen\n-\t\tsay >&3 \"expecting success: $2\"\n+\t\tsay >&3 \"expecting success of '$1': $2\"\n \t\tif test_run_ \"$2\"\n \t\tthen\n \t\t\ttest_ok_ \"$1\"\n-- \n2.23.0.rc1.309.g896d8c5f5f\n\n"},{"id":"379919","messageId":"nycvar.QRO.7.76.6.1908042113300.46@tvgsbejvaqbjf.bet","threadId":"51580","inReplyTo":"20190803080126.29488-1-szeder.dev@gmail.com","subject":"Re: [PATCH] test-lib-functions: show the test name at the start of verbose output","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-08-04T19:14:46Z","receivedAt":"2019-08-04T19:15:09Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi,\n\nOn Sat, 3 Aug 2019, SZEDER Gábor wrote:\n\n> So the dummy test above would start like this:\n>\n>   expecting success of 'commit works':\n>           echo content >file &&\n>   [...]\n\nMaybe it would make sense to also mention the test and test case number,\nlike so?\n\n\texpecting success of t9876.54 'it works':\n\nCiao,\nDscho\n"},{"id":"379931","messageId":"20190805101237.GA20404@szeder.dev","threadId":"51580","inReplyTo":"nycvar.QRO.7.76.6.1908042113300.46@tvgsbejvaqbjf.bet","subject":"Re: [PATCH] test-lib-functions: show the test name at the start of verbose output","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-05T10:12:37Z","receivedAt":"2019-08-05T10:12:45Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Sun, Aug 04, 2019 at 09:14:46PM +0200, Johannes Schindelin wrote:\n> Hi,\n> \n> On Sat, 3 Aug 2019, SZEDER Gábor wrote:\n> \n> > So the dummy test above would start like this:\n> >\n> >   expecting success of 'commit works':\n> >           echo content >file &&\n> >   [...]\n> \n> Maybe it would make sense to also mention the test and test case number,\n> like so?\n> \n> \texpecting success of t9876.54 'it works':\n\nIt's easy enough to do so, but I don't readily see any benefits.\n\nThe '--verbose-log' of each test script is written to a separate\nfile, whose name already contains the test number, so there is no use\nincluding it for each test case in there.  When running a test script\nand looking at its '--verbose' output, then surely all test numbers\nmust be from that particular test script, so there is no use, either.\n\nAs for the test case number, since the test cases are not numbered in\nthe test scripts, I just ignore them right away, and look for test\nnames anyway.\n\nCould you give an example?\n\n"},{"id":"379933","messageId":"nycvar.QRO.7.76.6.1908051329301.46@tvgsbejvaqbjf.bet","threadId":"51580","inReplyTo":"20190805101237.GA20404@szeder.dev","subject":"Re: [PATCH] test-lib-functions: show the test name at the start of verbose output","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-08-05T11:32:12Z","receivedAt":"2019-08-05T11:32:34Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Gábor,\n\nOn Mon, 5 Aug 2019, SZEDER Gábor wrote:\n\n> On Sun, Aug 04, 2019 at 09:14:46PM +0200, Johannes Schindelin wrote:\n> >\n> > On Sat, 3 Aug 2019, SZEDER Gábor wrote:\n> >\n> > > So the dummy test above would start like this:\n> > >\n> > >   expecting success of 'commit works':\n> > >           echo content >file &&\n> > >   [...]\n> >\n> > Maybe it would make sense to also mention the test and test case number,\n> > like so?\n> >\n> > \texpecting success of t9876.54 'it works':\n>\n> It's easy enough to do so, but I don't readily see any benefits.\n>\n> The '--verbose-log' of each test script is written to a separate\n> file, whose name already contains the test number, so there is no use\n> including it for each test case in there.  When running a test script\n> and looking at its '--verbose' output, then surely all test numbers\n> must be from that particular test script, so there is no use, either.\n>\n> As for the test case number, since the test cases are not numbered in\n> the test scripts, I just ignore them right away, and look for test\n> names anyway.\n>\n> Could you give an example?\n\nOh, my common way to read test logs is to sift through CI builds' logs,\nin particular for the branches on https://github.com/gitster/git that\nare based on commits without support for the convenient Tests tab in\nAzure Pipelines.\n\nSo I hit Ctrl+F and look for `not ok` in literally hundreds/thousands of\nlines. Of course, this is already the unrolled log _only_ of the failed\ntest scripts. Still, it is no fun to scoll back from test case 64 all\nthe way to 1 just to find out which test script contains this particular\nfailed test case.\n\nCiao,\nDscho\n"},{"id":"379954","messageId":"20190805210447.7169-1-szeder.dev@gmail.com","threadId":"51580","inReplyTo":"20190803080126.29488-1-szeder.dev@gmail.com","subject":"[PATCH v2 0/2] tests: show the test name and number at the start of verbose output","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-05T21:04:45Z","receivedAt":"2019-08-05T21:04:56Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Include the test script number, test number, and the test name at the\nstart of the verbose output of each test, to help navigating the\ntests' logs.\n\nChanges since v1:\n\n  - Include not only the test name, but the test script number and\n    test number as well.\n\n  - An additional small adjustment was necessary to 't0000-basic.sh',\n    which I thought is better as a separate preparatory patch, to ease\n    review a bit.\n\nSZEDER Gábor (2):\n  t0000-basic: use realistic test script names in the verbose tests\n  tests: show the test name and number at the start of verbose output\n\n t/t0000-basic.sh        | 20 ++++++++++----------\n t/test-lib-functions.sh |  4 ++--\n t/test-lib.sh           |  2 ++\n 3 files changed, 14 insertions(+), 12 deletions(-)\n\n-- \n2.23.0.rc1.309.g896d8c5f5f\n\n"},{"id":"379955","messageId":"20190805210447.7169-3-szeder.dev@gmail.com","threadId":"51580","inReplyTo":"20190805210447.7169-1-szeder.dev@gmail.com","subject":"[PATCH v2 2/2] tests: show the test name and number at the start of verbose output","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-05T21:04:47Z","receivedAt":"2019-08-05T21:04:59Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The verbose output of every test looks something like this:\n\n  expecting success:\n          echo content >file &&\n          git add file &&\n          git commit -m \"add file\"\n\n  [master (root-commit) d1fbfbd] add file\n   Author: A U Thor <author@example.com>\n   1 file changed, 1 insertion(+)\n   create mode 100644 file\n  ok 1 - commit works\n\ni.e. first an \"expecting success\" (or \"checking known breakage\") line\nfollowed by the commands to be executed, then the output of those\ncomamnds, and finally an \"ok\"/\"not ok\" line containing the test name.\nNote that the test's name is only shown at the very end.\n\nWith '-x' tracing enabled and/or in longer tests the verbose output\nmight be several screenfulls long, making it harder than necessary to\nfind where the output of the test with a given name starts (especially\nwhen the outputs to different file descriptors are racing, and the\n\"expecting success\"/command block arrives earlier than the \"ok\" line\nof the previous test).\n\nPrint the test name at the start of the test's verbose output, i.e. at\nthe end of the \"expecting success\" and \"checking known breakage\"\nlines, to make the start of a particular test a bit easier to\nrecognize.  Also print the test script and test case numbers, to help\nthose poor souls who regularly have to scan through the combined\nverbose output of several test scripts.\n\nSo the dummy test above would start like this:\n\n  expecting success of 9999.1 'commit works':\n          echo content >file &&\n  [...]\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t0000-basic.sh        | 8 ++++----\n t/test-lib-functions.sh | 4 ++--\n t/test-lib.sh           | 2 ++\n 3 files changed, 8 insertions(+), 6 deletions(-)\n\ndiff --git a/t/t0000-basic.sh b/t/t0000-basic.sh\nindex d2b3dde89e..360eae5348 100755\n--- a/t/t0000-basic.sh\n+++ b/t/t0000-basic.sh\n@@ -285,14 +285,14 @@ test_expect_success C_LOCALE_OUTPUT 'test --verbose' '\n \tmv t1234-verbose/out t1234-verbose/out+ &&\n \tgrep -v \"^Initialized empty\" t1234-verbose/out+ >t1234-verbose/out &&\n \tcheck_sub_test_lib_test t1234-verbose <<-\\EOF\n-\t> expecting success: true\n+\t> expecting success of 1234.1 '\\''passing test'\\'': true\n \t> ok 1 - passing test\n \t> Z\n-\t> expecting success: echo foo\n+\t> expecting success of 1234.2 '\\''test with output'\\'': echo foo\n \t> foo\n \t> ok 2 - test with output\n \t> Z\n-\t> expecting success: false\n+\t> expecting success of 1234.3 '\\''failing test'\\'': false\n \t> not ok 3 - failing test\n \t> #\tfalse\n \t> Z\n@@ -313,7 +313,7 @@ test_expect_success 'test --verbose-only' '\n \tcheck_sub_test_lib_test t2345-verbose-only-2 <<-\\EOF\n \t> ok 1 - passing test\n \t> Z\n-\t> expecting success: echo foo\n+\t> expecting success of 2345.2 '\\''test with output'\\'': echo foo\n \t> foo\n \t> ok 2 - test with output\n \t> Z\ndiff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh\nindex d4f199391f..a3d06899e2 100644\n--- a/t/test-lib-functions.sh\n+++ b/t/test-lib-functions.sh\n@@ -580,7 +580,7 @@ test_expect_failure () {\n \texport test_prereq\n \tif ! test_skip \"$@\"\n \tthen\n-\t\tsay >&3 \"checking known breakage: $2\"\n+\t\tsay >&3 \"checking known breakage of $TEST_NUMBER.$test_count '$1': $2\"\n \t\tif test_run_ \"$2\" expecting_failure\n \t\tthen\n \t\t\ttest_known_broken_ok_ \"$1\"\n@@ -600,7 +600,7 @@ test_expect_success () {\n \texport test_prereq\n \tif ! test_skip \"$@\"\n \tthen\n-\t\tsay >&3 \"expecting success: $2\"\n+\t\tsay >&3 \"expecting success of $TEST_NUMBER.$test_count '$1': $2\"\n \t\tif test_run_ \"$2\"\n \t\tthen\n \t\t\ttest_ok_ \"$1\"\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 30b07e310f..a9d45642a5 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -212,6 +212,8 @@ fi\n \n TEST_STRESS_JOB_SFX=\"${GIT_TEST_STRESS_JOB_NR:+.stress-$GIT_TEST_STRESS_JOB_NR}\"\n TEST_NAME=\"$(basename \"$0\" .sh)\"\n+TEST_NUMBER=\"${TEST_NAME%%-*}\"\n+TEST_NUMBER=\"${TEST_NUMBER#t}\"\n TEST_RESULTS_DIR=\"$TEST_OUTPUT_DIRECTORY/test-results\"\n TEST_RESULTS_BASE=\"$TEST_RESULTS_DIR/$TEST_NAME$TEST_STRESS_JOB_SFX\"\n TRASH_DIRECTORY=\"trash directory.$TEST_NAME$TEST_STRESS_JOB_SFX\"\n-- \n2.23.0.rc1.309.g896d8c5f5f\n\n"},{"id":"379956","messageId":"20190805210447.7169-2-szeder.dev@gmail.com","threadId":"51580","inReplyTo":"20190805210447.7169-1-szeder.dev@gmail.com","subject":"[PATCH v2 1/2] t0000-basic: use realistic test script names in the verbose tests","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-05T21:04:46Z","receivedAt":"2019-08-05T21:04:59Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Our test scripts are named something like 't1234-command.sh', but the\nscript names used in 't0000-basic.sh' don't follow this naming\nconvention.  Normally this doesn't matter, because the test scripts\nthemselves don't care how they are called.  However, the next patch\nwill start to include the test number in the test's verbose output, so\nthe test script's name will matter in the two tests checking the\nverbose output.\n\nUpdate the tests 'test --verbose' and 'test --verbose-only' to follow\nout test script naming convention.\n\nLeave the other tests in 't0000' unchanged: changing the names of\ntheir test scripts would be only pointless code churn.\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t0000-basic.sh | 12 ++++++------\n 1 file changed, 6 insertions(+), 6 deletions(-)\n\ndiff --git a/t/t0000-basic.sh b/t/t0000-basic.sh\nindex e89438e619..d2b3dde89e 100755\n--- a/t/t0000-basic.sh\n+++ b/t/t0000-basic.sh\n@@ -276,15 +276,15 @@ test_expect_success 'pretend we have a mix of all possible results' \"\n \n test_expect_success C_LOCALE_OUTPUT 'test --verbose' '\n \ttest_must_fail run_sub_test_lib_test \\\n-\t\ttest-verbose \"test verbose\" --verbose <<-\\EOF &&\n+\t\tt1234-verbose \"test verbose\" --verbose <<-\\EOF &&\n \ttest_expect_success \"passing test\" true\n \ttest_expect_success \"test with output\" \"echo foo\"\n \ttest_expect_success \"failing test\" false\n \ttest_done\n \tEOF\n-\tmv test-verbose/out test-verbose/out+ &&\n-\tgrep -v \"^Initialized empty\" test-verbose/out+ >test-verbose/out &&\n-\tcheck_sub_test_lib_test test-verbose <<-\\EOF\n+\tmv t1234-verbose/out t1234-verbose/out+ &&\n+\tgrep -v \"^Initialized empty\" t1234-verbose/out+ >t1234-verbose/out &&\n+\tcheck_sub_test_lib_test t1234-verbose <<-\\EOF\n \t> expecting success: true\n \t> ok 1 - passing test\n \t> Z\n@@ -303,14 +303,14 @@ test_expect_success C_LOCALE_OUTPUT 'test --verbose' '\n \n test_expect_success 'test --verbose-only' '\n \ttest_must_fail run_sub_test_lib_test \\\n-\t\ttest-verbose-only-2 \"test verbose-only=2\" \\\n+\t\tt2345-verbose-only-2 \"test verbose-only=2\" \\\n \t\t--verbose-only=2 <<-\\EOF &&\n \ttest_expect_success \"passing test\" true\n \ttest_expect_success \"test with output\" \"echo foo\"\n \ttest_expect_success \"failing test\" false\n \ttest_done\n \tEOF\n-\tcheck_sub_test_lib_test test-verbose-only-2 <<-\\EOF\n+\tcheck_sub_test_lib_test t2345-verbose-only-2 <<-\\EOF\n \t> ok 1 - passing test\n \t> Z\n \t> expecting success: echo foo\n-- \n2.23.0.rc1.309.g896d8c5f5f\n\n"},{"id":"380165","messageId":"nycvar.QRO.7.76.6.1908082211550.46@tvgsbejvaqbjf.bet","threadId":"51580","inReplyTo":"20190805210447.7169-1-szeder.dev@gmail.com","subject":"Re: [PATCH v2 0/2] tests: show the test name and number at the start of verbose output","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2019-08-08T20:12:23Z","receivedAt":"2019-08-08T20:12:30Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Gábor,\n\nOn Mon, 5 Aug 2019, SZEDER Gábor wrote:\n\n> Include the test script number, test number, and the test name at the\n> start of the verbose output of each test, to help navigating the\n> tests' logs.\n>\n> Changes since v1:\n>\n>   - Include not only the test name, but the test script number and\n>     test number as well.\n>\n>   - An additional small adjustment was necessary to 't0000-basic.sh',\n>     which I thought is better as a separate preparatory patch, to ease\n>     review a bit.\n\nLooks good to me!\n\nThanks,\nDscho\n\n>\n> SZEDER Gábor (2):\n>   t0000-basic: use realistic test script names in the verbose tests\n>   tests: show the test name and number at the start of verbose output\n>\n>  t/t0000-basic.sh        | 20 ++++++++++----------\n>  t/test-lib-functions.sh |  4 ++--\n>  t/test-lib.sh           |  2 ++\n>  3 files changed, 14 insertions(+), 12 deletions(-)\n>\n> --\n> 2.23.0.rc1.309.g896d8c5f5f\n>\n>\n"},{"id":"380178","messageId":"xmqqk1bne2df.fsf@gitster-ct.c.googlers.com","threadId":"51580","inReplyTo":"nycvar.QRO.7.76.6.1908082211550.46@tvgsbejvaqbjf.bet","subject":"Re: [PATCH v2 0/2] tests: show the test name and number at the start of verbose output","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2019-08-08T22:09:00Z","receivedAt":"2019-08-08T22:09:04Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Johannes Schindelin <Johannes.Schindelin@gmx.de> writes:\n\n> On Mon, 5 Aug 2019, SZEDER Gábor wrote:\n>\n>> Include the test script number, test number, and the test name at the\n>> start of the verbose output of each test, to help navigating the\n>> tests' logs.\n>> ...\n>\n> Looks good to me!\n\nThanks, both.\n"}]}