diff --git a/engine.c b/engine.c index cf4a0a4..4744744 100644 --- a/engine.c +++ b/engine.c @@ -1,5 +1,6 @@ #include "engine.h" #include "carla.h" +#include "logging.h" #define MAX_NFRAMES 8192 #include @@ -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); diff --git a/logging.c b/logging.c index e69de29..196fa34 100644 --- a/logging.c +++ b/logging.c @@ -0,0 +1,96 @@ +#include "logging.h" +#include +#include +#include +#include +#include +#include + +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); +} diff --git a/logging.h b/logging.h index e69de29..00e4efa 100644 --- a/logging.h +++ b/logging.h @@ -0,0 +1,36 @@ +#ifndef LOGGING_H +#define LOGGING_H + +#include +#include +#include + +// 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 diff --git a/main.c b/main.c index 519493e..632c5ad 100644 --- a/main.c +++ b/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; }