test: output_strictly_contains check leads to non-deterministic test failures

[jasondellaluce]

Which jobs are failing:
tests/integration-static

Which test(s) are failing:
stdout_output_strict, stdout_output_json_strict

Test link:

falco/test/falco_tests.yaml

Line 675 in 2a8c0e8

stdout_output_strict:

falco/test/falco_tests.yaml

Line 686 in 2a8c0e8

stdout_output_json_strict:

Reason for failure:
The output_strictly_contains check ensures that the expected output (read from a file) is contained in the actual Falco's output by using simple string inclusion comparison (if expected not in actual: self.fail(...)). As such, the test is fragile and can fail if even a single character in the actual output breaks the pattern of the expected string.

Since merging #1451, alerts are written on the outputs by an additional worker thread. While running integration tests, it may happen that the main thread terminates before the last alert has been emitted by the working thread. As such, Falco's termination message Events detected: ... Rule counts by severity: ... may be written on stdout before the last alert.

In this specific scenario, output_strictly_contains fails because the termination message appears in the middle of the output, thus not matching the expected string. This only happens while checking the stdout output. This is not deterministically reproducible, and happens in execution environments with poor computation resources.

Anything else we need to know:
The tests/integration-static job occasionally fails on CircleCI. Failures related to this issue have an error message like the following:

Output 'stdout' does not strictly contains the expected content 'output_files/single_rule_with_cat_write.json'

An example of this failure is visible in one of the currently open PRs: https://app.circleci.com/pipelines/github/Spartan-65/falco/3/workflows/44b81732-5123-47f5-9642-d56708092bd2/jobs/37/parallel-runs/0/steps/0-103

The log lines containing the corrupted output, and the error, are reported below:

04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.881781397+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.881781397Z", "output_fields": {"evt.time.iso8601":1470327477881781397,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.881785348+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.881785348Z", "output_fields": {"evt.time.iso8601":1470327477881785348,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.881796705+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.881796705Z", "output_fields": {"evt.time.iso8601":1470327477881796705,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.881799840+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.881799840Z", "output_fields": {"evt.time.iso8601":1470327477881799840,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stderr] Driver Events:0
04:21:35 DEBUG| [stderr] Driver Drops:0
04:21:35 DEBUG| [stderr] Elapsed time: 0.001, Captured Events: 14, 13397.13 eps
04:21:35 DEBUG| [stderr] Syscall event drop monitoring:
04:21:35 DEBUG| [stderr]    - event drop detected: 0 occurrences
04:21:35 DEBUG| [stderr]    - num times actions taken: 0
04:21:35 DEBUG| [stdout] Events detected: 8
04:21:35 DEBUG| [stdout] Rule counts by severity:
04:21:35 DEBUG| [stdout]    WARNING: 8
04:21:35 DEBUG| [stdout] Triggered rules by rule name:
04:21:35 DEBUG| [stdout]    open_from_cat: 8
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.882003104+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.882003104Z", "output_fields": {"evt.time.iso8601":1470327477882003104,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.882008208+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.882008208Z", "output_fields": {"evt.time.iso8601":1470327477882008208,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.882045694+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.882045694Z", "output_fields": {"evt.time.iso8601":1470327477882045694,"proc.cmdline":"cat /dev/null"}}
04:21:35 DEBUG| [stdout] {"output":"2016-08-04T16:17:57.882054739+0000: Warning An open was seen (command=cat /dev/null)","priority":"Warning","rule":"open_from_cat","time":"2016-08-04T16:17:57.882054739Z", "output_fields": {"evt.time.iso8601":1470327477882054739,"proc.cmdline":"cat /dev/null"}}
04:21:35 INFO | Command '/build-static/release/userspace/falco/falco -r /source-static/falco/test/rules/single_rule.yaml   -c /source-static/falco/test/confs/stdout_output.yaml -e /build-static/release/test/trace_files/cat_write.scap -o json_output=True -o json_include_output_property=True -o priority=debug -v -o time_format_iso_8601=true' finished with 0 after 0.20952129364013672s
04:21:35 DEBUG| Expected warning rules: set()
04:21:35 DEBUG| Actual warning rules: set()
04:21:35 ERROR| 
04:21:35 ERROR| Reproduced traceback from: /root/.local/lib/python3.7/site-packages/avocado/core/test.py:844
04:21:35 ERROR| Traceback (most recent call last):
04:21:35 ERROR|   File "/source-static/falco/test/falco_test.py", line 684, in test
04:21:35 ERROR|     self.check_output_strictly_contains(res)
04:21:35 ERROR|   File "/source-static/falco/test/falco_test.py", line 414, in check_output_strictly_contains
04:21:35 ERROR|     output['actual'], output['expected']))
04:21:35 ERROR|   File "/root/.local/lib/python3.7/site-packages/avocado/core/test.py", line 1030, in fail
04:21:35 ERROR|     raise exceptions.TestFail(message)
04:21:35 ERROR| avocado.core.exceptions.TestFail: Output 'stdout' does not strictly contains the expected content 'output_files/single_rule_with_cat_write.json'

[jasondellaluce]

/kind failing-test

[jasondellaluce]

Fixed by: #1724