Refactor main.go to integrate slog logger for improved logging and error handling

main.go

@@ -3,7 +3,7 @@ package main
 import (
 	"flag"
 	"fmt"
-	"log"
+	"log/slog"
 	"math"
 	"os"
 	"time"
@@ -22,6 +22,7 @@ var (
 	hopMs       = flag.Int("hop", 50, "Hop size (ms)")
 	ratioThresh = flag.Float64("ratio", 0.65, "Power ratio threshold for tone detection")
 	rmsThresh   = flag.Float64("rms", 300.0, "Minimum RMS for valid signal")
+	verbose     = flag.Bool("verbose", false, "Enable debug logging")
 )
 
 // Goertzel struct for frequency detection
@@ -103,9 +104,10 @@ type twoToneDetector struct {
 	bStart      time.Time
 	bEnd        time.Time
 	gapRemainMs int
+	logger      *slog.Logger
 }
 
-func newTwoToneDetector(fs, winN, hopN int, ratioThresh, rmsThresh float64, minAms, minBms, gapMaxMs int) *twoToneDetector {
+func newTwoToneDetector(fs, winN, hopN int, ratioThresh, rmsThresh float64, minAms, minBms, gapMaxMs int, logger *slog.Logger) *twoToneDetector {
 	freqs := make([]float64, 0)
 	for f := 300.0; f <= 3000.0; f += 10.0 {
 		freqs = append(freqs, f)
@@ -125,6 +127,7 @@ func newTwoToneDetector(fs, winN, hopN int, ratioThresh, rmsThresh float64, minA
 		gapMaxMs:    gapMaxMs,
 		freqs:       freqs,
 		gzBank:      gzBank,
+		logger:      logger,
 	}
 }
 
@@ -142,6 +145,10 @@ func (d *twoToneDetector) stepWindow(pcms []int16, t0 time.Time) (event string,
 	now := t0
 
 	if r < d.rmsThresh {
+		d.logger.Debug("RMS below threshold, resetting",
+			"time", now.Format(time.RFC3339),
+			"rms", fmt.Sprintf("%.2f", r),
+			"threshold", d.rmsThresh)
 		d.reset()
 		return "", 0, 0, 0, 0, time.Time{}
 	}
@@ -158,6 +165,10 @@ func (d *twoToneDetector) stepWindow(pcms []int16, t0 time.Time) (event string,
 	}
 	ratio := bestPow / (total + 1e-12)
 	if ratio < d.ratioThresh {
+		d.logger.Debug("Ratio below threshold, resetting",
+			"time", now.Format(time.RFC3339),
+			"ratio", fmt.Sprintf("%.3f", ratio),
+			"threshold", d.ratioThresh)
 		d.reset()
 		return "", 0, 0, 0, 0, time.Time{}
 	}
@@ -179,11 +190,18 @@ func (d *twoToneDetector) stepWindow(pcms []int16, t0 time.Time) (event string,
 				d.gapRemainMs = d.gapMaxMs
 			}
 		} else {
+			d.logger.Debug("Frequency differs from Tone A, resetting",
+				"time", now.Format(time.RFC3339),
+				"freq", fmt.Sprintf("%.1f", freq),
+				"tone_a_freq", fmt.Sprintf("%.1f", d.aFreq))
 			d.reset()
 		}
 	} else if d.waitingB {
 		d.gapRemainMs -= int(hopDur.Milliseconds())
 		if d.gapRemainMs <= 0 {
+			d.logger.Debug("Gap exceeded max duration, resetting",
+				"time", now.Format(time.RFC3339),
+				"gap_max_ms", d.gapMaxMs)
 			d.reset()
 		} else if math.Abs(freq-d.aFreq) > 10.0 {
 			// Check for Tone B
@@ -191,6 +209,10 @@ func (d *twoToneDetector) stepWindow(pcms []int16, t0 time.Time) (event string,
 				d.bFreq = freq
 				d.bStart = now
 			} else if math.Abs(freq-d.bFreq) > 10.0 {
+				d.logger.Debug("Frequency differs from Tone B, resetting B",
+					"time", now.Format(time.RFC3339),
+					"freq", fmt.Sprintf("%.1f", freq),
+					"tone_b_freq", fmt.Sprintf("%.1f", d.bFreq))
 				d.bFreq = freq
 				d.bAccumMs = 0
 				d.bStart = now
@@ -201,6 +223,12 @@ func (d *twoToneDetector) stepWindow(pcms []int16, t0 time.Time) (event string,
 				event = "TWO_TONE_DETECTED"
 				aDurMs := float64(d.aEnd.Sub(d.aStart).Milliseconds())
 				bDurMs := float64(d.bEnd.Sub(d.bStart).Milliseconds())
+				d.logger.Info("Two-tone detected",
+					"time", now.Format(time.RFC3339),
+					"tone_a_freq", fmt.Sprintf("%.1f", d.aFreq),
+					"tone_a_duration_ms", fmt.Sprintf("%.0f", aDurMs),
+					"tone_b_freq", fmt.Sprintf("%.1f", d.bFreq),
+					"tone_b_duration_ms", fmt.Sprintf("%.0f", bDurMs))
 				return event, d.aFreq, aDurMs, d.bFreq, bDurMs, now
 			}
 		}
@@ -224,33 +252,52 @@ func (d *twoToneDetector) reset() {
 
 func main() {
 	flag.Parse()
+
+	// Initialize slog logger
+	logLevel := &slog.LevelVar{}
+	logLevel.Set(slog.LevelInfo)
+	if *verbose {
+		logLevel.Set(slog.LevelDebug)
+	}
+	logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
+		Level: logLevel,
+	}))
+
 	if *wavFile == "" {
-		log.Fatal("WAV file path is required (use -wav flag)")
+		logger.Error("WAV file path is required", "flag", "-wav")
+		os.Exit(1)
 	}
 
 	file, err := os.Open(*wavFile)
 	if err != nil {
-		log.Fatalf("Failed to open WAV file: %v", err)
+		logger.Error("Failed to open WAV file", "error", err)
+		os.Exit(1)
 	}
 	defer file.Close()
 
 	decoder := wav.NewDecoder(file)
 	if !decoder.IsValidFile() {
-		log.Fatal("Invalid WAV file")
+		logger.Error("Invalid WAV file")
+		os.Exit(1)
 	}
 	if decoder.Format().SampleRate != 8000 || decoder.Format().NumChannels != 1 {
-		log.Fatalf("WAV file must be mono 8kHz, got %d Hz, %d channels",
+		logger.Error("WAV file must be mono 8kHz",
-			decoder.Format().SampleRate, decoder.Format().NumChannels)
+			"sample_rate", decoder.Format().SampleRate,
+			"channels", decoder.Format().NumChannels)
+		os.Exit(1)
 	}
 
 	const fs = 8000
 	winN := int(float64(fs) * float64(*winMs) / 1000.0)
 	hopN := int(float64(fs) * float64(*hopMs) / 1000.0)
 	if winN <= 0 || hopN <= 0 || hopN > winN {
-		log.Fatalf("Invalid window/hop: winN=%d, hopN=%d", winN, hopN)
+		logger.Error("Invalid window/hop parameters",
+			"winN", winN,
+			"hopN", hopN)
+		os.Exit(1)
 	}
 
-	det := newTwoToneDetector(fs, winN, hopN, *ratioThresh, *rmsThresh, *minAms, *minBms, *gapMaxMs)
+	det := newTwoToneDetector(fs, winN, hopN, *ratioThresh, *rmsThresh, *minAms, *minBms, *gapMaxMs, logger)
 
 	buf := &audio.IntBuffer{
 		Format:         &audio.Format{SampleRate: fs, NumChannels: 1},
@@ -260,11 +307,13 @@ func main() {
 	sampleCount := 0
 	startTime := time.Now()
 
-	log.Println("Processing WAV file...")
+	logger.Info("Processing WAV file")
 	for {
 		n, err := decoder.PCMBuffer(buf)
 		if err != nil || n == 0 || len(buf.Data) == 0 {
-			log.Printf("Finished processing %d samples (%.2f seconds)", sampleCount, float64(sampleCount)/float64(fs))
+			logger.Info("Finished processing",
+				"samples", sampleCount,
+				"duration_sec", fmt.Sprintf("%.2f", float64(sampleCount)/float64(fs)))
 			break
 		}