fix: add debug print to process_callback to verify it runs

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>
@@ -12,6 +13,13 @@ static int process_callback(jack_nframes_t nframes, void *arg) {
     Engine *engine = (Engine *)arg;
     if (!engine || !engine->dispatch) return 0;
     
+    // Debug: print every 50th callback
+    static int cb_count = 0;
+    if (cb_count++ % 50 == 0) {
+        fprintf(stdout, "LOOPER_CB: nframes=%u, dispatch=%p, state=%p\n", 
+                nframes, (void*)engine->dispatch, (void*)engine->state);
+    }
+    
     jack_default_audio_sample_t *audio_in[MAX_CHANNELS];
     jack_default_audio_sample_t *audio_out[MAX_CHANNELS];
     
@@ -47,6 +55,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 +73,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 +94,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 +144,26 @@ 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;
+        
+        // Debug: check if we're receiving audio
+        static int debug_counter = 0;
+        if (debug_counter++ % 50 == 0) {
+            fprintf(stderr, "LOOPER DEBUG: Channel %d audio_in[0] = %f, nframes = %u\n", 
+                    ch, audio_in[ch][0], nframes);
+        }
+        
         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 +172,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 +180,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 +189,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;
 }

makefile

@@ -4,28 +4,28 @@ LDFLAGS = -ljack -lm -lncurses -lpthread
 
 all: jack-looper test_engine test_tui test_gui test_cli test_stress test_wav_io test_audio_routing
 
-jack-looper: main.o engine.o tui.o gui.o cli.o transport.o dispatcher.o lib/microui.o wav_io.o carla.o fs.o
+jack-looper: main.o engine.o tui.o gui.o cli.o transport.o dispatcher.o lib/microui.o wav_io.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_engine: test_engine.o engine.o transport.o wav_io.o dispatcher.o carla.o fs.o
+test_engine: test_engine.o engine.o transport.o wav_io.o dispatcher.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_tui: test_tui.o engine.o transport.o wav_io.o dispatcher.o carla.o fs.o
+test_tui: test_tui.o engine.o transport.o wav_io.o dispatcher.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_gui: test_gui.o gui.o engine.o transport.o lib/microui.o wav_io.o dispatcher.o carla.o fs.o
+test_gui: test_gui.o gui.o engine.o transport.o lib/microui.o wav_io.o dispatcher.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_cli: test_cli.o engine.o cli.o transport.o wav_io.o dispatcher.o carla.o fs.o
+test_cli: test_cli.o engine.o cli.o transport.o wav_io.o dispatcher.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_stress: test_stress.o engine.o wav_io.o dispatcher.o carla.o fs.o
+test_stress: test_stress.o engine.o wav_io.o dispatcher.o carla.o fs.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_wav_io: test_wav_io.o wav_io.o
+test_wav_io: test_wav_io.o wav_io.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
-test_audio_routing: test_audio_routing.o
+test_audio_routing: test_audio_routing.o logging.o
 	$(CC) $(CFLAGS) -o $@ $^ $(LDFLAGS)
 
 
@@ -62,6 +62,9 @@ dispatcher.o: dispatcher.c dispatcher.h carla.h fs.h
 fs.o: fs.c fs.h dispatcher.h wav_io.h
 	$(CC) $(CFLAGS) -c -o $@ $<
 
+logging.o: logging.c logging.h
+	$(CC) $(CFLAGS) -c -o $@ $<
+
 test_engine.o: test_engine.c engine.h transport.h dispatcher.h
 	$(CC) $(CFLAGS) -c -o $@ $<
 
@@ -90,7 +93,7 @@ cli.o: cli.c cli.h engine.h transport.h
 clean:
 	rm -f *.o lib/microui.o wav_io.o jack-looper test_engine test_tui test_gui test_cli test_stress test_wav_io
 
-test: test_engine test_tui test_cli test_wav_io test_audio_routing
+test: jack-looper test_engine test_tui test_cli test_wav_io test_audio_routing
 	./test_engine
 	./test_tui
 	./test_cli

test_audio_routing.c

@@ -48,6 +48,11 @@ static float test_audio_input[MAX_CHANNELS][MAX_SAMPLES];
 static atomic_size_t test_audio_input_count[MAX_CHANNELS];
 static atomic_size_t test_audio_input_read[MAX_CHANNELS];
 
+// Debug counters
+static atomic_ulong test_callback_count;
+static atomic_ulong test_midi_sent_count;
+static atomic_ulong test_audio_written_count;
+
 // Shared MIDI buffer (written by test thread, read by JACK callback)
 static uint8_t test_midi_buffer[3];  // status, note, velocity
 static atomic_bool test_midi_pending;
