victorialogs crash

[vZ2JEZsZW]

Describe the bug

victorialogs crahes when serving request from vmui with _time:500m | sort by (_time desc) query

# docker run --rm -it -p 9428:9428 --mount type=volume,src=vl_vol_data,dst=/victoria-logs-data docker.io/victoriametrics/victoria-logs:v0.6.0-victorialogs
2024-05-12T20:44:02.615Z	info	VictoriaMetrics/lib/logger/flag.go:12	build version: victoria-logs-20240512-192959-tags-v0.6.0-victorialogs-0-g89c4dc1d8d
2024-05-12T20:44:02.615Z	info	VictoriaMetrics/lib/logger/flag.go:13	command-line flags
2024-05-12T20:44:02.615Z	info	VictoriaMetrics/app/victoria-logs/main.go:42	starting VictoriaLogs at "[:9428]"...
2024-05-12T20:44:02.615Z	info	VictoriaMetrics/app/vlstorage/main.go:59	opening storage at -storageDataPath=victoria-logs-data
2024-05-12T20:44:02.615Z	info	VictoriaMetrics/lib/memory/memory.go:42	limiting caches to 2295056793 bytes, leaving 1530037863 bytes to the OS according to -memory.allowedPercent=60
2024-05-12T20:44:02.619Z	info	VictoriaMetrics/app/vlstorage/main.go:65	successfully opened storage in 0.005 seconds; smallParts: 7; bigParts: 0; smallPartBlocks: 7; bigPartBlocks: 0; smallPartRows: 56; bigPartRows: 0; smallPartSize: 10090 bytes; bigPartSize: 0 bytes
2024-05-12T20:44:02.620Z	info	VictoriaMetrics/app/victoria-logs/main.go:50	started VictoriaLogs in 0.005 seconds; see https://docs.victoriametrics.com/VictoriaLogs/
2024-05-12T20:44:02.620Z	info	VictoriaMetrics/lib/httpserver/httpserver.go:119	starting server at http://127.0.0.1:9428/
2024-05-12T20:44:02.620Z	info	VictoriaMetrics/lib/httpserver/httpserver.go:120	pprof handlers are exposed at http://127.0.0.1:9428/debug/pprof/
panic: runtime error: index out of range [150] with length 2

goroutine 53 [running]:
github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver.handlerWrapper.func1()
	github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver/httpserver.go:291 +0x5b
panic({0x934840?, 0xc00002a630?})
	runtime/panic.go:770 +0x132
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*blockResult).getBucketedDictValues(0xc0002780a0, {0xc0001f49e8, 0xb, 0x80?}, {0xc0001f49c8?, 0x7b0d00?, 0xc00009c350?}, 0x10?)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/block_result.go:596 +0x1e5
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*blockResult).getBucketedColumnValues(0x4b?, 0xc0000d5208?, 0xc000097100?)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/block_result.go:459 +0x89
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*blockResultColumn).getValues(...)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/block_result.go:1459
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*blockResultColumn).getValueAtRow(0xc00025a9d0, 0xc00004d808?, 0xa)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/block_result.go:1430 +0x85
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*pipeSortWriteContext).writeRow(0xc0002888f0, 0xc000234180?, 0x0?)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/pipe_sort.go:503 +0x99a
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*pipeSortProcessor).flush(0xc000134fa0)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/pipe_sort.go:406 +0x425
github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage.(*Storage).RunQuery(0xc0000bc840, {0xb1c900, 0xc000134f00}, {0xc00004a6e0, 0x1, 0x1}, 0xc00015e000, 0xc0001c28b8)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/logstorage/storage_search.go:114 +0x55f
github.com/VictoriaMetrics/VictoriaMetrics/app/vlstorage.RunQuery(...)
	github.com/VictoriaMetrics/VictoriaMetrics/app/vlstorage/main.go:111
github.com/VictoriaMetrics/VictoriaMetrics/app/vlselect/logsql.ProcessQueryRequest({0xb1c900, 0xc000134e60}, {0xb1b2e0, 0xc0001c2870}, 0xc0000c6360)
	github.com/VictoriaMetrics/VictoriaMetrics/app/vlselect/logsql/logsql.go:67 +0x4f6
