search

brimdata / zed

A novel data lake based on super-structured data
https://zed.brimdata.io/
BSD 3-Clause "New" or "Revised" License
1.37k stars 67 forks source link

Improve linkage back to markdown from test failures in annotated examples #2264

Closed philrz closed 3 years ago

philrz commented 3 years ago

This issue is regarding the automated tests of the annotated examples in our markdown docs (#301). @mccanne pointed out that when there's a failure during make test-heavy, it's not always easy to find the way back to the example in the markdown that caused the failure. Here's an example from a failure I intentionally just triggered:

$ make test-heavy
...
=== CONT  TestMarkdownExamples/zql/docs/search-syntax/README.md12
=== CONT  TestMarkdownExamples/zql/docs/search-syntax/README.md3
    heavy_test.go:21: 
            Error Trace:    heavy_test.go:21
            Error:          Not equal: 
                            expected: <nil>(<nil>)
                            actual  : *exec.ExitError(&exec.ExitError{ProcessState:(*os.ProcessState)(0xc0005d2000), Stderr:[]uint8(nil)})
            Test:           TestMarkdownExamples/zql/docs/search-syntax/README.md3
            Messages:       error running command [/Users/phil/work/zq/dist/zq -f tzng coutn() by _path | sort /Users/phil/work/zq/zq-sample-data/zeek-default/capture_loss.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/conn.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/dce_rpc.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/dns.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/dpd.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/files.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/ftp.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/http.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/kerberos.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/modbus.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/notice.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/ntlm.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/ntp.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/pe.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/rdp.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/rfb.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/smb_files.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/smb_mapping.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/smtp.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/snmp.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/ssh.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/ssl.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/stats.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/syslog.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/weird.log.gz /Users/phil/work/zq/zq-sample-data/zeek-default/x509.log.gz]: exit status 1
=== CONT  TestMarkdownExamples/zql/docs/processors/README.md23
=== CONT  TestMarkdownExamples/zql/docs/processors/README.md17
...

So in this case I'd go to the zql/docs/search-syntax/README.md file and do a search for zq -f tzng count() by _path | sort.

If there were a way to enhance the error output to simply point at the specific line number in the markdown file where you'll find the Z that failed, that might do the trick.

If that's not easily done, @mccanne suggested another way to improve on this might be to support some kind of tag that could be mentioned in the failure & then searched for instead. Just to see what would happen, I went ahead and added one like this:

#### Example #2:
```zq-command tag:mytest
zq -f tzng 'coutn() by _path | sort' *.log.gz  # Shorthand for: zq '* | count() by _path | sort' *.log.gz


`make test-system` still ran fine (I assume it's just being ignored, but that's a start). So if we went this route, it seems like a couple things we'd want to do from there:

1.  Have the automation ensure there's a unique tag attached to every example (I'd be happy to through and seed all these examples if/when we add the enhancement)
2.  Make sure the tag is mentioned prominently in the output (something like: "Failure with example tagged `mytest` in `zql/docs/search-syntax/README.md`")
philrz commented 3 years ago

Verified in Zed commit fd273d1.

To test, I intentionally broke the first example in https://github.com/brimdata/zed/blob/main/docs/language/search-syntax/README.md by increasing the head tag by one from 4 to 5. The line number where I made the change is 36.

#### Example:
```zq-command
zq -z '*' conn.log.gz

Output:

{_path:"conn",ts:2018-03-24T17:15:21.255387Z,uid:"C8Tful1TvM3Zf5x8fl" (bstring),id:{orig_h:10.164.94.120,orig_p:39681 (port=(uint16)),resp_h:10.47.3.155,resp_p:3389 (port)} (=0),proto:"tcp" (=zenum),service:null (bstring),duration:4.266ms,orig_bytes:97 (uint64),resp_bytes:19 (uint64),conn_state:"RSTR" (bstring),local_orig:null (bool),local_resp:null (bool),missed_bytes:0 (uint64),history:"ShADTdtr" (bstring),orig_pkts:10 (uint64),orig_ip_bytes:730 (uint64),resp_pkts:6 (uint64),resp_ip_bytes:342 (uint64),tunnel_parents:null (1=(|[bstring]|))} (=2)
{_path:"conn",ts:2018-03-24T17:15:21.411148Z,uid:"CXWfTK3LRdiuQxBbM6",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:"tcp",service:null,duration:486us,orig_bytes:0,resp_bytes:0,conn_state:"REJ",local_orig:null,local_resp:null,missed_bytes:0,history:"Sr",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)
{_path:"conn",ts:2018-03-24T17:15:21.926018Z,uid:"CM59GGQhNEoKONb5i",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:"tcp",service:null,duration:538us,orig_bytes:0,resp_bytes:0,conn_state:"REJ",local_orig:null,local_resp:null,missed_bytes:0,history:"Sr",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)
{_path:"conn",ts:2018-03-24T17:15:22.690601Z,uid:"CuKFds250kxFgkhh8f",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:"tcp",service:null,duration:546us,orig_bytes:0,resp_bytes:0,conn_state:"REJ",local_orig:null,local_resp:null,missed_bytes:0,history:"Sr",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)
...

The failure:

$ make test-heavy --- FAIL: TestMarkdownExamples (0.06s) --- FAIL: TestMarkdownExamples/docs/language/search-syntax/README.md:32 (16.17s) heavy_test.go:22: Error Trace: heavy_test.go:22 Error: Not equal: expected: "{_path:\"conn\",ts:2018-03-24T17:15:21.255387Z,uid:\"C8Tful1TvM3Zf5x8fl\" (bstring),id:{orig_h:10.164.94.120,orig_p:39681 (port=(uint16)),resp_h:10.47.3.155,resp_p:3389 (port)} (=0),proto:\"tcp\" (=zenum),service:null (bstring),duration:4.266ms,orig_bytes:97 (uint64),resp_bytes:19 (uint64),conn_state:\"RSTR\" (bstring),local_orig:null (bool),local_resp:null (bool),missed_bytes:0 (uint64),history:\"ShADTdtr\" (bstring),orig_pkts:10 (uint64),orig_ip_bytes:730 (uint64),resp_pkts:6 (uint64),resp_ip_bytes:342 (uint64),tunnel_parents:null (1=(|[bstring]|))} (=2)\n{_path:\"conn\",ts:2018-03-24T17:15:21.411148Z,uid:\"CXWfTK3LRdiuQxBbM6\",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:\"tcp\",service:null,duration:486us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n{_path:\"conn\",ts:2018-03-24T17:15:21.926018Z,uid:\"CM59GGQhNEoKONb5i\",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:\"tcp\",service:null,duration:538us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n{_path:\"conn\",ts:2018-03-24T17:15:22.690601Z,uid:\"CuKFds250kxFgkhh8f\",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:\"tcp\",service:null,duration:546us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n" actual : "{_path:\"conn\",ts:2018-03-24T17:15:21.255387Z,uid:\"C8Tful1TvM3Zf5x8fl\" (bstring),id:{orig_h:10.164.94.120,orig_p:39681 (port=(uint16)),resp_h:10.47.3.155,resp_p:3389 (port)} (=0),proto:\"tcp\" (=zenum),service:null (bstring),duration:4.266ms,orig_bytes:97 (uint64),resp_bytes:19 (uint64),conn_state:\"RSTR\" (bstring),local_orig:null (bool),local_resp:null (bool),missed_bytes:0 (uint64),history:\"ShADTdtr\" (bstring),orig_pkts:10 (uint64),orig_ip_bytes:730 (uint64),resp_pkts:6 (uint64),resp_ip_bytes:342 (uint64),tunnel_parents:null (1=(|[bstring]|))} (=2)\n{_path:\"conn\",ts:2018-03-24T17:15:21.411148Z,uid:\"CXWfTK3LRdiuQxBbM6\",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:\"tcp\",service:null,duration:486us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n{_path:\"conn\",ts:2018-03-24T17:15:21.926018Z,uid:\"CM59GGQhNEoKONb5i\",id:{orig_h:10.47.25.80,orig_p:50817,resp_h:10.128.0.218,resp_p:23189},proto:\"tcp\",service:null,duration:538us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n{_path:\"conn\",ts:2018-03-24T17:15:22.690601Z,uid:\"CuKFds250kxFgkhh8f\",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:\"tcp\",service:null,duration:546us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n{_path:\"conn\",ts:2018-03-24T17:15:23.205187Z,uid:\"CBrzd94qfowOqJwCHa\",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:\"tcp\",service:null,duration:605us,orig_bytes:0,resp_bytes:0,conn_state:\"REJ\",local_orig:null,local_resp:null,missed_bytes:0,history:\"Sr\",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)\n"

                            Diff:
                            --- Expected
                            +++ Actual
                            @@ -4,2 +4,3 @@
                             {_path:"conn",ts:2018-03-24T17:15:22.690601Z,uid:"CuKFds250kxFgkhh8f",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:"tcp",service:null,duration:546us,orig_bytes:0,resp_bytes:0,conn_state:"REJ",local_orig:null,local_resp:null,missed_bytes:0,history:"Sr",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)
                            +{_path:"conn",ts:2018-03-24T17:15:23.205187Z,uid:"CBrzd94qfowOqJwCHa",id:{orig_h:10.47.25.80,orig_p:50813,resp_h:10.128.0.218,resp_p:27765},proto:"tcp",service:null,duration:605us,orig_bytes:0,resp_bytes:0,conn_state:"REJ",local_orig:null,local_resp:null,missed_bytes:0,history:"Sr",orig_pkts:2,orig_ip_bytes:104,resp_pkts:2,resp_ip_bytes:80,tunnel_parents:null} (2)

            Test:           TestMarkdownExamples/docs/language/search-syntax/README.md:32
            Messages:       output mismatch with command [/Users/phil/work/zed/dist/zq -z * /Users/phil/work/zed/zed-sample-data/zeek-default/conn.log.gz]

FAIL FAIL github.com/brimdata/zed/tests 54.786s FAIL make: *** [test-heavy] Error 1


The referenced line number `:32` happens to correspond to this line:

zq -z '*' conn.log.gz



...which makes sense, since that's the command that failed.

Thanks @nwt!