diff --git a/gumble/gumbleopenal/stream.go b/gumble/gumbleopenal/stream.go index 46e3167..4c2918e 100644 --- a/gumble/gumbleopenal/stream.go +++ b/gumble/gumbleopenal/stream.go @@ -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 }