diff --git a/.gitignore b/.gitignore index 670dd91..71179e4 100644 --- a/.gitignore +++ b/.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 diff --git a/cmd/sdrd/helpers.go b/cmd/sdrd/helpers.go index a47343c..c59f96b 100644 --- a/cmd/sdrd/helpers.go +++ b/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:] } diff --git a/cmd/sdrd/main.go b/cmd/sdrd/main.go index 624c752..77a9814 100644 --- a/cmd/sdrd/main.go +++ b/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()} diff --git a/cmd/sdrd/pipeline_runtime.go b/cmd/sdrd/pipeline_runtime.go index c5e3c04..6d7f3c1 100644 --- a/cmd/sdrd/pipeline_runtime.go +++ b/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:] diff --git a/cmd/sdrd/ws_handlers.go b/cmd/sdrd/ws_handlers.go index 5e60c5a..2e54cb1 100644 --- a/cmd/sdrd/ws_handlers.go +++ b/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 } } diff --git a/config.yaml b/config.yaml index bdf5c98..ea437ed 100644 --- a/config.yaml +++ b/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 diff --git a/go.mod b/go.mod index 346efce..f0b6695 100644 --- a/go.mod +++ b/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 +) diff --git a/go.sum b/go.sum index 88769af..aa91158 100644 --- a/go.sum +++ b/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= diff --git a/internal/config/config.go b/internal/config/config.go index fd8ab6a..1cd1fb7 100644 --- a/internal/config/config.go +++ b/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" } diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 0000000..e560688 --- /dev/null +++ b/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 + } +} diff --git a/internal/recorder/streamer.go b/internal/recorder/streamer.go index 1de7ec7..a815cac 100644 --- a/internal/recorder/streamer.go +++ b/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) }