github.com/VictoriaMetrics/VictoriaMetrics/app/vlselect.RequestHandler({0xb1b2e0, 0xc0001c2870}, 0xc0000c6360)
	github.com/VictoriaMetrics/VictoriaMetrics/app/vlselect/main.go:147 +0x8af
main.requestHandler({0xb1b2e0, 0xc0001c2870}, 0xc0000c6360)
	github.com/VictoriaMetrics/VictoriaMetrics/app/victoria-logs/main.go:92 +0x195
github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver.handlerWrapper(0xc0000247a0, {0xb1bc40, 0xc0000a4820}, 0xc0000c6360, 0xa9acd8)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver/httpserver.go:416 +0x1003
github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver.gzipHandler.func1({0xb1bc40?, 0xc0000a4820?}, 0x0?)
	github.com/VictoriaMetrics/VictoriaMetrics/lib/httpserver/httpserver.go:250 +0x31
net/http.HandlerFunc.ServeHTTP(0xfa5f80?, {0xb1bc40?, 0xc0000a4820?}, 0x4?)
	net/http/server.go:2166 +0x29
github.com/klauspost/compress/gzhttp.NewWrapper.func1.1({0xb1b1c0, 0xc0001c81c0}, 0xc0000c6360)
	github.com/klauspost/compress@v1.17.8/gzhttp/compress.go:495 +0x54f
net/http.HandlerFunc.ServeHTTP(0x40ed65?, {0xb1b1c0?, 0xc0001c81c0?}, 0xc0001c8101?)
	net/http/server.go:2166 +0x29
net/http.serverHandler.ServeHTTP({0xb19e20?}, {0xb1b1c0?, 0xc0001c81c0?}, 0x6?)
	net/http/server.go:3137 +0x8e
net/http.(*conn).serve(0xc0001027e0, {0xb1c8c8, 0xc000147a40})
	net/http/server.go:2039 +0x5e8
created by net/http.(*Server).Serve in goroutine 52
	net/http/server.go:3285 +0x4b4

To Reproduce

open vmui, type _time:500m | sort by (_time desc), click "execute query"

Version

victoria-logs-20240512-192959-tags-v0.6.0-victorialogs-0-g89c4dc1d8d

Logs

No response

Screenshots

No response

Used command-line flags

No response

Additional information

No response

[lujiajing1126]

Same issue

This leads to vl crash

[valyala]

@vZ2JEZsZW , thanks for filing the bugreport!

It looks like VictoriaLogs contains only 56 log entries according to the following line from VictoriaLogs log:

successfully opened storage in 0.005 seconds; smallParts: 7; bigParts: 0; smallPartBlocks: 7; bigPartBlocks: 0; smallPartRows: 56; bigPartRows: 0; smallPartSize: 10090 bytes; bigPartSize: 0 bytes

@vZ2JEZsZW , could you provide all these log entries in JSON line form? This will allow reproducing the issue and fixing it faster. The ingested log entries can be collected from the logs generated by VictoriaLogs if it is started with -logIngestedRows command-line flag as described here. Another option is to pass debug=1 query arg to HTTP-based data ingestion APIs. You can pass debug=1 arg to HTTP-based VictoriaLogs data ingestion API at log shipper side. Note that VictoriaLogs doesn't store the ingested logs when they are written to VictoriaLogs log output.

[vZ2JEZsZW]

-logIngestedRows

Tried running it with -logIngestedRows, but there was no rows on the container output. Apparently this requires sending the new records, but I can't do the ingestion currently. (not actually using it, but watching occasionally if I can use it). Also, I assume sending new records would change the state of data files. Attached is data volume in its current state issue6258-viclogsdatavol.tar.gz just in case this can be of any help for debugging

[valyala]

@vZ2JEZsZW , thanks for the provided data! The issue should be fixed in VictoriaLogs v0.6.1.