From 1f88dab95feefb06a7b2cea0e41e5f2279654ce4 Mon Sep 17 00:00:00 2001 From: Alex P Date: Tue, 16 Sep 2025 11:48:10 +0300 Subject: [PATCH] [WIP] Maintainability Improvement: Add debug logging throughout the audio system for easy debugging and troubleshooting --- DEVELOPMENT.md | 4 +- dev_deploy.sh | 2 +- internal/audio/c/audio.c | 376 ++++++++++++++++++++++----- internal/audio/cgo_audio.go | 59 ++++- internal/audio/core_handlers.go | 5 - internal/audio/input_server_main.go | 7 +- internal/audio/input_supervisor.go | 5 + internal/audio/output_server_main.go | 25 +- internal/audio/output_supervisor.go | 8 +- internal/audio/quality_presets.go | 91 ------- 10 files changed, 403 insertions(+), 179 deletions(-) diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md index 9a7ceb76..bd510d13 100644 --- a/DEVELOPMENT.md +++ b/DEVELOPMENT.md @@ -409,7 +409,7 @@ npm install ```bash # Enable debug logging -export LOG_TRACE_SCOPES="jetkvm,cloud,websocket,native,jsonrpc" +export LOG_TRACE_SCOPES="jetkvm,cloud,websocket,native,jsonrpc,audio" # Frontend development export JETKVM_PROXY_URL="ws://" @@ -461,7 +461,7 @@ curl http://api:$JETKVM_PASSWORD@YOUR_DEVICE_IP/developer/pprof/ ```bash # Enable trace logging (useful for debugging) -export LOG_TRACE_SCOPES="jetkvm,cloud,websocket,native,jsonrpc" +export LOG_TRACE_SCOPES="jetkvm,cloud,websocket,native,jsonrpc,audio" # For frontend development export JETKVM_PROXY_URL="ws://" diff --git a/dev_deploy.sh b/dev_deploy.sh index 5e2efd97..15add887 100755 --- a/dev_deploy.sh +++ b/dev_deploy.sh @@ -41,7 +41,7 @@ REMOTE_USER="root" REMOTE_PATH="/userdata/jetkvm/bin" SKIP_UI_BUILD=false RESET_USB_HID_DEVICE=false -LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES:-jetkvm,cloud,websocket,native,jsonrpc}" +LOG_TRACE_SCOPES="${LOG_TRACE_SCOPES:-jetkvm,cloud,websocket,native,jsonrpc,audio}" RUN_GO_TESTS=false RUN_GO_TESTS_ONLY=false INSTALL_APP=false diff --git a/internal/audio/c/audio.c b/internal/audio/c/audio.c index 20b0461d..dad5eeba 100644 --- a/internal/audio/c/audio.c +++ b/internal/audio/c/audio.c @@ -1,3 +1,11 @@ +/* + * JetKVM Audio Processing Module + * + * This module handles bidirectional audio processing for JetKVM: + * - Audio INPUT: Client microphone → Device speakers (decode Opus → ALSA playback) + * - Audio OUTPUT: Device microphone → Client speakers (ALSA capture → encode Opus) + */ + #include #include #include @@ -6,39 +14,74 @@ #include #include -// C state for ALSA/Opus with safety flags -static snd_pcm_t *pcm_capture_handle = NULL; -static snd_pcm_t *pcm_playback_handle = NULL; -static OpusEncoder *encoder = NULL; -static OpusDecoder *decoder = NULL; -// Opus encoder settings - initialized from Go configuration -static int opus_bitrate = 96000; // Will be set from Config.CGOOpusBitrate -static int opus_complexity = 3; // Will be set from Config.CGOOpusComplexity -static int opus_vbr = 1; // Will be set from Config.CGOOpusVBR -static int opus_vbr_constraint = 1; // Will be set from Config.CGOOpusVBRConstraint -static int opus_signal_type = 3; // Will be set from Config.CGOOpusSignalType -static int opus_bandwidth = 1105; // OPUS_BANDWIDTH_WIDEBAND for compatibility (was 1101) -static int opus_dtx = 0; // Will be set from Config.CGOOpusDTX -static int opus_lsb_depth = 16; // LSB depth for improved bit allocation on constrained hardware -static int sample_rate = 48000; // Will be set from Config.CGOSampleRate -static int channels = 2; // Will be set from Config.CGOChannels -static int frame_size = 960; // Will be set from Config.CGOFrameSize -static int max_packet_size = 1500; // Will be set from Config.CGOMaxPacketSize -static int sleep_microseconds = 1000; // Will be set from Config.CGOUsleepMicroseconds -static int max_attempts_global = 5; // Will be set from Config.CGOMaxAttempts -static int max_backoff_us_global = 500000; // Will be set from Config.CGOMaxBackoffMicroseconds -// Hardware optimization flags for constrained environments -static int optimized_buffer_size = 1; // Disable optimized buffer sizing for stability (was 1) +// ============================================================================ +// GLOBAL STATE VARIABLES +// ============================================================================ -// C function declarations (implementations are below) -int jetkvm_audio_capture_init(); -void jetkvm_audio_capture_close(); -int jetkvm_audio_read_encode(void *opus_buf); -int jetkvm_audio_decode_write(void *opus_buf, int opus_size); -int jetkvm_audio_playback_init(); -void jetkvm_audio_playback_close(); +// ALSA device handles +static snd_pcm_t *pcm_capture_handle = NULL; // Device microphone (OUTPUT path) +static snd_pcm_t *pcm_playback_handle = NULL; // Device speakers (INPUT path) -// Function to update constants from Go configuration +// Opus codec instances +static OpusEncoder *encoder = NULL; // For OUTPUT path (device mic → client) +static OpusDecoder *decoder = NULL; // For INPUT path (client → device speakers) +// Audio format configuration +static int sample_rate = 48000; // Sample rate in Hz +static int channels = 2; // Number of audio channels (stereo) +static int frame_size = 960; // Frames per Opus packet + +// Opus encoder configuration +static int opus_bitrate = 96000; // Bitrate in bits/second +static int opus_complexity = 3; // Encoder complexity (0-10) +static int opus_vbr = 1; // Variable bitrate enabled +static int opus_vbr_constraint = 1; // Constrained VBR +static int opus_signal_type = 3; // Audio signal type +static int opus_bandwidth = 1105; // Bandwidth setting +static int opus_dtx = 0; // Discontinuous transmission +static int opus_lsb_depth = 16; // LSB depth for bit allocation + +// Network and buffer configuration +static int max_packet_size = 1500; // Maximum Opus packet size + +// Error handling and retry configuration +static int sleep_microseconds = 1000; // Base sleep time for retries +static int max_attempts_global = 5; // Maximum retry attempts +static int max_backoff_us_global = 500000; // Maximum backoff time + +// Performance optimization flags +static int optimized_buffer_size = 1; // Use optimized buffer sizing +static int trace_logging_enabled = 0; // Enable detailed trace logging + +// ============================================================================ +// FUNCTION DECLARATIONS +// ============================================================================ + +// Audio OUTPUT path functions (device microphone → client speakers) +int jetkvm_audio_capture_init(); // Initialize capture device and Opus encoder +void jetkvm_audio_capture_close(); // Cleanup capture resources +int jetkvm_audio_read_encode(void *opus_buf); // Read PCM, encode to Opus + +// Audio INPUT path functions (client microphone → device speakers) +int jetkvm_audio_playback_init(); // Initialize playback device and Opus decoder +void jetkvm_audio_playback_close(); // Cleanup playback resources +int jetkvm_audio_decode_write(void *opus_buf, int opus_size); // Decode Opus, write PCM + +// Configuration and utility functions +void update_audio_constants(int bitrate, int complexity, int vbr, int vbr_constraint, + int signal_type, int bandwidth, int dtx, int lsb_depth, int sr, int ch, + int fs, int max_pkt, int sleep_us, int max_attempts, int max_backoff); +void set_trace_logging(int enabled); +int update_opus_encoder_params(int bitrate, int complexity, int vbr, int vbr_constraint, + int signal_type, int bandwidth, int dtx); + +// ============================================================================ +// CONFIGURATION FUNCTIONS +// ============================================================================ + +/** + * Update audio configuration constants from Go + * Called during initialization to sync C variables with Go config + */ void update_audio_constants(int bitrate, int complexity, int vbr, int vbr_constraint, int signal_type, int bandwidth, int dtx, int lsb_depth, int sr, int ch, int fs, int max_pkt, int sleep_us, int max_attempts, int max_backoff) { @@ -59,22 +102,38 @@ void update_audio_constants(int bitrate, int complexity, int vbr, int vbr_constr max_backoff_us_global = max_backoff; } -// State tracking to prevent race conditions during rapid start/stop -static volatile int capture_initializing = 0; -static volatile int capture_initialized = 0; -static volatile int playback_initializing = 0; -static volatile int playback_initialized = 0; +/** + * Enable or disable trace logging + * When enabled, detailed debug information is printed to stdout + * Zero overhead when disabled - no function calls or string formatting occur + */ +void set_trace_logging(int enabled) { + trace_logging_enabled = enabled; +} -// Function to dynamically update Opus encoder parameters +// ============================================================================ +// INITIALIZATION STATE TRACKING +// ============================================================================ + +// Thread-safe initialization state tracking to prevent race conditions +static volatile int capture_initializing = 0; // OUTPUT path init in progress +static volatile int capture_initialized = 0; // OUTPUT path ready +static volatile int playback_initializing = 0; // INPUT path init in progress +static volatile int playback_initialized = 0; // INPUT path ready + +/** + * Update Opus encoder parameters dynamically + * Used for OUTPUT path (device microphone → client speakers) + * + * @return 0 on success, -1 if encoder not initialized, >0 if some settings failed + */ int update_opus_encoder_params(int bitrate, int complexity, int vbr, int vbr_constraint, int signal_type, int bandwidth, int dtx) { - // This function updates encoder parameters for audio input (capture) - // Only capture uses the encoder; playback uses a separate decoder if (!encoder || !capture_initialized) { - return -1; // Audio encoder not initialized + return -1; } - // Update the static variables + // Update local configuration opus_bitrate = bitrate; opus_complexity = complexity; opus_vbr = vbr; @@ -83,7 +142,7 @@ int update_opus_encoder_params(int bitrate, int complexity, int vbr, int vbr_con opus_bandwidth = bandwidth; opus_dtx = dtx; - // Apply the new settings to the encoder + // Apply settings to Opus encoder int result = 0; result |= opus_encoder_ctl(encoder, OPUS_SET_BITRATE(opus_bitrate)); result |= opus_encoder_ctl(encoder, OPUS_SET_COMPLEXITY(opus_complexity)); @@ -93,10 +152,22 @@ int update_opus_encoder_params(int bitrate, int complexity, int vbr, int vbr_con result |= opus_encoder_ctl(encoder, OPUS_SET_BANDWIDTH(opus_bandwidth)); result |= opus_encoder_ctl(encoder, OPUS_SET_DTX(opus_dtx)); - return result; // 0 on success, non-zero on error + return result; } -// Enhanced ALSA device opening with exponential backoff retry logic +// ============================================================================ +// ALSA UTILITY FUNCTIONS +// ============================================================================ + +/** + * Safely open ALSA device with exponential backoff retry logic + * Handles common device busy/unavailable scenarios with appropriate retry strategies + * + * @param handle Pointer to PCM handle to be set + * @param device ALSA device name (e.g., "hw:1,0") + * @param stream Stream direction (capture or playback) + * @return 0 on success, negative error code on failure + */ static int safe_alsa_open(snd_pcm_t **handle, const char *device, snd_pcm_stream_t stream) { int attempt = 0; int err; @@ -134,7 +205,14 @@ static int safe_alsa_open(snd_pcm_t **handle, const char *device, snd_pcm_stream return err; } -// Optimized ALSA configuration with stack allocation and performance tuning +/** + * Configure ALSA device with optimized parameters + * Sets up hardware and software parameters for optimal performance on constrained hardware + * + * @param handle ALSA PCM handle + * @param device_name Device name for debugging (not used in current implementation) + * @return 0 on success, negative error code on failure + */ static int configure_alsa_device(snd_pcm_t *handle, const char *device_name) { snd_pcm_hw_params_t *params; snd_pcm_sw_params_t *sw_params; @@ -212,7 +290,22 @@ static int configure_alsa_device(snd_pcm_t *handle, const char *device_name) { return snd_pcm_prepare(handle); } -// Initialize ALSA and Opus encoder with improved safety +// ============================================================================ +// AUDIO OUTPUT PATH FUNCTIONS (Device Microphone → Client Speakers) +// ============================================================================ + +/** + * Initialize audio OUTPUT path: device microphone capture and Opus encoder + * This enables sending device audio to the client + * + * Thread-safe with atomic operations to prevent concurrent initialization + * + * @return 0 on success, negative error codes on failure: + * -EBUSY: Already initializing + * -1: ALSA device open failed + * -2: ALSA device configuration failed + * -3: Opus encoder creation failed + */ int jetkvm_audio_capture_init() { int err; @@ -282,9 +375,26 @@ int jetkvm_audio_capture_init() { return 0; } -// jetkvm_audio_read_encode captures audio from ALSA, encodes with Opus, and handles errors. -// Implements robust error recovery for buffer underruns and device suspension. -// Returns: >0 (bytes written), -1 (init error), -2 (unrecoverable error) +/** + * Capture audio from device microphone and encode to Opus (OUTPUT path) + * + * This function: + * 1. Reads PCM audio from device microphone via ALSA + * 2. Handles ALSA errors with robust recovery strategies + * 3. Encodes PCM to Opus format for network transmission + * 4. Provides zero-overhead trace logging when enabled + * + * Error recovery includes handling: + * - Buffer underruns (-EPIPE) + * - Device suspension (-ESTRPIPE) + * - I/O errors (-EIO) + * - Device busy conditions (-EBUSY, -EAGAIN) + * + * @param opus_buf Buffer to store encoded Opus data (must be at least max_packet_size) + * @return >0: Number of Opus bytes written + * 0: No audio data available (not an error) + * -1: Initialization error or unrecoverable failure + */ int jetkvm_audio_read_encode(void *opus_buf) { short pcm_buffer[1920]; // max 2ch*960 unsigned char *out = (unsigned char*)opus_buf; @@ -294,6 +404,10 @@ int jetkvm_audio_read_encode(void *opus_buf) { // Safety checks if (!capture_initialized || !pcm_capture_handle || !encoder || !opus_buf) { + if (trace_logging_enabled) { + printf("[AUDIO_OUTPUT] jetkvm_audio_read_encode: Failed safety checks - capture_initialized=%d, pcm_capture_handle=%p, encoder=%p, opus_buf=%p\n", + capture_initialized, pcm_capture_handle, encoder, opus_buf); + } return -1; } @@ -383,10 +497,29 @@ retry_read: } int nb_bytes = opus_encode(encoder, pcm_buffer, frame_size, out, max_packet_size); + + if (trace_logging_enabled && nb_bytes > 0) { + printf("[AUDIO_OUTPUT] jetkvm_audio_read_encode: Successfully encoded %d PCM frames to %d Opus bytes\n", pcm_rc, nb_bytes); + } + return nb_bytes; } -// Initialize ALSA playback with improved safety +// ============================================================================ +// AUDIO INPUT PATH FUNCTIONS (Client Microphone → Device Speakers) +// ============================================================================ + +/** + * Initialize audio INPUT path: ALSA playback device and Opus decoder + * This enables playing client audio through device speakers + * + * Thread-safe with atomic operations to prevent concurrent initialization + * + * @return 0 on success, negative error codes on failure: + * -EBUSY: Already initializing + * -1: ALSA device open failed or configuration failed + * -2: Opus decoder creation failed + */ int jetkvm_audio_playback_init() { int err; @@ -446,8 +579,30 @@ int jetkvm_audio_playback_init() { return 0; } -// jetkvm_audio_decode_write decodes Opus data and writes PCM to ALSA playback device -// with error recovery and packet loss concealment +/** + * Decode Opus audio and play through device speakers (INPUT path) + * + * This function: + * 1. Validates input parameters and Opus packet size + * 2. Decodes Opus data to PCM format + * 3. Implements packet loss concealment for network issues + * 4. Writes PCM to device speakers via ALSA + * 5. Handles ALSA playback errors with recovery strategies + * 6. Provides zero-overhead trace logging when enabled + * + * Error recovery includes handling: + * - Buffer underruns (-EPIPE) with progressive recovery + * - Device suspension (-ESTRPIPE) with resume logic + * - I/O errors (-EIO) with device reset + * - Device not ready (-EAGAIN) with retry logic + * + * @param opus_buf Buffer containing Opus-encoded audio data + * @param opus_size Size of Opus data in bytes + * @return >0: Number of PCM frames written to speakers + * 0: Frame skipped (not an error) + * -1: Invalid input or decode failure + * -2: Unrecoverable ALSA error + */ int jetkvm_audio_decode_write(void *opus_buf, int opus_size) { short pcm_buffer[1920]; // max 2ch*960 unsigned char *in = (unsigned char*)opus_buf; @@ -457,22 +612,44 @@ 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] jetkvm_audio_decode_write: Opus packet too large - size=%d, max=%d\n", opus_size, max_packet_size); + } return -1; } + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] jetkvm_audio_decode_write: Packet loss concealment also failed with error %d\n", pcm_frames); + } return -1; } + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] jetkvm_audio_decode_write: Packet loss concealment succeeded, recovered %d frames\n", pcm_frames); + } + } else if (trace_logging_enabled) { + printf("[AUDIO_INPUT] jetkvm_audio_decode_write: Opus decode successful - decoded %d PCM frames\n", pcm_frames); } retry_write: @@ -480,36 +657,60 @@ 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] jetkvm_audio_decode_write: Buffer underrun recovery failed after %d attempts\n", max_recovery_attempts); + } return -2; } + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { @@ -517,64 +718,98 @@ retry_write: resume_attempts++; } if (err < 0) { - printf("[AUDIO] jetkvm_audio_decode_write: Device resume failed (%s), trying prepare fallback\n", snd_strerror(err)); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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) { - printf("[AUDIO] jetkvm_audio_decode_write: Prepare fallback failed (%s)\n", snd_strerror(err)); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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"); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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"); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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"); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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"); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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)); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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"); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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)); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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)); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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); + if (trace_logging_enabled) { + printf("[AUDIO_INPUT] 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 + +// ============================================================================ +// CLEANUP FUNCTIONS +// ============================================================================ + +/** + * Cleanup audio INPUT path resources (client microphone → device speakers) + * + * Thread-safe cleanup with atomic operations to prevent double-cleanup + * Properly drains ALSA buffers before closing to avoid audio artifacts + */ void jetkvm_audio_playback_close() { // Wait for any ongoing operations to complete while (playback_initializing) { @@ -597,7 +832,12 @@ void jetkvm_audio_playback_close() { } } -// Safe capture cleanup +/** + * Cleanup audio OUTPUT path resources (device microphone → client speakers) + * + * Thread-safe cleanup with atomic operations to prevent double-cleanup + * Properly drains ALSA buffers before closing to avoid audio artifacts + */ void jetkvm_audio_capture_close() { // Wait for any ongoing operations to complete while (capture_initializing) { diff --git a/internal/audio/cgo_audio.go b/internal/audio/cgo_audio.go index 35688793..db9ae00d 100644 --- a/internal/audio/cgo_audio.go +++ b/internal/audio/cgo_audio.go @@ -5,10 +5,15 @@ package audio import ( "errors" "fmt" + "os" + "strings" "sync" "sync/atomic" "time" "unsafe" + + "github.com/jetkvm/kvm/internal/logging" + "github.com/rs/zerolog" ) /* @@ -19,9 +24,7 @@ import ( */ import "C" -// Optimized Go wrappers with reduced overhead var ( - // Base error types for wrapping with context errAudioInitFailed = errors.New("failed to init ALSA/Opus") errAudioReadEncode = errors.New("audio read/encode error") errAudioDecodeWrite = errors.New("audio decode/write error") @@ -91,6 +94,30 @@ func cgoAudioInit() error { cache := GetCachedConfig() cache.Update() + // Enable C trace logging if Go audio scope trace level is active + + // Enable C trace logging if Go audio scope trace level is active + audioLogger := logging.GetSubsystemLogger("audio") + loggerTraceEnabled := audioLogger.GetLevel() <= zerolog.TraceLevel + + // Manual check for audio scope in PION_LOG_TRACE (workaround for logging system bug) + manualTraceEnabled := false + pionTrace := os.Getenv("PION_LOG_TRACE") + if pionTrace != "" { + scopes := strings.Split(strings.ToLower(pionTrace), ",") + for _, scope := range scopes { + if strings.TrimSpace(scope) == "audio" { + manualTraceEnabled = true + break + } + } + } + + // Use manual check as fallback if logging system fails + traceEnabled := loggerTraceEnabled || manualTraceEnabled + + CGOSetTraceLogging(traceEnabled) + // Update C constants from cached config (atomic access, no locks) C.update_audio_constants( C.int(cache.opusBitrate.Load()), @@ -174,7 +201,7 @@ type AudioConfigCache struct { // Global audio config cache instance var globalAudioConfigCache = &AudioConfigCache{ - cacheExpiry: 30 * time.Second, // Increased from 10s to 30s to further reduce cache updates + cacheExpiry: 30 * time.Second, } // GetCachedConfig returns the global audio config cache instance @@ -318,6 +345,10 @@ func cgoAudioPlaybackInit() error { cache := GetCachedConfig() cache.Update() + // Enable C trace logging if Go audio scope trace level is active + audioLogger := logging.GetSubsystemLogger("audio") + CGOSetTraceLogging(audioLogger.GetLevel() <= zerolog.TraceLevel) + // No need to update C constants here as they're already set in cgoAudioInit ret := C.jetkvm_audio_playback_init() @@ -333,12 +364,12 @@ func cgoAudioPlaybackClose() { // 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) + audioDecodeWriteTotal atomic.Int64 + audioDecodeWriteSuccess atomic.Int64 + audioDecodeWriteFailures atomic.Int64 + audioDecodeWriteRecovery atomic.Int64 + audioDecodeWriteLastError atomic.Value + audioDecodeWriteLastTime atomic.Int64 ) // GetAudioDecodeWriteStats returns current audio decode/write statistics @@ -594,3 +625,13 @@ func CGOAudioDecodeWrite(opusData []byte, pcmBuffer []byte) (int, error) { func CGOUpdateOpusEncoderParams(bitrate, complexity, vbr, vbrConstraint, signalType, bandwidth, dtx int) error { return updateOpusEncoderParams(bitrate, complexity, vbr, vbrConstraint, signalType, bandwidth, dtx) } + +func CGOSetTraceLogging(enabled bool) { + var cEnabled C.int + if enabled { + cEnabled = 1 + } else { + cEnabled = 0 + } + C.set_trace_logging(cEnabled) +} diff --git a/internal/audio/core_handlers.go b/internal/audio/core_handlers.go index 69d7ec91..501ad1f7 100644 --- a/internal/audio/core_handlers.go +++ b/internal/audio/core_handlers.go @@ -241,11 +241,6 @@ func (s *AudioControlService) SetAudioQuality(quality AudioQuality) { SetAudioQuality(quality) } -// SetMicrophoneQuality sets the microphone input quality -func (s *AudioControlService) SetMicrophoneQuality(quality AudioQuality) { - SetMicrophoneQuality(quality) -} - // GetAudioQualityPresets returns available audio quality presets func (s *AudioControlService) GetAudioQualityPresets() map[AudioQuality]AudioConfig { return GetAudioQualityPresets() diff --git a/internal/audio/input_server_main.go b/internal/audio/input_server_main.go index 46defce9..8b67e0f4 100644 --- a/internal/audio/input_server_main.go +++ b/internal/audio/input_server_main.go @@ -17,6 +17,7 @@ import ( "time" "github.com/jetkvm/kvm/internal/logging" + "github.com/rs/zerolog" ) // Global audio input server instance @@ -46,7 +47,7 @@ func RecoverGlobalAudioInputServer() { // RunAudioInputServer runs the audio input server subprocess // This should be called from main() when the subprocess is detected func RunAudioInputServer() error { - logger := logging.GetDefaultLogger().With().Str("component", "audio-input-server").Logger() + logger := logging.GetSubsystemLogger("audio").With().Str("component", "audio-input-server").Logger() // Parse OPUS configuration from environment variables bitrate, complexity, vbr, signalType, bandwidth, dtx := parseOpusConfig() @@ -85,6 +86,10 @@ func RunAudioInputServer() error { logger.Info().Msg("audio input server started, waiting for connections") + // Update C trace logging based on current audio scope log level (after environment variables are processed) + traceEnabled := logger.GetLevel() <= zerolog.TraceLevel + CGOSetTraceLogging(traceEnabled) + // Set up signal handling for graceful shutdown ctx, cancel := context.WithCancel(context.Background()) defer cancel() diff --git a/internal/audio/input_supervisor.go b/internal/audio/input_supervisor.go index 59cddbf0..4b92d1fa 100644 --- a/internal/audio/input_supervisor.go +++ b/internal/audio/input_supervisor.go @@ -119,6 +119,11 @@ func (ais *AudioInputSupervisor) startProcess() error { // Set environment variables for IPC and OPUS configuration env := append(os.Environ(), "JETKVM_AUDIO_INPUT_IPC=true") // Enable IPC mode env = append(env, ais.opusEnv...) // Add OPUS configuration + + // Pass logging environment variables directly to subprocess + // The subprocess will inherit all PION_LOG_* variables from os.Environ() + // This ensures the audio scope gets the correct trace level + ais.cmd.Env = env // Set process group to allow clean termination diff --git a/internal/audio/output_server_main.go b/internal/audio/output_server_main.go index 1b536e10..2863fd8c 100644 --- a/internal/audio/output_server_main.go +++ b/internal/audio/output_server_main.go @@ -4,10 +4,12 @@ import ( "context" "os" "os/signal" + "strings" "syscall" "time" "github.com/jetkvm/kvm/internal/logging" + "github.com/rs/zerolog" ) // getEnvInt reads an integer from environment variable with a default value @@ -15,7 +17,7 @@ import ( // RunAudioOutputServer runs the audio output server subprocess // This should be called from main() when the subprocess is detected func RunAudioOutputServer() error { - logger := logging.GetDefaultLogger().With().Str("component", "audio-output-server").Logger() + logger := logging.GetSubsystemLogger("audio").With().Str("component", "audio-output-server").Logger() // Parse OPUS configuration from environment variables bitrate, complexity, vbr, signalType, bandwidth, dtx := parseOpusConfig() @@ -52,6 +54,27 @@ func RunAudioOutputServer() error { logger.Info().Msg("audio output server started, waiting for connections") + // Update C trace logging based on current audio scope log level (after environment variables are processed) + loggerTraceEnabled := logger.GetLevel() <= zerolog.TraceLevel + + // Manual check for audio scope in PION_LOG_TRACE (workaround for logging system bug) + manualTraceEnabled := false + pionTrace := os.Getenv("PION_LOG_TRACE") + if pionTrace != "" { + scopes := strings.Split(strings.ToLower(pionTrace), ",") + for _, scope := range scopes { + if strings.TrimSpace(scope) == "audio" { + manualTraceEnabled = true + break + } + } + } + + // Use manual check as fallback if logging system fails + traceEnabled := loggerTraceEnabled || manualTraceEnabled + + CGOSetTraceLogging(traceEnabled) + // Set up signal handling for graceful shutdown ctx, cancel := context.WithCancel(context.Background()) defer cancel() diff --git a/internal/audio/output_supervisor.go b/internal/audio/output_supervisor.go index 9da939e5..a0483508 100644 --- a/internal/audio/output_supervisor.go +++ b/internal/audio/output_supervisor.go @@ -217,7 +217,13 @@ func (s *AudioOutputSupervisor) startProcess() error { s.cmd.Stderr = os.Stderr // Set environment variables for OPUS configuration - s.cmd.Env = append(os.Environ(), s.opusEnv...) + env := append(os.Environ(), s.opusEnv...) + + // Pass logging environment variables directly to subprocess + // The subprocess will inherit all PION_LOG_* variables from os.Environ() + // This ensures the audio scope gets the correct trace level + + s.cmd.Env = env // Start the process if err := s.cmd.Start(); err != nil { diff --git a/internal/audio/quality_presets.go b/internal/audio/quality_presets.go index d57a61ff..47e4692a 100644 --- a/internal/audio/quality_presets.go +++ b/internal/audio/quality_presets.go @@ -260,97 +260,6 @@ func GetAudioConfig() AudioConfig { return currentConfig } -// Simplified OPUS parameter lookup table -var opusParams = map[AudioQuality]struct { - complexity, vbr, signalType, bandwidth, dtx int -}{ - AudioQualityLow: {Config.AudioQualityLowOpusComplexity, Config.AudioQualityLowOpusVBR, Config.AudioQualityLowOpusSignalType, Config.AudioQualityLowOpusBandwidth, Config.AudioQualityLowOpusDTX}, - AudioQualityMedium: {Config.AudioQualityMediumOpusComplexity, Config.AudioQualityMediumOpusVBR, Config.AudioQualityMediumOpusSignalType, Config.AudioQualityMediumOpusBandwidth, Config.AudioQualityMediumOpusDTX}, - AudioQualityHigh: {Config.AudioQualityHighOpusComplexity, Config.AudioQualityHighOpusVBR, Config.AudioQualityHighOpusSignalType, Config.AudioQualityHighOpusBandwidth, Config.AudioQualityHighOpusDTX}, - AudioQualityUltra: {Config.AudioQualityUltraOpusComplexity, Config.AudioQualityUltraOpusVBR, Config.AudioQualityUltraOpusSignalType, Config.AudioQualityUltraOpusBandwidth, Config.AudioQualityUltraOpusDTX}, -} - -// SetMicrophoneQuality updates the current microphone quality configuration -func SetMicrophoneQuality(quality AudioQuality) { - // Validate audio quality parameter - if err := ValidateAudioQuality(quality); err != nil { - // Log validation error but don't fail - maintain backward compatibility - logger := logging.GetDefaultLogger().With().Str("component", "audio").Logger() - logger.Warn().Err(err).Int("quality", int(quality)).Msg("invalid microphone quality, using current config") - return - } - - presets := GetMicrophoneQualityPresets() - if config, exists := presets[quality]; exists { - currentMicrophoneConfig = config - - // Get OPUS parameters using lookup table - params, exists := opusParams[quality] - if !exists { - // Fallback to medium quality - params = opusParams[AudioQualityMedium] - } - - // Update audio input subprocess configuration dynamically without restart - logger := logging.GetDefaultLogger().With().Str("component", "audio").Logger() - - // Set new OPUS configuration for future restarts - if supervisor := GetAudioInputSupervisor(); supervisor != nil { - supervisor.SetOpusConfig(config.Bitrate*1000, params.complexity, params.vbr, params.signalType, params.bandwidth, params.dtx) - - // Check if microphone is active but IPC control is broken - inputManager := getAudioInputManager() - if inputManager.IsRunning() && !supervisor.IsConnected() { - // Reconnect the IPC control channel - supervisor.Stop() - time.Sleep(50 * time.Millisecond) - if err := supervisor.Start(); err != nil { - logger.Debug().Err(err).Msg("failed to reconnect IPC control channel") - } - } - - // Send dynamic configuration update to running subprocess via IPC - if supervisor.IsConnected() { - // Convert AudioConfig to UnifiedIPCOpusConfig with complete Opus parameters - opusConfig := UnifiedIPCOpusConfig{ - SampleRate: config.SampleRate, - Channels: config.Channels, - FrameSize: int(config.FrameSize.Milliseconds() * int64(config.SampleRate) / 1000), // Convert ms to samples - Bitrate: config.Bitrate * 1000, // Convert kbps to bps - Complexity: params.complexity, - VBR: params.vbr, - SignalType: params.signalType, - Bandwidth: params.bandwidth, - DTX: params.dtx, - } - - if err := supervisor.SendOpusConfig(opusConfig); err != nil { - logger.Debug().Err(err).Msg("failed to send dynamic Opus config update via IPC") - // Fallback to subprocess restart if IPC update fails - supervisor.Stop() - if err := supervisor.Start(); err != nil { - logger.Error().Err(err).Msg("failed to restart audio input subprocess after IPC update failure") - } - } else { - logger.Info().Msg("audio input quality updated dynamically via IPC") - - // Reset audio input stats after config update - go func() { - time.Sleep(Config.QualityChangeSettleDelay) // Wait for quality change to settle - // Reset audio input server stats to clear persistent warnings - ResetGlobalAudioInputServerStats() - // Attempt recovery if microphone is still having issues - time.Sleep(1 * time.Second) - RecoverGlobalAudioInputServer() - }() - } - } else { - logger.Info().Bool("supervisor_running", supervisor.IsRunning()).Msg("audio input subprocess not connected, configuration will apply on next start") - } - } - } -} - // GetMicrophoneConfig returns the current microphone configuration func GetMicrophoneConfig() AudioConfig { return currentMicrophoneConfig