Page MenuHomePhabricator

mtail testing infrastructure does not report Runtime errors
Open, MediumPublic

Description

Currently, our testing infrastructure for mtail programs captures mtail compilation errors and reports them appropriately. For example:

------------------------------ Captured log call -------------------------------
WARNING  mtail_store:mtail_store.py:42 mtail path: /usr/bin/mtail
WARNING  mtail_store:mtail_store.py:44 b'mtail\t3.0.0~rc35-3+wmf3\n'
WARNING  mtail_store:mtail_store.py:45 I0625 09:17:04.155841  262393 main.go:102] mtail version 3.0.0~rc35 git revision 3.0.0~rc35-3+wmf3 go version go1.11.6 go arch amd64 go os linux
I0625 09:17:04.155947  262393 main.go:103] Commandline: ["mtail" "-one_shot" "-logtostderr" "-progs" "/home/ema/wmf/operations-puppet/modules/mtail/files/test/../programs/varnishsli.mtail" "-logs" "/home/ema/wmf/operations-puppet/modules/mtail/files/test/logs/varnish.sli.test"]
I0625 09:17:04.157220  262393 log_watcher.go:261] No abspath in watched list, added new one for /home/ema/wmf/operations-puppet/modules/mtail/files/programs/varnishsli.mtail
E0625 09:17:04.158525  262393 main.go:173] Compile encountered errors:
compile failed for varnishsli.mtail:
varnishsli.mtail:22:28: Internal compiler error, aborting compilation: can't convert "Float" to "Int" on node &{varnishsli.mtail:22:28 int 0xc00012f080 {{0 0} 0 0 0 0} 0xc000352cf0}

Instead, Runtime errors such as those caused by specific types of input data go unnoticed. As an example, the following program:

/^([-0-9\.]+)$/ {
    internal_time += $1
}

Works fine with input data such as:

0.1
0.5
0.3

But fails with a runtime error if the input is not numeric:

0.1
-
0.3

The error is not shown by running pytest-3 modules/mtail/files, and the problem may or may not be found depending on the specific test case being written. However, by looking for 'Runtime error' in stderr and printing it:

diff --git modules/mtail/files/test/mtail_store.py modules/mtail/files/test/mtail_store.py
index 60dc867fd8..241f10f292 100644
--- modules/mtail/files/test/mtail_store.py
+++ modules/mtail/files/test/mtail_store.py
@@ -25,6 +25,9 @@ class MtailMetricStore(object):
     def parse_metric_store(self, stdout, stderr):
         metrics_store = []
 
+        if 'Runtime error' in stderr:
+            print(stderr)
+
         in_json = False
         for line in stdout.splitlines():
             if in_json:

We get a much clearer picture on what happened running the program:

----------------------------------------------------------------------------------------------- Captured stdout call -----------------------------------------------------------------------------------------------
I0625 09:27:32.472328  264630 main.go:102] mtail version 3.0.0~rc35 git revision 3.0.0~rc35-3+wmf3 go version go1.11.6 go arch amd64 go os linux
I0625 09:27:32.472435  264630 main.go:103] Commandline: ["mtail" "-one_shot" "-logtostderr" "-progs" "/home/ema/wmf/operations-puppet/modules/mtail/files/test/../programs/varnishsli.mtail" "-logs" "/home/ema/wmf/operations-puppet/modules/mtail/files/test/logs/varnish.sli.test"]
I0625 09:27:32.473685  264630 log_watcher.go:261] No abspath in watched list, added new one for /home/ema/wmf/operations-puppet/modules/mtail/files/programs/varnishsli.mtail
I0625 09:27:32.474818  264630 loader.go:229] Loaded program varnishsli.mtail
I0625 09:27:32.474897  264630 log_watcher.go:261] No abspath in watched list, added new one for /home/ema/wmf/operations-puppet/modules/mtail/files/test/logs
I0625 09:27:32.474954  264630 log_watcher.go:261] No abspath in watched list, added new one for /home/ema/wmf/operations-puppet/modules/mtail/files/test/logs/varnish.sli.test
I0625 09:27:32.474983  264630 log_watcher.go:266] Found this processor in watched list
I0625 09:27:32.475049  264630 log_watcher.go:266] Found this processor in watched list
I0625 09:27:32.475428  264630 vm.go:107] varnishsli.mtail: Runtime error: strconv.ParseFloat: parsing "-": invalid syntax
Error occurred at instruction 59 {s2f, <nil>}, originating in varnishsli.mtail at line 26
[...]

In case of a Runtime error when running a mtail test suite, the tests should fail and the error should be printed.