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

@@ -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"; \
+        CFLAGS="-g -O2 -DDEBUG"; \
-        STRIP_CMD=""; \
+        STRIP_CMD="echo 'Keeping debug symbols'"; \
-        echo "Building with DEBUG symbols enabled"; \
+        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 \

relay.pid

@@ -1 +1 @@
-1987115
+2211317

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 <stdio.h>
 #include <stdlib.h>
@@ -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;
@@ -91,6 +102,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) {
+        if (*endptr != '\0' || throttle_seconds < 0 || throttle_seconds > 3600) {
-            char* response_content = "❌ Invalid throttle value\n\nThrottle must be between 1 and 3600 seconds.";
+            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);
         }
 

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");
 
     

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_PATCH 8
-#define CRELAY_VERSION "v1.1.7"
+#define CRELAY_VERSION "v1.1.8"
 
 // Relay metadata (authoritative source for NIP-11 information)
 #define RELAY_NAME "C-Relay"

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);
@@ -2693,6 +2698,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;
         int rc = sqlite3_prepare_v2(g_db, sql, -1, &stmt, NULL);
@@ -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;
     }