search

brimdata / super

An analytics database that puts JSON and relational tables on equal footing
https://zed.brimdata.io/
BSD 3-Clause "New" or "Revised" License
1.4k stars 67 forks source link

CSV export panic #1942

Closed philrz closed 3 years ago

philrz commented 3 years ago

Repro is with zq commit fcad36bc and the attached test file repro.tzng.gz:

#0:record[_path:string,ts:time,ts_delta:duration,peer:bstring,gaps:uint64,acks:uint64,percent_lost:float64]
0:[capture_loss;1521835214.3314;111.694792;zeek;15;72667;0.020642;]
#port=uint16
#1:record[event_type:bstring,src_ip:ip,src_port:port,dest_ip:ip,dest_port:port,vlan:array[uint16],proto:bstring,app_proto:bstring,alert:record[severity:uint16,signature:bstring,category:bstring,action:bstring,signature_id:uint64,gid:uint64,rev:uint64,metadata:record[signature_severity:array[bstring],former_category:array[bstring],attack_target:array[bstring],deployment:array[bstring],affected_product:array[bstring],created_at:array[bstring],performance_impact:array[bstring],updated_at:array[bstring],malware_family:array[bstring],tag:array[bstring]]],flow_id:uint64,pcap_cnt:uint64,ts:time,tx_id:uint64,icmp_code:uint64,icmp_type:uint64,community_id:bstring]
1:[alert;13.107.4.50;80;10.47.8.154;51006;-;TCP;http;[3;SURICATA STREAM ESTABLISHED packet out of window;Generic Protocol Command Decode;allowed;2210020;1;2;[-;-;-;-;-;-;-;-;-;-;]]1741344505971013;1650919;1521835214.3314;-;-;-;1:kZkWyvbJTmfVpW38Axh1yk/fHKE=;]
#2:record[_path:string,ts:time,peer:bstring,mem:uint64,pkts_proc:uint64,bytes_recv:uint64,pkts_dropped:uint64,pkts_link:uint64,pkt_lag:duration,events_proc:uint64,events_queued:uint64,active_tcp_conns:uint64,active_udp_conns:uint64,active_icmp_conns:uint64,tcp_conns:uint64,udp_conns:uint64,icmp_conns:uint64,timers:uint64,active_timers:uint64,files:uint64,active_files:uint64,dns_requests:uint64,active_dns_requests:uint64,reassem_tcp_size:uint64,reassem_file_size:uint64,reassem_frag_size:uint64,reassem_unknown_size:uint64]
2:[stats;1521835214.3314;zeek;534;1650918;473585160;-;-;-;1060403;1060403;29135;87;1446;392651;1453;1447;1217499;0;4155;6;15;0;64425;0;0;0;]
$ zq -version
Version: v0.27.0-1-gfcad36bc

$ zq -f csv repro.tzng.gz 
panic: runtime error: slice bounds out of range [11:2]

goroutine 1 [running]:
github.com/brimsec/zq/zcode.(*Iter).Next(0xc00021f8c0, 0x2, 0x51, 0xc000343600, 0x0, 0x0, 0x1d)
    /Users/phil/work/zq/zcode/iter.go:34 +0x22a
github.com/brimsec/zq/zng.(*TypeArray).StringOf(0xc00030c160, 0xc00035062f, 0x2, 0x51, 0x3, 0x0, 0x51, 0x20)
    /Users/phil/work/zq/zng/array.go:58 +0x165
github.com/brimsec/zq/zng.Value.Format(...)
    /Users/phil/work/zq/zng/value.go:74
github.com/brimsec/zq/zio/csvio.(*Writer).Write(0xc000312080, 0xc00031a320, 0x0, 0x0)
    /Users/phil/work/zq/zio/csvio/writer.go:97 +0x45e
github.com/brimsec/zq/zbuf.CopyWithContext(0x1a13b80, 0xc000038080, 0xa100088, 0xc000312080, 0x1a03ae0, 0xc000316000, 0x0, 0x0)
    /Users/phil/work/zq/zbuf/zbuf.go:63 +0x86
github.com/brimsec/zq/zbuf.Copy(...)
    /Users/phil/work/zq/zbuf/zbuf.go:71
github.com/brimsec/zq/proc/fuse.(*writeCloser).Close(0xc00030c040, 0xc0002d9c50, 0x1a13e40)
    /Users/phil/work/zq/proc/fuse/writer.go:23 +0x91
main.(*Command).Run(0xc0002a5080, 0xc0000320b0, 0x1, 0x1, 0x0, 0x0)
    /Users/phil/work/zq/cmd/zq/zq.go:185 +0x83f
github.com/mccanne/charm.(*instance).run(0xc00000fc20, 0xc000032090, 0x3, 0x3, 0x0, 0x0)
    /Users/phil/.go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/instance.go:53 +0x293
github.com/mccanne/charm.(*Spec).ExecRoot(0x1e54d00, 0xc000032090, 0x3, 0x3, 0xc00021ff78, 0x1007f65, 0xc00009a058, 0x0)
    /Users/phil/.go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/charm.go:77 +0x96
main.main()
    /Users/phil/work/zq/cmd/zq/main.go:9 +0x85

I've also confirmed this is not a new bug. While the automatic fuse for CSV is new functionality, if I go back to the prior GA release of zq tagged v0.26.0, I can trigger the same repro if I include an explicit call to fuse.

$ zq -version
Version: v0.26.0

$ zq -f csv 'fuse' repro.tzng.gz 
panic: runtime error: slice bounds out of range [11:2]

