Avoid debug logging induced UDP loss

gumble/gumble/udp.go

@@ -59,7 +59,10 @@ func (c *Client) udpReadRoutine() {
 			return
 		}
 		packetCount++
-		if log.Enabled(log.LevelDebug) {
+		// A synchronous log write for every UDP datagram can itself make the
+		// reader fall behind and lose voice packets. Keep enough samples to
+		// diagnose framing while avoiding work on the audio hot path.
+		if log.Enabled(log.LevelDebug) && (packetCount <= 3 || packetCount%1000 == 0) {
 			log.Debug("UDP recv #%d: %d bytes from %s hex=%s",
 				packetCount, n, addr, hex.EncodeToString(buf[:n]))
 		}

gumble/gumble/udp15.go

@@ -639,8 +639,10 @@ func (c *Client) WriteAudioUDP15(format byte, target uint32, sequence int64, dat
 		return false, err
 	}
 
-	log.Debug("UDP15 send: frame=%d opus_len=%d enc_len=%d final=%v",
+	if log.Enabled(log.LevelDebug) && (frameNum < 3 || frameNum%1000 == 0 || final) {
-		frameNum, len(data), len(encrypted), final)
+		log.Debug("UDP15 send: frame=%d opus_len=%d enc_len=%d final=%v",
+			frameNum, len(data), len(encrypted), final)
+	}
 
 	_, err = udpConn.Write(encrypted)
 	if err != nil {
@@ -675,7 +677,9 @@ func (c *Client) HandleUDPPacket15(packet []byte, pktNum uint64) {
 		return
 	}
 
-	log.Debug("UDP15 #%d: decrypt OK, plaintext_len=%d", pktNum, len(plaintext))
+	if log.Enabled(log.LevelDebug) && (pktNum <= 3 || pktNum%1000 == 0) {
+		log.Debug("UDP15 #%d: decrypt OK, plaintext_len=%d", pktNum, len(plaintext))
+	}
 	c.markUDPActive()
 
 	// Check type byte (0x00 = Audio, 0x01 = Ping)
@@ -841,7 +845,9 @@ func (c *Client) decodeAndDispatch(pktNum uint64, user *User, decoder AudioDecod
 		return
 	}
 
-	log.Debug("UDP15 #%d: Opus OK for %s, pcm_samples=%d", pktNum, user.Name, len(pcm))
+	if log.Enabled(log.LevelDebug) && (pktNum <= 3 || pktNum%1000 == 0) {
+		log.Debug("UDP15 #%d: Opus OK for %s, pcm_samples=%d", pktNum, user.Name, len(pcm))
+	}
 	user.audioSequence = frameNum
 	user.audioSequenceValid = true
 	user.audioFrameStep = audioFrameStep(len(pcm))

gumble/gumbleopenal/stream.go

@@ -486,6 +486,7 @@ func (s *Stream) OnAudioStream(e *gumble.AudioStreamEvent) {
 		var jitterBuf []*gumble.AudioPacket
 		var jitterNextSeq int64
 		var jitterInit, jitterStarted bool
+		var jitterDrainLogCounter, jitterAnomalyLogCounter int
 
 		// insertSorted inserts a packet into the jitter buffer sorted
 		// by sequence number.
@@ -563,7 +564,6 @@ func (s *Stream) OnAudioStream(e *gumble.AudioStreamEvent) {
 			jitterStarted = true
 
 			// Drain all packets that are ready (in sequence order)
-			drainedCount := 0
 			for {
 				pkt := popNext()
 				if pkt == nil {
@@ -571,16 +571,22 @@ func (s *Stream) OnAudioStream(e *gumble.AudioStreamEvent) {
 						if jitterBuf[0].Sequence < jitterNextSeq {
 							// Late or duplicate: discard so it doesn't
 							// permanently block the drain loop.
-							log.Debug("jitter: discarding late seq=%d for %s (next=%d buf=%d)",
+							jitterAnomalyLogCounter++
-								jitterBuf[0].Sequence, e.User.Name, jitterNextSeq, len(jitterBuf))
+							if jitterAnomalyLogCounter <= 3 || jitterAnomalyLogCounter%1000 == 0 {
+								log.Debug("jitter: discarding late seq=%d for %s (next=%d buf=%d)",
+									jitterBuf[0].Sequence, e.User.Name, jitterNextSeq, len(jitterBuf))
+							}
 							jitterBuf = jitterBuf[1:]
 							continue
 						}
 						if jitterBuf[0].Sequence > jitterNextSeq {
 							// Gap in sequence: skip ahead so we don't
 							// wait forever for a lost packet.
-							log.Debug("jitter: seq gap for %s, skipping from %d to %d (buf=%d)",
+							jitterAnomalyLogCounter++
-								e.User.Name, jitterNextSeq, jitterBuf[0].Sequence, len(jitterBuf))
+							if jitterAnomalyLogCounter <= 3 || jitterAnomalyLogCounter%1000 == 0 {
+								log.Debug("jitter: seq gap for %s, skipping from %d to %d (buf=%d)",
+									e.User.Name, jitterNextSeq, jitterBuf[0].Sequence, len(jitterBuf))
+							}
 							jitterNextSeq = jitterBuf[0].Sequence
 							continue
 						}
@@ -589,8 +595,8 @@ func (s *Stream) OnAudioStream(e *gumble.AudioStreamEvent) {
 					}
 					break
 				}
-				drainedCount++
+				jitterDrainLogCounter++
-				if drainedCount <= 3 || drainedCount%50 == 0 {
+				if jitterDrainLogCounter <= 3 || jitterDrainLogCounter%1000 == 0 {
 					log.Debug("jitter: draining seq=%d for %s (buf=%d emptyBufs=%d)",
 						pkt.Sequence, e.User.Name, len(jitterBuf), len(emptyBufs))
 				}