logging: honour --log-level across nfs, dbserver, and device - #27
Merged
Conversation
The --log-level contract says trace adds per-packet NFS hex dumps and debug adds mount/portmap detail, but the nfs package only ever got a partial dlog conversion: the raw-packet dumps were trace-gated while some 50 log.Printf calls remained, so the default info level logged two to three lines per READ - hex dumps included - which is a steady spam stream during playback (a deck issues READs continuously). Reclassified per the contract: per-packet lines (the RPC call line, per-op one-liners, LOOKUP/READ body and response hex) move to trace; per-file and browse detail (LOOKUP resolutions, first-READ summaries, MNT/UMOUNT/EXPORT, GETPORT responses) move to debug; startup lines, bind/IO errors, protocol anomalies, and write attempts stay at info; the path-traversal block and the port-111 CDJ-mode warning become warnings. A test pins the gate by dispatching a crafted RPC READ call and asserting info logs nothing per-packet while trace does.
Same partial-conversion story as the nfs package: the SEND hex dump
was trace-gated but some 130 raw log.Printf calls remained, so the
default info level logged every deck interaction - a browse line per
button press ("get artists returning N items" and friends), a
per-message type line, discovery and handshake hex, and per-request
blob detail for every artwork, waveform, and beat-grid fetch.
Reclassified per the --log-level contract: per-message and hex/arg
dumps (msg type line, setup RECV remarshal, discovery and handshake
hex, REPLAY, artwork/drill arg dumps) move to trace; per-request
browse and blob detail (category listings, drill-downs, playlists,
menu renders, metadata/waveform/beat-grid/ANLZ-tag responses, cue
loads) move to debug; session lifecycle, errors, protocol anomalies,
and deck writes (rating updates, cue writes) stay at info; the
artwork resize failure becomes a warning. A test pins the gate: a
root-menu browse logs nothing at info, its detail at debug, and the
per-message line at trace.
The nfs and dbserver sweeps missed the device package: four hex dumps still fired at the default info level - the media query (with a full packet dump per source-list refresh, the most visible offender), the startup sample of our own keep-alive, the first keep-alive from each CDJ peer, and the unknown-status-type dump. The media query keeps a one-line summary at debug with the dump at trace; the two keep-alive dumps (wire-RE artifacts) go to debug and trace respectively; the unknown-type line stays at info as a one-liner so new packet types get noticed, with the bytes for reverse- engineering them at trace. Deliberately left at info: the 0x46 link-keepalive cadence line and the play-state change lines - both exist to diagnose the intermittent track-end load failure on real decks, and that diagnosis needs them present in default-level logs when the bug strikes.
"sent load track command: track=47" means nothing when reading a log after the fact, and the load/play-state lines are exactly what gets scanned while chasing the intermittent track-end load failure. The load command, the 0x1c rejection, and the deck play-state transition lines now carry the track title next to the ID; the ID stays so lines remain correlatable with dbserver and NFS entries. LoadTrackOnCDJ takes the display name from its caller (the API server, which has the library row) and stows it on the pending-load attempt so the rejection path can report it too. The play-state line reuses the name the monitor already resolves for the PLAYERS view, so external tracks with fetched metadata show their titles as well; unknown tracks fall back to the bare ID. Logging-only change: nothing on the wire moves.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What & why
The --log-level contract (trace = per-packet hex dumps, debug = per-request detail, info = operationally useful lines) was only ever partially wired up: dlog gated a handful of raw-packet dumps while some 180 log.Printf calls across nfs, dbserver, and device fired regardless of level. At the default info level a browsing, playing deck produced a steady spam stream - two to three lines per NFS READ with hex included, a browse line per deck button press, per-fetch blob detail for every artwork and waveform, and a full media-query packet dump per source-list refresh. The TUI's new Logs tab made this impossible to ignore.
Reclassified per the contract, one commit per package. nfs: per-packet lines and LOOKUP/READ hex move to trace, per-file summaries and mount/portmap detail to debug; startup, bind/IO errors, protocol anomalies, and write attempts stay at info; the path-traversal block and the port-111 CDJ-mode warning become warnings. dbserver: the per-message type line, discovery/handshake hex, and arg dumps move to trace, all browse and blob detail to debug; session lifecycle, errors, anomalies, and deck writes (rating updates, cue writes) stay at info. device: the media-query, keep-alive, and unknown-status-type hex dumps gate behind debug/trace, with the unknown-type one-liner kept at info so new packet types still get noticed.
Two lines were deliberately kept at info despite being periodic: the 0x46 link-keepalive cadence line and the play-state transition line. Both exist to diagnose the intermittent track-end load failure on real decks, and that diagnosis needs them present in default-level logs when the bug strikes.
The last commit makes the surviving load-path lines readable: the load command, the 0x1c rejection, and the play-state transitions now log the track title alongside the ID (the ID stays for correlating with dbserver/NFS entries; external tracks with fetched metadata show titles too). Logging only - nothing on the wire moves anywhere in this branch.
Each converted package gains a test pinning the gate: a crafted NFS READ call logs nothing at info and its per-packet lines at trace, and a dbserver root-menu browse logs nothing at info, its detail at debug, and the per-message line at trace.
Hardware testing
Checklist
go build ./...,go vet ./..., andgo test ./...passgofmt -l .is cleanGPL-3.0-or-later)