Add verbose packet-level logging throughout UDP audio pipeline

Logs every step of UDP send/receive:

SEND path (WriteAudioUDP):
  - counter, nonce, plaintext len, opus len, final flag
  - full packet hex dump after encryption

RECEIVE path (udpReadRoutine -> handleUDPPacket -> handleUDPTunnel):
  - raw packet hex on arrival
  - type byte, audio type, target parsed
  - session ID, sequence number, header/encrypted lengths
  - user lookup result
  - cryptIn state, counter, nonce for decryption
  - encrypted payload hex
  - decrypt success/failure with error detail
  - plaintext hex after decryption
  - dispatch to handleUDPTunnel

UDPTUNNEL path (handleUDPTunnel):
  - session, seq, audio length, final flag, buffer remaining
  - Opus decode success/failure
  - pcm sample count after decode

CRYPTO SETUP (cryptState.setup):
  - key, IV, encrypted IV, computed nonce prefix

All at log.Info level so they show up with -log=info (no --debug needed).

gumble/gumble/crypt.go

@@ -4,6 +4,7 @@ import (
 	"crypto/aes"
 	"crypto/cipher"
 	"encoding/binary"
+	"encoding/hex"
 	"errors"
 	"sync"
 
@@ -251,6 +252,13 @@ func (cs *cryptState) setup(key, iv []byte) error {
 	copy(cs.nonce[:4], encIV[:4])
 
 	cs.initialized = true
+
+	log.Info("cryptState setup: key=%s iv=%s encIV=%s nonce_prefix=%s",
+		hex.EncodeToString(cs.key[:]),
+		hex.EncodeToString(iv),
+		hex.EncodeToString(encIV[:]),
+		hex.EncodeToString(cs.nonce[:]))
+
 	return nil
 }
 

gumble/gumble/handlers.go

@@ -79,14 +79,16 @@ func (c *Client) handleVersion(buffer []byte) error {
 
 func (c *Client) handleUDPTunnel(buffer []byte) error {
 	if len(buffer) < 1 {
+		log.Warn("handleUDPTunnel: empty buffer")
 		return errInvalidProtobuf
 	}
 	audioType := (buffer[0] >> 5) & 0x7
 	audioTarget := buffer[0] & 0x1F
 
 	// Opus only
-	// TODO: add handling for other packet types
 	if audioType != audioCodecIDOpus {
+		log.Warn("handleUDPTunnel: unsupported audio type %d (target=%d)",
+			audioType, audioTarget)
 		return errUnsupportedAudio
 	}
 
@@ -94,27 +96,31 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
 	buffer = buffer[1:]
 	session, n := varint.Decode(buffer)
 	if n <= 0 {
+		log.Warn("handleUDPTunnel: session varint decode failed")
 		return errInvalidProtobuf
 	}
 	buffer = buffer[n:]
 	user := c.Users[uint32(session)]
 	if user == nil {
+		log.Warn("handleUDPTunnel: unknown user session=%d", session)
 		return errInvalidProtobuf
 	}
 	decoder := user.decoder
 	if decoder == nil {
-		// TODO: decoder pool
 		codec := c.audioCodec
 		if codec == nil {
+			log.Warn("handleUDPTunnel: no audio codec available")
 			return errNoCodec
 		}
 		decoder = codec.NewDecoder()
 		user.decoder = decoder
+		log.Info("handleUDPTunnel: created new decoder for %s", user.Name)
 	}
 
 	// Sequence
 	seq, n := varint.Decode(buffer)
 	if n <= 0 {
+		log.Warn("handleUDPTunnel: seq varint decode failed")
 		return errInvalidProtobuf
 	}
 	buffer = buffer[n:]
@@ -122,21 +128,21 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
 	// Detect sequence gaps (packet loss). Use Opus Packet Loss
 	// Concealment to fill gaps rather than resetting the decoder,
 	// which would cause audible glitches.
-	// Mumble uses a monotonically increasing sequence that wraps at MaxInt32.
 	if user.audioSequenceValid {
 		gap := seq - user.audioSequence
 		if gap > 1 && gap < 100 {
-			log.Debug("audio seq gap for %s: %d -> %d (loss=%d), generating PLC",
+			log.Info("audio seq gap for %s: %d -> %d (loss=%d), generating PLC",
 				user.Name, user.audioSequence, seq, gap-1)
-			// Lost packets detected; generate PLC frames for each.
 			for i := int64(1); i < gap; i++ {
 				c.dispatchPLC(user, audioTarget, decoder)
 			}
 		} else if gap < 0 && gap > -100 {
-			log.Debug("audio seq reorder for %s: %d -> %d, resetting decoder",
+			log.Info("audio seq reorder for %s: %d -> %d, resetting decoder",
 				user.Name, user.audioSequence, seq)
-			// Reordered packet — reset decoder to prevent corruption.
 			decoder.Reset()
+		} else if gap == 0 {
+			log.Info("audio seq duplicate for %s: seq=%d", user.Name, seq)
+			return nil
 		}
 	}
 	user.audioSequence = seq
@@ -145,22 +151,35 @@ func (c *Client) handleUDPTunnel(buffer []byte) error {
 	// Length
 	length, n := varint.Decode(buffer)
 	if n <= 0 {
+		log.Warn("handleUDPTunnel: length varint decode failed")
 		return errInvalidProtobuf
 	}
 	buffer = buffer[n:]
 	// Opus audio packets set the 13th bit in the size field as the terminator.
 	audioLength := int(length) &^ 0x2000
+	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) {
+		log.Warn("handleUDPTunnel: audio length %d > remaining buffer %d",
+			audioLength, len(buffer))
 		return errInvalidProtobuf
 	}
 
 	pcm, err := decoder.Decode(buffer[:audioLength], AudioMaximumFrameSize)
 	if err != nil {
 		// Decode failure indicates corrupted decoder state; reset and drop.
+		log.Warn("handleUDPTunnel: Opus decode FAILED for %s seq=%d: %v",
+			user.Name, seq, err)
 		decoder.Reset()
 		return err
 	}
 
+	log.Info("handleUDPTunnel: Opus decode OK for %s seq=%d pcm_samples=%d",
+		user.Name, seq, len(pcm))
+
 	event := AudioPacket{
 		Client: c,
 		Sender: user,

gumble/gumble/udp.go

@@ -2,6 +2,7 @@ package gumble
 
 import (
 	"encoding/binary"
+	"encoding/hex"
 	"errors"
 	"math"
 	"net"
@@ -58,12 +59,11 @@ func (c *Client) udpReadRoutine() {
 			return
 		}
 		packetCount++
-		if packetCount <= 3 || packetCount%100 == 0 {
-			log.Debug("UDP recv #%d: %d bytes from %s", packetCount, n, addr)
-		}
+		log.Info("UDP recv #%d: %d bytes from %s hex=%s",
+			packetCount, n, addr, hex.EncodeToString(buf[:n]))
 		packet := make([]byte, n)
 		copy(packet, buf[:n])
-		c.handleUDPPacket(packet)
+		c.handleUDPPacket(packet, packetCount)
 	}
 }
 
@@ -101,18 +101,14 @@ func (c *Client) sendUDPPing(counter uint32) {
 // WriteAudioUDP writes an encrypted audio packet over UDP.
 // Returns true if the packet was sent over UDP, false if TCP should be used.
 var firstUDPSendLogged bool
+var udpSendCount uint64
 
 func (c *Client) WriteAudioUDP(format, target byte, sequence int64, final bool, data []byte, X, Y, Z *float32) (bool, error) {
 	if c.udpConn == nil || !c.cryptOut.initialized {
 		return false, nil
 	}
 
-	if !firstUDPSendLogged {
-		firstUDPSendLogged = true
-		log.Info("first UDP audio packet sent — UDP transport active")
-	} else {
-		log.Debug("UDP send: seq=%d len=%d final=%v", sequence, len(data), final)
-	}
+	udpSendCount++
 
 	// Build the unencrypted header
 	var header [1 + varint.MaxVarintLen*2]byte
@@ -157,10 +153,16 @@ func (c *Client) WriteAudioUDP(format, target byte, sequence int64, final bool,
 	c.cryptOut.mu.Lock()
 	counter := c.cryptOut.counter
 	c.cryptOut.counter++
+	nonce := c.cryptOut.nonceForPacket(counter)
 	c.cryptOut.mu.Unlock()
 
+	log.Info("UDP send #%d: seq=%d counter=%d nonce=%s plain_len=%d opus_len=%d final=%v",
+		udpSendCount, sequence, counter, hex.EncodeToString(nonce[:]),
+		len(plainPayload), len(data), final)
+
 	encrypted, err := c.cryptOut.encrypt(counter, plainPayload)
 	if err != nil {
+		log.Error("UDP send #%d: encrypt FAILED: %v", udpSendCount, err)
 		return false, err
 	}
 
@@ -169,23 +171,35 @@ func (c *Client) WriteAudioUDP(format, target byte, sequence int64, final bool,
 	copy(packet, header[:headerLen])
 	copy(packet[headerLen:], encrypted)
 
+	log.Info("UDP send #%d: header_len=%d enc_len=%d total=%d hex=%s",
+		udpSendCount, headerLen, len(encrypted), len(packet),
+		hex.EncodeToString(packet))
+
 	_, err = c.udpConn.Write(packet)
 	if err != nil {
+		log.Error("UDP send #%d: write FAILED: %v", udpSendCount, err)
 		return false, err
 	}
 	return true, nil
 }
 
 // handleUDPPacket processes an incoming UDP audio packet.
-func (c *Client) handleUDPPacket(packet []byte) {
+func (c *Client) handleUDPPacket(packet []byte, pktNum uint64) {
 	if len(packet) < 1 {
+		log.Warn("UDP #%d: empty packet, ignoring", pktNum)
 		return
 	}
 
-	audioType := (packet[0] >> 5) & 0x7
+	typeByte := packet[0]
+	audioType := (typeByte >> 5) & 0x7
+	target := typeByte & 0x1F
 
-	// Skip ping packets
+	log.Info("UDP #%d: type_byte=0x%02x audio_type=%d target=%d pkt_len=%d",
+		pktNum, typeByte, audioType, target, len(packet))
+
+	// Skip ping packets (type 0, 1, or 2 in bits 5-7 = type 0)
 	if audioType != udpPacketTypeOpus {
+		log.Info("UDP #%d: skipping non-Opus packet (audio_type=%d)", pktNum, audioType)
 		return
 	}
 
@@ -193,6 +207,8 @@ func (c *Client) handleUDPPacket(packet []byte) {
 	buf := packet[1:]
 	session, n := varint.Decode(buf)
 	if n <= 0 {
+		log.Warn("UDP #%d: failed to decode session varint (buf_len=%d first_byte=0x%02x)",
+			pktNum, len(buf), buf[0])
 		return
 	}
 	buf = buf[n:]
@@ -200,36 +216,50 @@ func (c *Client) handleUDPPacket(packet []byte) {
 	// Parse sequence for decryption nonce
 	seq, m := varint.Decode(buf)
 	if m <= 0 {
-		return
-	}
-	buf = buf[m:]
-
-	user := c.Users[uint32(session)]
-	if user == nil {
-		log.Debug("UDP packet from unknown session %d", session)
+		log.Warn("UDP #%d: failed to decode seq varint (buf_len=%d)", pktNum, len(buf))
 		return
 	}
 
-	// Decrypt the payload
 	headerLen := 1 + n + m
 	encrypted := packet[headerLen:]
 
+	log.Info("UDP #%d: session=%d seq=%d header_len=%d encrypted_len=%d",
+		pktNum, session, seq, headerLen, len(encrypted))
+
+	user := c.Users[uint32(session)]
+	if user == nil {
+		log.Warn("UDP #%d: unknown session %d (known sessions: %d)",
+			pktNum, session, len(c.Users))
+		return
+	}
+
+	log.Info("UDP #%d: user=%s", pktNum, user.Name)
+
+	// Decrypt the payload
 	if !c.cryptIn.initialized {
-		log.Debug("UDP packet arrived before crypto initialized")
+		log.Warn("UDP #%d: cryptIn not initialized, dropping", pktNum)
 		return
 	}
 
 	c.cryptIn.mu.Lock()
 	counter := c.cryptIn.counter
 	c.cryptIn.counter++
+	nonce := c.cryptIn.nonceForPacket(counter)
 	c.cryptIn.mu.Unlock()
 
+	log.Info("UDP #%d: decrypting with counter=%d nonce=%s encrypted_hex=%s",
+		pktNum, counter, hex.EncodeToString(nonce[:]), hex.EncodeToString(encrypted))
+
 	plaintext, err := c.cryptIn.decrypt(counter, encrypted)
 	if err != nil {
-		log.Warn("UDP decrypt failed for %s (counter=%d): %v", user.Name, counter, err)
+		log.Warn("UDP #%d: decrypt FAILED for %s (counter=%d): %v",
+			pktNum, user.Name, counter, err)
 		return
 	}
 
+	log.Info("UDP #%d: decrypt OK, plaintext_len=%d hex=%s",
+		pktNum, len(plaintext), hex.EncodeToString(plaintext))
+
 	// Now feed the decrypted payload through the existing TCP audio handler.
 	// We reconstruct the full UDPTunnel format: type byte + session + seq + payload.
 	// The handleUDPTunnel expects: [type/target byte] [session varint] [seq varint] [length varint] [data] [pos]
@@ -241,6 +271,9 @@ func (c *Client) handleUDPPacket(packet []byte) {
 	varint.Encode(fullPacket[1+n:], seq)
 	copy(fullPacket[1+n+m:], plaintext)
 
+	log.Info("UDP #%d: dispatching to handleUDPTunnel (fullPacket_len=%d)",
+		pktNum, len(fullPacket))
+
 	c.handleUDPTunnel(fullPacket)
 }