Runtime test support for multi-line json output

[jordalgo]

bpftrace can output multiple lines of valid json
instead of one large valid json blob. This adds
test runner support to check multiple json lines.

Added a test for multiple map json output as an
example.

Related issue:
#2902

Checklist

• Language changes are updated in man/adoc/bpftrace.adoc
• User-visible and non-trivial changes updated in CHANGELOG.md
• The new behaviour is covered by tests

[jordalgo]

Here is what a multi-line failure looks like:

[  FAILED  ] json-output.multiple maps
	Command: /home/parallels/Desktop/shared/repos/bpftrace/build/src/bpftrace -q -f json -e 'BEGIN { @map1["key1"] = 2; @map2["key2"] = 3; exit(); }'
	Expected JSON:

{
  "type": "map",
  "data": {
    "@map1": {
      "key1": 2
    }
  }
}
{
  "type": "map",
  "data": {
    "@map2": {
      "key3": 3
    }
  }
}
	Found:

{
  "type": "map",
  "data": {
    "@map1": {
      "key1": 2
    }
  }
}
{
  "type": "map",
  "data": {
    "@map2": {
      "key2": 3
    }
  }
}

[jordalgo]

I'm checking the file extension to determine if we just want a single line check but maybe we should be more explicit with different directive e.g. EXPECT_JSON_LINES or something

[danobi]

how about a .ndjson extension?

[danobi]

we could even tighten up the man page to say bpftrace outputs ndjson

[ajor]

Wasn't part of the original problem that one particular test case (#3035) was returning multiple JSON blobs when only one was expected?

I think the JSON parser will still fail in the same way for this scenario. Would it make sense to always try parsing bpftrace output as NDJSON, in order to handle unexpected extra data?

[danobi]

Suggested change

	Note: the json output is ndjson, meaning each new line of the streamed output is a single blob of valid json.
	Note: the json output is ndjson, meaning each line of the streamed output is a single blob of valid json.

[danobi]

The original test should probably be fixed to only output a single json blob. While treating all expected output as ndjson makes sense, I think there could be value in having nicer formatting in the checked in json files. If it was all ndjson, then it'd get smushed onto a single line

[jordalgo]

If it was all ndjson, then it'd get smushed onto a single line

This is exactly why I didn't make it all ndjson - if you look at the histogram json tests, it would be impossible to read if it was all on one line.

[jordalgo]

Wasn't part of the original problem that one particular test case (#3035) was returning multiple JSON blobs when only one was expected?

I was thinking of fixing this in a follow-up but I think I have an idea, which I can implement in this PR.

[ajor]

delete() is a synchronous function, so will always complete before exit() is run. I think the only race condition that can happen in this test is that it doesn't run 1024 times before the TIMEOUT expires (say if it takes 5 seconds for bpftrace to start up for some reason). Increasing the timeout to 10 seconds like you've done might be all that's needed to fix it

[jordalgo]

delete() is a synchronous function, so will always complete before exit() is run. I think the only race condition that can happen in this test is that it doesn't run 1024 times before the TIMEOUT expires

This is not what I was experiencing locally. The output was including the map e.g. {"type": "map", "data": {"@n": 3}} - and the value of @n changed often. This was happening with a more frequent interval e.g. i:us:100, which is why I changed it to ms:1. That being said, I was still occasionally seeing the map in the output (after deletion) even if this less frequent interval, which is why I just set it to 1 - this strategy seemed to work best. So perhaps there are multiple issues at play here.

[ajor]

Ah, I think another possible problem is a race condition with @n++ if the probes fire too close together. That would explain increasing the interval having helped.

But whatever the cause of us not getting @n = 1024, I'd expect the data in the histogram to also be incorrect. I've not reproduced this failure myself, but #3035 does show an incomplete histogram (192 entries instead of 1024) along with @n = 202

How about this as a fix for the race condition:

BEGIN { $i = 0; while ($i < 1024) { @ = hist($i, 3); $i++; } exit(); }

[ajor]

(I'm getting a bit off track for this PR, sorry)

[jordalgo]

BEGIN { $i = 0; while ($i < 1024) { @ = hist($i, 3); $i++; } exit(); }

Ah good idea! This worked very well.

[jordalgo]

@ajor Ok to merge?

[ajor]

Yep!