diff --git a/cmd/soundtouch-cli/cmd_discover.go b/cmd/soundtouch-cli/cmd_discover.go index 771f206..e45d044 100644 --- a/cmd/soundtouch-cli/cmd_discover.go +++ b/cmd/soundtouch-cli/cmd_discover.go @@ -15,6 +15,11 @@ import ( func discoverDevices(c *cli.Context) error { fmt.Printf("Discovering SoundTouch devices...\n") + // CLI discovery is interactive — flip on verbose protocol logging + // so operators can see per-packet / per-header detail. The service + // binary leaves this off so its log stays terse. + discovery.SetVerbose(c.Bool("verbose")) + // Load configuration cfg, err := config.LoadFromEnv() if err != nil { diff --git a/cmd/soundtouch-cli/main.go b/cmd/soundtouch-cli/main.go index b96f2a3..0c388ac 100644 --- a/cmd/soundtouch-cli/main.go +++ b/cmd/soundtouch-cli/main.go @@ -132,6 +132,11 @@ func main() { Aliases: []string{"a"}, Usage: "Show detailed information for all devices", }, + &cli.BoolFlag{ + Name: "verbose", + Aliases: []string{"v"}, + Usage: "Print per-packet/per-header SSDP and mDNS trace logs", + }, }, }, }, diff --git a/pkg/discovery/logger.go b/pkg/discovery/logger.go new file mode 100644 index 0000000..1dae8e8 --- /dev/null +++ b/pkg/discovery/logger.go @@ -0,0 +1,40 @@ +package discovery + +import ( + "log" + "sync/atomic" +) + +// verboseLogging toggles the per-packet / per-header diagnostic output +// that was historically emitted unconditionally during UPnP and mDNS +// discovery. The service binary leaves it at its zero value (off) so +// the log stays useful at info-level; the CLI's `discover` command +// flips it on so interactive runs surface full protocol details. +// +// Stored as an int32 so the read path in logVerbose is allocation- +// free (atomic.Bool would work too on Go 1.19+, but a uint8 lookup +// keeps the toggle hot-path even on older toolchains we still build +// against in CI). +var verboseLogging atomic.Bool + +// SetVerbose enables (or disables) the package-wide verbose-discovery +// log toggle. Safe to call from any goroutine. +func SetVerbose(v bool) { + verboseLogging.Store(v) +} + +// IsVerbose reports the current value of the verbose toggle. Mainly +// for tests that want to assert the CLI flipped it on. +func IsVerbose() bool { + return verboseLogging.Load() +} + +// logVerbose forwards to log.Printf only when verbose-discovery +// logging is enabled. The fast path (verbose off) is a single +// atomic load + branch, so it's safe to scatter calls liberally +// across the hot path. +func logVerbose(format string, args ...any) { + if verboseLogging.Load() { + log.Printf(format, args...) + } +} diff --git a/pkg/discovery/logger_test.go b/pkg/discovery/logger_test.go new file mode 100644 index 0000000..efa8d0f --- /dev/null +++ b/pkg/discovery/logger_test.go @@ -0,0 +1,73 @@ +package discovery + +import ( + "bytes" + "log" + "strings" + "testing" +) + +// captureLog redirects log output into a buffer and returns the buffer +// plus a cleanup func that restores the original log destination. Used +// by the tests below to assert what logVerbose / SetVerbose actually +// produces under each toggle state. +func captureLog(t *testing.T) (*bytes.Buffer, func()) { + t.Helper() + + buf := &bytes.Buffer{} + original := log.Writer() + log.SetOutput(buf) + + return buf, func() { + log.SetOutput(original) + } +} + +func TestVerboseToggle_DefaultIsQuiet(t *testing.T) { + // Reset to default state (zero value of atomic.Bool is false). + SetVerbose(false) + t.Cleanup(func() { SetVerbose(false) }) + + buf, restore := captureLog(t) + defer restore() + + logVerbose("noisy: should-be-suppressed message") + + if buf.Len() != 0 { + t.Errorf("expected no log output when verbose is off, got: %q", buf.String()) + } + + if IsVerbose() { + t.Errorf("IsVerbose() = true, want false") + } +} + +func TestVerboseToggle_OnEmitsToLog(t *testing.T) { + SetVerbose(true) + t.Cleanup(func() { SetVerbose(false) }) + + buf, restore := captureLog(t) + defer restore() + + logVerbose("trace: %s = %d", "answer", 42) + + if !strings.Contains(buf.String(), "trace: answer = 42") { + t.Errorf("expected trace output, got: %q", buf.String()) + } + + if !IsVerbose() { + t.Errorf("IsVerbose() = false, want true") + } +} + +func TestVerboseToggle_StaysOffByDefaultAfterPackageInit(t *testing.T) { + // New goroutines / new processes see the zero-value default. This + // codifies that contract for callers like cmd/soundtouch-service + // that rely on never having to call SetVerbose. + t.Cleanup(func() { SetVerbose(false) }) + SetVerbose(false) + + if IsVerbose() { + t.Errorf("default verbose state must be false") + } +} diff --git a/pkg/discovery/mdns.go b/pkg/discovery/mdns.go index 9438f67..697370d 100644 --- a/pkg/discovery/mdns.go +++ b/pkg/discovery/mdns.go @@ -73,7 +73,7 @@ func (m *MDNSDiscoveryService) DiscoverDevices(ctx context.Context) ([]*models.D } wg.Wait() - log.Printf("mDNS: All %d service-type queries finished", len(soundTouchServiceTypes)) + logVerbose("mDNS: All %d service-type queries finished", len(soundTouchServiceTypes)) }() // Collect discovered devices, deduplicating by host:port since a single @@ -93,12 +93,12 @@ func (m *MDNSDiscoveryService) DiscoverDevices(ctx context.Context) ([]*models.D return devices, nil } - log.Printf("mDNS: Received service entry: Name='%s', Host='%s', Port=%d, AddrV4=%v, AddrV6=%v", + logVerbose("mDNS: Received service entry: Name='%s', Host='%s', Port=%d, AddrV4=%v, AddrV6=%v", entry.Name, entry.Host, entry.Port, entry.AddrV4, entry.AddrV6) // Only process SoundTouch-family services. if !isSoundTouchServiceName(entry.Name) { - log.Printf("mDNS: Skipping non-SoundTouch service: %s", entry.Name) + logVerbose("mDNS: Skipping non-SoundTouch service: %s", entry.Name) continue } @@ -110,13 +110,13 @@ func (m *MDNSDiscoveryService) DiscoverDevices(ctx context.Context) ([]*models.D key := fmt.Sprintf("%s:%d", device.Host, device.Port) if seen[key] { - log.Printf("mDNS: Skipping duplicate device %s (already seen via another service-type query)", key) + logVerbose("mDNS: Skipping duplicate device %s (already seen via another service-type query)", key) continue } seen[key] = true - log.Printf("mDNS: Successfully converted to device: %s at %s:%d", device.Name, device.Host, device.Port) + logVerbose("mDNS: Successfully converted to device: %s at %s:%d", device.Name, device.Host, device.Port) devices = append(devices, device) } } @@ -128,7 +128,7 @@ func (m *MDNSDiscoveryService) DiscoverDevices(ctx context.Context) ([]*models.D // All results stream into the shared entries channel; the caller is // responsible for fan-in deduplication. func (m *MDNSDiscoveryService) queryService(service string, entries chan<- *mdns.ServiceEntry) { - log.Printf("mDNS: Query '%s.%s' starting", service, soundTouchDomain) + logVerbose("mDNS: Query '%s.%s' starting", service, soundTouchDomain) err := mdns.Query(&mdns.QueryParam{ Service: service, @@ -139,7 +139,7 @@ func (m *MDNSDiscoveryService) queryService(service string, entries chan<- *mdns Interface: m.getIPv4Interface(), }) if err == nil { - log.Printf("mDNS: Query '%s' (IPv4) completed successfully", service) + logVerbose("mDNS: Query '%s' (IPv4) completed successfully", service) return } @@ -154,14 +154,14 @@ func (m *MDNSDiscoveryService) queryService(service string, entries chan<- *mdns if err != nil { log.Printf("mDNS: Query '%s' (dual-stack) failed: %v", service, err) } else { - log.Printf("mDNS: Query '%s' (dual-stack) completed successfully", service) + logVerbose("mDNS: Query '%s' (dual-stack) completed successfully", service) } } // serviceEntryToDevice converts an mdns ServiceEntry to a DiscoveredDevice func (m *MDNSDiscoveryService) serviceEntryToDevice(entry *mdns.ServiceEntry) *models.DiscoveredDevice { if entry == nil { - log.Printf("mDNS: Received nil service entry") + logVerbose("mDNS: Received nil service entry") return nil } @@ -176,15 +176,15 @@ func (m *MDNSDiscoveryService) serviceEntryToDevice(entry *mdns.ServiceEntry) *m host = entry.AddrV4.String() ipSource = "IPv4" - log.Printf("mDNS: Using IPv4 address: %s", host) + logVerbose("mDNS: Using IPv4 address: %s", host) case entry.AddrV6 != nil: host = entry.AddrV6.String() ipSource = "IPv6" - log.Printf("mDNS: Using IPv6 address: %s", host) + logVerbose("mDNS: Using IPv6 address: %s", host) default: // Try to resolve from hostname - log.Printf("mDNS: No direct IP address, trying to resolve hostname: %s", entry.Host) + logVerbose("mDNS: No direct IP address, trying to resolve hostname: %s", entry.Host) ips, err := net.LookupIP(entry.Host) if err != nil || len(ips) == 0 { @@ -198,7 +198,7 @@ func (m *MDNSDiscoveryService) serviceEntryToDevice(entry *mdns.ServiceEntry) *m host = ip.String() ipSource = "resolved IPv4" - log.Printf("mDNS: Resolved to IPv4 address: %s", host) + logVerbose("mDNS: Resolved to IPv4 address: %s", host) break } @@ -213,7 +213,7 @@ func (m *MDNSDiscoveryService) serviceEntryToDevice(entry *mdns.ServiceEntry) *m ipSource = "resolved IPv6 (fallback)" } - log.Printf("mDNS: Using fallback address (%s): %s", ipSource, host) + logVerbose("mDNS: Using fallback address (%s): %s", ipSource, host) } } @@ -256,7 +256,7 @@ func (m *MDNSDiscoveryService) serviceEntryToDevice(entry *mdns.ServiceEntry) *m MDNSService: entry.Name, } - log.Printf("mDNS: Created device '%s' at %s:%d (IP source: %s)", name, host, port, ipSource) + logVerbose("mDNS: Created device '%s' at %s:%d (IP source: %s)", name, host, port, ipSource) return device } @@ -277,7 +277,7 @@ func (m *MDNSDiscoveryService) getIPv4Interface() *net.Interface { return nil } - log.Printf("mDNS: Using configured IPv4 interface: %s", iface.Name) + logVerbose("mDNS: Using configured IPv4 interface: %s", iface.Name) return iface } @@ -300,12 +300,12 @@ func (m *MDNSDiscoveryService) getIPv4Interface() *net.Interface { continue } - log.Printf("mDNS: Using IPv4 interface: %s", iface.Name) + logVerbose("mDNS: Using IPv4 interface: %s", iface.Name) return &iface } - log.Printf("mDNS: No suitable IPv4 interface found") + logVerbose("mDNS: No suitable IPv4 interface found") return nil } diff --git a/pkg/discovery/upnp.go b/pkg/discovery/upnp.go index e74c3af..1988f10 100644 --- a/pkg/discovery/upnp.go +++ b/pkg/discovery/upnp.go @@ -225,7 +225,7 @@ func (d *Service) setupUDPListener() (*net.UDPConn, error) { } } - log.Printf("UPnP: Created UDP listener on %s", localAddr.String()) + logVerbose("UPnP: Created UDP listener on %s", localAddr.String()) return listener, nil } @@ -274,7 +274,7 @@ func (d *Service) resolveListenInterface() (net.IP, *net.Interface, error) { func (d *Service) sendMSearch(listener *net.UDPConn, multicastAddr *net.UDPAddr) error { msearchRequest := d.buildMSearchRequest() - log.Printf("UPnP: Sending M-SEARCH request to %s:\n%s", ssdpAddr, strings.TrimSpace(msearchRequest)) + logVerbose("UPnP: Sending M-SEARCH request to %s:\n%s", ssdpAddr, strings.TrimSpace(msearchRequest)) bytesWritten, err := listener.WriteToUDP([]byte(msearchRequest), multicastAddr) if err != nil { @@ -282,7 +282,7 @@ func (d *Service) sendMSearch(listener *net.UDPConn, multicastAddr *net.UDPAddr) return fmt.Errorf("failed to send M-SEARCH: %w", err) } - log.Printf("UPnP: Successfully sent M-SEARCH request (%d bytes)", bytesWritten) + logVerbose("UPnP: Successfully sent M-SEARCH request (%d bytes)", bytesWritten) return nil } @@ -297,21 +297,21 @@ func (d *Service) listenForResponses(ctx context.Context, listener *net.UDPConn, return 0, fmt.Errorf("failed to set read deadline: %w", err) } - log.Printf("UPnP: Set read deadline to %v, now listening for responses...", deadline.Format("15:04:05.000")) + logVerbose("UPnP: Set read deadline to %v, now listening for responses...", deadline.Format("15:04:05.000")) buffer := make([]byte, 4096) for time.Now().Before(deadline) { select { case <-ctx.Done(): - log.Printf("UPnP: Discovery cancelled by context") + logVerbose("UPnP: Discovery cancelled by context") return responseCount, ctx.Err() default: n, remoteAddr, err := listener.ReadFromUDP(buffer) if err != nil { var netErr net.Error if errors.As(err, &netErr) && netErr.Timeout() { - log.Printf("UPnP: Read timeout reached after %v, stopping discovery", d.timeout) + logVerbose("UPnP: Read timeout reached after %v, stopping discovery", d.timeout) return responseCount, nil } @@ -322,7 +322,7 @@ func (d *Service) listenForResponses(ctx context.Context, listener *net.UDPConn, responseCount++ responseText := string(buffer[:n]) - log.Printf("UPnP: Received response #%d (%d bytes) from %s:\n%s", responseCount, n, remoteAddr.String(), strings.TrimSpace(responseText)) + logVerbose("UPnP: Received response #%d (%d bytes) from %s:\n%s", responseCount, n, remoteAddr.String(), strings.TrimSpace(responseText)) device, err := d.parseResponse(responseText) if err != nil { @@ -331,10 +331,10 @@ func (d *Service) listenForResponses(ctx context.Context, listener *net.UDPConn, } if device != nil { - log.Printf("UPnP: Successfully parsed device from response #%d: %s at %s:%d", responseCount, device.Name, device.Host, device.Port) + logVerbose("UPnP: Successfully parsed device from response #%d: %s at %s:%d", responseCount, device.Name, device.Host, device.Port) devices[device.Host] = device } else { - log.Printf("UPnP: Response #%d from %s did not contain a valid SoundTouch device", responseCount, remoteAddr.String()) + logVerbose("UPnP: Response #%d from %s did not contain a valid SoundTouch device", responseCount, remoteAddr.String()) } } } @@ -368,7 +368,7 @@ func (d *Service) buildMSearchRequest() string { // parseResponse parses UPnP SSDP response and extracts device information func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, error) { - log.Printf("UPnP: Parsing response (%d chars): %.100s...", len(response), strings.ReplaceAll(response, "\r\n", "\\r\\n")) + logVerbose("UPnP: Parsing response (%d chars): %.100s...", len(response), strings.ReplaceAll(response, "\r\n", "\\r\\n")) // Try both \r\n and \n line endings var lines []string @@ -384,7 +384,7 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro return nil, fmt.Errorf("invalid HTTP response") } - log.Printf("UPnP: Valid HTTP response detected") + logVerbose("UPnP: Valid HTTP response detected") headers := make(map[string]string) @@ -402,10 +402,10 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro } } - log.Printf("UPnP: Parsed %d headers from response", len(headers)) + logVerbose("UPnP: Parsed %d headers from response", len(headers)) for key, value := range headers { - log.Printf("UPnP: Header: %s = %s", key, value) + logVerbose("UPnP: Header: %s = %s", key, value) } // Check if it's a SoundTouch device @@ -415,7 +415,7 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro return nil, fmt.Errorf("no ST header found") } - log.Printf("UPnP: Found ST header: %s", st) + logVerbose("UPnP: Found ST header: %s", st) // Accept both MediaRenderer and any device type for now - we'll validate it's a SoundTouch later if !strings.Contains(strings.ToLower(st), "mediarenderer") && !strings.Contains(strings.ToLower(st), "upnp:rootdevice") { @@ -423,7 +423,7 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro return nil, fmt.Errorf("not a MediaRenderer device") } - log.Printf("UPnP: Device type '%s' is acceptable", st) + logVerbose("UPnP: Device type '%s' is acceptable", st) location, exists := headers["location"] if !exists { @@ -431,7 +431,7 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro return nil, fmt.Errorf("no location header found") } - log.Printf("UPnP: Found Location header: %s", location) + logVerbose("UPnP: Found Location header: %s", location) // Extract device information from location URL device, err := d.parseLocationURL(location, headers["usn"]) @@ -440,19 +440,19 @@ func (d *Service) parseResponse(response string) (*models.DiscoveredDevice, erro return nil, fmt.Errorf("failed to parse location URL: %w", err) } - log.Printf("UPnP: Successfully parsed device from location: %s at %s:%d", device.Name, device.Host, device.Port) + logVerbose("UPnP: Successfully parsed device from location: %s at %s:%d", device.Name, device.Host, device.Port) // Try to get more device info from the location URL. Crucially this // also lets us reject non-Bose UPnP MediaRenderers (LG TVs, Onkyo / // Yamaha receivers, Dreambox tuners, etc.) that responded to our // generic `ST: …MediaRenderer:1` M-SEARCH. See issues #269 / #359. if err := d.EnrichDeviceInfo(device, location); err != nil { - log.Printf("UPnP: Could not enrich device info from location '%s': %v — accepting tentatively (will be re-verified by /info probe)", location, err) + logVerbose("UPnP: Could not enrich device info from location '%s': %v — accepting tentatively (will be re-verified by /info probe)", location, err) } else if !isBoseUPnPDevice(device) { log.Printf("UPnP: Rejecting non-Bose device: model=%q (manufacturer not Bose / model not SoundTouch)", device.ModelID) return nil, fmt.Errorf("non-Bose UPnP device: %s", device.ModelID) } else { - log.Printf("UPnP: Successfully enriched device info for %s (model=%q)", device.Name, device.ModelID) + logVerbose("UPnP: Successfully enriched device info for %s (model=%q)", device.Name, device.ModelID) } return device, nil @@ -488,7 +488,7 @@ func isBoseUPnPDevice(device *models.DiscoveredDevice) bool { // parseLocationURL extracts basic device info from the location URL func (d *Service) parseLocationURL(location, usn string) (*models.DiscoveredDevice, error) { - log.Printf("UPnP: Parsing location URL: %s", location) + logVerbose("UPnP: Parsing location URL: %s", location) // Parse the URL to extract host and port re := regexp.MustCompile(`http://([^:]+):(\d+)`) @@ -501,7 +501,7 @@ func (d *Service) parseLocationURL(location, usn string) (*models.DiscoveredDevi host := matches[1] port := 8090 // Default SoundTouch port - log.Printf("UPnP: Extracted host='%s', using default port=%d", host, port) + logVerbose("UPnP: Extracted host='%s', using default port=%d", host, port) device := &models.DiscoveredDevice{ Host: host, @@ -520,7 +520,7 @@ func (d *Service) parseLocationURL(location, usn string) (*models.DiscoveredDevi // EnrichDeviceInfo tries to get additional device information from the device description func (d *Service) EnrichDeviceInfo(device *models.DiscoveredDevice, location string) error { - log.Printf("UPnP: Attempting to enrich device info by fetching %s", location) + logVerbose("UPnP: Attempting to enrich device info by fetching %s", location) resp, err := d.httpClient.Get(location) if err != nil { @@ -532,7 +532,7 @@ func (d *Service) EnrichDeviceInfo(device *models.DiscoveredDevice, location str _ = resp.Body.Close() }() - log.Printf("UPnP: Successfully fetched device description from %s (Status: %s)", location, resp.Status) + logVerbose("UPnP: Successfully fetched device description from %s (Status: %s)", location, resp.Status) if resp.StatusCode != http.StatusOK { return fmt.Errorf("unexpected status code: %d", resp.StatusCode) @@ -574,7 +574,7 @@ func (d *Service) EnrichDeviceInfo(device *models.DiscoveredDevice, location str device.UPnPSerial = upnpRoot.Device.SerialNumber } - log.Printf("UPnP: Enriched device info: Name='%s', Manufacturer='%s', Model='%s', UPnPSerial='%s'", + logVerbose("UPnP: Enriched device info: Name='%s', Manufacturer='%s', Model='%s', UPnPSerial='%s'", device.Name, device.Manufacturer, device.ModelID, device.UPnPSerial) return nil