@@ -81,6 +86,8 @@ static int test_process_callback(jack_nframes_t nframes, void *arg) {
     (void)arg;
     if (!atomic_load(&test_running)) return 0;
     
+    atomic_fetch_add(&test_callback_count, 1);
+    
     pthread_mutex_lock(&test_buffer_mutex);
     
     // Write test audio to output ports (to be sent to looper)
@@ -91,14 +98,17 @@ static int test_process_callback(jack_nframes_t nframes, void *arg) {
         size_t read_pos = atomic_load(&test_audio_input_read[ch]);
         size_t count = atomic_load(&test_audio_input_count[ch]);
         
+        bool wrote_audio = false;
         for (jack_nframes_t i = 0; i < nframes; i++) {
             if (read_pos + i < count) {
                 out[i] = test_audio_input[ch][read_pos + i];
+                if (test_audio_input[ch][read_pos + i] != 0.0f) wrote_audio = true;
             } else {
                 out[i] = 0.0f;
             }
         }
         atomic_store(&test_audio_input_read[ch], read_pos + nframes);
+        if (wrote_audio) atomic_fetch_add(&test_audio_written_count, 1);
     }
     
     // Read audio from looper outputs
@@ -160,7 +170,7 @@ static int start_looper(const char *client_name) {
         cpu_limit.rlim_max = 10;
         setrlimit(RLIMIT_CPU, &cpu_limit);
         
-        execl("./jack-looper", "jack-looper", "-n", client_name, "-i", NULL);
+        execl("./jack-looper", "jack-looper", "-n", client_name, "-t", NULL);
         perror("execl failed");
         exit(1);
     }
@@ -171,6 +181,32 @@ static int start_looper(const char *client_name) {
     
     // Wait for looper to start
     usleep(500000);  // 500ms
+    
+    // Check if looper is still running
+    if (kill(looper_pid, 0) != 0) {
+        fprintf(stderr, "Looper process died\n");
+        return -1;
+    }
+    
+    // Check log file for debug messages
+    FILE *log = fopen("jack-looper.log", "r");
+    if (log) {
+        char line[256];
+        int has_debug = 0;
+        while (fgets(line, sizeof(line), log)) {
+            if (strstr(line, "Channel") && strstr(line, "nframes")) {
+                has_debug = 1;
+                printf("    [LOG] %s", line);
+            }
+        }
+        fclose(log);
+        if (!has_debug) {
+            printf("    [LOG] No process callback debug messages found\n");
+        }
+    } else {
+        printf("    [LOG] Could not open jack-looper.log\n");
+    }
+    
     return 0;
 }
 
@@ -238,6 +274,26 @@ static int connect_test_client(const char *looper_name) {
     snprintf(looper_port, sizeof(looper_port), "%s:midi_out", looper_name);
     jack_connect(test_client, looper_port, "test_routing:test_midi_in");
     
+    // Wait for JACK to process and check log file
+    usleep(500000);
+    FILE *log = fopen("jack-looper.log", "r");
+    if (log) {
+        char line[256];
+        int has_debug = 0;
+        while (fgets(line, sizeof(line), log)) {
+            if (strstr(line, "Channel") && strstr(line, "nframes")) {
+                has_debug = 1;
+                printf("    [LOG] %s", line);
+            }
+        }
+        fclose(log);
+        if (!has_debug) {
+            printf("    [LOG] No process callback debug messages found after connect\n");
+        }
+    } else {
+        printf("    [LOG] Could not open jack-looper.log after connect\n");
+    }
+    
     return 0;
 }
 
@@ -269,6 +325,10 @@ static void send_sine_wave(int channel, float frequency, float amplitude, jack_n
     // Wait for the JACK callback to consume the audio
     // (the callback runs in a separate thread)
     usleep(duration * 1000 + 300000);  // duration ms + 300ms extra
+    
+    unsigned long cb_count = atomic_load(&test_callback_count);
+    unsigned long aw_count = atomic_load(&test_audio_written_count);
+    printf("    [DEBUG] Callback count: %lu, Audio written: %lu\n", cb_count, aw_count);
 }
 
 static void send_midi_note(int note, int velocity) {
@@ -282,11 +342,16 @@ static void send_midi_note(int note, int velocity) {
     test_midi_buffer[1] = note & 0x7F;
     test_midi_buffer[2] = velocity & 0x7F;
     atomic_store(&test_midi_pending, true);
+    atomic_fetch_add(&test_midi_sent_count, 1);
     
     pthread_mutex_unlock(&test_buffer_mutex);
     
     // Wait longer for JACK to process the MIDI message
     usleep(300000);  // 300ms to let JACK process
+    
+    unsigned long cb_count = atomic_load(&test_callback_count);
+    unsigned long ms_count = atomic_load(&test_midi_sent_count);
+    printf("    [DEBUG] Callback count: %lu, MIDI sent: %lu\n", cb_count, ms_count);
 }
 
 static float get_channel_rms(int channel) {
@@ -561,6 +626,9 @@ int main(void) {
     atomic_store(&tests_failed, 0);
     atomic_store(&test_running, true);
     atomic_store(&test_timeout, false);
+    atomic_store(&test_callback_count, 0);
+    atomic_store(&test_midi_sent_count, 0);
+    atomic_store(&test_audio_written_count, 0);
     
     // Start watchdog thread
     pthread_t watchdog;