Add structured logging with categories and rate limiting

.gitignore

@@ -9,8 +9,13 @@
 
 # runtime data
 data/
+logs/
 config.autosave.yaml
 
+# local scripts/prompts
+codex_prompt.txt
+run_codex.ps1
+
 # local prompts
 prompt*.txt
 

cmd/sdrd/helpers.go

@@ -11,6 +11,7 @@ import (
 	"sdr-wideband-suite/internal/demod/gpudemod"
 	"sdr-wideband-suite/internal/detector"
 	"sdr-wideband-suite/internal/dsp"
+	"sdr-wideband-suite/internal/logging"
 )
 
 func mustParseDuration(raw string, fallback time.Duration) time.Duration {
@@ -260,6 +261,7 @@ func extractForStreaming(
 	// Prepend overlap from previous frame so FIR kernel has real halo data
 	var gpuIQ []complex64
 	overlapLen := len(overlap.tail)
+	logging.Debug("extract", "overlap", "len", overlapLen, "needed", overlapNeeded, "allIQ", len(allIQ))
 	if overlapLen > 0 {
 		gpuIQ = make([]complex64, overlapLen+len(allIQ))
 		copy(gpuIQ, overlap.tail)
@@ -343,6 +345,9 @@ func extractForStreaming(
 					decim = 1
 				}
 				trimSamples := overlapLen / decim
+				if i == 0 {
+					logging.Debug("extract", "gpu_result", "rate", res.Rate, "outRate", outRate, "decim", decim, "trim", trimSamples)
+				}
 				// Update phase state — advance only by NEW data length, not overlap
 				phaseInc := -2.0 * math.Pi * jobs[i].OffsetHz / float64(sampleRate)
 				phaseState[signals[i].ID].phase += phaseInc * float64(len(allIQ))
@@ -411,6 +416,9 @@ func extractForStreaming(
 
 		// Trim overlap
 		trimSamples := overlapLen / decim
+		if i == 0 {
+			logging.Debug("extract", "cpu_result", "outRate", outRate, "decim", decim, "trim", trimSamples)
+		}
 		if trimSamples > 0 && trimSamples < len(decimated) {
 			decimated = decimated[trimSamples:]
 		}

cmd/sdrd/main.go

@@ -17,6 +17,7 @@ import (
 	"sdr-wideband-suite/internal/detector"
 	fftutil "sdr-wideband-suite/internal/fft"
 	"sdr-wideband-suite/internal/fft/gpufft"
+	"sdr-wideband-suite/internal/logging"
 	"sdr-wideband-suite/internal/mock"
 	"sdr-wideband-suite/internal/recorder"
 	"sdr-wideband-suite/internal/runtime"
@@ -43,6 +44,10 @@ func main() {
 	if err != nil {
 		log.Fatalf("load config: %v", err)
 	}
+	if err := logging.Init(logging.Config(cfg.Logging)); err != nil {
+		log.Fatalf("logging init: %v", err)
+	}
+	defer logging.Close()
 
 	cfgManager := runtime.New(cfg)
 	gpuState := &gpuStatus{Available: gpufft.Available()}

cmd/sdrd/pipeline_runtime.go

@@ -13,6 +13,7 @@ import (
 	"sdr-wideband-suite/internal/demod"
 	"sdr-wideband-suite/internal/detector"
 	"sdr-wideband-suite/internal/dsp"
+	"sdr-wideband-suite/internal/logging"
 	fftutil "sdr-wideband-suite/internal/fft"
 	"sdr-wideband-suite/internal/fft/gpufft"
 	"sdr-wideband-suite/internal/pipeline"
@@ -346,6 +347,7 @@ func (rt *dspRuntime) captureSpectrum(srcMgr *sourceManager, rec *recorder.Manag
 			available = required
 		}
 	}
+	logging.Debug("capture", "read_iq", "required", required, "available", available, "buf", st.BufferSamples, "reset", st.Resets, "drop", st.Dropped)
 	allIQ, err := srcMgr.ReadIQ(available)
 	if err != nil {
 		return nil, err
@@ -353,6 +355,7 @@ func (rt *dspRuntime) captureSpectrum(srcMgr *sourceManager, rec *recorder.Manag
 	if rec != nil {
 		rec.Ingest(time.Now(), allIQ)
 	}
+	logging.Debug("capture", "iq_len", "len", len(allIQ), "surv_fft", rt.cfg.FFTSize, "detail_fft", rt.detailFFT)
 	survIQ := allIQ
 	if len(allIQ) > rt.cfg.FFTSize {
 		survIQ = allIQ[len(allIQ)-rt.cfg.FFTSize:]

cmd/sdrd/ws_handlers.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/gorilla/websocket"
 
+	"sdr-wideband-suite/internal/logging"
 	"sdr-wideband-suite/internal/recorder"
 )
 
@@ -161,6 +162,7 @@ func registerWSHandlers(mux *http.ServeMux, h *hub, recMgr *recorder.Manager) {
 		}()
 
 		log.Printf("ws/audio: client connected freq=%.1fMHz mode=%s", freq/1e6, mode)
+		logging.Info("ws", "audio_connect", "freq_mhz", freq/1e6, "mode", mode)
 
 		// LL-2: Send actual audio info (channels, sample rate from session)
 		info := map[string]any{
@@ -215,6 +217,7 @@ func registerWSHandlers(mux *http.ServeMux, h *hub, recMgr *recorder.Manager) {
 				}
 				if err := conn.WriteMessage(msgType, payload); err != nil {
 					log.Printf("ws/audio: write error: %v", err)
+					logging.Warn("ws", "audio_write_error", "err", err.Error())
 					return
 				}
 			case <-ping.C:
@@ -224,6 +227,7 @@ func registerWSHandlers(mux *http.ServeMux, h *hub, recMgr *recorder.Manager) {
 				}
 			case <-done:
 				log.Printf("ws/audio: client disconnected freq=%.1fMHz", freq/1e6)
+				logging.Info("ws", "audio_disconnect", "freq_mhz", freq/1e6)
 				return
 			}
 		}

config.yaml

@@ -248,6 +248,16 @@ decoder:
   dstar_cmd: tools/dsd-neo/bin/dsd-neo.exe -fd -i {audio} -s {sr} -o null
   fsk_cmd: tools/fsk/fsk_decoder --iq {iq} --sample-rate {sr}
   psk_cmd: tools/psk/psk_decoder --iq {iq} --sample-rate {sr}
+logging:
+  level: debug
+  categories: [capture, extract, demod, resample, drop, ws]
+  rate_limit_ms: 500
+  stdout: true
+  stdout_color: true
+  file: logs/trace.log
+  file_level: debug
+  time_format: "15:04:05"
+  disable_time: false
 web_addr: :8080
 event_path: data/events.jsonl
 frame_rate: 12

go.mod

@@ -4,8 +4,14 @@ go 1.22
 
 require (
 	github.com/gorilla/websocket v1.5.1
+	github.com/rs/zerolog v1.33.0
 	gonum.org/v1/gonum v0.15.0
 	gopkg.in/yaml.v3 v3.0.1
 )
 
-require golang.org/x/net v0.17.0 // indirect
+require (
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
+	golang.org/x/net v0.17.0 // indirect
+	golang.org/x/sys v0.13.0 // indirect
+)

go.sum

@@ -1,9 +1,25 @@
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gorilla/websocket v1.5.1 h1:gmztn0JnHVt9JZquRuzLw3g4wouNVzKL15iLr/zn/QY=
 github.com/gorilla/websocket v1.5.1/go.mod h1:x3kM2JMyaluk02fnUJpQuwD2dCS5NDG2ZHL0uE0tcaY=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
+github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa h1:FRnLl4eNAQl8hwxVVC17teOw8kdjVDVAiFMtgUdTSRQ=
 golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa/go.mod h1:zk2irFbV9DP96SEBUUAy67IdHUaZuSnrz1n472HUCLE=
 golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM=
 golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.13.0 h1:Af8nKPmuFypiUBjVoU9V20FiaFXOcuZI21p0ycVYYGE=
+golang.org/x/sys v0.13.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gonum.org/v1/gonum v0.15.0 h1:2lYxjRbTYyxkJxlhC+LvJIx3SsANPdRybu1tGj9/OrQ=
 gonum.org/v1/gonum v0.15.0/go.mod h1:xzZVBJBtS+Mz4q0Yl2LJTk+OxOg4jiXZ7qBoM0uISGo=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=

internal/config/config.go

@@ -53,6 +53,18 @@ type DetectorConfig struct {
 	CFAREnabled *bool `yaml:"cfar_enabled,omitempty" json:"cfar_enabled,omitempty"`
 }
 
+type LogConfig struct {
+	Level       string   `yaml:"level" json:"level"`
+	Categories  []string `yaml:"categories" json:"categories"`
+	RateLimitMs int      `yaml:"rate_limit_ms" json:"rate_limit_ms"`
+	Stdout      bool     `yaml:"stdout" json:"stdout"`
+	StdoutColor bool     `yaml:"stdout_color" json:"stdout_color"`
+	File        string   `yaml:"file" json:"file"`
+	FileLevel   string   `yaml:"file_level" json:"file_level"`
+	TimeFormat  string   `yaml:"time_format" json:"time_format"`
+	DisableTime bool     `yaml:"disable_time" json:"disable_time"`
+}
+
 type RecorderConfig struct {
 	Enabled     bool     `yaml:"enabled" json:"enabled"`
 	MinSNRDb    float64  `yaml:"min_snr_db" json:"min_snr_db"`
@@ -157,6 +169,7 @@ type Config struct {
 	Detector       DetectorConfig     `yaml:"detector" json:"detector"`
 	Recorder       RecorderConfig     `yaml:"recorder" json:"recorder"`
 	Decoder        DecoderConfig      `yaml:"decoder" json:"decoder"`
+	Logging        LogConfig          `yaml:"logging" json:"logging"`
 	WebAddr        string             `yaml:"web_addr" json:"web_addr"`
 	EventPath      string             `yaml:"event_path" json:"event_path"`
 	FrameRate      int                `yaml:"frame_rate" json:"frame_rate"`
@@ -408,7 +421,18 @@ func Default() Config {
 			ExtractionBwMult: 1.2,
 		},
 		Decoder:        DecoderConfig{},
-		WebAddr:        ":8080",
+		Logging: LogConfig{
+			Level:       "informal",
+			Categories:  []string{},
+			RateLimitMs: 500,
+			Stdout:      true,
+			StdoutColor: true,
+			File:        "logs/trace.log",
+			FileLevel:   "",
+			TimeFormat:  "15:04:05",
+			DisableTime: false,
+		},
+		WebAddr: ":8080",
 		EventPath:      "data/events.jsonl",
 		FrameRate:      15,
 		WaterfallLines: 200,
@@ -517,6 +541,15 @@ func applyDefaults(cfg Config) Config {
 	if cfg.Surveillance.Strategy == "" {
 		cfg.Surveillance.Strategy = "single-resolution"
 	}
+	if cfg.Logging.Level == "" {
+		cfg.Logging.Level = "informal"
+	}
+	if cfg.Logging.RateLimitMs <= 0 {
+		cfg.Logging.RateLimitMs = 500
+	}
+	if cfg.Logging.File == "" {
+		cfg.Logging.File = "logs/trace.log"
+	}
 	if cfg.Surveillance.DerivedDetection == "" {
 		cfg.Surveillance.DerivedDetection = "auto"
 	}

internal/logging/logging.go

@@ -0,0 +1,173 @@
+package logging
+
+import (
+	"errors"
+	"io"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync"
+	"time"
+
+	"github.com/rs/zerolog"
+)
+
+type Config struct {
+	Level        string   `yaml:"level" json:"level"`
+	Categories   []string `yaml:"categories" json:"categories"`
+	RateLimitMs  int      `yaml:"rate_limit_ms" json:"rate_limit_ms"`
+	Stdout       bool     `yaml:"stdout" json:"stdout"`
+	StdoutColor  bool     `yaml:"stdout_color" json:"stdout_color"`
+	File         string   `yaml:"file" json:"file"`
+	FileLevel    string   `yaml:"file_level" json:"file_level"`
+	TimeFormat   string   `yaml:"time_format" json:"time_format"`
+	DisableTime  bool     `yaml:"disable_time" json:"disable_time"`
+}
+
+type rateLimiter struct {
+	mu    sync.Mutex
+	last  map[string]time.Time
+	limit time.Duration
+}
+
+func (r *rateLimiter) allow(key string) bool {
+	if r.limit <= 0 {
+		return true
+	}
+	now := time.Now()
+	r.mu.Lock()
+	defer r.mu.Unlock()
+	if t, ok := r.last[key]; ok {
+		if now.Sub(t) < r.limit {
+			return false
+		}
+	}
+	r.last[key] = now
+	return true
+}
+
+var (
+	logger     zerolog.Logger
+	fileLogger zerolog.Logger
+	cfg        Config
+	cats       map[string]bool
+	rlim       = &rateLimiter{last: map[string]time.Time{}}
+	fileHandle *os.File
+)
+
+func Init(c Config) error {
+	cfg = c
+	if cfg.TimeFormat == "" {
+		cfg.TimeFormat = "15:04:05"
+	}
+	cats = map[string]bool{}
+	for _, c := range cfg.Categories {
+		cats[strings.ToLower(strings.TrimSpace(c))] = true
+	}
+	rl := time.Duration(cfg.RateLimitMs) * time.Millisecond
+	rlim.limit = rl
+
+	level := parseLevel(cfg.Level)
+	writers := make([]io.Writer, 0, 2)
+	if cfg.Stdout {
+		cw := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: cfg.TimeFormat, NoColor: !cfg.StdoutColor}
+		if cfg.DisableTime {
+			cw.PartsExclude = append(cw.PartsExclude, zerolog.TimestampFieldName)
+		}
+		writers = append(writers, cw)
+	}
+	if cfg.File != "" {
+		dir := filepath.Dir(cfg.File)
+		if dir != "." && dir != "" {
+			if err := os.MkdirAll(dir, 0o755); err != nil {
+				return err
+			}
+		}
+		fh, err := os.OpenFile(cfg.File, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o644)
+		if err != nil {
+			return err
+		}
+		fileHandle = fh
+		writers = append(writers, fh)
+		fileLevel := parseLevel(cfg.FileLevel)
+		fileLogger = zerolog.New(fh).Level(fileLevel).With().Timestamp().Logger()
+	}
+	if len(writers) == 0 {
+		return errors.New("logging: no outputs enabled")
+	}
+	mw := io.MultiWriter(writers...)
+	logger = zerolog.New(mw).Level(level).With().Timestamp().Logger()
+	return nil
+}
+
+func Close() {
+	if fileHandle != nil {
+		_ = fileHandle.Close()
+		fileHandle = nil
+	}
+}
+
+func EnabledCategory(cat string) bool {
+	if len(cats) == 0 {
+		return true
+	}
+	_, ok := cats[strings.ToLower(cat)]
+	return ok
+}
+
+func logf(level zerolog.Level, cat, msg string, kv ...any) {
+	if !EnabledCategory(cat) {
+		return
+	}
+	key := cat + ":" + level.String()
+	if !rlim.allow(key) {
+		return
+	}
+	if level < logger.GetLevel() {
+		return
+	}
+	l := logger.With().Str("cat", cat).Logger()
+	e := (&l).WithLevel(level)
+	for i := 0; i+1 < len(kv); i += 2 {
+		k, ok := kv[i].(string)
+		if !ok {
+			continue
+		}
+		switch v := kv[i+1].(type) {
+		case string:
+			e = e.Str(k, v)
+		case int:
+			e = e.Int(k, v)
+		case int64:
+			e = e.Int64(k, v)
+		case float64:
+			e = e.Float64(k, v)
+		case bool:
+			e = e.Bool(k, v)
+		default:
+			e = e.Interface(k, v)
+		}
+	}
+	e.Msg(msg)
+}
+
+func Debug(cat, msg string, kv ...any) { logf(zerolog.DebugLevel, cat, msg, kv...) }
+func Info(cat, msg string, kv ...any)  { logf(zerolog.InfoLevel, cat, msg, kv...) }
+func Warn(cat, msg string, kv ...any)  { logf(zerolog.WarnLevel, cat, msg, kv...) }
+func Error(cat, msg string, kv ...any) { logf(zerolog.ErrorLevel, cat, msg, kv...) }
+
+func parseLevel(raw string) zerolog.Level {
+	s := strings.ToLower(strings.TrimSpace(raw))
+	switch s {
+	case "debug":
+		return zerolog.DebugLevel
+	case "info", "informal":
+		return zerolog.InfoLevel
+	case "warn", "warning":
+		return zerolog.WarnLevel
+	case "error":
+		return zerolog.ErrorLevel
+	default:
+		return zerolog.InfoLevel
+	}
+}

internal/recorder/streamer.go

@@ -18,6 +18,7 @@ import (
 	"sdr-wideband-suite/internal/demod"
 	"sdr-wideband-suite/internal/detector"
 	"sdr-wideband-suite/internal/dsp"
+	"sdr-wideband-suite/internal/logging"
 )
 
 // ---------------------------------------------------------------------------
@@ -162,6 +163,9 @@ type Streamer struct {
 	feedCh   chan streamFeedMsg
 	done     chan struct{}
 
+	droppedFeed uint64
+	droppedPCM  uint64
+
 	// pendingListens are subscribers waiting for a matching session.
 	pendingListens map[int64]*pendingListen
 }
@@ -264,6 +268,8 @@ func (st *Streamer) FeedSnippets(items []streamFeedItem) {
 	select {
 	case st.feedCh <- streamFeedMsg{items: items}:
 	default:
+		st.droppedFeed++
+		logging.Warn("drop", "feed_drop", "count", st.droppedFeed)
 	}
 }
 
@@ -646,6 +652,7 @@ func (sess *streamSession) processSnippet(snippet []complex64, snipRate int) ([]
 		decim1 = 1
 	}
 	actualDemodRate := snipRate / decim1
+	logging.Debug("demod", "rates", "snipRate", snipRate, "decim1", decim1, "actual", actualDemodRate)
 
 	var dec []complex64
 	if decim1 > 1 {
@@ -725,12 +732,14 @@ func (sess *streamSession) processSnippet(snippet []complex64, snipRate int) ([]
 	if actualDemodRate != streamAudioRate {
 		if channels > 1 {
 			if sess.stereoResampler == nil || sess.stereoResamplerRate != actualDemodRate {
+				logging.Info("resample", "reset", "mode", "stereo", "rate", actualDemodRate)
 				sess.stereoResampler = dsp.NewStereoResampler(actualDemodRate, streamAudioRate, resamplerTaps)
 				sess.stereoResamplerRate = actualDemodRate
 			}
 			audio = sess.stereoResampler.Process(audio)
 		} else {
 			if sess.monoResampler == nil || sess.monoResamplerRate != actualDemodRate {
+				logging.Info("resample", "reset", "mode", "mono", "rate", actualDemodRate)
 				sess.monoResampler = dsp.NewResampler(actualDemodRate, streamAudioRate, resamplerTaps)
 				sess.monoResamplerRate = actualDemodRate
 			}
@@ -1278,6 +1287,8 @@ func (st *Streamer) fanoutPCM(sess *streamSession, pcm []byte, pcmLen int) {
 		select {
 		case sub.ch <- tagged:
 		default:
+			st.droppedPCM++
+			logging.Warn("drop", "pcm_drop", "count", st.droppedPCM)
 		}
 		alive = append(alive, sub)
 	}