From 326e5d6f73a047c858e065e829947abf9ada85da Mon Sep 17 00:00:00 2001 From: Vynull App Date: Mon, 27 Jul 2026 18:04:59 +0000 Subject: [PATCH 1/4] nfs: finish the dlog conversion so READ stops spamming at info 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. --- nfs/loglevel_test.go | 57 ++++++++++++++++++++++++++++++++++++++++++++ nfs/mount.go | 8 +++---- nfs/portmap.go | 6 ++--- nfs/server.go | 34 +++++++++++++------------- 4 files changed, 81 insertions(+), 24 deletions(-) create mode 100644 nfs/loglevel_test.go diff --git a/nfs/loglevel_test.go b/nfs/loglevel_test.go new file mode 100644 index 0000000..08e130c --- /dev/null +++ b/nfs/loglevel_test.go @@ -0,0 +1,57 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +package nfs + +import ( + "bytes" + "encoding/binary" + "log" + "strings" + "testing" + + "github.com/vynulldev/vynull/internal/dlog" +) + +// rpcReadCall builds a minimal Sun-RPC NFS READ call (prog 100003 v2 proc 6) +// with null auth and a zeroed fh/offset/count body. +func rpcReadCall() []byte { + var b bytes.Buffer + for _, v := range []uint32{0x12345678, 0 /* CALL */, 2, 100003, 2, 6 /* READ */} { + binary.Write(&b, binary.BigEndian, v) + } + b.Write(make([]byte, 16)) // null credential + verifier + b.Write(make([]byte, 40)) // fh(32) + offset(4) + count(4) + return b.Bytes() +} + +// TestReadLoggingLevelGated pins the --log-level contract for the NFS +// per-packet lines: at the default info level a READ produces NO log output +// (the old behaviour logged three lines per packet, hex dumps included, +// which spammed the log during playback); at trace the per-packet lines +// appear. +func TestReadLoggingLevelGated(t *testing.T) { + srv := NewServer(t.TempDir()) + pkt := rpcReadCall() + + capture := func(level dlog.Level) string { + var buf bytes.Buffer + prev := log.Writer() + log.SetOutput(&buf) + defer log.SetOutput(prev) + defer dlog.SetLevel(dlog.Info) + dlog.SetLevel(level) + srv.dispatchRPC(pkt, srv.handleNFS) + return buf.String() + } + + if out := capture(dlog.Info); strings.Contains(out, "nfs: READ") { + t.Errorf("info level logged per-packet READ lines:\n%s", out) + } + out := capture(dlog.Trace) + if !strings.Contains(out, "nfs: READ") { + t.Errorf("trace level missing per-packet READ lines:\n%s", out) + } + if !strings.Contains(out, "nfs: RPC call") { + t.Errorf("trace level missing RPC call line:\n%s", out) + } +} diff --git a/nfs/mount.go b/nfs/mount.go index 57d3124..2e20426 100644 --- a/nfs/mount.go +++ b/nfs/mount.go @@ -23,7 +23,7 @@ func (s *Server) handleMount(hdr *rpcHeader) []byte { case mountMnt: return s.mountMnt(hdr) case mountUmnt, mountUmntAll: - log.Printf("mount: UMOUNT") + dlog.Debugf("mount: UMOUNT") return buildRPCReply(hdr.XID).bytes() case mountExport: return s.mountExport(hdr) @@ -47,7 +47,7 @@ func (s *Server) mountMnt(hdr *rpcHeader) []byte { } r := newXDRReader(hdr.body) path, _ := r.str() - log.Printf("mount: MNT %q -> %s", path, s.exportRoot) + dlog.Debugf("mount: MNT %q -> %s", path, s.exportRoot) // Use all-zeros file handle matching rekordbox behavior. var rootFH [fhSize]byte @@ -70,11 +70,11 @@ func (s *Server) mountMnt(hdr *rpcHeader) []byte { func (s *Server) mountExport(hdr *rpcHeader) []byte { w := buildRPCReply(hdr.XID) if s.LinkedFn != nil && !s.LinkedFn() { - log.Printf("mount: EXPORT (unlinked — empty list)") + dlog.Debugf("mount: EXPORT (unlinked — empty list)") w.putU32(0) // value-follows = false, no exports return w.bytes() } - log.Printf("mount: EXPORT") + dlog.Debugf("mount: EXPORT") w.putU32(1) // value-follows = true w.putBytes([]byte("/C/")) diff --git a/nfs/portmap.go b/nfs/portmap.go index 7cf5803..b7d175a 100644 --- a/nfs/portmap.go +++ b/nfs/portmap.go @@ -64,7 +64,7 @@ func (pm *Portmapper) Start(ctx context.Context) error { } } if pm.cdjMode && !has111 { - log.Printf("portmapper: WARNING — port 111 is NOT bound; CDJ-mode track loading WILL FAIL " + + dlog.Warnf("portmapper: WARNING — port 111 is NOT bound; CDJ-mode track loading WILL FAIL " + "(the deck can't locate the NFS mount). Grant the port with ONE of: " + "`sudo sysctl -w net.ipv4.ip_unprivileged_port_start=111` (system-wide, survives rebuilds), " + "`sudo setcap 'cap_net_bind_service=+ep' ` (re-run after each build), or run with sudo. " + @@ -142,10 +142,10 @@ func (pm *Portmapper) handleGetPort(hdr *rpcHeader) []byte { switch prog { case progMount: port = pm.mountPort - log.Printf("portmap: GETPORT mount vers=%d proto=%d -> %d", vers, proto, port) + dlog.Debugf("portmap: GETPORT mount vers=%d proto=%d -> %d", vers, proto, port) case progNFS: port = pm.nfsPort - log.Printf("portmap: GETPORT nfs vers=%d proto=%d -> %d", vers, proto, port) + dlog.Debugf("portmap: GETPORT nfs vers=%d proto=%d -> %d", vers, proto, port) default: log.Printf("portmap: GETPORT unknown program %d", prog) } diff --git a/nfs/server.go b/nfs/server.go index c8ee9f0..0fcde06 100644 --- a/nfs/server.go +++ b/nfs/server.go @@ -307,7 +307,7 @@ func (s *Server) dispatchRPC(data []byte, handler func(*rpcHeader) []byte) []byt log.Printf("nfs: RPC parse error: %v (data len=%d)", err, len(data)) return nil } - log.Printf("nfs: RPC call prog=%d vers=%d proc=%d xid=%08x", hdr.Program, hdr.Version, hdr.Proc, hdr.XID) + dlog.Tracef("nfs: RPC call prog=%d vers=%d proc=%d xid=%08x", hdr.Program, hdr.Version, hdr.Proc, hdr.XID) return handler(hdr) } @@ -315,22 +315,22 @@ func (s *Server) dispatchRPC(data []byte, handler func(*rpcHeader) []byte) []byt func (s *Server) handleNFS(hdr *rpcHeader) []byte { switch hdr.Proc { case nfsNull: - log.Printf("nfs: NULL") + dlog.Tracef("nfs: NULL") return buildRPCReply(hdr.XID).bytes() case nfsGetAttr: - log.Printf("nfs: GETATTR") + dlog.Tracef("nfs: GETATTR") return s.nfsGetAttr(hdr) case nfsLookup: - log.Printf("nfs: LOOKUP") + dlog.Tracef("nfs: LOOKUP") return s.nfsLookup(hdr) case nfsRead: - log.Printf("nfs: READ") + dlog.Tracef("nfs: READ") return s.nfsRead(hdr) case nfsReadDir: - log.Printf("nfs: READDIR") + dlog.Tracef("nfs: READDIR") return s.nfsReadDir(hdr) case nfsStatFS: - log.Printf("nfs: STATFS") + dlog.Tracef("nfs: STATFS") return s.nfsStatFS(hdr) case nfsSetAttr: log.Printf("nfs: SETATTR (write attempt)") @@ -396,7 +396,7 @@ func (s *Server) nfsLookup(hdr *rpcHeader) []byte { return nil } - log.Printf("nfs: LOOKUP raw body (%d bytes): %x", len(hdr.body), hdr.body[:min(len(hdr.body), 80)]) + dlog.Tracef("nfs: LOOKUP raw body (%d bytes): %x", len(hdr.body), hdr.body[:min(len(hdr.body), 80)]) // Detect UTF-16LE vs ASCII. CDJ sends UTF-16LE (every other byte is 0x00 // for ASCII chars). Linux sends plain ASCII. @@ -432,15 +432,15 @@ func (s *Server) nfsLookup(hdr *rpcHeader) []byte { childPath := filepath.Clean(filepath.Join(dirPath, name)) // Prevent path traversal outside the export root. if !strings.HasPrefix(childPath, s.exportRoot) { - log.Printf("nfs: LOOKUP %q in %q: path traversal blocked (resolved to %q)", name, dirPath, childPath) + dlog.Warnf("nfs: LOOKUP %q in %q: path traversal blocked (resolved to %q)", name, dirPath, childPath) w := buildRPCReply(hdr.XID) w.putU32(nfsNoEnt) return w.bytes() } - log.Printf("nfs: LOOKUP %q in %q -> %q", name, dirPath, childPath) + dlog.Debugf("nfs: LOOKUP %q in %q -> %q", name, dirPath, childPath) info, err := os.Stat(childPath) if err != nil { - log.Printf("nfs: LOOKUP %q: %v", childPath, err) + dlog.Debugf("nfs: LOOKUP %q: %v", childPath, err) w := buildRPCReply(hdr.XID) w.putU32(nfsNoEnt) return w.bytes() @@ -454,7 +454,7 @@ func (s *Server) nfsLookup(hdr *rpcHeader) []byte { putFAttr(w, info, childPath, !s.Transcode) resp := w.bytes() - log.Printf("nfs: LOOKUP OK %q size=%d isdir=%v fh=%x resp_hex=%x", + dlog.Tracef("nfs: LOOKUP OK %q size=%d isdir=%v fh=%x resp_hex=%x", name, info.Size(), info.IsDir(), childFH[:8], resp) return resp @@ -462,7 +462,7 @@ func (s *Server) nfsLookup(hdr *rpcHeader) []byte { func (s *Server) nfsRead(hdr *rpcHeader) []byte { if len(hdr.body) >= 8 { - log.Printf("nfs: READ body (%d bytes) first 48: %x", len(hdr.body), hdr.body[:min(len(hdr.body), 48)]) + dlog.Tracef("nfs: READ body (%d bytes) first 48: %x", len(hdr.body), hdr.body[:min(len(hdr.body), 48)]) } r := newXDRReader(hdr.body) fh, err := r.fh() @@ -472,7 +472,7 @@ func (s *Server) nfsRead(hdr *rpcHeader) []byte { offset, _ := r.u32() count, _ := r.u32() _, _ = r.u32() // totalcount (unused in v2) - log.Printf("nfs: READ fh=%x... offset=%d count=%d", fh[:8], offset, count) + dlog.Tracef("nfs: READ fh=%x... offset=%d count=%d", fh[:8], offset, count) path, ok := s.handles.Resolve(fh) if !ok { @@ -498,7 +498,7 @@ func (s *Server) nfsRead(hdr *rpcHeader) []byte { return w.bytes() } if offset == 0 { - log.Printf("nfs: READ transcode %s offset=0 count=%d read=%d", + dlog.Debugf("nfs: READ transcode %s offset=0 count=%d read=%d", filepath.Base(path), count, len(wavBytes)) } w := buildRPCReply(hdr.XID) @@ -528,7 +528,7 @@ func (s *Server) nfsRead(hdr *rpcHeader) []byte { info, _ := f.Stat() if offset == 0 { - log.Printf("nfs: READ %s offset=0 count=%d read=%d first_bytes=%x", + dlog.Debugf("nfs: READ %s offset=0 count=%d read=%d first_bytes=%x", filepath.Base(path), count, n, data[:min(n, 16)]) } @@ -713,7 +713,7 @@ func (s *Server) nfsWriteStub(hdr *rpcHeader, op string) []byte { s.handles.mu.RLock() path := s.handles.toPath[fh] s.handles.mu.RUnlock() - log.Printf("nfs: %s target path: %s (body %d bytes)", op, path, len(hdr.body)) + dlog.Debugf("nfs: %s target path: %s (body %d bytes)", op, path, len(hdr.body)) } w := buildRPCReply(hdr.XID) w.putU32(nfsROFS) // read-only filesystem From d6e11cd2d3e64a8abcf7b4c0e7ae037d9435ec0e Mon Sep 17 00:00:00 2001 From: Vynull App Date: Mon, 27 Jul 2026 18:13:24 +0000 Subject: [PATCH 2/4] dbserver: finish the dlog conversion for browse and packet logging 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. --- dbserver/categories.go | 46 +++++++++++++------------- dbserver/cuepoints.go | 7 ++-- dbserver/drilldown.go | 44 ++++++++++++------------- dbserver/handler.go | 17 +++++----- dbserver/loglevel_test.go | 45 +++++++++++++++++++++++++ dbserver/playlist.go | 16 ++++----- dbserver/render.go | 4 +-- dbserver/server.go | 8 ++--- dbserver/track.go | 69 ++++++++++++++++++++------------------- 9 files changed, 152 insertions(+), 104 deletions(-) create mode 100644 dbserver/loglevel_test.go diff --git a/dbserver/categories.go b/dbserver/categories.go index aedb274..a46ed37 100644 --- a/dbserver/categories.go +++ b/dbserver/categories.go @@ -4,7 +4,7 @@ package dbserver import ( "fmt" - "log" + "github.com/vynulldev/vynull/internal/dlog" "sort" "strings" @@ -27,7 +27,7 @@ func (h *Handler) handleGetTracks(msg *proto.DBMessage) []*proto.DBMessage { h.pendingItems = h.tracksToStdItems(tracks) } sortItems(h.pendingItems, getSortOrder(msg)) - log.Printf("dbserver: get tracks returning %d items (sort=%d)", len(h.pendingItems), getSortOrder(msg)) + dlog.Debugf("dbserver: get tracks returning %d items (sort=%d)", len(h.pendingItems), getSortOrder(msg)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -54,7 +54,7 @@ func (h *Handler) handleGetArtists(msg *proto.DBMessage) []*proto.DBMessage { } } sortItems(h.pendingItems, sortTitle) // artists always sorted by name - log.Printf("dbserver: get artists returning %d items", len(h.pendingItems)) + dlog.Debugf("dbserver: get artists returning %d items", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -81,7 +81,7 @@ func (h *Handler) handleGetAlbums(msg *proto.DBMessage) []*proto.DBMessage { } } sortItems(h.pendingItems, sortTitle) // albums always sorted by name - log.Printf("dbserver: get albums returning %d items", len(h.pendingItems)) + dlog.Debugf("dbserver: get albums returning %d items", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -95,7 +95,7 @@ func (h *Handler) handleGetGenres(msg *proto.DBMessage) []*proto.DBMessage { ItemType: 0x06, // genre } } - log.Printf("dbserver: get genres returning %d items", len(h.pendingItems)) + dlog.Debugf("dbserver: get genres returning %d items", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -120,7 +120,7 @@ func (h *Handler) handleGetBPM(msg *proto.DBMessage) []*proto.DBMessage { }) } h.setPendingAll(msg, items) - log.Printf("dbserver: get BPM returning %d items", len(items)) + dlog.Debugf("dbserver: get BPM returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -164,7 +164,7 @@ func (h *Handler) handleGetBPMRanges(msg *proto.DBMessage) []*proto.DBMessage { }) } h.setPendingAll(msg, items) - log.Printf("dbserver: BPM ranges for %d returning 7 items", targetBPM/100) + dlog.Debugf("dbserver: BPM ranges for %d returning 7 items", targetBPM/100) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -179,7 +179,7 @@ func (h *Handler) handleGetTracksByBPM(msg *proto.DBMessage) []*proto.DBMessage tracks := h.tracksForBPMBucket(targetBPM100, pctRange) items := h.tracksToStdItems(tracks) h.setPendingAll(msg, items) - log.Printf("dbserver: tracks for BPM %.0f +/-%d%% returning %d items", float64(targetBPM100)/100.0, pctRange, len(items)) + dlog.Debugf("dbserver: tracks for BPM %.0f +/-%d%% returning %d items", float64(targetBPM100)/100.0, pctRange, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -253,7 +253,7 @@ func (h *Handler) handleGetYearsForDecade(msg *proto.DBMessage) []*proto.DBMessa } h.setPendingAll(msg, items) - log.Printf("dbserver: years for decade %d returning %d items", decadeStart, len(items)) + dlog.Debugf("dbserver: years for decade %d returning %d items", decadeStart, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -282,7 +282,7 @@ func (h *Handler) handleGetTracksByYear(msg *proto.DBMessage) []*proto.DBMessage } items := h.tracksToStdItems(tracks) h.setPendingAll(msg, items) - log.Printf("dbserver: tracks for decade %d year 0x%08x returning %d items", decadeStart, yearID, len(items)) + dlog.Debugf("dbserver: tracks for decade %d year 0x%08x returning %d items", decadeStart, yearID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -306,7 +306,7 @@ func (h *Handler) handleGetYears(msg *proto.DBMessage) []*proto.DBMessage { } sort.Slice(items, func(i, j int) bool { return items[i].ID > items[j].ID }) h.setPendingAll(msg, items) - log.Printf("dbserver: get decades returning %d items", len(items)) + dlog.Debugf("dbserver: get decades returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } func (h *Handler) handleGetRating(msg *proto.DBMessage) []*proto.DBMessage { @@ -320,7 +320,7 @@ func (h *Handler) handleGetRating(msg *proto.DBMessage) []*proto.DBMessage { {ID: 5, Label1: "5", ItemType: 0x0a}, } h.setPendingAll(msg, items) - log.Printf("dbserver: RATING list returning %d items", len(items)) + dlog.Debugf("dbserver: RATING list returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -339,7 +339,7 @@ func (h *Handler) handleGetTracksByRating(msg *proto.DBMessage) []*proto.DBMessa } items := h.tracksToStdItems(matches) h.setPendingAll(msg, items) - log.Printf("dbserver: RATING drill rating=%d returning %d tracks", rating, len(items)) + dlog.Debugf("dbserver: RATING drill rating=%d returning %d tracks", rating, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -367,7 +367,7 @@ func (h *Handler) handleGetTime(msg *proto.DBMessage) []*proto.DBMessage { } sort.Slice(items, func(i, j int) bool { return items[i].ID < items[j].ID }) h.setPendingAll(msg, items) - log.Printf("dbserver: TIME list returning %d items", len(items)) + dlog.Debugf("dbserver: TIME list returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -388,7 +388,7 @@ func (h *Handler) handleGetTracksByTime(msg *proto.DBMessage) []*proto.DBMessage } items := h.tracksToStdItems(matches) h.setPendingAll(msg, items) - log.Printf("dbserver: TIME drill minute=%d returning %d tracks", bucket, len(items)) + dlog.Debugf("dbserver: TIME drill minute=%d returning %d tracks", bucket, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -409,7 +409,7 @@ func (h *Handler) handleGetTracksByBitrate(msg *proto.DBMessage) []*proto.DBMess } items := h.tracksToStdItems(matches) h.setPendingAll(msg, items) - log.Printf("dbserver: BITRATE drill kbps=%d returning %d tracks", bitrate, len(items)) + dlog.Debugf("dbserver: BITRATE drill kbps=%d returning %d tracks", bitrate, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -434,7 +434,7 @@ func (h *Handler) handleGetBitrate(msg *proto.DBMessage) []*proto.DBMessage { } sort.Slice(items, func(i, j int) bool { return items[i].ID < items[j].ID }) h.setPendingAll(msg, items) - log.Printf("dbserver: BITRATE list returning %d items", len(items)) + dlog.Debugf("dbserver: BITRATE list returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -461,7 +461,7 @@ func (h *Handler) handleGetFilename(msg *proto.DBMessage) []*proto.DBMessage { } sort.Slice(items, func(i, j int) bool { return items[i].Label1 < items[j].Label1 }) h.setPendingAll(msg, items) - log.Printf("dbserver: FILENAME list returning %d items", len(items)) + dlog.Debugf("dbserver: FILENAME list returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -470,7 +470,7 @@ func (h *Handler) handleGetFilename(msg *proto.DBMessage) []*proto.DBMessage { // entry (single empty row). func (h *Handler) handleGetHotCueBank(msg *proto.DBMessage) []*proto.DBMessage { h.setPendingAll(msg, nil) - log.Printf("dbserver: HOT CUE BANK list (empty — not stored)") + dlog.Debugf("dbserver: HOT CUE BANK list (empty — not stored)") return []*proto.DBMessage{h.successWithCount(msg)} } @@ -506,7 +506,7 @@ func (h *Handler) handleGetKeys(msg *proto.DBMessage) []*proto.DBMessage { h.pendingItems = nil } sortItems(h.pendingItems, sortTitle) - log.Printf("dbserver: get keys returning %d items", len(h.pendingItems)) + dlog.Debugf("dbserver: get keys returning %d items", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -527,7 +527,7 @@ func (h *Handler) handleGetLabels(msg *proto.DBMessage) []*proto.DBMessage { } h.pendingItems = items sortItems(h.pendingItems, sortTitle) - log.Printf("dbserver: get labels returning %d items", len(h.pendingItems)) + dlog.Debugf("dbserver: get labels returning %d items", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -549,7 +549,7 @@ func (h *Handler) handleGetRemixers(msg *proto.DBMessage) []*proto.DBMessage { } sortItems(items, sortTitle) h.setPendingAll(msg, items) - log.Printf("dbserver: get remixers returning %d items", len(items)) + dlog.Debugf("dbserver: get remixers returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -571,6 +571,6 @@ func (h *Handler) handleGetOriginalArtists(msg *proto.DBMessage) []*proto.DBMess } sortItems(items, sortTitle) h.setPendingAll(msg, items) - log.Printf("dbserver: get original artists returning %d items", len(items)) + dlog.Debugf("dbserver: get original artists returning %d items", len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } diff --git a/dbserver/cuepoints.go b/dbserver/cuepoints.go index 1e13c81..4e1d15e 100644 --- a/dbserver/cuepoints.go +++ b/dbserver/cuepoints.go @@ -6,6 +6,7 @@ import ( "encoding/binary" "encoding/json" "fmt" + "github.com/vynulldev/vynull/internal/dlog" "log" "os" "path/filepath" @@ -62,7 +63,7 @@ func ParseCueBlob(blob []byte, trackID uint32) (*CuePoint, error) { } cue.ColorID = cueColorFromBlob(blob) - log.Printf("cuestore: parsed cue #%d type=%d time=%dms loop=%d color_id=%d (0x%x) track=%d", + dlog.Debugf("cuestore: parsed cue #%d type=%d time=%dms loop=%d color_id=%d (0x%x) track=%d", cue.Number, cue.Type, cue.TimeMs, cue.LoopMs, cue.ColorID, cue.ColorID, trackID) return cue, nil } @@ -338,11 +339,11 @@ func (cs *CueStore) loadAll() { } var cues []CuePoint if err := json.Unmarshal(data, &cues); err != nil { - log.Printf("cuestore: parse %s: %v", e.Name(), err) + dlog.Debugf("cuestore: parse %s: %v", e.Name(), err) continue } cs.data[trackID] = cues - log.Printf("cuestore: loaded %d cues for track %d", len(cues), trackID) + dlog.Debugf("cuestore: loaded %d cues for track %d", len(cues), trackID) } // Load raw blob files. var bTrackID uint32 diff --git a/dbserver/drilldown.go b/dbserver/drilldown.go index 06e52ff..e3c6d2e 100644 --- a/dbserver/drilldown.go +++ b/dbserver/drilldown.go @@ -4,7 +4,7 @@ package dbserver import ( "fmt" - "log" + "github.com/vynulldev/vynull/internal/dlog" "strings" "github.com/vynulldev/vynull/library" @@ -20,7 +20,7 @@ import ( func (h *Handler) handleNXS2MenuLoad(msg *proto.DBMessage) []*proto.DBMessage { menu := dmstMenu(msg) - log.Printf("dbserver: NXS2 menu load 0x1010 menu=%d args=%d", menu, len(msg.Args)) + dlog.Debugf("dbserver: NXS2 menu load 0x1010 menu=%d args=%d", menu, len(msg.Args)) // Populate the category if we can. switch menu { @@ -54,9 +54,9 @@ func (h *Handler) handleNXS2MenuLoad(msg *proto.DBMessage) []*proto.DBMessage { // The DMST menu byte identifies the category context. func (h *Handler) handleNXS2DrillDown(msg *proto.DBMessage) []*proto.DBMessage { menu := dmstMenu(msg) - log.Printf("dbserver: NXS2 drill-down 0x%04x menu=%d args=%d", msg.Type, menu, len(msg.Args)) + dlog.Debugf("dbserver: NXS2 drill-down 0x%04x menu=%d args=%d", msg.Type, menu, len(msg.Args)) for i, a := range msg.Args { - log.Printf("dbserver: NXS2 drill arg[%d] = 0x%08x (%d)", i, a.Int(), a.Int()) + dlog.Tracef("dbserver: NXS2 drill arg[%d] = 0x%08x (%d)", i, a.Int(), a.Int()) } var items []*menuItem @@ -100,7 +100,7 @@ func (h *Handler) handleNXS2DrillDown(msg *proto.DBMessage) []*proto.DBMessage { // shape but the log line difference helps debugging which path fired. func (h *Handler) handleNXS2DrillOrSearchSetup(msg *proto.DBMessage) []*proto.DBMessage { if len(msg.Args) <= 2 { - log.Printf("dbserver: SEARCH category setup (0x1012 with %d args)", len(msg.Args)) + dlog.Debugf("dbserver: SEARCH category setup (0x1012 with %d args)", len(msg.Args)) // Echo the request type and a 0-item count. The deck takes this // as the cue to open its on-screen keyboard; the first keystroke // then arrives as a 0x1300 query. @@ -131,7 +131,7 @@ func (h *Handler) handleSearch(msg *proto.DBMessage) []*proto.DBMessage { // trimmed by DecodeUTF16BE. query = proto.DecodeUTF16BE([]byte(msg.Args[3].Str)) } - log.Printf("dbserver: SEARCH query=%q", query) + dlog.Debugf("dbserver: SEARCH query=%q", query) var items []*menuItem if h.lib != nil && query != "" { @@ -204,7 +204,7 @@ func (h *Handler) searchTrackItem(t *library.Track) *menuItem { // follow-up "give me tracks of colour N" drill (0x110d) can route // to handleGetTracksByColor. func (h *Handler) handleGetColors(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver: COLOR list (0x100d)") + dlog.Debugf("dbserver: COLOR list (0x100d)") items := []*menuItem{ {ID: 0, Label1: "NO COLOR", ItemType: 0x13}, {ID: 1, Label1: "PINK", ItemType: 0x14}, @@ -229,7 +229,7 @@ func (h *Handler) handleGetTracksByColor(msg *proto.DBMessage) []*proto.DBMessag if len(msg.Args) >= 3 { colorID = msg.Args[2].Int() } - log.Printf("dbserver: COLOR drill (0x110d) color=%d", colorID) + dlog.Debugf("dbserver: COLOR drill (0x110d) color=%d", colorID) var matches []*library.Track if h.lib != nil { @@ -271,7 +271,7 @@ func (h *Handler) handleUndecodedStub(msg *proto.DBMessage) []*proto.DBMessage { // request. Our previous bogus "success" reply was an unexpected extra // message that corrupted the deck's load state (0x1c rejections after a // couple of loads). Returning nil → the dispatch writes nothing. - log.Printf("dbserver: ignoring 0x%04x (no response, matching rekordbox) args=[%s]", msg.Type, strings.Join(argParts, " ")) + dlog.Debugf("dbserver: ignoring 0x%04x (no response, matching rekordbox) args=[%s]", msg.Type, strings.Join(argParts, " ")) return nil } @@ -303,7 +303,7 @@ func (h *Handler) handleSearchSelect(msg *proto.DBMessage) []*proto.DBMessage { if len(msg.Args) >= 3 { id = msg.Args[2].Int() } - log.Printf("dbserver: 0x1200 search-select id=%d", id) + dlog.Debugf("dbserver: 0x1200 search-select id=%d", id) var items []*menuItem if h.lib != nil && id != 0 { @@ -439,7 +439,7 @@ func (h *Handler) handleGetArtistsForLabel(msg *proto.DBMessage) []*proto.DBMess sortItems(items[1:], sortTitle) // sort artists, keep [ALL] first h.setPendingAll(msg, items) - log.Printf("dbserver: artists for label 0x%08x returning %d items", labelID, len(items)) + dlog.Debugf("dbserver: artists for label 0x%08x returning %d items", labelID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -454,7 +454,7 @@ func (h *Handler) handleGetAlbumsForLabel(msg *proto.DBMessage) []*proto.DBMessa items := h.getAlbumsForLabelArtist(labelID, artistID) h.setPendingAll(msg, items) - log.Printf("dbserver: albums for label 0x%08x artist 0x%08x returning %d items", labelID, artistID, len(items)) + dlog.Debugf("dbserver: albums for label 0x%08x artist 0x%08x returning %d items", labelID, artistID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -488,7 +488,7 @@ func (h *Handler) handleGetTracksByLabel(msg *proto.DBMessage) []*proto.DBMessag } items := h.tracksToStdItems(tracks) h.setPendingAll(msg, items) - log.Printf("dbserver: tracks for label 0x%08x artist 0x%08x returning %d items", labelID, artistID, len(items)) + dlog.Debugf("dbserver: tracks for label 0x%08x artist 0x%08x returning %d items", labelID, artistID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -519,7 +519,7 @@ func (h *Handler) handleGetKeyDistances(msg *proto.DBMessage) []*proto.DBMessage }) } h.setPendingAll(msg, items) - log.Printf("dbserver: key distances for %q returning %d groups", keyName, len(items)) + dlog.Debugf("dbserver: key distances for %q returning %d groups", keyName, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -555,7 +555,7 @@ func (h *Handler) handleGetTracksByKey(msg *proto.DBMessage) []*proto.DBMessage } items := h.tracksToStdItems(tracks) h.setPendingAll(msg, items) - log.Printf("dbserver: tracks for key %q dist=%d returning %d tracks", keyName, distance, len(items)) + dlog.Debugf("dbserver: tracks for key %q dist=%d returning %d tracks", keyName, distance, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -676,7 +676,7 @@ func (h *Handler) handleGetByArtist(msg *proto.DBMessage) []*proto.DBMessage { } } h.pendingItems = items - log.Printf("dbserver: get by artist %d returning %d albums (PDB)", artistID, len(items)) + dlog.Debugf("dbserver: get by artist %d returning %d albums (PDB)", artistID, len(items)) sortItems(items, sortTitle) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -711,7 +711,7 @@ func (h *Handler) handleGetByArtist(msg *proto.DBMessage) []*proto.DBMessage { } } h.pendingItems = items - log.Printf("dbserver: get by artist %q returning %d albums", artistName, len(h.pendingItems)) + dlog.Debugf("dbserver: get by artist %q returning %d albums", artistName, len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -741,7 +741,7 @@ func (h *Handler) handleGetTracksByAlbum(msg *proto.DBMessage) []*proto.DBMessag } sortItems(items, getSortOrder(msg)) h.pendingItems = items - log.Printf("dbserver: get tracks by album %d (PDB) returning %d tracks", albumID, len(items)) + dlog.Debugf("dbserver: get tracks by album %d (PDB) returning %d tracks", albumID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -758,7 +758,7 @@ func (h *Handler) handleGetTracksByAlbum(msg *proto.DBMessage) []*proto.DBMessag matchTracks = h.lib.TracksByAlbum(albumName) } h.pendingItems = h.tracksToStdItems(matchTracks) - log.Printf("dbserver: get tracks by album (0x1202) returning %d tracks", len(h.pendingItems)) + dlog.Debugf("dbserver: get tracks by album (0x1202) returning %d tracks", len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -779,7 +779,7 @@ func (h *Handler) handleGetByAlbum(msg *proto.DBMessage) []*proto.DBMessage { } sortItems(items, getSortOrder(msg)) h.pendingItems = items - log.Printf("dbserver: get by album %d (PDB) returning %d tracks", albumID, len(items)) + dlog.Debugf("dbserver: get by album %d (PDB) returning %d tracks", albumID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -796,7 +796,7 @@ func (h *Handler) handleGetByAlbum(msg *proto.DBMessage) []*proto.DBMessage { } tracks := h.lib.TracksByAlbum(albumName) h.pendingItems = h.tracksToStdItems(tracks) - log.Printf("dbserver: get by album %q returning %d tracks", albumName, len(h.pendingItems)) + dlog.Debugf("dbserver: get by album %q returning %d tracks", albumName, len(h.pendingItems)) return []*proto.DBMessage{h.successWithCount(msg)} } @@ -820,6 +820,6 @@ func (h *Handler) handleGetByGenre(msg *proto.DBMessage) []*proto.DBMessage { tracks := h.lib.TracksByGenre(genreName) items := h.tracksToStdItems(tracks) h.setPendingAll(msg, items) - log.Printf("dbserver: get by genre %q returning %d tracks", genreName, len(items)) + dlog.Debugf("dbserver: get by genre %q returning %d tracks", genreName, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } diff --git a/dbserver/handler.go b/dbserver/handler.go index 1da6bda..f7d9adc 100644 --- a/dbserver/handler.go +++ b/dbserver/handler.go @@ -4,6 +4,7 @@ package dbserver import ( "fmt" + "github.com/vynulldev/vynull/internal/dlog" "log" "path/filepath" "strings" @@ -172,7 +173,7 @@ func (h *Handler) storeAnalysisResult(trackID uint32, r *analysis.Result) { // Handle dispatches a message to the appropriate handler and returns // zero or more response messages. func (h *Handler) Handle(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver msg type=0x%04x txid=%08x args=%d", msg.Type, msg.TxID, len(msg.Args)) + dlog.Tracef("dbserver msg type=0x%04x txid=%08x args=%d", msg.Type, msg.TxID, len(msg.Args)) switch msg.Type { case proto.DBMsgSetup: @@ -216,13 +217,13 @@ func (h *Handler) Handle(msg *proto.DBMessage) []*proto.DBMessage { // Respond with [0x1602, 0]. Leaving it // unhandled appears to make the deck stall before entering // some categories (SEARCH keyboard not opening in particular). - log.Printf("dbserver: 0x1602 preflight ack") + dlog.Debugf("dbserver: 0x1602 preflight ack") return []*proto.DBMessage{{ TxID: msg.TxID, Type: proto.DBMsgSuccess, Args: []proto.DBArg{proto.ArgI32(uint32(msg.Type)), proto.ArgI32(0)}, }} case 0x3001: // metadata notification (CDJ sends ~1min after loading); no response expected - log.Printf("dbserver: 0x3001 notification (no response)") + dlog.Debugf("dbserver: 0x3001 notification (no response)") return nil case proto.DBMsgGetTracks: return h.handleGetTracks(msg) @@ -398,7 +399,7 @@ func (h *Handler) handleSetup(msg *proto.DBMessage) []*proto.DBMessage { for i, a := range msg.Args { args += fmt.Sprintf(" arg[%d]=tag0x%02x/%d", i, a.Tag, a.Int()) } - log.Printf("dbserver setup RECV: txid=0x%08x argc=%d%s remarshal=[% x]", + dlog.Tracef("dbserver setup RECV: txid=0x%08x argc=%d%s remarshal=[% x]", msg.TxID, len(msg.Args), args, proto.MarshalDBMessage(msg)) // Response must have TWO int32 args: [0, server_player_number] return []*proto.DBMessage{{ @@ -412,7 +413,7 @@ func (h *Handler) handleSetup(msg *proto.DBMessage) []*proto.DBMessage { } func (h *Handler) handleMediaInfo(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver: media info (0x3007)") + dlog.Debugf("dbserver: media info (0x3007)") // Respond: success with [echo_type, 0] — matches the CDJ return []*proto.DBMessage{{ TxID: msg.TxID, @@ -422,7 +423,7 @@ func (h *Handler) handleMediaInfo(msg *proto.DBMessage) []*proto.DBMessage { } func (h *Handler) handleNXS2Extension(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver: NXS2 extension (0x3e03)") + dlog.Debugf("dbserver: NXS2 extension (0x3e03)") // Respond: type 0x4b02 with [echo_type, 0, 2, ""] — matches the CDJ return []*proto.DBMessage{{ TxID: msg.TxID, @@ -470,7 +471,7 @@ func (h *Handler) rootMenu() []*menuItem { } func (h *Handler) handleRootMenu(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver: root menu (0x1000)") + dlog.Debugf("dbserver: root menu (0x1000)") // The deck is back at the root menu, so any "most recent category/detail // list" context is stale. Clear it — otherwise the follow-up root render // (menu=1/7) can match lastCategoryItems by count and show that stale @@ -479,7 +480,7 @@ func (h *Handler) handleRootMenu(msg *proto.DBMessage) []*proto.DBMessage { // so browsing the menu after INFO rendered the track info. h.lastCategoryItems = nil items := h.rootMenu() - log.Printf("dbserver: root menu returning %d categories", len(items)) + dlog.Debugf("dbserver: root menu returning %d categories", len(items)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: proto.DBMsgSuccess, diff --git a/dbserver/loglevel_test.go b/dbserver/loglevel_test.go new file mode 100644 index 0000000..f52b8f8 --- /dev/null +++ b/dbserver/loglevel_test.go @@ -0,0 +1,45 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +package dbserver + +import ( + "bytes" + "log" + "strings" + "testing" + + "github.com/vynulldev/vynull/internal/dlog" + "github.com/vynulldev/vynull/library" + "github.com/vynulldev/vynull/proto" +) + +// TestBrowseLoggingLevelGated pins the --log-level contract for dbserver: +// at the default info level a routine browse request (root menu) produces +// NO log output — the old behaviour logged the per-message type line plus +// per-request menu detail for every deck button press — while debug shows +// the browse detail and trace adds the per-message line. +func TestBrowseLoggingLevelGated(t *testing.T) { + h := &Handler{lib: library.New()} + msg := &proto.DBMessage{Type: 0x1000} // root menu request + + capture := func(level dlog.Level) string { + var buf bytes.Buffer + prev := log.Writer() + log.SetOutput(&buf) + defer log.SetOutput(prev) + defer dlog.SetLevel(dlog.Info) + dlog.SetLevel(level) + h.Handle(msg) + return buf.String() + } + + if out := capture(dlog.Info); strings.Contains(out, "dbserver") { + t.Errorf("info level logged browse lines:\n%s", out) + } + if out := capture(dlog.Debug); !strings.Contains(out, "root menu") { + t.Errorf("debug level missing browse detail:\n%s", out) + } + if out := capture(dlog.Trace); !strings.Contains(out, "dbserver msg type=") { + t.Errorf("trace level missing per-message line:\n%s", out) + } +} diff --git a/dbserver/playlist.go b/dbserver/playlist.go index c009d1b..a5e825b 100644 --- a/dbserver/playlist.go +++ b/dbserver/playlist.go @@ -3,7 +3,7 @@ package dbserver import ( - "log" + "github.com/vynulldev/vynull/internal/dlog" "path/filepath" "github.com/vynulldev/vynull/pdb" @@ -16,7 +16,7 @@ import ( // trackIDsToMenuItems shared converter. func (h *Handler) handleGetHistory(msg *proto.DBMessage) []*proto.DBMessage { - log.Printf("dbserver: HISTORY list (0x1016)") + dlog.Debugf("dbserver: HISTORY list (0x1016)") var items []*menuItem if h.playlists != nil { folderID := h.playlists.HistoryFolderID() @@ -45,7 +45,7 @@ func (h *Handler) handleGetHistoryTracks(msg *proto.DBMessage) []*proto.DBMessag if len(msg.Args) >= 3 { playlistID = msg.Args[2].Int() } - log.Printf("dbserver: HISTORY drill (0x1116) playlist=%d", playlistID) + dlog.Debugf("dbserver: HISTORY drill (0x1116) playlist=%d", playlistID) var items []*menuItem if h.playlists != nil && playlistID != 0 { @@ -105,13 +105,13 @@ func (h *Handler) handleGetPlaylist(msg *proto.DBMessage) []*proto.DBMessage { }) } h.pendingItems = items - log.Printf("dbserver: user-playlist folder %d returning %d items", folderID, len(items)) + dlog.Debugf("dbserver: user-playlist folder %d returning %d items", folderID, len(items)) } else { trackIDs := h.playlists.Tracks(folderID) items := h.trackIDsToMenuItems(trackIDs) sortItems(items, getSortOrder(msg)) h.pendingItems = items - log.Printf("dbserver: user-playlist %d returning %d tracks", folderID, len(items)) + dlog.Debugf("dbserver: user-playlist %d returning %d tracks", folderID, len(items)) } return []*proto.DBMessage{h.successWithCount(msg)} } @@ -142,13 +142,13 @@ func (h *Handler) handleGetPlaylist(msg *proto.DBMessage) []*proto.DBMessage { }) } h.pendingItems = items - log.Printf("dbserver: playlist folder %d returning %d items (filesystem fallback)", folderID, len(items)) + dlog.Debugf("dbserver: playlist folder %d returning %d items (filesystem fallback)", folderID, len(items)) } else { trackIDs := h.folders.TrackIDs(folderID) items := h.trackIDsToMenuItems(trackIDs) sortItems(items, getSortOrder(msg)) h.pendingItems = items - log.Printf("dbserver: playlist %d returning %d tracks (filesystem fallback)", folderID, len(items)) + dlog.Debugf("dbserver: playlist %d returning %d tracks (filesystem fallback)", folderID, len(items)) } return []*proto.DBMessage{h.successWithCount(msg)} @@ -218,7 +218,7 @@ func (h *Handler) handleGetFolder(msg *proto.DBMessage) []*proto.DBMessage { }) } h.pendingItems = items - log.Printf("dbserver: folder %d returning %d items", folderID, len(items)) + dlog.Debugf("dbserver: folder %d returning %d items", folderID, len(items)) return []*proto.DBMessage{h.successWithCount(msg)} } diff --git a/dbserver/render.go b/dbserver/render.go index ca1f1c3..2bb3588 100644 --- a/dbserver/render.go +++ b/dbserver/render.go @@ -4,7 +4,7 @@ package dbserver import ( "fmt" - "log" + "github.com/vynulldev/vynull/internal/dlog" "sort" "github.com/vynulldev/vynull/library" @@ -73,7 +73,7 @@ func (h *Handler) handleRenderMenu(msg *proto.DBMessage) []*proto.DBMessage { if len(pending) == 0 && menu > 12 && len(h.pendingItems) > 0 { pending = h.pendingItems } - log.Printf("dbserver: render menu=%d args=%v pendingItems=%d", menu, argVals, len(pending)) + dlog.Debugf("dbserver: render menu=%d args=%v pendingItems=%d", menu, argVals, len(pending)) offset := 0 limit := len(pending) diff --git a/dbserver/server.go b/dbserver/server.go index c62575b..21d79cc 100644 --- a/dbserver/server.go +++ b/dbserver/server.go @@ -288,13 +288,13 @@ func (s *Server) handleDiscovery(conn net.Conn) { } } - log.Printf("dbserver discovery from %s (%d bytes):\n%s", + dlog.Tracef("dbserver discovery from %s (%d bytes):\n%s", conn.RemoteAddr(), n, hex.Dump(buf[:n])) // Respond with dynamic port number for the dbserver. resp := make([]byte, 2) binary.BigEndian.PutUint16(resp, s.dynamicPort) - log.Printf("dbserver discovery: sent port %d to %s", s.dynamicPort, conn.RemoteAddr()) + dlog.Debugf("dbserver discovery: sent port %d to %s", s.dynamicPort, conn.RemoteAddr()) if _, err := conn.Write(resp); err != nil { log.Printf("dbserver discovery write: %v", err) } @@ -347,7 +347,7 @@ func (s *Server) handleSession(ctx context.Context, conn net.Conn) { log.Printf("dbserver handshake write: %v", err) return } - log.Printf("dbserver handshake: echo %s", hex.EncodeToString(clientHandshake)) + dlog.Tracef("dbserver handshake: echo %s", hex.EncodeToString(clientHandshake)) log.Printf("dbserver handshake complete with %s", conn.RemoteAddr()) conn.SetReadDeadline(time.Time{}) // clear deadline @@ -405,7 +405,7 @@ func (s *Server) handleSession(ctx context.Context, conn net.Conn) { if replacement := s.findReplay(resp.Type, len(data), msg); replacement != nil { // Fix up the txid to match the current request. binary.BigEndian.PutUint32(replacement[6:10], msg.TxID) - log.Printf("dbserver REPLAY type=0x%04x txid=%08x (%d bytes from recording)", + dlog.Tracef("dbserver REPLAY type=0x%04x txid=%08x (%d bytes from recording)", resp.Type, msg.TxID, len(replacement)) data = replacement } diff --git a/dbserver/track.go b/dbserver/track.go index eb6bbdc..0a52b30 100644 --- a/dbserver/track.go +++ b/dbserver/track.go @@ -4,6 +4,7 @@ package dbserver import ( "encoding/binary" + "github.com/vynulldev/vynull/internal/dlog" "log" "math" "strings" @@ -80,7 +81,7 @@ func (h *Handler) handleGetMetadata(msg *proto.DBMessage) []*proto.DBMessage { }} } - log.Printf("dbserver: metadata for track %d: %q by %q", trackID, title, artist) + dlog.Debugf("dbserver: metadata for track %d: %q by %q", trackID, title, artist) // Metadata items in the standard format. // Item types: 0x000b=duration(secs), 0x000d=BPM(*100), 0x000f=key @@ -192,7 +193,7 @@ func (h *Handler) handleSetRating(msg *proto.DBMessage) []*proto.DBMessage { func (h *Handler) handleGetArtwork(msg *proto.DBMessage) []*proto.DBMessage { for i, a := range msg.Args { - log.Printf("dbserver: 0x%04x artwork arg[%d] = 0x%08x (%d)", msg.Type, i, a.Int(), a.Int()) + dlog.Tracef("dbserver: 0x%04x artwork arg[%d] = 0x%08x (%d)", msg.Type, i, a.Int(), a.Int()) } if len(msg.Args) < 2 { return []*proto.DBMessage{h.success(msg)} @@ -211,7 +212,7 @@ func (h *Handler) handleGetArtwork(msg *proto.DBMessage) []*proto.DBMessage { // If not found by direct ID, try resolving via track's ArtID. if art == nil && h.lib != nil { if t := h.lib.Track(artID); t != nil && t.ArtID > 0 { - log.Printf("dbserver: artwork %d → track %d artID=%d", artID, t.ID, t.ArtID) + dlog.Debugf("dbserver: artwork %d → track %d artID=%d", artID, t.ID, t.ArtID) art = h.lib.Artwork.Get(t.ArtID) } } @@ -228,7 +229,7 @@ func (h *Handler) handleGetArtwork(msg *proto.DBMessage) []*proto.DBMessage { h.lib.Artwork.AddWithID(art.ID, "image/jpeg", small) art = h.lib.Artwork.Get(art.ID) } else { - log.Printf("dbserver: artwork %d oversized (%d bytes), resize failed (%v) — skipping to protect the deck", art.ID, len(art.Data), err) + dlog.Warnf("dbserver: artwork %d oversized (%d bytes), resize failed (%v) — skipping to protect the deck", art.ID, len(art.Data), err) art = nil } } @@ -249,7 +250,7 @@ func (h *Handler) handleGetArtwork(msg *proto.DBMessage) []*proto.DBMessage { }} } - log.Printf("dbserver: artwork %d: %d bytes (%s)", artID, len(art.Data), art.MIMEType) + dlog.Debugf("dbserver: artwork %d: %d bytes (%s)", artID, len(art.Data), art.MIMEType) // Response type 0x4002 with [echo_type, 0, size, jpeg_blob]. return []*proto.DBMessage{{ @@ -277,7 +278,7 @@ func (h *Handler) handleGetWavePreview(msg *proto.DBMessage) []*proto.DBMessage if trackID > 0 { if r := h.lazyAnalyze(trackID); r != nil && len(r.WavePreview) > 0 { blob := r.WavePreview - log.Printf("dbserver: wave preview for track %d (%d bytes)", trackID, len(blob)) + dlog.Debugf("dbserver: wave preview for track %d (%d bytes)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4402, Args: []proto.DBArg{ @@ -290,7 +291,7 @@ func (h *Handler) handleGetWavePreview(msg *proto.DBMessage) []*proto.DBMessage } } - log.Printf("dbserver: wave preview 0x%04x (no data)", msg.Type) + dlog.Debugf("dbserver: wave preview 0x%04x (no data)", msg.Type) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4402, Args: []proto.DBArg{ @@ -310,7 +311,7 @@ func (h *Handler) handleGetWaveDetail(msg *proto.DBMessage) []*proto.DBMessage { if trackID > 0 { if r := h.lazyAnalyze(trackID); r != nil && len(r.WaveDetailMono) > 0 { - log.Printf("dbserver: wave detail mono for track %d (%d bytes)", trackID, len(r.WaveDetailMono)) + dlog.Debugf("dbserver: wave detail mono for track %d (%d bytes)", trackID, len(r.WaveDetailMono)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4a02, Args: []proto.DBArg{ @@ -324,7 +325,7 @@ func (h *Handler) handleGetWaveDetail(msg *proto.DBMessage) []*proto.DBMessage { } } - log.Printf("dbserver: wave detail 0x2904 (no data)") + dlog.Debugf("dbserver: wave detail 0x2904 (no data)") return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4a02, Args: []proto.DBArg{ @@ -348,7 +349,7 @@ func (h *Handler) handleGetBeatGrid(msg *proto.DBMessage) []*proto.DBMessage { if trackID > 0 { if r := h.lazyAnalyze(trackID); r != nil && len(r.BeatGrid) > 0 { blob := h.beatGridForTrack(trackID, r) - log.Printf("dbserver: beat grid for track %d (%d bytes)", trackID, len(blob)) + dlog.Debugf("dbserver: beat grid for track %d (%d bytes)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4602, Args: []proto.DBArg{ @@ -362,7 +363,7 @@ func (h *Handler) handleGetBeatGrid(msg *proto.DBMessage) []*proto.DBMessage { } } - log.Printf("dbserver: beat grid (no data)") + dlog.Debugf("dbserver: beat grid (no data)") return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4602, Args: []proto.DBArg{ @@ -498,7 +499,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage // Reverse to get the actual fourcc. tagFourCC = string([]byte{b[3], b[2], b[1], b[0]}) } - log.Printf("dbserver: 0x2c04 track=%d tag=%q", trackID, tagFourCC) + dlog.Debugf("dbserver: 0x2c04 track=%d tag=%q", trackID, tagFourCC) if trackID > 0 { r := h.lazyAnalyze(trackID) @@ -514,7 +515,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage extPath = h.exportRoot + extPath } if realBlob := analysis.ReadANLZSection(extPath, "PWV4"); realBlob != nil { - log.Printf("dbserver: PWV4 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) + dlog.Debugf("dbserver: PWV4 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -530,7 +531,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage } if len(r.WaveColorPreview) > 0 { blob := analysis.WrapANLZ("PWV4", 6, r.WaveColorPreview) - log.Printf("dbserver: PWV4 for track %d (%d bytes, generated)", trackID, len(blob)) + dlog.Debugf("dbserver: PWV4 for track %d (%d bytes, generated)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -551,7 +552,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage extPath = h.exportRoot + extPath } if realBlob := analysis.ReadANLZSection(extPath, "PWV5"); realBlob != nil { - log.Printf("dbserver: PWV5 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) + dlog.Debugf("dbserver: PWV5 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -567,7 +568,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage } if len(r.WaveDetail) > 0 { blob := analysis.WrapANLZ("PWV5", 2, r.WaveDetail) - log.Printf("dbserver: PWV5 for track %d (%d bytes, generated)", trackID, len(blob)) + dlog.Debugf("dbserver: PWV5 for track %d (%d bytes, generated)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -595,7 +596,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage } if len(body) > 0 { blob := analysis.WrapANLZ(tagFourCC, entrySize, body) - log.Printf("dbserver: %s for track %d (%d bytes)", tagFourCC, trackID, len(blob)) + dlog.Debugf("dbserver: %s for track %d (%d bytes)", tagFourCC, trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -610,7 +611,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage case "PSSI": // song structure / phrase analysis if r.SongStructure != nil { blob := analysis.WrapANLZ("PSSI", 24, r.SongStructure) - log.Printf("dbserver: PSSI for track %d (%d bytes, generated)", trackID, len(blob)) + dlog.Debugf("dbserver: PSSI for track %d (%d bytes, generated)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -639,7 +640,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage extPath = h.exportRoot + extPath } if realBlob := analysis.ReadANLZSection(extPath, "PVB2"); realBlob != nil { - log.Printf("dbserver: PVB2 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) + dlog.Debugf("dbserver: PVB2 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -660,10 +661,10 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage // be probed. blob := analysis.VBRSeekIndex(h.resolveTrackPath(trackID)) if blob != nil { - log.Printf("dbserver: PVB2 for track %d (%d bytes, generated seek index)", trackID, len(blob)) + dlog.Debugf("dbserver: PVB2 for track %d (%d bytes, generated seek index)", trackID, len(blob)) } else { blob = prolink.GeneratePVB2() - log.Printf("dbserver: PVB2 for track %d (%d bytes, placeholder — probe failed)", trackID, len(blob)) + dlog.Debugf("dbserver: PVB2 for track %d (%d bytes, placeholder — probe failed)", trackID, len(blob)) } return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, @@ -687,7 +688,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage extPath = h.exportRoot + extPath } if realBlob := analysis.ReadANLZSection(extPath, "PQT2"); realBlob != nil { - log.Printf("dbserver: PQT2 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) + dlog.Debugf("dbserver: PQT2 for track %d (%d bytes, from ANLZ file)", trackID, len(realBlob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -703,7 +704,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage } if r.BeatGridPQT2 != nil { blob := r.BeatGridPQT2 // complete ANLZ section with 56-byte header - log.Printf("dbserver: PQT2 for track %d (%d bytes, generated)", trackID, len(blob)) + dlog.Debugf("dbserver: PQT2 for track %d (%d bytes, generated)", trackID, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, Args: []proto.DBArg{ @@ -719,7 +720,7 @@ func (h *Handler) handleGetExtAnalysis(msg *proto.DBMessage) []*proto.DBMessage } } - log.Printf("dbserver: ext analysis 0x2c04 tag=%q (not found)", tagFourCC) + dlog.Debugf("dbserver: ext analysis 0x2c04 tag=%q (not found)", tagFourCC) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4f02, DeclaredArgCount: 5, @@ -739,7 +740,7 @@ func (h *Handler) handleGetSongStructure(msg *proto.DBMessage) []*proto.DBMessag if len(msg.Args) >= 2 { trackID = msg.Args[1].Int() } - log.Printf("dbserver: song structure track=%d", trackID) + dlog.Debugf("dbserver: song structure track=%d", trackID) var data []byte if r := h.analysis.Get(trackID); r != nil && r.SongStructure != nil { @@ -763,7 +764,7 @@ func (h *Handler) handleGetSongStructure(msg *proto.DBMessage) []*proto.DBMessag // via 0x2c04 with the PSSI tag. This response signals that // phrase data may be available. placeholder := make([]byte, 1604) - log.Printf("dbserver: song structure placeholder for track %d (1604 bytes)", trackID) + dlog.Debugf("dbserver: song structure placeholder for track %d (1604 bytes)", trackID) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4502, Args: []proto.DBArg{ @@ -797,7 +798,7 @@ func (h *Handler) handleWritePVB2(msg *proto.DBMessage) []*proto.DBMessage { break } } - log.Printf("dbserver: PVB2 write 0x2805 track=%d (%d-byte section) — acking", trackID, len(section)) + dlog.Debugf("dbserver: PVB2 write 0x2805 track=%d (%d-byte section) — acking", trackID, len(section)) // Wrap with the 4-byte little-endian length prefix used by the dbserver // ANLZ blob format (matches ReadANLZSection / GeneratePVB2 output). @@ -820,7 +821,7 @@ func (h *Handler) handleWritePVB2(msg *proto.DBMessage) []*proto.DBMessage { func (h *Handler) handleGetNXS2Cues(msg *proto.DBMessage) []*proto.DBMessage { // 0x3d03: NXS2 cue/loop point data. The response returns count=6. // The CDJ checks this count but doesn't render items for it. - log.Printf("dbserver: NXS2 cue data (count=6)") + dlog.Debugf("dbserver: NXS2 cue data (count=6)") return []*proto.DBMessage{{ TxID: msg.TxID, Type: proto.DBMsgSuccess, Args: []proto.DBArg{ @@ -857,7 +858,7 @@ func (h *Handler) handleMountInfo(msg *proto.DBMessage) []*proto.DBMessage { } } } - log.Printf("dbserver: mount info (0x3100) shortcut id=0x%x -> root offset %d", wantID, offset) + dlog.Debugf("dbserver: mount info (0x3100) shortcut id=0x%x -> root offset %d", wantID, offset) return []*proto.DBMessage{{ TxID: msg.TxID, Type: proto.DBMsgSuccess, @@ -871,7 +872,7 @@ func (h *Handler) handleMountInfo(msg *proto.DBMessage) []*proto.DBMessage { func (h *Handler) handleGetTrackInfo(msg *proto.DBMessage) []*proto.DBMessage { // Returns file path and basic track info. for i, a := range msg.Args { - log.Printf("dbserver: 0x2102 arg[%d] = 0x%08x (%d)", i, a.Int(), a.Int()) + dlog.Tracef("dbserver: 0x2102 arg[%d] = 0x%08x (%d)", i, a.Int(), a.Int()) } if len(msg.Args) < 2 { return []*proto.DBMessage{{ @@ -959,7 +960,7 @@ func (h *Handler) handleGetTrackInfo(msg *proto.DBMessage) []*proto.DBMessage { } } - log.Printf("dbserver: track info for track %d: path=%s dur=%d bpm=%d", trackID, relPath, duration, tempo) + dlog.Debugf("dbserver: track info for track %d: path=%s dur=%d bpm=%d", trackID, relPath, duration, tempo) // The response returns 7 items: title, duration, BPM, comment, path, unknown, key. infoItems := []*menuItem{ @@ -990,7 +991,7 @@ func (h *Handler) handleGetCuePoints(msg *proto.DBMessage) []*proto.DBMessage { if len(msg.Args) >= 2 { trackID = msg.Args[1].Int() } - log.Printf("dbserver: cue points 0x2104 track=%d (empty)", trackID) + dlog.Debugf("dbserver: cue points 0x2104 track=%d (empty)", trackID) return []*proto.DBMessage{{ TxID: msg.TxID, Type: proto.DBMsgSuccess, Args: []proto.DBArg{proto.ArgI32(uint32(msg.Type)), proto.ArgI32(0)}, @@ -1013,7 +1014,7 @@ func (h *Handler) handleGetNXS2CuePoints(msg *proto.DBMessage) []*proto.DBMessag } if len(blob) == 0 { - log.Printf("dbserver: NXS2 cues 0x2b04 track=%d (empty)", trackID) + dlog.Debugf("dbserver: NXS2 cues 0x2b04 track=%d (empty)", trackID) // Wire format: descriptor=06 06 06 03 06, sends 4 int32 on wire. // Arg3 typed as binary(03) in descriptor but sent as int32(0). // Arg4 is phantom (declared but not sent). @@ -1031,7 +1032,7 @@ func (h *Handler) handleGetNXS2CuePoints(msg *proto.DBMessage) []*proto.DBMessag }} } - log.Printf("dbserver: NXS2 cues 0x2b04 track=%d (%d cues, %d bytes)", trackID, cueCount, len(blob)) + dlog.Debugf("dbserver: NXS2 cues 0x2b04 track=%d (%d cues, %d bytes)", trackID, cueCount, len(blob)) return []*proto.DBMessage{{ TxID: msg.TxID, Type: 0x4e02, From f57a6b7d075d0ac0f827b55e2ec2fb0b96ca0796 Mon Sep 17 00:00:00 2001 From: Vynull App Date: Mon, 27 Jul 2026 18:26:38 +0000 Subject: [PATCH 3/4] device: gate the remaining wire dumps behind debug/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. --- device/device.go | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/device/device.go b/device/device.go index 507b4c6..240fbbc 100644 --- a/device/device.go +++ b/device/device.go @@ -13,6 +13,7 @@ import ( "sync/atomic" "time" + "github.com/vynulldev/vynull/internal/dlog" "github.com/vynulldev/vynull/proto" ) @@ -228,8 +229,10 @@ func (d *VirtualDevice) Start(ctx context.Context) error { go d.statusBroadcastLoop(ctx) // Log one keep-alive packet for debugging (purely informational). - sample := proto.MarshalKeepAlive(d.Name, d.DeviceNumber, d.DeviceType, d.MAC, d.IP, 0) - log.Printf("keep-alive packet (%d bytes):\n%s", len(sample), hex.Dump(sample)) + if dlog.Enabled(dlog.Debug) { + sample := proto.MarshalKeepAlive(d.Name, d.DeviceNumber, d.DeviceType, d.MAC, d.IP, 0) + dlog.Debugf("keep-alive packet (%d bytes):\n%s", len(sample), hex.Dump(sample)) + } log.Printf("starting claim sequence on %s (device %d, type %s)", d.IP, d.DeviceNumber, d.DeviceType) // Claim sequence is synchronous — keep-alive loop must NOT start @@ -752,8 +755,12 @@ func (d *VirtualDevice) listenStatus(ctx context.Context) { // and failure alike — see the load watchdog in LoadTrackOnCDJ // for the actual "did the load take" check). default: - log.Printf("status recv unknown type=0x%02x from %s (%d bytes)\n%s", - pktType, addr, n, hex.Dump(buf[:n])) + // One-liner at info so new packet types get noticed; the wire + // bytes for reverse-engineering them are trace. + log.Printf("status recv unknown type=0x%02x from %s (%d bytes)", pktType, addr, n) + if dlog.Enabled(dlog.Trace) { + dlog.Tracef("status unknown 0x%02x dump:\n%s", pktType, hex.Dump(buf[:n])) + } } // Respond to media queries and status queries on port 50002. @@ -781,8 +788,11 @@ func (d *VirtualDevice) listenStatus(ctx context.Context) { // Check if this is a media query (type 0x05, 48 bytes). mq, ok := proto.ParseMediaQuery(buf[:n]) if ok { - log.Printf("media query from device %d, target %d, slot %d at %s\n%s", - mq.DeviceNumber, mq.TargetDevice, mq.SlotRequested, addr, hex.Dump(buf[:n])) + dlog.Debugf("media query from device %d, target %d, slot %d at %s", + mq.DeviceNumber, mq.TargetDevice, mq.SlotRequested, addr) + if dlog.Enabled(dlog.Trace) { + dlog.Tracef("media query dump:\n%s", hex.Dump(buf[:n])) + } resp := proto.MarshalMediaResponse(d.Name, d.DeviceNumber, d.MediaSlot, d.TrackCount, d.MAC, d.IP) d.sendStatus(resp, replyAddr) d.sendStatus(resp, replyAddr) // sent twice @@ -976,8 +986,8 @@ func (d *VirtualDevice) listenAnnouncements(ctx context.Context) { loggedPeer[peerKey] = true log.Printf("peer: %s (%s) device %d at %s", ka.Name, ka.DeviceType, ka.DeviceNumber, ka.IP) - if ka.DeviceType == proto.DeviceCDJ { - log.Printf("CDJ keep-alive (%d bytes):\n%s", n, hex.Dump(buf[:n])) + if ka.DeviceType == proto.DeviceCDJ && dlog.Enabled(dlog.Trace) { + dlog.Tracef("CDJ keep-alive (%d bytes):\n%s", n, hex.Dump(buf[:n])) } } } From 65d1f494ae7c33253c227f386d966611d9e214f0 Mon Sep 17 00:00:00 2001 From: Vynull App Date: Mon, 27 Jul 2026 18:38:41 +0000 Subject: [PATCH 4/4] device + api: log track names alongside IDs on the load path "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. --- api/api.go | 10 ++++++++-- device/device.go | 19 ++++++++++++++++--- device/monitor.go | 8 ++++++-- 3 files changed, 30 insertions(+), 7 deletions(-) diff --git a/api/api.go b/api/api.go index eece652..d8013bf 100644 --- a/api/api.go +++ b/api/api.go @@ -910,8 +910,14 @@ func (s *Server) handleLoadTrack(w http.ResponseWriter, r *http.Request) { return } - // Send the load track command - err := s.Device.LoadTrackOnCDJ(req.TrackID, req.DeviceNumber, targetIP) + // Send the load track command. The name rides along for the logs. + loadName := "" + if s.Library != nil { + if t := s.Library.Track(req.TrackID); t != nil { + loadName = t.Title + } + } + err := s.Device.LoadTrackOnCDJ(req.TrackID, loadName, req.DeviceNumber, targetIP) if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) return diff --git a/device/device.go b/device/device.go index 240fbbc..9ec6f2f 100644 --- a/device/device.go +++ b/device/device.go @@ -80,15 +80,27 @@ type VirtualDevice struct { type loadAttempt struct { TrackID uint32 + TrackName string // display name for logs; "" when the caller has no metadata TargetDevice uint8 SentAt time.Time Retried bool } +// logTrack renders a track reference for logs: name plus ID when the name +// is known, bare ID otherwise. The ID always appears so log lines stay +// correlatable with dbserver/NFS entries. +func logTrack(id uint32, name string) string { + if name == "" { + return fmt.Sprintf("track=%d", id) + } + return fmt.Sprintf("%q (track=%d)", name, id) +} + // LoadTrackOnCDJ sends a remote track load command (type 0x19) to a CDJ. // First ensures the CDJ has received Link activation + media info so it // has a proper NFS mount context for file access. -func (d *VirtualDevice) LoadTrackOnCDJ(trackID uint32, targetDevice uint8, targetIP net.IP) error { +// name is the track's display title, used only in logs (pass "" if unknown). +func (d *VirtualDevice) LoadTrackOnCDJ(trackID uint32, name string, targetDevice uint8, targetIP net.IP) error { if d.statusConn == nil { return fmt.Errorf("status connection not ready") } @@ -130,11 +142,12 @@ func (d *VirtualDevice) LoadTrackOnCDJ(trackID uint32, targetDevice uint8, targe } d.pendingLoad[targetIP.String()] = &loadAttempt{ TrackID: trackID, + TrackName: name, TargetDevice: targetDevice, SentAt: time.Now(), } d.statusMu.Unlock() - log.Printf("sent load track command (x2): track=%d -> device %d (%s)", trackID, targetDevice, targetIP) + log.Printf("sent load track command (x2): %s -> device %d (%s)", logTrack(trackID, name), targetDevice, targetIP) return nil } @@ -781,7 +794,7 @@ func (d *VirtualDevice) listenStatus(ctx context.Context) { pending := d.pendingLoad[addr.IP.String()] d.statusMu.Unlock() if pending != nil { - log.Printf("status: 0x1c rejection of load track=%d from %s (not resending media — deck self-recovers)", pending.TrackID, addr.IP) + log.Printf("status: 0x1c rejection of load %s from %s (not resending media — deck self-recovers)", logTrack(pending.TrackID, pending.TrackName), addr.IP) } } diff --git a/device/monitor.go b/device/monitor.go index fbb1211..ad5582f 100644 --- a/device/monitor.go +++ b/device/monitor.go @@ -431,8 +431,12 @@ func (m *PlayerMonitor) Update(status *proto.CDJStatus) { // trigger for "stuck on now-loading"). Only fires on change, so a steady // playing/paused deck stays quiet. if status.PlayState != prevPlay || status.TrackID != prevTID { - log.Printf("deck %d: play-state %s (0x%02x) track=%d [was 0x%02x track=%d]", - dev, status.PlayStateString(), status.PlayState, status.TrackID, prevPlay, prevTID) + name := "" + if trackName != "" { + name = fmt.Sprintf(" %q", trackName) + } + log.Printf("deck %d: play-state %s (0x%02x) track=%d%s [was 0x%02x track=%d]", + dev, status.PlayStateString(), status.PlayState, status.TrackID, name, prevPlay, prevTID) } // Track history + play-count detection: both keyed off "current track