search

brimdata / super

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

zq change causing Brim error messages during pcap import #1087

Closed philrz closed 4 years ago

philrz commented 4 years ago

Brim commit 8c496e0 represents the advance of its zq dependency to a zq commit that includes the change for https://github.com/brimsec/zq/pull/1081. Per the attached video, importing example pcap wrccdc.2018-03-23.010014000000000.pcap.gz now causes multiple error messages to be triggered, including "Unexpected token p in JSON at position 31" and "Malformed zng value". These error messages were not present when importing the same pcap at the Brim commit 9da5f05 that came just prior.

Repro.zip

I also see error messages on the NPM console during import:

zqd2020/08/11 13:36:33 http: superfluous response.WriteHeader call from github.com/brimsec/zq/zqd.(*recordingResponseWriter).WriteHeader (middleware.go:118)
alfred-landrum commented 4 years ago

I caught this response during a repro:

{"type":"TaskStart","task_id":0}

{"type":"TaskEnd","task_id":0}
panic: runtime error: slice bounds out of range [17:15]
goroutine 72 [running]:
runtime/debug.Stack(0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.14.5/libexec/src/runtime/debug/stack.go:24 +0x9d
github.com/brimsec/zq/zqe.RecoverError(0x1b31420, 0xc000039040, 0x5, 0xc0005ae080)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqe/error.go:124 +0x26
github.com/brimsec/zq/zqd.panicCatchMiddleware.func1.1.1(0xc0001e66c0, 0x1e3e180, 0xc0006f2200)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/middleware.go:81 +0x1da
panic(0x1b31420, 0xc000039040)
    /usr/local/Cellar/go/1.14.5/libexec/src/runtime/panic.go:969 +0x166
github.com/brimsec/zq/zcode.(*Iter).Next(0xc00048ce10, 0xc0008cc100, 0x2, 0x2, 0x3, 0xc0005ae040, 0x2)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zcode/iter.go:31 +0x22c
github.com/brimsec/zq/zio/zjsonio.encodeContainer(0x1e47e40, 0xc000744b40, 0xc00049c002, 0x30, 0x3fc0, 0x1f40, 0xc0005aa000, 0xc00048cfb0, 0x1)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zio/zjsonio/stream.go:100 +0x174
github.com/brimsec/zq/zio/zjsonio.(*Stream).Transform(0xc0008a8160, 0xc0003e25c0, 0x64, 0xc0005aa000, 0x1e47940)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zio/zjsonio/stream.go:32 +0xf3
github.com/brimsec/zq/zqd/search.(*JSON).formatRecords(0xc0006f2320, 0xc0004aa000, 0x64, 0x100, 0x0, 0x0, 0x0, 0x0, 0x0)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/search/json.go:32 +0x88
github.com/brimsec/zq/zqd/search.(*JSON).SendBatch(0xc0006f2320, 0x0, 0x1e47940, 0xc0006f28a0, 0x0, 0x0)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/search/json.go:49 +0xe1
github.com/brimsec/zq/zqd/search.(*searchdriver).Write(0xc0006f2340, 0x0, 0x1e47940, 0xc0006f28a0, 0x0, 0x0)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/search/search.go:144 +0x51
github.com/brimsec/zq/driver.runMux(0xc0000a02d0, 0x1e43f40, 0xc0006f2340, 0xc000200b40, 0xc00037a310, 0x3591370)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/driver/driver.go:59 +0x253
github.com/brimsec/zq/driver.Run(0x1e43b80, 0xc0003e2240, 0x1e43f40, 0xc0006f2340, 0x1e2c620, 0xc000744540, 0xc00037a310, 0x3591370, 0xc000250370, 0x0, ...)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/driver/driver.go:30 +0x17f
github.com/brimsec/zq/zqd/search.(*SearchOp).Run(0xc000472040, 0x1e43b80, 0xc0003e2240, 0x3591188, 0xc0003a3440, 0x1e43ec0, 0xc0006f2320, 0x0, 0x0)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/search/search.go:84 +0x384
github.com/brimsec/zq/zqd.handleSearch(0xc0004304b0, 0x1e3e180, 0xc0006f2200, 0xc0008e2300)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/handlers.go:109 +0x3f9
github.com/brimsec/zq/zqd.(*handler).Handle.func1(0x1e3e180, 0xc0006f2200, 0xc0008e2300)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/handler.go:21 +0x50
net/http.HandlerFunc.ServeHTTP(0xc00042d100, 0x1e3e180, 0xc0006f2200, 0xc0008e2300)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2041 +0x44
github.com/brimsec/zq/zqd.panicCatchMiddleware.func1.1(0x1e3e180, 0xc0006f2200, 0xc0008e2300)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/middleware.go:85 +0x87
net/http.HandlerFunc.ServeHTTP(0xc0006f2060, 0x1e3e180, 0xc0006f2200, 0xc0008e2300)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2041 +0x44
github.com/brimsec/zq/zqd.accessLogMiddleware.func1.1(0x1e3f840, 0xc0001ba460, 0xc0008e2300)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/middleware.go:67 +0x925
net/http.HandlerFunc.ServeHTTP(0xc0006f2080, 0x1e3f840, 0xc0001ba460, 0xc0008e2300)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2041 +0x44
github.com/brimsec/zq/zqd.requestIDMiddleware.func1.1(0x1e3f840, 0xc0001ba460, 0xc0008e2200)
    /Users/alfred/.npm/_cacache/tmp/git-clone-5dac50cd/zqd/middleware.go:38 +0x2a1
net/http.HandlerFunc.ServeHTTP(0xc0006f20a0, 0x1e3f840, 0xc0001ba460, 0xc0008e2200)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2041 +0x44
github.com/gorilla/mux.(*Router).ServeHTTP(0xc00042a180, 0x1e3f840, 0xc0001ba460, 0xc0008e2000)
    /Users/alfred/src/go/pkg/mod/github.com/gorilla/mux@v1.7.5-0.20200711200521-98cb6bf42e08/mux.go:210 +0xe2
net/http.serverHandler.ServeHTTP(0xc0001ba2a0, 0x1e3f840, 0xc0001ba460, 0xc0008e2000)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2836 +0xa3
net/http.(*conn).serve(0xc00014b220, 0x1e43b80, 0xc0003e2000)
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:1924 +0x86c
created by net/http.(*Server).Serve
    /usr/local/Cellar/go/1.14.5/libexec/src/net/http/server.go:2962 +0x35c
alfred-landrum commented 4 years ago

I've been able to narrow down the repro, and think it was introduced with https://github.com/brimsec/zq/pull/1063 .

I pulled the logs from the pcap above, and was able to easily repro at the cli:

zq "*" x509.log > t.zng ; zq -t "*" ./t.zng >/dev/null
panic: runtime error: slice bounds out of range [408:315]

goroutine 1 [running]:
github.com/brimsec/zq/zcode.(*Iter).Next(0xc00031f880, 0x1a50440, 0x24998c0, 0xc000422012, 0x12, 0x3f40, 0x0)
    /Users/alfred/work/zq/zcode/iter.go:31 +0x22c
github.com/brimsec/zq/zio/tzngio.(*Writer).writeContainer(0xc000326da0, 0x1a50840, 0xc00033bc50, 0xc000422003, 0x15c, 0x3f4f, 0x1, 0x2)
    /Users/alfred/work/zq/zio/tzngio/writer.go:124 +0x23e
github.com/brimsec/zq/zio/tzngio.(*Writer).Write(0xc000326da0, 0xc0002ff1c0, 0x0, 0x0)
    /Users/alfred/work/zq/zio/tzngio/writer.go:55 +0x199
github.com/brimsec/zq/driver.(*CLI).Write(0xc00033b950, 0x0, 0x1a50340, 0xc000326fc0, 0x0, 0x0)
    /Users/alfred/work/zq/driver/driver.go:75 +0xcd
github.com/brimsec/zq/driver.Run(0xc00009b090, 0x1a4e180, 0xc00033b950, 0x0, 0xc000326dc0, 0x1a3d320)
    /Users/alfred/work/zq/driver/driver.go:46 +0x253
main.(*Command).Run(0xc0001942a0, 0xc0000320a0, 0x2, 0x2, 0x0, 0x0)
    /Users/alfred/work/zq/cmd/zq/zq.go:260 +0x86b
github.com/mccanne/charm.(*instance).run(0xc00000fe20, 0xc000032090, 0x3, 0x3, 0x0, 0x0)
    /Users/alfred/src/go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/instance.go:53 +0x28c
github.com/mccanne/charm.(*Spec).ExecRoot(0x1f3aa00, 0xc000032090, 0x3, 0x3, 0xc00031ff78, 0x10077af, 0xc00009c058, 0x0)
    /Users/alfred/src/go/pkg/mod/github.com/mccanne/charm@v0.0.3-0.20191224190439-b05e1b7b1be3/charm.go:77 +0x96
main.main()
    /Users/alfred/work/zq/cmd/zq/main.go:9 +0x78

That panic doesn't fire before a1a817e0a3d2e1781807df51533bd7794d97d8f7 .

philrz commented 4 years ago

Verified in Brim commit 9ba4ec9 talking to zqd commit 9310cd0.

Per the attached sped-up video, importing the same pcap as done in the original repro now completes without any error messages.

Verify.mp4.zip

Thanks @nwt!