From fb98c4edcbade90c1043a60cd1f117a28dac4b2b Mon Sep 17 00:00:00 2001 From: Alex P Date: Tue, 16 Sep 2025 11:11:18 +0300 Subject: [PATCH] [WIP] Maintainability: Add debug / trace logs to make it easy to debug audio input issues --- internal/audio/c/audio.c | 44 ++++++++++++++++-- internal/audio/cgo_audio.go | 92 ++++++++++++++++++++++++++++++++++--- internal/audio/ipc_input.go | 87 ++++++++++++++++++++++++++++++++--- 3 files changed, 206 insertions(+), 17 deletions(-) diff --git a/internal/audio/c/audio.c b/internal/audio/c/audio.c index 9a3150ef..47bb863b 100644 --- a/internal/audio/c/audio.c +++ b/internal/audio/c/audio.c @@ -457,20 +457,32 @@ int jetkvm_audio_decode_write(void *opus_buf, int opus_size) { // Safety checks if (!playback_initialized || !pcm_playback_handle || !decoder || !opus_buf || opus_size <= 0) { + printf("[AUDIO] jetkvm_audio_decode_write: Failed safety checks - playback_initialized=%d, pcm_playback_handle=%p, decoder=%p, opus_buf=%p, opus_size=%d\n", + playback_initialized, pcm_playback_handle, decoder, opus_buf, opus_size); return -1; } // Additional bounds checking if (opus_size > max_packet_size) { + printf("[AUDIO] jetkvm_audio_decode_write: Opus packet too large - size=%d, max=%d\n", opus_size, max_packet_size); return -1; } + printf("[AUDIO] jetkvm_audio_decode_write: Processing Opus packet - size=%d bytes\n", opus_size); + // Decode Opus to PCM with error handling int pcm_frames = opus_decode(decoder, in, opus_size, pcm_buffer, frame_size, 0); if (pcm_frames < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: Opus decode failed with error %d, attempting packet loss concealment\n", pcm_frames); // Try packet loss concealment on decode error pcm_frames = opus_decode(decoder, NULL, 0, pcm_buffer, frame_size, 0); - if (pcm_frames < 0) return -1; + if (pcm_frames < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: Packet loss concealment also failed with error %d\n", pcm_frames); + return -1; + } + printf("[AUDIO] jetkvm_audio_decode_write: Packet loss concealment succeeded, recovered %d frames\n", pcm_frames); + } else { + printf("[AUDIO] jetkvm_audio_decode_write: Opus decode successful - decoded %d PCM frames\n", pcm_frames); } retry_write: @@ -478,32 +490,44 @@ retry_write: // Write PCM to playback device with robust recovery int pcm_rc = snd_pcm_writei(pcm_playback_handle, pcm_buffer, pcm_frames); if (pcm_rc < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: ALSA write failed with error %d (%s), attempt %d/%d\n", + pcm_rc, snd_strerror(pcm_rc), recovery_attempts + 1, max_recovery_attempts); + if (pcm_rc == -EPIPE) { // Buffer underrun - implement progressive recovery recovery_attempts++; if (recovery_attempts > max_recovery_attempts) { + printf("[AUDIO] jetkvm_audio_decode_write: Buffer underrun recovery failed after %d attempts\n", max_recovery_attempts); return -2; } + printf("[AUDIO] jetkvm_audio_decode_write: Buffer underrun detected, attempting recovery (attempt %d)\n", recovery_attempts); // Try to recover with prepare err = snd_pcm_prepare(pcm_playback_handle); if (err < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: snd_pcm_prepare failed (%s), trying drop+prepare\n", snd_strerror(err)); // If prepare fails, try drop and prepare snd_pcm_drop(pcm_playback_handle); err = snd_pcm_prepare(pcm_playback_handle); - if (err < 0) return -2; + if (err < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: drop+prepare recovery failed (%s)\n", snd_strerror(err)); + return -2; + } } // Wait before retry to allow device to stabilize snd_pcm_wait(pcm_playback_handle, sleep_microseconds * recovery_attempts / 1000); + printf("[AUDIO] jetkvm_audio_decode_write: Buffer underrun recovery successful, retrying write\n"); goto retry_write; } else if (pcm_rc == -ESTRPIPE) { // Device suspended, implement robust resume logic recovery_attempts++; if (recovery_attempts > max_recovery_attempts) { + printf("[AUDIO] jetkvm_audio_decode_write: Device suspend recovery failed after %d attempts\n", max_recovery_attempts); return -2; } + printf("[AUDIO] jetkvm_audio_decode_write: Device suspended, attempting resume (attempt %d)\n", recovery_attempts); // Try to resume with timeout int resume_attempts = 0; while ((err = snd_pcm_resume(pcm_playback_handle)) == -EAGAIN && resume_attempts < 10) { @@ -511,47 +535,61 @@ retry_write: resume_attempts++; } if (err < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: Device resume failed (%s), trying prepare fallback\n", snd_strerror(err)); // Resume failed, try prepare as fallback err = snd_pcm_prepare(pcm_playback_handle); - if (err < 0) return -2; + if (err < 0) { + printf("[AUDIO] jetkvm_audio_decode_write: Prepare fallback failed (%s)\n", snd_strerror(err)); + return -2; + } } // Wait before retry to allow device to stabilize snd_pcm_wait(pcm_playback_handle, sleep_microseconds * recovery_attempts / 1000); + printf("[AUDIO] jetkvm_audio_decode_write: Device suspend recovery successful, skipping frame\n"); return 0; // Skip this frame but don't fail } else if (pcm_rc == -ENODEV) { // Device disconnected - critical error + printf("[AUDIO] jetkvm_audio_decode_write: Device disconnected (ENODEV) - critical error\n"); return -2; } else if (pcm_rc == -EIO) { // I/O error - try recovery once recovery_attempts++; if (recovery_attempts <= max_recovery_attempts) { + printf("[AUDIO] jetkvm_audio_decode_write: I/O error detected, attempting recovery\n"); snd_pcm_drop(pcm_playback_handle); err = snd_pcm_prepare(pcm_playback_handle); if (err >= 0) { snd_pcm_wait(pcm_playback_handle, sleep_microseconds / 1000); + printf("[AUDIO] jetkvm_audio_decode_write: I/O error recovery successful, retrying write\n"); goto retry_write; } + printf("[AUDIO] jetkvm_audio_decode_write: I/O error recovery failed (%s)\n", snd_strerror(err)); } return -2; } else if (pcm_rc == -EAGAIN) { // Device not ready - brief wait and retry recovery_attempts++; if (recovery_attempts <= max_recovery_attempts) { + printf("[AUDIO] jetkvm_audio_decode_write: Device not ready (EAGAIN), waiting and retrying\n"); usleep(sleep_microseconds / 4); goto retry_write; } + printf("[AUDIO] jetkvm_audio_decode_write: Device not ready recovery failed after %d attempts\n", max_recovery_attempts); return -2; } else { // Other errors - limited retry for transient issues recovery_attempts++; if (recovery_attempts <= 1 && (pcm_rc == -EINTR || pcm_rc == -EBUSY)) { + printf("[AUDIO] jetkvm_audio_decode_write: Transient error %d (%s), retrying once\n", pcm_rc, snd_strerror(pcm_rc)); usleep(sleep_microseconds / 2); goto retry_write; } + printf("[AUDIO] jetkvm_audio_decode_write: Unrecoverable error %d (%s)\n", pcm_rc, snd_strerror(pcm_rc)); return -2; } } + printf("[AUDIO] jetkvm_audio_decode_write: Successfully wrote %d PCM frames to USB Gadget audio device\n", pcm_frames); return pcm_frames; } // Safe playback cleanup with double-close protection diff --git a/internal/audio/cgo_audio.go b/internal/audio/cgo_audio.go index bb99da68..35688793 100644 --- a/internal/audio/cgo_audio.go +++ b/internal/audio/cgo_audio.go @@ -331,9 +331,44 @@ func cgoAudioPlaybackClose() { C.jetkvm_audio_playback_close() } +// Audio decode/write metrics for monitoring USB Gadget audio success +var ( + audioDecodeWriteTotal atomic.Int64 // Total decode/write attempts + audioDecodeWriteSuccess atomic.Int64 // Successful decode/write operations + audioDecodeWriteFailures atomic.Int64 // Failed decode/write operations + audioDecodeWriteRecovery atomic.Int64 // Recovery attempts + audioDecodeWriteLastError atomic.Value // Last error (string) + audioDecodeWriteLastTime atomic.Int64 // Last operation timestamp (unix nano) +) + +// GetAudioDecodeWriteStats returns current audio decode/write statistics +func GetAudioDecodeWriteStats() (total, success, failures, recovery int64, lastError string, lastTime time.Time) { + total = audioDecodeWriteTotal.Load() + success = audioDecodeWriteSuccess.Load() + failures = audioDecodeWriteFailures.Load() + recovery = audioDecodeWriteRecovery.Load() + + if err := audioDecodeWriteLastError.Load(); err != nil { + lastError = err.(string) + } + + lastTimeNano := audioDecodeWriteLastTime.Load() + if lastTimeNano > 0 { + lastTime = time.Unix(0, lastTimeNano) + } + + return +} + func cgoAudioDecodeWrite(buf []byte) (int, error) { + start := time.Now() + audioDecodeWriteTotal.Add(1) + audioDecodeWriteLastTime.Store(start.UnixNano()) + // Minimal validation - assume caller provides correct size if len(buf) == 0 { + audioDecodeWriteFailures.Add(1) + audioDecodeWriteLastError.Store("empty buffer") return 0, errEmptyBuffer } @@ -342,14 +377,31 @@ func cgoAudioDecodeWrite(buf []byte) (int, error) { // Fast path for success if n >= 0 { + audioDecodeWriteSuccess.Add(1) return n, nil } // Error handling with static errors - if n == -1 { - return 0, errAudioInitFailed + audioDecodeWriteFailures.Add(1) + var errMsg string + var err error + + switch n { + case -1: + errMsg = "audio system not initialized" + err = errAudioInitFailed + case -2: + errMsg = "audio device error or recovery failed" + err = errAudioDecodeWrite + audioDecodeWriteRecovery.Add(1) + default: + errMsg = fmt.Sprintf("unknown error code %d", n) + err = errAudioDecodeWrite } - return 0, errAudioDecodeWrite + + audioDecodeWriteLastError.Store(errMsg) + + return 0, err } // updateOpusEncoderParams dynamically updates OPUS encoder parameters @@ -454,11 +506,19 @@ func GetBatchProcessingStats() (count, frames, avgTimeUs int64) { // cgoAudioDecodeWriteWithBuffers decodes opus data and writes to PCM buffer // This implementation uses separate buffers for opus data and PCM output func cgoAudioDecodeWriteWithBuffers(opusData []byte, pcmBuffer []byte) (int, error) { + start := time.Now() + audioDecodeWriteTotal.Add(1) + audioDecodeWriteLastTime.Store(start.UnixNano()) + // Validate input if len(opusData) == 0 { + audioDecodeWriteFailures.Add(1) + audioDecodeWriteLastError.Store("empty opus data") return 0, errEmptyBuffer } - if len(pcmBuffer) == 0 { + if cap(pcmBuffer) == 0 { + audioDecodeWriteFailures.Add(1) + audioDecodeWriteLastError.Store("empty pcm buffer capacity") return 0, errEmptyBuffer } @@ -480,26 +540,44 @@ func cgoAudioDecodeWriteWithBuffers(opusData []byte, pcmBuffer []byte) (int, err // Ensure data doesn't exceed max packet size maxPacketSize := cache.GetMaxPacketSize() if len(opusData) > maxPacketSize { + audioDecodeWriteFailures.Add(1) + errMsg := fmt.Sprintf("opus packet too large: %d > %d", len(opusData), maxPacketSize) + audioDecodeWriteLastError.Store(errMsg) return 0, newBufferTooLargeError(len(opusData), maxPacketSize) } + // Metrics tracking only - detailed logging handled at application level + // Direct CGO call with minimal overhead - unsafe.Pointer(&slice[0]) is never nil for non-empty slices n := int(C.jetkvm_audio_decode_write(unsafe.Pointer(&opusData[0]), C.int(len(opusData)))) // Fast path for success case if n >= 0 { + audioDecodeWriteSuccess.Add(1) return n, nil } // Handle error cases with static error codes to reduce allocations + audioDecodeWriteFailures.Add(1) + var errMsg string + var err error + switch n { case -1: - return 0, errAudioInitFailed + errMsg = "audio system not initialized" + err = errAudioInitFailed case -2: - return 0, errAudioDecodeWrite + errMsg = "audio device error or recovery failed" + err = errAudioDecodeWrite + audioDecodeWriteRecovery.Add(1) default: - return 0, newAudioDecodeWriteError(n) + errMsg = fmt.Sprintf("unknown error code %d", n) + err = newAudioDecodeWriteError(n) } + + audioDecodeWriteLastError.Store(errMsg) + + return 0, err } // Optimized CGO function aliases - use direct function calls to reduce overhead diff --git a/internal/audio/ipc_input.go b/internal/audio/ipc_input.go index ec69d21c..750ed299 100644 --- a/internal/audio/ipc_input.go +++ b/internal/audio/ipc_input.go @@ -461,13 +461,9 @@ func (ais *AudioInputServer) processMessage(msg *UnifiedIPCMessage) error { // processOpusFrame processes an Opus audio frame func (ais *AudioInputServer) processOpusFrame(data []byte) error { - // Fast path: skip empty frame check - caller should handle this - dataLen := len(data) - if dataLen == 0 { - return nil - } - // Inline validation for critical audio path - avoid function call overhead + dataLen := len(data) + cachedMaxFrameSize := maxFrameSize if dataLen > cachedMaxFrameSize { return ErrFrameDataTooLarge } @@ -480,8 +476,85 @@ func (ais *AudioInputServer) processOpusFrame(data []byte) error { pcmBuffer := GetBufferFromPool(cache.MaxPCMBufferSize) defer ReturnBufferToPool(pcmBuffer) + // Log audio processing details periodically for monitoring + totalFrames := atomic.AddInt64(&ais.totalFrames, 1) + + // Zero-cost debug logging for buffer allocation (first few operations) + // Only perform computations if trace logging is actually enabled + if totalFrames <= 5 { + logger := logging.GetDefaultLogger().With().Str("component", AudioInputServerComponent).Logger() + if logger.GetLevel() <= zerolog.TraceLevel { + logger.Trace(). + Int("requested_buffer_size", cache.MaxPCMBufferSize). + Int("pcm_buffer_length", len(pcmBuffer)). + Int("pcm_buffer_capacity", cap(pcmBuffer)). + Msg("PCM buffer allocated from pool") + } + } + if totalFrames <= 5 || totalFrames%500 == 1 { + logger := logging.GetDefaultLogger().With().Str("component", AudioInputServerComponent).Logger() + if logger.GetLevel() <= zerolog.TraceLevel { + logger.Trace(). + Int("opus_frame_size", dataLen). + Int("pcm_buffer_size", len(pcmBuffer)). + Int64("total_frames_processed", totalFrames). + Msg("Processing audio frame for USB Gadget output") + } + } + // Direct CGO call - avoid wrapper function overhead - _, err := CGOAudioDecodeWrite(data, pcmBuffer) + start := time.Now() + framesWritten, err := CGOAudioDecodeWrite(data, pcmBuffer) + duration := time.Since(start) + + // Log the result with detailed context + logger := logging.GetDefaultLogger().With().Str("component", AudioInputServerComponent).Logger() + + if err != nil { + // Log error with detailed context for debugging + atomic.AddInt64(&ais.droppedFrames, 1) + + // Get current statistics for context + total, success, failures, recovery, lastError, _ := GetAudioDecodeWriteStats() + successRate := float64(success) / float64(total) * 100 + + logger.Error(). + Err(err). + Int("opus_frame_size", dataLen). + Dur("processing_duration", duration). + Int64("frames_written", int64(framesWritten)). + Int64("total_operations", total). + Int64("successful_operations", success). + Int64("failed_operations", failures). + Int64("recovery_attempts", recovery). + Float64("success_rate_percent", successRate). + Str("last_error", lastError). + Int64("total_frames_processed", totalFrames). + Int64("dropped_frames", atomic.LoadInt64(&ais.droppedFrames)). + Msg("Failed to decode/write audio frame to USB Gadget") + + return err + } + + // Log successful operations periodically to monitor health (zero-cost when trace disabled) + if (totalFrames <= 5 || totalFrames%1000 == 1) && logger.GetLevel() <= zerolog.TraceLevel { + // Get current statistics for context (only when trace is enabled) + total, success, failures, recovery, _, _ := GetAudioDecodeWriteStats() + successRate := float64(success) / float64(total) * 100 + + logger.Trace(). + Int("opus_frame_size", dataLen). + Int64("frames_written", int64(framesWritten)). + Int64("total_operations", total). + Int64("successful_operations", success). + Int64("failed_operations", failures). + Int64("recovery_attempts", recovery). + Float64("success_rate_percent", successRate). + Int64("total_frames_processed", totalFrames). + Int64("dropped_frames", atomic.LoadInt64(&ais.droppedFrames)). + Msg("Successfully decoded/wrote audio frame to USB Gadget") + } + return err }