Superminaren
/
kvm
mirror of https://github.com/jetkvm/kvm.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

[WIP] Maintainability: Add debug / trace logs to make it easy to debug audio input issues

This commit is contained in:
Alex P 2025-09-16 11:11:18 +03:00
parent e894470ca8
commit fb98c4edcb
3 changed files with 206 additions and 17 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

44
internal/audio/c/audio.c
View File

@ -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

92
internal/audio/cgo_audio.go
View File

@ -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

87
internal/audio/ipc_input.go
View File

@ -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
}