Add debug logging for OpenAL playback and jitter buffer pipeline

- Log OpenAL vendor/version/renderer at startup
- Log buffer creation count and user volume on new audio stream
- Enhanced reclaim(): log source state, processed/queued/empty counts,
  and check for OpenAL errors; log every 50th cycle or on unusual state
- Log jitter buffer drain events (first 3 + periodic) with buffer counts
- Log sequence gap skips in jitter buffer
- WARN when processAudioPacket has no empty buffers (audio dropped)
- Check OpenAL errors after Buffer.SetData, QueueBuffer, and Play()
- Log source state transitions when calling Play() on non-playing source
This commit is contained in:
Brandon McGinty (deepseek)
2026-08-10 18:03:43 -04:00
committed by Brandon McGinty
parent fd6b7514bf
commit 3613a42fce
+47 -3
View File
@@ -200,6 +200,14 @@ func New(client *gumble.Client, inputDevice *string, outputDevice *string, test
openal.NullContext.Activate()
s.startRenderer()
// Log OpenAL device info on the render thread
s.render(func() {
log.Info("OpenAL playback: vendor=%q version=%q renderer=%q",
openal.GetString(0xB001),
openal.GetString(0xB002),
openal.GetString(0xB003))
})
return s, nil
}
@@ -445,16 +453,31 @@ func (s *Stream) OnAudioStream(e *gumble.AudioStreamEvent) {
if bufferCount < 64 {
bufferCount = 64
}
log.Info("OnAudioStream: creating %d buffers for %s (volume=%.2f gain=%.2f)",
bufferCount, e.User.Name, e.User.Volume(), source.GetGain())
emptyBufs = openal.NewBuffers(bufferCount)
})
var reclaimLogCounter int
reclaim := func() {
s.render(func() {
if n := source.BuffersProcessed(); n > 0 {
reclaimedBufs := make(openal.Buffers, n)
processed := source.BuffersProcessed()
queued := source.BuffersQueued()
srcState := source.State()
if processed > 0 {
reclaimedBufs := make(openal.Buffers, processed)
source.UnqueueBuffers(reclaimedBufs)
emptyBufs = append(emptyBufs, reclaimedBufs...)
}
reclaimLogCounter++
// Log every 50th reclaim to avoid spam, but always log if state is unusual
if reclaimLogCounter%50 == 1 || processed == 0 || srcState != openal.Playing {
log.Debug("reclaim #%d: state=%s processed=%d queued=%d empty=%d",
reclaimLogCounter, srcState, processed, queued, len(emptyBufs))
}
if oe := openal.Err(); oe != nil {
log.Error("reclaim: OpenAL error: %v", oe)
}
})
}
@@ -521,17 +544,25 @@ 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 {
// A locally dropped packet must not permanently stall the
// jitter buffer waiting for a sequence number that cannot arrive.
if len(jitterBuf) > 0 && jitterBuf[0].Sequence > jitterNextSeq {
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
}
break
}
drainedCount++
if drainedCount <= 3 || drainedCount%50 == 0 {
log.Debug("jitter: draining seq=%d for %s (buf=%d emptyBufs=%d)",
pkt.Sequence, e.User.Name, len(jitterBuf), len(emptyBufs))
}
reclaim()
s.render(func() {
emptyBufs = s.processAudioPacket(pkt, e.User, &source, emptyBufs, &raw)
@@ -684,6 +715,7 @@ func (s *Stream) processAudioPacket(packet *gumble.AudioPacket, user *gumble.Use
}
if len(emptyBufs) == 0 {
log.Warn("processAudioPacket: NO EMPTY BUFFERS for %s seq=%d — audio packet dropped!", user.Name, packet.Sequence)
return emptyBufs
}
@@ -693,10 +725,22 @@ func (s *Stream) processAudioPacket(packet *gumble.AudioPacket, user *gumble.Use
emptyBufs = emptyBufs[:last]
buffer.SetData(format, (*raw)[:rawPtr], gumble.AudioSampleRate)
if oe := openal.Err(); oe != nil {
log.Error("processAudioPacket: Buffer.SetData error for %s seq=%d: %v", user.Name, packet.Sequence, oe)
}
source.QueueBuffer(buffer)
if oe := openal.Err(); oe != nil {
log.Error("processAudioPacket: QueueBuffer error for %s seq=%d: %v", user.Name, packet.Sequence, oe)
}
if source.State() != openal.Playing {
srcState := source.State()
if srcState != openal.Playing {
log.Debug("processAudioPacket: source state=%s (not playing), calling Play() for %s seq=%d bufs=%d", srcState, user.Name, packet.Sequence, len(emptyBufs))
source.Play()
if oe := openal.Err(); oe != nil {
log.Error("processAudioPacket: Source.Play error for %s seq=%d: %v", user.Name, packet.Sequence, oe)
}
log.Debug("processAudioPacket: after Play(), state=%s for %s seq=%d", source.State(), user.Name, packet.Sequence)
}
return emptyBufs
}