log the incoming audio path at packet level

Record decoder creation, sequence numbers, frame lengths, and decode
results for each tunneled audio packet, and note when a slow listener
has a packet dropped.
Diagnosing a codec or ordering problem previously meant adding print
statements and rebuilding. These sit at info and debug, so they cost
nothing unless -logfile is given.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
Brandon McGinty
2026-08-20 14:42:52 -04:00
co-authored by Claude Opus 5
parent 872149c977
commit d02177af71
2 changed files with 19 additions and 5 deletions
+17 -2
View File
@@ -118,28 +118,31 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
buffer = buffer[1:] buffer = buffer[1:]
session, n := varint.Decode(buffer) session, n := varint.Decode(buffer)
if n <= 0 { if n <= 0 {
log.Warn("handleUDPTunnel: session varint decode failed")
return errInvalidProtobuf return errInvalidProtobuf
} }
buffer = buffer[n:] buffer = buffer[n:]
user := c.Users[uint32(session)] user := c.Users[uint32(session)]
if user == nil { if user == nil {
log.Warn("handleUDPTunnel: unknown user session=%d", session)
return errInvalidProtobuf return errInvalidProtobuf
} }
decoder := user.decoder decoder := user.decoder
if decoder == nil { if decoder == nil {
// TODO: decoder pool
// TODO: de-reference after stream is done
codec := c.audioCodec codec := c.audioCodec
if codec == nil { if codec == nil {
log.Warn("handleUDPTunnel: no audio codec available")
return errNoCodec return errNoCodec
} }
decoder = codec.NewDecoder() decoder = codec.NewDecoder()
user.decoder = decoder user.decoder = decoder
log.Info("handleUDPTunnel: created new decoder for %s", user.Name)
} }
// Sequence // Sequence
seq, n := varint.Decode(buffer) seq, n := varint.Decode(buffer)
if n <= 0 { if n <= 0 {
log.Warn("handleUDPTunnel: seq varint decode failed")
return errInvalidProtobuf return errInvalidProtobuf
} }
buffer = buffer[n:] buffer = buffer[n:]
@@ -170,13 +173,20 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
// Length // Length
length, n := varint.Decode(buffer) length, n := varint.Decode(buffer)
if n <= 0 { if n <= 0 {
log.Warn("handleUDPTunnel: length varint decode failed")
return errInvalidProtobuf return errInvalidProtobuf
} }
buffer = buffer[n:] buffer = buffer[n:]
// Opus audio packets set the 13th bit in the size field as the terminator. // Opus audio packets set the 13th bit in the size field as the terminator.
audioLength := int(length) &^ 0x2000 audioLength := int(length) &^ 0x2000
isFinal := (length & 0x2000) != 0 isFinal := (length & 0x2000) != 0
log.Info("handleUDPTunnel: %s session=%d seq=%d audio_len=%d final=%v buf_remain=%d",
user.Name, session, seq, audioLength, isFinal, len(buffer))
if audioLength > len(buffer) { if audioLength > len(buffer) {
log.Warn("handleUDPTunnel: audio length %d > remaining buffer %d",
audioLength, len(buffer))
return errInvalidProtobuf return errInvalidProtobuf
} }
@@ -189,6 +199,9 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
return err return err
} }
log.Info("handleUDPTunnel: Opus decode OK for %s seq=%d pcm_samples=%d",
user.Name, seq, len(pcm))
event := AudioPacket{ event := AudioPacket{
Client: c, Client: c,
Sender: user, Sender: user,
@@ -271,6 +284,7 @@ func (c *Client) dispatchAudio(user *User, packet *AudioPacket) {
for _, delivery := range deliveries { for _, delivery := range deliveries {
if delivery.new { if delivery.new {
log.Debug("new audio stream from %s (session=%d)", user.Name, user.Session)
delivery.listener.OnAudioStream(&AudioStreamEvent{Client: c, User: user, C: delivery.ch}) delivery.listener.OnAudioStream(&AudioStreamEvent{Client: c, User: user, C: delivery.ch})
} }
// User removal can run on a different protocol goroutine. Keep the // User removal can run on a different protocol goroutine. Keep the
@@ -283,6 +297,7 @@ func (c *Client) dispatchAudio(user *User, packet *AudioPacket) {
case delivery.ch <- packet: case delivery.ch <- packet:
default: default:
// Never allow a slow listener to block protocol processing. // Never allow a slow listener to block protocol processing.
log.Debug("dropping buffered audio for slow listener (session=%d)", user.Session)
} }
} }
listeners.mu.Unlock() listeners.mu.Unlock()
+2 -3
View File
@@ -204,8 +204,8 @@ func main() {
} }
b.Config.Buffers = *buffers b.Config.Buffers = *buffers
b.Config.AudioInterval = selectedAudioInterval b.Config.AudioInterval = selectedAudioInterval
b.Config.DisableUDP = *tcpOnly
b.Config.IncomingAudioBuffer = selectedJitterBuffer b.Config.IncomingAudioBuffer = selectedJitterBuffer
b.Config.DisableUDP = *tcpOnly
b.Hotkeys = b.UserConfig.GetHotkeys() b.Hotkeys = b.UserConfig.GetHotkeys()
if err := b.UserConfig.SaveConfig(); err != nil { if err := b.UserConfig.SaveConfig(); err != nil {
@@ -275,8 +275,7 @@ func jitterBufferDuration(milliseconds int) (time.Duration, error) {
} }
} }
// serverAddress appends Mumble's default port unless the address already has // serverAddress adds Mumble's default port without corrupting an IPv6 literal.
// one. A bracketed or bare IPv6 literal is not a host:port pair.
func serverAddress(address string) string { func serverAddress(address string) string {
if _, port, err := net.SplitHostPort(address); err == nil && port != "" { if _, port, err := net.SplitHostPort(address); err == nil && port != "" {
return address return address