From 2ed4b96058783eea7dd82938b3008622e9b5eb93 Mon Sep 17 00:00:00 2001 From: Your Name Date: Mon, 2 Feb 2026 11:20:11 -0400 Subject: [PATCH] v1.1.8 - Add comprehensive database query logging with timing at debug level 3, fix schema version compatibility (v6-v9), add version logging at startup, allow monitoring throttle=0 to disable monitoring --- Dockerfile.alpine-musl | 8 ++-- relay.pid | 2 +- src/api.c | 53 +++++++++++++++++++--- src/main.c | 100 ++++++++++++++++++++++++++++++++++++++++- src/main.h | 4 +- src/websockets.c | 18 ++++++++ 6 files changed, 169 insertions(+), 16 deletions(-) diff --git a/Dockerfile.alpine-musl b/Dockerfile.alpine-musl index 8094fbb..6f189da 100644 --- a/Dockerfile.alpine-musl +++ b/Dockerfile.alpine-musl @@ -107,13 +107,13 @@ COPY Makefile /build/Makefile # Disable fortification to avoid __*_chk symbols that don't exist in MUSL # Use conditional compilation flags based on DEBUG_BUILD argument RUN if [ "$DEBUG_BUILD" = "true" ]; then \ - CFLAGS="-g -O0 -DDEBUG"; \ - STRIP_CMD=""; \ - echo "Building with DEBUG symbols enabled"; \ + CFLAGS="-g -O2 -DDEBUG"; \ + STRIP_CMD="echo 'Keeping debug symbols'"; \ + echo "Building with DEBUG symbols enabled (optimized with -O2)"; \ else \ CFLAGS="-O2"; \ STRIP_CMD="strip /build/c_relay_static"; \ - echo "Building optimized production binary"; \ + echo "Building optimized production binary (symbols stripped)"; \ fi && \ gcc -static $CFLAGS -Wall -Wextra -std=c99 \ -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=0 \ diff --git a/relay.pid b/relay.pid index 138eb5a..0581262 100644 --- a/relay.pid +++ b/relay.pid @@ -1 +1 @@ -1987115 +2211317 diff --git a/src/api.c b/src/api.c index e3a9a1a..933599a 100644 --- a/src/api.c +++ b/src/api.c @@ -1,6 +1,11 @@ // Define _GNU_SOURCE to ensure all POSIX features are available #define _GNU_SOURCE +// Forward declaration for query logging (defined in main.c) +extern void log_query_execution(const char* query_type, const char* sub_id, + const char* client_ip, const char* sql, + long elapsed_us, int rows_returned); + // API module for serving embedded web content and admin API functions #include #include @@ -66,6 +71,10 @@ cJSON* query_event_kind_distribution(void) { sqlite3_stmt* stmt; const char* sql = "SELECT kind, COUNT(*) as count FROM events GROUP BY kind ORDER BY count DESC"; + // Start timing + struct timespec query_start, query_end; + clock_gettime(CLOCK_MONOTONIC, &query_start); + if (sqlite3_prepare_v2(g_db, sql, -1, &stmt, NULL) != SQLITE_OK) { DEBUG_ERROR("Failed to prepare event kind distribution query"); return NULL; @@ -77,8 +86,10 @@ cJSON* query_event_kind_distribution(void) { cJSON* kinds_array = cJSON_CreateArray(); long long total_events = 0; + int row_count = 0; while (sqlite3_step(stmt) == SQLITE_ROW) { + row_count++; int kind = sqlite3_column_int(stmt, 0); long long count = sqlite3_column_int64(stmt, 1); total_events += count; @@ -90,6 +101,13 @@ cJSON* query_event_kind_distribution(void) { } sqlite3_finalize(stmt); + + // Stop timing and log + clock_gettime(CLOCK_MONOTONIC, &query_end); + long elapsed_us = (query_end.tv_sec - query_start.tv_sec) * 1000000L + + (query_end.tv_nsec - query_start.tv_nsec) / 1000L; + + log_query_execution("MONITOR", "event_kinds", NULL, sql, elapsed_us, row_count); cJSON_AddNumberToObject(distribution, "total_events", total_events); cJSON_AddItemToObject(distribution, "kinds", kinds_array); @@ -245,6 +263,10 @@ cJSON* query_subscription_details(void) { DEBUG_LOG("=== SUBSCRIPTION_DETAILS QUERY DEBUG ==="); DEBUG_LOG("Query: %s", sql); + // Start timing + struct timespec query_start, query_end; + clock_gettime(CLOCK_MONOTONIC, &query_start); + if (sqlite3_prepare_v2(g_db, sql, -1, &stmt, NULL) != SQLITE_OK) { DEBUG_ERROR("Failed to prepare subscription details query"); return NULL; @@ -351,8 +373,15 @@ cJSON* query_subscription_details(void) { cJSON_AddItemToObject(subscriptions_data, "data", data); + // Stop timing and log + clock_gettime(CLOCK_MONOTONIC, &query_end); + long elapsed_us = (query_end.tv_sec - query_start.tv_sec) * 1000000L + + (query_end.tv_nsec - query_start.tv_nsec) / 1000L; + + log_query_execution("MONITOR", "subscription_details", NULL, sql, elapsed_us, row_count); + // DEBUG: Log final summary - DEBUG_LOG("Total subscriptions found: %d", cJSON_GetArraySize(subscriptions_array)); + DEBUG_LOG("Total subscriptions found: %d", row_count); DEBUG_LOG("=== END SUBSCRIPTION_DETAILS QUERY DEBUG ==="); return subscriptions_data; @@ -499,10 +528,15 @@ int generate_monitoring_event_for_type(const char* d_tag_value, cJSON* (*query_f // Monitoring hook called when an event is stored void monitoring_on_event_stored(void) { - // Check throttling first (cheapest check) + // Check if monitoring is disabled (throttle = 0) + int throttle_seconds = get_monitoring_throttle_seconds(); + if (throttle_seconds == 0) { + return; // Monitoring disabled + } + + // Check throttling static time_t last_monitoring_time = 0; time_t current_time = time(NULL); - int throttle_seconds = get_monitoring_throttle_seconds(); if (current_time - last_monitoring_time < throttle_seconds) { return; @@ -521,10 +555,15 @@ void monitoring_on_event_stored(void) { // Monitoring hook called when subscriptions change (create/close) void monitoring_on_subscription_change(void) { - // Check throttling first (cheapest check) + // Check if monitoring is disabled (throttle = 0) + int throttle_seconds = get_monitoring_throttle_seconds(); + if (throttle_seconds == 0) { + return; // Monitoring disabled + } + + // Check throttling static time_t last_monitoring_time = 0; time_t current_time = time(NULL); - int throttle_seconds = get_monitoring_throttle_seconds(); if (current_time - last_monitoring_time < throttle_seconds) { return; @@ -2761,8 +2800,8 @@ int handle_monitoring_command(cJSON* event, const char* command, char* error_mes char* endptr; long throttle_seconds = strtol(arg, &endptr, 10); - if (*endptr != '\0' || throttle_seconds < 1 || throttle_seconds > 3600) { - char* response_content = "❌ Invalid throttle value\n\nThrottle must be between 1 and 3600 seconds."; + if (*endptr != '\0' || throttle_seconds < 0 || throttle_seconds > 3600) { + char* response_content = "❌ Invalid throttle value\n\nThrottle must be between 0 and 3600 seconds (0 = disabled)."; return send_admin_response(sender_pubkey, response_content, request_id, error_message, error_size, wsi); } diff --git a/src/main.c b/src/main.c index 5cb0868..49e8bdf 100644 --- a/src/main.c +++ b/src/main.c @@ -229,6 +229,65 @@ void send_notice_message(struct lws* wsi, struct per_session_data* pss, const ch } +///////////////////////////////////////////////////////////////////////////////////////// +///////////////////////////////////////////////////////////////////////////////////////// +// DATABASE QUERY LOGGING +///////////////////////////////////////////////////////////////////////////////////////// +///////////////////////////////////////////////////////////////////////////////////////// + +/** + * Log database query execution with timing and context + * Only logs at debug level 3 (DEBUG) or higher + * Warns if query takes >10ms (slow query) + * + * @param query_type Type of query (REQ, COUNT, INSERT, CONFIG, etc.) + * @param sub_id Subscription ID (NULL if not applicable) + * @param client_ip Client IP address (NULL if not applicable) + * @param sql SQL query text + * @param elapsed_us Execution time in microseconds + * @param rows_returned Number of rows returned or affected + */ +void log_query_execution(const char* query_type, const char* sub_id, + const char* client_ip, const char* sql, + long elapsed_us, int rows_returned) { + // Only log at debug level 3 (INFO) or higher + if (g_debug_level < DEBUG_LEVEL_INFO) { + return; + } + + // Truncate SQL if too long (keep first 500 chars) + char sql_truncated[512]; + if (strlen(sql) > 500) { + snprintf(sql_truncated, sizeof(sql_truncated), "%.497s...", sql); + } else { + snprintf(sql_truncated, sizeof(sql_truncated), "%s", sql); + } + + // Get timestamp + time_t now = time(NULL); + struct tm* tm_info = localtime(&now); + char timestamp[32]; + strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", tm_info); + + // Log query with all context (direct to stdout/stderr, not through DEBUG_LOG) + fprintf(stderr, "[%s] [QUERY] type=%s sub=%s ip=%s time=%ldus rows=%d sql=%s\n", + timestamp, + query_type, + sub_id ? sub_id : "N/A", + client_ip ? client_ip : "N/A", + elapsed_us, + rows_returned, + sql_truncated); + + // Warn if query is slow (>10ms = 10000us) + if (elapsed_us > 10000) { + fprintf(stderr, "[%s] [SLOW_QUERY] %ldms: %s\n", + timestamp, elapsed_us / 1000, sql_truncated); + } + + fflush(stderr); +} + ///////////////////////////////////////////////////////////////////////////////////////// ///////////////////////////////////////////////////////////////////////////////////////// // DATABASE FUNCTIONS @@ -370,12 +429,17 @@ int init_database(const char* database_path_override) { if (!db_version || strcmp(db_version, "5") == 0) { needs_migration = 1; } else if (strcmp(db_version, "6") == 0) { - // Database is already at current schema version v6 + // Database is at schema version v6 (compatible) + } else if (strcmp(db_version, "7") == 0) { + // Database is at schema version v7 (compatible) + } else if (strcmp(db_version, "8") == 0) { + // Database is at schema version v8 (compatible) } else if (strcmp(db_version, EMBEDDED_SCHEMA_VERSION) == 0) { // Database is at current schema version } else { char warning_msg[256]; - snprintf(warning_msg, sizeof(warning_msg), "Unknown database schema version: %s", db_version); + snprintf(warning_msg, sizeof(warning_msg), "Unknown database schema version: %s (expected %s)", + db_version, EMBEDDED_SCHEMA_VERSION); DEBUG_WARN(warning_msg); } } else { @@ -1192,6 +1256,10 @@ int handle_req_message(const char* sub_id, cJSON* filters, struct lws *wsi, stru snprintf(sql_ptr, remaining, " LIMIT 500"); } + // Start query timing + struct timespec query_start, query_end; + clock_gettime(CLOCK_MONOTONIC, &query_start); + // Execute query and send events sqlite3_stmt* stmt; int rc = sqlite3_prepare_v2(g_db, sql, -1, &stmt, NULL); @@ -1199,6 +1267,22 @@ int handle_req_message(const char* sub_id, cJSON* filters, struct lws *wsi, stru char error_msg[256]; snprintf(error_msg, sizeof(error_msg), "Failed to prepare subscription query: %s", sqlite3_errmsg(g_db)); DEBUG_ERROR(error_msg); + + // Log the failed query so we can see what SQL was generated + if (g_debug_level >= DEBUG_LEVEL_DEBUG) { + time_t now = time(NULL); + struct tm* tm_info = localtime(&now); + char timestamp[32]; + strftime(timestamp, sizeof(timestamp), "%Y-%m-%d %H:%M:%S", tm_info); + fprintf(stderr, "[%s] [QUERY_FAILED] type=REQ sub=%s ip=%s error=%s sql=%s\n", + timestamp, + sub_id, + pss ? pss->client_ip : "N/A", + sqlite3_errmsg(g_db), + sql); + fflush(stderr); + } + continue; } @@ -1275,6 +1359,14 @@ int handle_req_message(const char* sub_id, cJSON* filters, struct lws *wsi, stru } sqlite3_finalize(stmt); + + // Stop query timing and log + clock_gettime(CLOCK_MONOTONIC, &query_end); + long elapsed_us = (query_end.tv_sec - query_start.tv_sec) * 1000000L + + (query_end.tv_nsec - query_start.tv_nsec) / 1000L; + + log_query_execution("REQ", sub_id, pss ? pss->client_ip : NULL, + sql, elapsed_us, row_count); } // Cleanup bind params @@ -1573,6 +1665,10 @@ int main(int argc, char* argv[]) { signal(SIGINT, signal_handler); signal(SIGTERM, signal_handler); + // Print version at startup (always, regardless of debug level) + fprintf(stderr, "[RELAY_VERSION] C Nostr Relay Server %s\n", CRELAY_VERSION); + fflush(stderr); + printf(BLUE BOLD "=== C Nostr Relay Server ===" RESET "\n"); diff --git a/src/main.h b/src/main.h index 58f09ee..d6dc42a 100644 --- a/src/main.h +++ b/src/main.h @@ -13,8 +13,8 @@ // Using CRELAY_ prefix to avoid conflicts with nostr_core_lib VERSION macros #define CRELAY_VERSION_MAJOR 1 #define CRELAY_VERSION_MINOR 1 -#define CRELAY_VERSION_PATCH 7 -#define CRELAY_VERSION "v1.1.7" +#define CRELAY_VERSION_PATCH 8 +#define CRELAY_VERSION "v1.1.8" // Relay metadata (authoritative source for NIP-11 information) #define RELAY_NAME "C-Relay" diff --git a/src/websockets.c b/src/websockets.c index cae8cf9..b156c71 100644 --- a/src/websockets.c +++ b/src/websockets.c @@ -86,6 +86,11 @@ int is_event_expired(cJSON* event, time_t current_time); int handle_req_message(const char* sub_id, cJSON* filters, struct lws *wsi, struct per_session_data *pss); int handle_count_message(const char* sub_id, cJSON* filters, struct lws *wsi, struct per_session_data *pss); +// Forward declaration for query logging (defined in main.c) +extern void log_query_execution(const char* query_type, const char* sub_id, + const char* client_ip, const char* sql, + long elapsed_us, int rows_returned); + // Forward declarations for rate limiting int is_client_rate_limited_for_malformed_requests(struct per_session_data *pss); void record_malformed_request(struct per_session_data *pss); @@ -2692,6 +2697,10 @@ int handle_count_message(const char* sub_id, cJSON* filters, struct lws *wsi, st } // Execute count query + + // Start query timing + struct timespec query_start, query_end; + clock_gettime(CLOCK_MONOTONIC, &query_start); // Execute count query sqlite3_stmt* stmt; @@ -2716,6 +2725,15 @@ int handle_count_message(const char* sub_id, cJSON* filters, struct lws *wsi, st // Filter count calculated sqlite3_finalize(stmt); + + // Stop query timing and log + clock_gettime(CLOCK_MONOTONIC, &query_end); + long elapsed_us = (query_end.tv_sec - query_start.tv_sec) * 1000000L + + (query_end.tv_nsec - query_start.tv_nsec) / 1000L; + + log_query_execution("COUNT", sub_id, pss ? pss->client_ip : NULL, + sql, elapsed_us, 1); // COUNT always returns 1 row + total_count += filter_count; }