goroutine 1 [running]:
github.com/brimsec/zq/zcode.(*Iter).Next(0xc00089d760, 0x2, 0x51, 0xc00099fa00, 0x0, 0x0, 0x1d)
    /Users/phil/work/zq/zcode/iter.go:34 +0x22a
github.com/brimsec/zq/zng.(*TypeArray).StringOf(0xc00000e120, 0xc0009d462f, 0x2, 0x51, 0x3, 0x0, 0x51, 0x20)
    /Users/phil/work/zq/zng/array.go:58 +0x165
github.com/brimsec/zq/zng.Value.Format(...)
    /Users/phil/work/zq/zng/value.go:74
github.com/brimsec/zq/zio/csvio.(*Writer).Write(0xc0000d87c0, 0xc0001803c0, 0x0, 0x0)
    /Users/phil/work/zq/zio/csvio/writer.go:85 +0x45e
github.com/brimsec/zq/driver.(*CLI).Write(0xc0000df050, 0x0, 0x1a0e2c0, 0xc00000e220, 0x0, 0x0)
    /Users/phil/work/zq/driver/driver.go:118 +0xcd
github.com/brimsec/zq/driver.runMux(0xc0001800f0, 0x1a0aa00, 0xc0000df050, 0x0, 0xc0000d8680, 0xc00089da70)
    /Users/phil/work/zq/driver/driver.go:86 +0x25a
github.com/brimsec/zq/driver.Run(0x1a0aa80, 0xc0000df080, 0x1a0aa00, 0xc0000df050, 0x19f9b80, 0xc0000ded80, 0xc0000d8680, 0x19fa4c0, 0xc0000deff0, 0x0, ...)
    /Users/phil/work/zq/driver/driver.go:32 +0x1d1
main.(*Command).Run(0xc000102900, 0xc000180080, 0x2, 0x2, 0x0, 0x0)
    /Users/phil/work/zq/cmd/zq/zq.go:183 +0xa25
github.com/mccanne/charm.(*instance).run(0xc0001a2e00, 0xc000180060, 0x4, 0x4, 0x0, 0x0)
    /Users/phil/.go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/instance.go:53 +0x293
github.com/mccanne/charm.(*Spec).ExecRoot(0x1e46c40, 0xc000180060, 0x4, 0x4, 0xc00089df78, 0x1007f65, 0xc000182058, 0x0)
    /Users/phil/.go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/charm.go:77 +0x96
main.main()
    /Users/phil/work/zq/cmd/zq/main.go:9 +0x85

(The original repro was actually seen by importing test pcap https://archive.wrccdc.org/pcaps/2018/wrccdc.2018-03-23.010014000000000.pcap.gz into Brim with a zqd based on a recent commit, then trying to use the new CSV export option without entering an explicit query and hence requesting all the data be exported as very wide CSV. I'd not noticed this issue before because in the verification of the CSV export feature, I happened to have used an explicit Z query of _path=http or _path=ssl first to isolate diverse records that would need the auto-fuse treatment, but apparently that was not the right data to trigger this bug. I've since confirmed that just the diversity in those three lines above is all that it takes to trigger it, though.)

philrz commented 3 years ago

Verified in zq commit fbf5fe4c.

Using the repro fragment above, the CSV is now generated without panic.

$ zq -version
Version: v0.27.0-6-gfbf5fe4c

$ zq -f csv repro.tzng.gz 
_path,ts,ts_delta,peer,gaps,acks,percent_lost,event_type,src_ip,src_port,dest_ip,dest_port,vlan,proto,app_proto,alert.severity,alert.signature,alert.category,alert.action,alert.signature_id,alert.gid,alert.rev,alert.metadata.signature_severity,alert.metadata.former_category,alert.metadata.attack_target,alert.metadata.deployment,alert.metadata.affected_product,alert.metadata.created_at,alert.metadata.performance_impact,alert.metadata.updated_at,alert.metadata.malware_family,alert.metadata.tag,flow_id,pcap_cnt,tx_id,icmp_code,icmp_type,community_id,mem,pkts_proc,bytes_recv,pkts_dropped,pkts_link,pkt_lag,events_proc,events_queued,active_tcp_conns,active_udp_conns,active_icmp_conns,tcp_conns,udp_conns,icmp_conns,timers,active_timers,files,active_files,dns_requests,active_dns_requests,reassem_tcp_size,reassem_file_size,reassem_frag_size,reassem_unknown_size
capture_loss,2018-03-23T20:00:14.3314Z,111.694792,zeek,15,72667,0.020642,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
,2018-03-23T20:00:14.3314Z,,,,,,alert,13.107.4.50,80,10.47.8.154,51006,,TCP,http,3,SURICATA STREAM ESTABLISHED packet out of window,Generic Protocol Command Decode,allowed,2210020,1,2,,,,,,,,,,,1741344505971013,1650919,,,,1:kZkWyvbJTmfVpW38Axh1yk/fHKE=,,,,,,,,,,,,,,,,,,,,,,,,
stats,2018-03-23T20:00:14.3314Z,,zeek,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,534,1650918,473585160,,,,1060403,1060403,29135,87,1446,392651,1453,1447,1217499,0,4155,6,15,0,64425,0,0,0

The same is true for the original larger ZNG based on the pcap linked above (line count is +1 as expected due to the CSV header line).

$ zq -t 'count()' all.zng 
#0:record[count:uint64]
0:[670822;]

$ zq -f csv all.zng > all.csv

$ wc -l all.csv 
  670823 all.csv

Thanks @mccanne!