feat(discovery): quiet per-packet logs by default; CLI keeps verbose

Discovery cycles emit one line per UPnP M-SEARCH header, one per
parsed response, and one per enrichment step — by default. A typical
service-binary cycle prints ~50–80 lines for a 3-speaker LAN. Most
operators want a startup-and-summary view; the per-packet trace is
only useful for debugging.

- New SetVerbose/IsVerbose/logVerbose helpers in pkg/discovery (atomic
  bool, zero-value off).
- Chatty log.Printf calls in upnp.go and mdns.go demoted to logVerbose:
  per-header dumps, per-response dumps, per-device enrichment steps,
  M-SEARCH details, read-deadline / cancel-context noise.
- Kept at default level: discovery start ("Starting SSDP discovery
  for…"), end ("Discovery completed. Processed N responses, found N
  unique devices" + per-device summary), warnings ("Configured
  interface not found", "Failed to fetch device description", …), and
  the new "Rejecting non-Bose device" classifier.
- cmd/soundtouch-cli/discover devices grew a --verbose / -v flag that
  flips the package toggle on; the service binary leaves it at the
  zero value.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

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 {

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",
+							},
 						},
 					},
 				},

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...)
+	}
+}

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")
+	}
+}

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
 }

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