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/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, diff --git a/device/device.go b/device/device.go index 507b4c6..9ec6f2f 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" ) @@ -79,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") } @@ -129,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 } @@ -228,8 +242,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 +768,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. @@ -774,15 +794,18 @@ 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) } } // 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 +999,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])) } } } 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 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