Jitter buffer v2, per-minute rx logging, websocket keepalive

The cohost sounded jittery on the 2026-11-03 show. v1 skipped ahead on an underrun and kept playing from an empty buffer, so after the first hiccup every later wobble was another glitch. It also never corrected a slow guest clock: ~12 glitches/min in simulation at 30 ppm slow. - Underrun: hold the sequence position and refill to a larger target - Drift correction both ways (drop/insert a frame in quiet moments), quiet judged relative to the guest's own noise floor - 80 ms start, 300 ms max, relaxes after 2 calm minutes - Log 'rx 1m:' stats, the selected route, and call totals - Ping the guest websocket every 25 s (the proxy closed it every 90 s) - Simulation kept in test/jb_sim_test.go.txt Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
2026-11-04 11:21:50 -06:00
1 parent b0e3b805b1
commit de7ed62d96
@@ -246,7 +246,10 @@ func (c *Call) updateRoute() {
 				continue
 			}
 			if pair, err := ice.GetSelectedCandidatePair(); err == nil && pair != nil {
-				c.route.Store(fmt.Sprintf("%s:%d <-> %s:%d (%s)", pair.Local.Address, pair.Local.Port, pair.Remote.Address, pair.Remote.Port, pair.Remote.Typ))
+				r := fmt.Sprintf("%s:%d <-> %s:%d (%s)", pair.Local.Address, pair.Local.Port, pair.Remote.Address, pair.Remote.Port, pair.Remote.Typ)
+				if old, _ := c.route.Swap(r).(string); old != r {
+					log.Printf("route: %s", r)
+				}
 				return
 			}
 		}
@@ -258,9 +261,36 @@ func (c *Call) Close() {
 		c.cancel()
 		c.pc.Close()
 		log.Printf("call closed after %s", time.Since(c.started).Round(time.Second))
+		c.jbMu.Lock()
+		jb := c.jb
+		c.jbMu.Unlock()
+		if jb != nil {
+			k, _, t := jb.snapshot()
+			log.Printf("call totals: lost %d (fec %d) concealed %d late %d underruns %d drift-drops %d inserted %d, final target %d ms",
+				k.Lost, k.FEC, k.PLC, k.Late, k.Underruns, k.Dropped, k.Inserted, t)
+		}
 	})
 }

