Skip to content

fix(tools): stop crush_logs dropping entries at 8KB chunk boundaries - #3988

Open
devYRPauli wants to merge 5 commits into
charmbracelet:mainfrom
devYRPauli:fix/crush-logs-chunk-boundary
Open

devYRPauli wants to merge 5 commits into
charmbracelet:mainfrom
devYRPauli:fix/crush-logs-chunk-boundary

Conversation

@devYRPauli

Copy link
Copy Markdown
Contributor

The crush_logs agent tool skips log entries and returns older entries in their place. For a log of 20KB entries, it returns Log file is empty.

readLastLines in internal/agent/tools/crush_logs.go reads the file backwards in 8KB chunks. It treats the line at the end of each chunk as the incomplete one. When reading backwards, the incomplete line is the first one in the chunk, because its start is in the earlier chunk. A line that crosses a chunk boundary is never joined back together. The tool drops it and reads further back to fill the count.

The crush logs command reads the same file with nxadm/tail and is not affected.

Effect

The log has 200 JSON entries of about 360 bytes each, and entry 150 is padded to 20KB. This is the file TestCrushLogs_EntriesAcrossChunkBoundaries writes. crush_logs with lines: 100:

entries returned missing from 100-199 older entries returned
main 100 118, 141, 150, 154, 177 94, 95, 97, 98, 99
this branch 100 none none

A log of 5 entries of 20KB each returns Log file is empty on main and all 5 entries on this branch.

Change

Each chunk carries its first line back, and the next, earlier chunk joins it to its own last line. The block after the loop that parsed a leftover remainder goes away, because the chunk at offset 0 has no incomplete line.

When the carried part grows past maxLogLineSize, the loop drops it and scans back to the previous newline. The parse loop already skipped such lines. Without the scan-back, the carried part is copied again for every 8KB chunk. I timed a log of 10 entries, one 20MB line and 10 more entries. With lines: 20, it takes about 20s on main and with only the carry fix. It takes about 65ms on this branch. All three versions return the same 20 entries.

Verification

New test TestCrushLogs_EntriesAcrossChunkBoundaries writes the file above and requires entries 100 to 199 in order. It fails before the change. This excerpt of the output cuts the long pad value and the Error Trace and Test lines, and shows tabs as spaces:

--- FAIL: TestCrushLogs_EntriesAcrossChunkBoundaries (0.00s)
    crush_logs_test.go:144:
                Error:          "10:30:00 INFO app.go:94 Entry 94 pad=xxx..." does not contain "Entry 100 pad="

It passes after it.

New test TestCrushLogs_ScanBackPastOversizedLine exercises the scan-back. Its big entry is longer than maxLogLineSize by more than one 8KB chunk. Of the 3 padded entries before it, 2 cross chunk boundaries, and 3 short entries share the chunk where the big entry starts. The test requires the 6 entries before the big entry and the entry after it, in order. It fails on main, and it fails if the scan-back skips the entries before the big entry.

New test TestCrushLogs_LinesAlignedToChunks guards the carry logic when every chunk starts at a line start, and it also passes on main.

go build ./... passes. go test -race ./internal/agent/tools/... passes, with 260 passing tests and subtests in internal/agent/tools, up from 257, and 4 skips on both. go test -race ./internal/app/... ./internal/cmd/... passes. Both depend on internal/agent/tools. golangci-lint run at the CI-pinned v2.13.1 reports 0 issues on ./internal/agent/tools/..., and gofumpt -l lists no changed file.

readLastLines reads the log backwards in 8KB chunks. It treated the
line at the end of each chunk as the incomplete one. When reading
backwards, the incomplete line is the first one in the chunk, because
its start is in the earlier chunk. Entries that crossed a chunk
boundary were dropped or replaced by older entries, and a log of lines
over 8KB returned no entries.

Carry the first line of each chunk back and join it with the earlier
chunk. When the carried part passes maxLogLineSize, scan back to the
previous newline instead of buffering the whole line.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant