From 1a880ef20b9ee8e3a598f07f389640ea6cfc2e96 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Tue, 31 Mar 2026 16:30:53 +0000
Subject: [PATCH] Add diagnostic logging for playback pipeline debugging

Adds info-level logs at each stage of the audio pipeline to help
diagnose why playback produces no audible output:
- FFmpeg first PCM data received
- FFmpeg process exit code
- FFmpeg stderr (errors/HTTP/stream info at info level)
- First opus frame encoded and emitted
- First voice packet sent to TeamSpeak
- Error catching in frame encoding loop

https://claude.ai/code/session_01EjpEsC2GCsvwbu4n3XC8EE
---
 src/audio/player.ts       | 44 +++++++++++++++++++++++++++++++--------
 src/ts-protocol/client.ts | 14 ++++++++++++-
 2 files changed, 48 insertions(+), 10 deletions(-)

diff --git a/src/audio/player.ts b/src/audio/player.ts
index 3b37273..4781771 100644
--- a/src/audio/player.ts
+++ b/src/audio/player.ts
@@ -109,11 +109,12 @@ export class AudioPlayer extends EventEmitter {
     this.logger.debug({ ffmpeg: ffmpegBin }, "Using ffmpeg binary");
     this.ffmpeg = spawn(ffmpegBin, args, { stdio: ["ignore", "pipe", "pipe"] });
 
-    this.ffmpeg.stderr!.on("data", (data: Buffer) => {
-      this.logger.debug({ stderr: data.toString().trimEnd() }, "FFmpeg stderr");
-    });
-
+    let gotFirstData = false;
     this.ffmpeg.stdout!.on("data", (chunk: Buffer) => {
+      if (!gotFirstData) {
+        gotFirstData = true;
+        this.logger.info({ bytes: chunk.length }, "FFmpeg: first PCM data received");
+      }
       this.pcmBuffer = Buffer.concat([this.pcmBuffer, chunk]);
       // Backpressure: pause FFmpeg stdout when buffer is too large
       if (this.pcmBuffer.length > AudioPlayer.BUFFER_HIGH_WATER && !this.ffmpegPaused && this.ffmpeg?.stdout) {
@@ -122,7 +123,8 @@ export class AudioPlayer extends EventEmitter {
       }
     });
 
-    this.ffmpeg.on("close", () => {
+    this.ffmpeg.on("close", (code) => {
+      this.logger.info({ exitCode: code, gotData: gotFirstData, framesPlayed: this.framesPlayed }, "FFmpeg process closed");
       if (this.sessionId === playSessionId) {
         this.ffmpeg = null; // Signal frame loop that no more data is coming
       }
@@ -135,6 +137,17 @@ export class AudioPlayer extends EventEmitter {
       }
     });
 
+    // Log FFmpeg stderr at info level for debugging playback issues
+    this.ffmpeg.stderr!.on("data", (data: Buffer) => {
+      const msg = data.toString().trimEnd();
+      // Log important FFmpeg messages at info level
+      if (msg.includes("Error") || msg.includes("error") || msg.includes("HTTP") || msg.includes("Opening") || msg.includes("Stream")) {
+        this.logger.info({ ffmpegStderr: msg }, "FFmpeg stderr");
+      } else {
+        this.logger.debug({ stderr: msg }, "FFmpeg stderr");
+      }
+    });
+
     this.state = "playing";
     this.startFrameLoop();
   }
@@ -191,10 +204,23 @@ export class AudioPlayer extends EventEmitter {
       this.ffmpegPaused = false;
     }
 
-    const adjusted = this.applyVolume(pcmFrame);
-    const opusFrame = this.encoder.encode(adjusted);
-    this.emit("frame", opusFrame);
-    this.framesPlayed++;
+    try {
+      const adjusted = this.applyVolume(pcmFrame);
+      const opusFrame = this.encoder.encode(adjusted);
+      this.emit("frame", opusFrame);
+      this.framesPlayed++;
+
+      if (this.framesPlayed === 1) {
+        this.logger.info({ opusBytes: opusFrame.length }, "First audio frame encoded and emitted");
+      }
+      // Log every ~10 seconds (500 frames * 20ms = 10s)
+      if (this.framesPlayed % 500 === 0) {
+        this.logger.debug({ framesPlayed: this.framesPlayed, elapsed: this.getElapsed() }, "Playback progress");
+      }
+    } catch (err) {
+      this.logger.error({ err }, "Error encoding/sending audio frame");
+      this.emit("error", err as Error);
+    }
   }
 
   private applyVolume(pcm: Buffer): Buffer {
diff --git a/src/ts-protocol/client.ts b/src/ts-protocol/client.ts
index 312eddf..1426801 100644
--- a/src/ts-protocol/client.ts
+++ b/src/ts-protocol/client.ts
@@ -175,9 +175,21 @@ export class TS3Client extends EventEmitter {
     }
   }
 
+  private voiceFramesSent = 0;
+
   sendVoiceData(opusFrame: Buffer): void {
     if (!this.client || this.disconnecting) return;
-    this.client.sendVoice(opusFrame, 5);
+    try {
+      this.client.sendVoice(opusFrame, 5);
+      this.voiceFramesSent++;
+      if (this.voiceFramesSent === 1) {
+        this.logger.info({ opusBytes: opusFrame.length, clientId: this.clientId }, "First voice packet sent to TeamSpeak");
+      }
+    } catch (err) {
+      if (this.voiceFramesSent === 0) {
+        this.logger.error({ err }, "Failed to send first voice packet");
+      }
+    }
   }
 
   getIdentityExport(): string {