+// logRx writes one line a minute about the guest's audio, so a bad night can be
+// diagnosed afterwards (v1 only showed these numbers live on the host console).
+func (c *Call) logRx(jb *jitterBuffer) {
+	t := time.NewTicker(time.Minute)
+	defer t.Stop()
+	var prev jbCounters
+	for {
+		select {
+		case <-c.ctx.Done():
+			return
+		case <-t.C:
+		}
+		k, d, tg := jb.snapshot()
+		log.Printf("rx 1m: buffer %d/%d ms, lost %d (fec %d), concealed %d, late %d, underruns %d, drift-drops %d, inserted %d",
+			d, tg, k.Lost-prev.Lost, k.FEC-prev.FEC, k.PLC-prev.PLC, k.Late-prev.Late, k.Underruns-prev.Underruns, k.Dropped-prev.Dropped, k.Inserted-prev.Inserted)
+		prev = k
+	}
+}
+
 func (c *Call) status() map[string]any {
 	st := map[string]any{
 		"pc":      c.pcState.Load(),
@@ -386,6 +416,7 @@ func (c *Call) startPlay(t *webrtc.TrackRemote) {
 	c.jb = jb
 	c.jbMu.Unlock()

+	go c.logRx(jb)
 	go func() { // network -> jitter buffer
 		for {
 			p, _, err := t.ReadRTP()
@@ -484,51 +515,101 @@ func (c *Call) playToFile(jb *jitterBuffer) error {
 // ---------------------------------------------------------------- jitter buffer

 // jitterBuffer reorders Opus packets, conceals losses (FEC, then PLC), adapts its depth to
-// network jitter, and corrects clock drift between the guest's sound card and the MOTU by
-// discarding quiet frames when it runs too deep.
+// network jitter, and corrects clock drift between the guest's sound card and the MOTU.
+//
+// It is pulled once per 20 ms by the MOTU clock. Rules (v2, 2026-11-04):
+//   - Underrun (nothing buffered): HOLD the sequence position and refill to the target
+//     before playing again. The delayed packets are then played, not discarded as late.
+//     (v1 skipped ahead and kept playing from an empty buffer, so every later wobble
+//     became another glitch - ~12/min with a guest clock 30 ppm slow.)
+//   - Too deep (fast guest clock / after a stall): discard quiet frames.
+//   - Too shallow (slow guest clock): insert a concealment frame during a quiet moment.
+//   - Underruns and late packets raise the target; it relaxes after 2 calm minutes.
 type jitterBuffer struct {
-	mu       sync.Mutex
-	dec      *opus.Decoder
-	pkts     map[uint16][]byte
-	nextSeq  uint16
-	started  bool
-	target   int // frames to hold before starting / after an underrun
-	misses   int
-	lastUnd  time.Time
-	pcm      []int16
-	lost     int
-	fec      int
-	plc      int
-	dropped  int
-	underrun int
-	late     int
+	mu        sync.Mutex
+	dec       *opus.Decoder
+	pkts      map[uint16][]byte
+	nextSeq   uint16
+	haveSeq   bool // nextSeq is meaningful
+	playing   bool // false = filling up to target
+	target    int  // frames
+	gap       int  // frames produced while refilling
+	lastBad   time.Time
+	lastBump  time.Time
+	lateRun   int
+	insertNow bool
+	floor     float64 // running estimate of the guest's background-noise RMS
+	pcm       []int16
+	c         jbCounters
+}
+
+type jbCounters struct {
+	Lost, FEC, PLC, Dropped, Inserted, Underruns, Late int
+}
+
+const (
+	jbFloor  = 4     // 80 ms minimum target
+	jbMax    = 15    // 300 ms maximum target
+	quietRMS = 0.003 // always counts as quiet (-50 dBFS)
+	quietCap = 0.02  // never counts as quiet (-34 dBFS)
+)
+
+// isQuiet: below -50 dBFS, or within ~6 dB of the guest's own noise floor (so drift
+// correction still works for a guest in a noisy room), but never above -34 dBFS.
+func (j *jitterBuffer) isQuiet(pcm []int16) bool {
+	r := rms(pcm)
+	if r < j.floor {
+		j.floor = r
+	} else {
+		j.floor *= 1.0005 // creeps up ~2.5%/s so it follows a rising floor
+	}
+	lim := math.Min(quietCap, math.Max(quietRMS, 2*j.floor))
+	return r < lim
 }

 func newJitterBuffer(dec *opus.Decoder) *jitterBuffer {
-	return &jitterBuffer{dec: dec, pkts: map[uint16][]byte{}, target: 3, pcm: make([]int16, 5760*channels), lastUnd: time.Now()}
+	return &jitterBuffer{dec: dec, pkts: map[uint16][]byte{}, target: jbFloor, pcm: make([]int16, 5760*channels), lastBad: time.Now(), floor: quietRMS}
 }

 func seqLess(a, b uint16) bool { return int16(a-b) < 0 }

+func (j *jitterBuffer) reset() {
+	j.pkts = map[uint16][]byte{}
+	j.haveSeq, j.playing, j.lateRun, j.insertNow = false, false, 0, false
+}
+
+// bump raises the target after an underrun or a late packet (at most once a second, so a
+// burst of late packets counts once).
+func (j *jitterBuffer) bump() {
+	j.lastBad = time.Now()
+	if j.target < jbMax && time.Since(j.lastBump) > time.Second {
+		j.target++
+		j.lastBump = time.Now()
+	}
+}
+
 func (j *jitterBuffer) push(p *rtp.Packet) {
 	j.mu.Lock()
 	defer j.mu.Unlock()
 	if len(p.Payload) == 0 {
 		return
 	}
-	if j.started {
+	if j.haveSeq {
 		if seqLess(p.SequenceNumber, j.nextSeq) {
-			j.late++
+			j.c.Late++
+			j.bump()
+			if j.lateRun++; j.lateRun > 50 { // sender restarted its sequence numbers
+				j.reset()
+			}
 			return
 		}
 		if d := uint16(p.SequenceNumber - j.nextSeq); d > 500 { // stream restarted
-			j.pkts = map[uint16][]byte{}
-			j.started = false
+			j.reset()
 		}
 	}
+	j.lateRun = 0
 	if len(j.pkts) > 100 { // hard cap - should never happen
-		j.pkts = map[uint16][]byte{}
-		j.started = false
+		j.reset()
 	}
 	j.pkts[p.SequenceNumber] = append([]byte(nil), p.Payload...)
 }
@@ -554,15 +635,16 @@ func (j *jitterBuffer) decode(p []byte) []int16 {
 	return append([]int16(nil), j.pcm[:n*channels]...)
 }

-func (j *jitterBuffer) conceal() []int16 {
+func (j *jitterBuffer) plcFrame() []int16 {
 	out := make([]int16, frameSamps*channels)
 	if err := j.dec.DecodePLC(out); err != nil {
 		return j.silence()
 	}
-	j.plc++
 	return out
 }

+func (j *jitterBuffer) conceal() []int16 { j.c.PLC++; return j.plcFrame() }
+
 func rms(pcm []int16) float64 {
 	if len(pcm) == 0 {
 		return 0
@@ -575,65 +657,73 @@ func rms(pcm []int16) float64 {
 	return math.Sqrt(s / float64(len(pcm)))
 }

+// fill is played while the buffer refills: a few concealment frames (Opus PLC fades out
+// naturally), then silence.
+func (j *jitterBuffer) fill() []int16 {
+	j.gap++
+	if j.haveSeq && j.gap <= 3 {
+		return j.conceal()
+	}
+	return j.silence()
+}
+
 // next returns the next block of interleaved PCM to play (normally 20 ms).
 func (j *jitterBuffer) next() []int16 {
 	j.mu.Lock()
 	defer j.mu.Unlock()

-	// Relax the target after a quiet minute.
-	if j.target > 3 && time.Since(j.lastUnd) > 60*time.Second {
+	// Relax the target after two calm minutes.
+	if j.target > jbFloor && time.Since(j.lastBad) > 2*time.Minute {
 		j.target--
-		j.lastUnd = time.Now()
+		j.lastBad = time.Now()
 	}

-	if !j.started {
+	if !j.playing {
 		if len(j.pkts) < j.target {
-			return j.silence()
+			return j.fill()
 		}
-		j.nextSeq = j.oldest()
-		j.started = true
-		j.misses = 0
+		if !j.haveSeq {
+			j.nextSeq, j.haveSeq = j.oldest(), true
+		}
+		j.playing, j.gap = true, 0
+	}
+
+	if j.insertNow { // slow guest clock: stretch a quiet moment by one frame
+		j.insertNow = false
+		j.c.Inserted++
+		return j.plcFrame()
 	}

 	for {
-		p, ok := j.pkts[j.nextSeq]
-		if ok {
+		if p, ok := j.pkts[j.nextSeq]; ok {
 			delete(j.pkts, j.nextSeq)
 			j.nextSeq++
-			j.misses = 0
 			pcm := j.decode(p)
 			depth := len(j.pkts)
-			// Drift / jitter-spike correction: too deep -> throw away quiet frames,
-			// or any frame if far too deep.
-			if (depth > j.target+3 && rms(pcm) < 0.003) || depth > j.target+12 {
-				j.dropped++
+			quiet := j.isQuiet(pcm)
+			if (depth > j.target+2 && quiet) || depth > j.target+10 {
+				j.c.Dropped++
 				continue
 			}
+			if depth < j.target-1 && quiet {
+				j.insertNow = true
+			}
 			return pcm
 		}
 		if len(j.pkts) == 0 {
-			// Underrun: nothing to play.
-			j.misses++
-			if j.misses == 1 {
-				j.underrun++
-				if j.target < 10 {
-					j.target++
-				}
-				j.lastUnd = time.Now()
-			}
-			if j.misses > 5 {
-				j.started = false // rebuffer to target, play silence meanwhile
-				return j.silence()
-			}
-			j.nextSeq++
-			return j.conceal()
+			// Underrun: keep our place and refill to a larger target.
+			j.c.Underruns++
+			j.lastBump = time.Time{} // an underrun always counts
+			j.bump()
+			j.playing = false
+			return j.fill()
 		}
-		// Gap with later packets present: the packet is lost.
-		j.lost++
+		// Gap with later packets present: this packet is lost (or too late to wait for).
+		j.c.Lost++
 		if fp, ok := j.pkts[j.nextSeq+1]; ok {
 			out := make([]int16, frameSamps*channels)
 			if err := j.dec.DecodeFEC(fp, out); err == nil {
-				j.fec++
+				j.c.FEC++
 				j.nextSeq++
 				return out
 			}
@@ -643,11 +733,17 @@ func (j *jitterBuffer) next() []int16 {
 	}
 }

-func (j *jitterBuffer) stats() map[string]any {
+func (j *jitterBuffer) snapshot() (c jbCounters, depthMs, targetMs int) {
 	j.mu.Lock()
 	defer j.mu.Unlock()
+	return j.c, len(j.pkts) * 20, j.target * 20
+}
+
+func (j *jitterBuffer) stats() map[string]any {
+	c, d, t := j.snapshot()
 	return map[string]any{
-		"depthMs": len(j.pkts) * 20, "targetMs": j.target * 20,
-		"lost": j.lost, "fec": j.fec, "plc": j.plc, "dropped": j.dropped, "underruns": j.underrun, "late": j.late,
+		"depthMs": d, "targetMs": t,
+		"lost": c.Lost, "fec": c.FEC, "plc": c.PLC, "dropped": c.Dropped, "inserted": c.Inserted,
+		"underruns": c.Underruns, "late": c.Late,
 	}
 }