testament does not show which megatest test failed for some tests

[timotheecour]

testament does not show which test (from megatest) failed; in the example below (where the failing test is tlenvarargs.nim) there is 0 indication of which test failed (by chance the logs showed the filename but that's coincidental because the test happened to print the file name).

Even if tlenvarargs.nim ends up in megatest, IIRC there used to be some logic where files that were run via megatest had the filename printed right before running that particular file so we'd be able to tell which test failed (even from looking at CI logs) but that doesn't appear to be the case anymore as shown below. This makes it hard to debug failing PR's where the failining test joins megatest.

Example

I observed that in #12907
I've made a permanent copy of the log downloaded from CI azure pipeline (https://dev.azure.com/nim-lang/Nim/_build/results?buildId=1211&view=logs) here: https://github.com/timotheecour/timn_pub_data/blob/master/data/D20191216T031056.txt

Current Output

2019-12-16T02:46:23.1151200Z PASS: examples/talk/tags.nim C                                     ( 0.56689906 secs)
2019-12-16T02:46:56.7788470Z --- outputExpected.txt     2019-12-16 02:46:56.000000000 +0000
2019-12-16T02:46:56.7789220Z +++ outputGotten.txt       2019-12-16 02:46:56.000000000 +0000
2019-12-16T02:46:56.7789640Z @@ -1710,7 +1710,7 @@
2019-12-16T02:46:56.7789730Z  tlenvarargs.nim:35:9 (1, 2)
2019-12-16T02:46:56.7789810Z  tlenvarargs.nim:36:9 12
2019-12-16T02:46:56.7789870Z  tlenvarargs.nim:37:9 1
2019-12-16T02:46:56.7790260Z -tlenvarargs.nim:38:8
2019-12-16T02:46:56.7790360Z +tlenvarargs.nim:38:8
2019-12-16T02:46:56.7790430Z  megatest:processing: tests/system/tnilconcats.nim
2019-12-16T02:46:56.7790510Z  @["", "", "", "", "", "", "", "meh"]
2019-12-16T02:46:56.7790580Z  megatest:processing: tests/system/tostring.nim
2019-12-16T02:46:56.7790660Z output different!
2019-12-16T02:47:39.3154620Z PASS: lib/pure/algorithm.nim C                                     ( 0.68025398 secs)

Expected Output

this is the missing line:

2019-12-16T02:47:39.3154620Z FAIL: tests/system/tlenvarargs.nim C                                     ( 0.68025398 secs)

2019-12-16T02:46:23.1151200Z PASS: examples/talk/tags.nim C                                     ( 0.56689906 secs)
2019-12-16T02:47:39.3154620Z FAIL: tests/system/tlenvarargs.nim C                                     ( 0.68025398 secs)
2019-12-16T02:46:56.7788470Z --- outputExpected.txt     2019-12-16 02:46:56.000000000 +0000
2019-12-16T02:46:56.7789220Z +++ outputGotten.txt       2019-12-16 02:46:56.000000000 +0000
2019-12-16T02:46:56.7789640Z @@ -1710,7 +1710,7 @@
2019-12-16T02:46:56.7789730Z  tlenvarargs.nim:35:9 (1, 2)
2019-12-16T02:46:56.7789810Z  tlenvarargs.nim:36:9 12
2019-12-16T02:46:56.7789870Z  tlenvarargs.nim:37:9 1
2019-12-16T02:46:56.7790260Z -tlenvarargs.nim:38:8
2019-12-16T02:46:56.7790360Z +tlenvarargs.nim:38:8
2019-12-16T02:46:56.7790430Z  megatest:processing: tests/system/tnilconcats.nim
2019-12-16T02:46:56.7790510Z  @["", "", "", "", "", "", "", "meh"]
2019-12-16T02:46:56.7790580Z  megatest:processing: tests/system/tostring.nim
2019-12-16T02:46:56.7790660Z output different!
2019-12-16T02:47:39.3154620Z PASS: lib/pure/algorithm.nim C                                     ( 0.68025398 secs)

[Araq]

megatest test results always were bad IME and we didn't change the logic. No idea what's going on here.

[timotheecour]

ok I see the problem: the logic I had added in #10089 doesn't work well when git diff context is too small to show the relevant line showing which test is running:

megatest:processing: tests/system/tlenvarargs.nim

here's a minimal reproducing example:

discard """
  output: '''
ok1
ok2
ok3
ok4
ok5
ok5
ok6
ok7
ok8
ok9
ok10
'''
"""

proc main()=
  echo "ok1"
  echo "ok2"
  echo "ok3"
  echo "ok4"
  echo "bad" # diff here will hide the line `megatest:processing: tests/system/tlenvarargs_temp.nim`
  echo "ok6"
  echo "ok7"
  echo "ok8"
  echo "ok9"
  echo "ok10"

main()

nim c -r testament/testament.nim --nim:bin/nim_temp.exp_fix_12908_megatest_FAIL.2 c megatest

joinable specs: 499
--- outputExpected.txt  2019-12-17 20:29:59.000000000 +0000
+++ outputGotten.txt    2019-12-17 20:29:59.000000000 +0000
@@ -1711,8 +1711,7 @@
 ok2
 ok3
 ok4
-ok5
-ok5
+bad
 ok6
 ok7
 ok8
output different!

note: a larger context would show those lines:

[e, f]
megatest:processing: tests/system/tlenvarargs_temp.nim
ok1
ok2
ok3
...
ok9
ok10
megatest:processing: tests/system/tnilconcats.nim
@["", "", "", "", "", "", "", "meh"]

but some tests have a lot of output so it may not be good to simply increase context with git diff -C 100

proposal 1

CI should export the diff files:
outputExpected.txt
outputGotten.txt

which would generally help with debugging CI failures

proposal 2 (maybe simpler)

manually parse outputExpected.txt and outputGotten.txt, keeping track of sections delimited by megatest:processing: xxx.nim, and report back which individual tests failed, right after showing the diff