feat: add logging system and debug audio routing

Co-authored-by: aider (deepseek/deepseek-coder) <aider@aider.chat>

engine.c

@@ -1,5 +1,6 @@
 #include "engine.h"
 #include "carla.h"
+#include "logging.h"
 
 #define MAX_NFRAMES 8192
 #include <stdio.h>
@@ -47,6 +48,8 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
         uint8_t velocity = data[2];
         
         if (status == 0x90 && channel == 0 && velocity > 0) {
+            LOG_DEBUG("MIDI Note On: note=%d velocity=%d channel=%d", note, velocity, channel);
+            
             // Trigger audio clip
             Action action = {
                 .type = ACTION_MIDI_NOTE_ON,
@@ -63,12 +66,8 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
             };
             engine->dispatch(midi_action);
             
-            // Record MIDI event into MIDI clip if recording
-            // Note: we modify the local copy, not the actual state.
-            // The actual recording should be done via an action.
-            // For now, we just dispatch the trigger and let the reducer handle it.
-            
             ClipState note_state = (ClipState)atomic_load(&state->clips[note % MAX_CLIPS].state);
+            LOG_DEBUG("Clip %d state after dispatch: %d", note % MAX_CLIPS, note_state);
             uint8_t out_velocity = clip_state_to_velocity(note_state);
             uint8_t out_msg[3] = {0x90 | channel, note, out_velocity};
             jack_midi_event_write(midi_out_buf, midi_event.time, out_msg, 3);
@@ -88,6 +87,7 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
         uint8_t velocity = data[2];
         
         if (status == 0x90 && velocity > 0) {
+            LOG_DEBUG("MIDI Scene Launch: note=%d", note);
             Action action = {
                 .type = ACTION_MIDI_SCENE_LAUNCH,
                 .data.midi_scene_launch = { .scene_index = note % MAX_SCENES, .time = midi_event.time }
@@ -137,10 +137,19 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
             continue;
         }
         
+        // Track if any clip is active on this channel
+        bool any_recording = false;
+        bool any_looping = false;
+        
         for (jack_nframes_t i = 0; i < nframes; i++) {
             // Start with live audio input
             rack_in[i] = audio_in[ch][i];
             
+            // Check if input has signal
+            if (i == 0 && fabsf(audio_in[ch][i]) > 0.001f) {
+                LOG_TRACE("Channel %d has audio input at sample %d: %f", ch, i, audio_in[ch][i]);
+            }
+            
             for (int s = 0; s < MAX_SCENES; s++) {
                 // Iterate over all grids for this scene and channel
                 for (int g = 0; g < 8; g++) {
@@ -149,6 +158,7 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
                     
                     ClipState clip_state = (ClipState)atomic_load(&clip->state);
                     if (clip_state == CLIP_RECORDING) {
+                        any_recording = true;
                         // Write to lock-free ring buffer instead of clip buffer directly
                         size_t wp = atomic_load(&state->record_write_pos[ch]);
                         state->record_buffer[ch][wp % MAX_BUFFER_SIZE] = audio_in[ch][i];
@@ -156,6 +166,7 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
                     }
                     
                     if (clip_state == CLIP_LOOPING && clip->buffer_size > 0 && clip->buffer != NULL) {
+                        any_looping = true;
                         size_t rp = atomic_load(&clip->read_position);
                         rack_in[i] += clip->buffer[rp];
                         atomic_store(&clip->read_position, (rp + 1) % clip->buffer_size);
@@ -164,6 +175,13 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
             }
         }
         
+        // Log channel state once per callback
+        static int log_counter = 0;
+        if (log_counter++ % 100 == 0) {
+            LOG_DEBUG("Channel %d: nframes=%d any_recording=%d any_looping=%d rack_in[0]=%f",
+                      ch, nframes, any_recording, any_looping, rack_in[0]);
+        }
+        
         // Process through Carla rack
         carla_process(&engine->carla_host, ch, rack_in, rack_out, nframes);
         

logging.c

@@ -0,0 +1,96 @@
+#include "logging.h"
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <stdarg.h>
+#include <time.h>
+#include <pthread.h>
+
+static struct {
+    FILE *file;
+    LogLevel level;
+    pthread_mutex_t mutex;
+    bool initialized;
+} logger = { .file = NULL, .level = LOG_LEVEL_INFO, .initialized = false };
+
+static const char* level_to_string(LogLevel level) {
+    switch (level) {
+        case LOG_LEVEL_ERROR: return "ERROR";
+        case LOG_LEVEL_WARN:  return "WARN";
+        case LOG_LEVEL_INFO:  return "INFO";
+        case LOG_LEVEL_DEBUG: return "DEBUG";
+        case LOG_LEVEL_TRACE: return "TRACE";
+        default:              return "UNKNOWN";
+    }
+}
+
+void log_init(const char *filename, LogLevel level) {
+    pthread_mutex_init(&logger.mutex, NULL);
+    logger.level = level;
+    
+    if (filename) {
+        logger.file = fopen(filename, "w");
+        if (!logger.file) {
+            fprintf(stderr, "Failed to open log file %s, logging to stderr\n", filename);
+            logger.file = stderr;
+        }
+    } else {
+        logger.file = stderr;
+    }
+    
+    logger.initialized = true;
+    
+    // Log header
+    time_t now = time(NULL);
+    struct tm *tm = localtime(&now);
+    char timebuf[64];
+    strftime(timebuf, sizeof(timebuf), "%Y-%m-%d %H:%M:%S", tm);
+    fprintf(logger.file, "=== Log started at %s ===\n", timebuf);
+    fprintf(logger.file, "Log level: %s\n\n", level_to_string(level));
+    fflush(logger.file);
+}
+
+void log_cleanup(void) {
+    if (logger.initialized) {
+        if (logger.file && logger.file != stderr) {
+            fclose(logger.file);
+        }
+        logger.file = NULL;
+        logger.initialized = false;
+        pthread_mutex_destroy(&logger.mutex);
+    }
+}
+
+void log_set_level(LogLevel level) {
+    logger.level = level;
+}
+
+void log_message(LogLevel level, const char *file, int line, const char *func, const char *format, ...) {
+    if (!logger.initialized || level > logger.level) return;
+    
+    pthread_mutex_lock(&logger.mutex);
+    
+    // Timestamp
+    struct timespec ts;
+    clock_gettime(CLOCK_REALTIME, &ts);
+    struct tm *tm = localtime(&ts.tv_sec);
+    char timebuf[32];
+    strftime(timebuf, sizeof(timebuf), "%H:%M:%S", tm);
+    
+    // Print header
+    fprintf(logger.file, "[%s.%03ld] [%s] [%s:%d %s] ",
+            timebuf, ts.tv_nsec / 1000000,
+            level_to_string(level),
+            file, line, func);
+    
+    // Print message
+    va_list args;
+    va_start(args, format);
+    vfprintf(logger.file, format, args);
+    va_end(args);
+    
+    fprintf(logger.file, "\n");
+    fflush(logger.file);
+    
+    pthread_mutex_unlock(&logger.mutex);
+}

logging.h

@@ -0,0 +1,36 @@
+#ifndef LOGGING_H
+#define LOGGING_H
+
+#include <stdio.h>
+#include <stdbool.h>
+#include <time.h>
+
+// Log levels
+typedef enum {
+    LOG_LEVEL_ERROR,
+    LOG_LEVEL_WARN,
+    LOG_LEVEL_INFO,
+    LOG_LEVEL_DEBUG,
+    LOG_LEVEL_TRACE
+} LogLevel;
+
+// Initialize logging system
+void log_init(const char *filename, LogLevel level);
+
+// Cleanup logging system
+void log_cleanup(void);
+
+// Set minimum log level
+void log_set_level(LogLevel level);
+
+// Log a message
+void log_message(LogLevel level, const char *file, int line, const char *func, const char *format, ...);
+
+// Convenience macros
+#define LOG_ERROR(...)   log_message(LOG_LEVEL_ERROR, __FILE__, __LINE__, __func__, __VA_ARGS__)
+#define LOG_WARN(...)    log_message(LOG_LEVEL_WARN, __FILE__, __LINE__, __func__, __VA_ARGS__)
+#define LOG_INFO(...)    log_message(LOG_LEVEL_INFO, __FILE__, __LINE__, __func__, __VA_ARGS__)
+#define LOG_DEBUG(...)   log_message(LOG_LEVEL_DEBUG, __FILE__, __LINE__, __func__, __VA_ARGS__)
+#define LOG_TRACE(...)   log_message(LOG_LEVEL_TRACE, __FILE__, __LINE__, __func__, __VA_ARGS__)
+
+#endif // LOGGING_H

main.c

@@ -10,6 +10,7 @@
 #include "dispatcher.h"
 #include "carla.h"
 #include "fs.h"
+#include "logging.h"
 
 static Engine engine;
 static volatile int keep_running = 1;
@@ -129,6 +130,10 @@ int main(int argc, char *argv[]) {
     dispatch = dispatcher_init(initial_state);
     free(initial_state);
     
+    // Initialize logging
+    log_init("jack-looper.log", LOG_LEVEL_DEBUG);
+    LOG_INFO("JACK Looper starting...");
+    
     // Initialize filesystem module (auto-save thread)
     fs_init();
     
@@ -192,6 +197,7 @@ int main(int argc, char *argv[]) {
     engine_cleanup(&engine);
     fs_cleanup();
     dispatcher_stop();
+    log_cleanup();
     
     return 0;
 }