Debug logging to disk

Introduced new schema debugdb_disk (on disk) and table debug_log .

Debug entries will now go to this new table based on the value of
variable admin-debug_output . If:
1) default behavior: write to stderr
2) write only to debugdb_disk.debug_log
3) 3 = 1+2 = write to stderr and to debugdb_disk.debug_log

All these functionalities exist only on debug build.

Table debugdb_disk.debug_log has also a column named "note" that can be used
to write user notes during debugging.

include/proxysql_admin.h

@@ -332,6 +332,10 @@ class ProxySQL_Admin {
 	SQLite3DB *configdb; // on disk
 	SQLite3DB *monitordb;	// in memory
 	SQLite3DB *statsdb_disk; // on disk
+#ifdef DEBUG
+	SQLite3DB *debugdb_disk; // on disk for debug
+	int debug_output;
+#endif
 	int pipefd[2];
 	void print_version();
 	bool init();

include/proxysql_debug.h

@@ -211,4 +211,10 @@ SQLite3_result* proxysql_get_message_stats(bool reset=false);
  */
 void proxysql_init_debug_prometheus_metrics();
 
+
+/**
+ * @brief Set or unset if Admin has debugdb_disk fully initialized
+ */
+void proxysql_set_status_admin_debugdb_disk(bool status);
+
 #endif

include/sqlite3db.h

@@ -7,6 +7,16 @@
 #include <vector>
 #define PROXYSQL_SQLITE3DB_PTHREAD_MUTEX
 
+#ifndef SAFE_SQLITE3_STEP2
+#define SAFE_SQLITE3_STEP2(_stmt) do {\
+  do {\
+    rc=(*proxy_sqlite3_step)(_stmt);\
+    if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
+      usleep(100);\
+    }\
+  } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
+} while (0)
+#endif // SAFE_SQLITE3_STEP2
 
 #ifndef MAIN_PROXY_SQLITE3
 extern int (*proxy_sqlite3_bind_double)(sqlite3_stmt*, int, double);

lib/ClickHouse_Server.cpp

@@ -58,15 +58,6 @@
   } while (rc!=SQLITE_DONE);\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-	do {\
-	rc=(*proxy_sqlite3_step)(_stmt);\
-		if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-			usleep(100);\
-		}\
-	} while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
-
 #include "clickhouse/client.h"
 
 using namespace clickhouse;

lib/MySQL_HostGroups_Manager.cpp

@@ -42,15 +42,6 @@ static unsigned long long array_mysrvc_cands = 0;
   } while (rc!=SQLITE_DONE);\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-	do {\
-		rc=(*proxy_sqlite3_step)(_stmt);\
-		if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-			usleep(100);\
-		}\
-	} while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
-
 extern ProxySQL_Admin *GloAdmin;
 
 extern MySQL_Threads_Handler *GloMTH;

lib/MySQL_Monitor.cpp

@@ -50,15 +50,6 @@ static MySQL_Monitor *GloMyMon;
 	} while (rc!=SQLITE_DONE);\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-        do {\
-                rc=(*proxy_sqlite3_step)(_stmt);\
-                if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-                        usleep(100);\
-                }\
-        } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
-
 using std::string;
 using std::set;
 using std::vector;

lib/ProxySQL_Admin.cpp

@@ -235,14 +235,6 @@ int sqlite3_json_init(
   } while (rc!=SQLITE_DONE);\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-        do {\
-                rc=(*proxy_sqlite3_step)(_stmt);\
-                if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-                        usleep(100);\
-                }\
-        } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
 
 typedef struct _arg_mysql_adm_t {
 	struct sockaddr * addr;
@@ -671,7 +663,8 @@ static char * admin_variables_names[]= {
 	(char *)"web_verbosity",
 	(char *)"prometheus_memory_metrics_interval",
 #ifdef DEBUG
-  (char *)"debug",
+	(char *)"debug",
+	(char *)"debug_output",
 #endif /* DEBUG */
   NULL
 };
@@ -5689,6 +5682,7 @@ ProxySQL_Admin::ProxySQL_Admin() :
 	serial_exposer(std::function<void()> { update_modules_metrics })
 {
 #ifdef DEBUG
+		debugdb_disk = NULL;
 		if (glovars.has_debug==false) {
 #else
 		if (glovars.has_debug==true) {
@@ -5803,6 +5797,7 @@ ProxySQL_Admin::ProxySQL_Admin() :
 	variables.p_memory_metrics_interval = 61;
 #ifdef DEBUG
 	variables.debug=GloVars.global.gdbg;
+	debug_output = 1;
 #endif /* DEBUG */
 
 	last_p_memory_metrics_ts = 0;
@@ -6091,6 +6086,22 @@ bool ProxySQL_Admin::init() {
 #ifdef DEBUG
 	admindb->execute("ATTACH DATABASE 'file:mem_mydb?mode=memory&cache=shared' AS myhgm");
 	admindb->execute("ATTACH DATABASE 'file:mem_monitor_internal_db?mode=memory&cache=shared' AS 'monitor_internal'");
+	{
+		string debugdb_disk_path = string(GloVars.datadir) + "/" + "proxysql_debug.db";
+		debugdb_disk = new SQLite3DB();
+		debugdb_disk->open((char *)debugdb_disk_path.c_str(), SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE | SQLITE_OPEN_FULLMUTEX);
+		debugdb_disk->execute("CREATE TABLE IF NOT EXISTS debug_log (id INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL , time INT NOT NULL , lapse INT NOT NULL , thread INT NOT NULL , file VARCHAR NOT NULL , line INT NOT NULL , funct VARCHAR NOT NULL , modnum INT NOT NULL , modname VARCHAR NOT NULL , verbosity INT NOT NULL , message VARCHAR , note VARCHAR , backtrace VARCHAR)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_time ON debug_log (time)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_thread ON debug_log (thread)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_file ON debug_log (file)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_file_line ON debug_log (file,line)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_funct ON debug_log (funct)");
+		debugdb_disk->execute("CREATE INDEX IF NOT EXISTS idx_debug_log_modnum ON debug_log (modnum)");
+		debugdb_disk->execute("PRAGMA synchronous=0");
+		string cmd = "ATTACH DATABASE '" + debugdb_disk_path + "' AS debugdb_disk";
+		admindb->execute(cmd.c_str());
+		proxysql_set_status_admin_debugdb_disk(true);
+	}
 #endif /* DEBUG */
 
 #ifdef DEBUG
@@ -6230,6 +6241,10 @@ void ProxySQL_Admin::admin_shutdown() {
 	delete configdb;
 	delete monitordb;
 	delete statsdb_disk;
+#ifdef DEBUG
+	proxysql_set_status_admin_debugdb_disk(false);
+	delete debugdb_disk;
+#endif
 	(*proxy_sqlite3_shutdown)();
 	if (main_poll_fds) {
 		for (i=0;i<main_poll_nfds;i++) {
@@ -7825,6 +7840,10 @@ char * ProxySQL_Admin::get_variable(char *name) {
 	if (!strcasecmp(name,"debug")) {
 		return strdup((variables.debug ? "true" : "false"));
 	}
+	if (!strcasecmp(name,"debug_output")) {
+		sprintf(intbuf, "%d", debug_output);
+		return strdup(intbuf);
+	}
 #endif /* DEBUG */
 	return NULL;
 }
@@ -8444,6 +8463,16 @@ bool ProxySQL_Admin::set_variable(char *name, char *value) {  // this is the pub
 		}
 		return false;
 	}
+	if (!strcasecmp(name,"debug_output")) {
+		const auto fval = atoi(value);
+		if (fval > 0 && fval <= 3) {
+			debug_output = fval;
+			return true;
+		} else {
+			return false;
+		}
+		return false;
+	}
 #endif /* DEBUG */
 	return false;
 }

lib/ProxySQL_Cluster.cpp

@@ -33,15 +33,6 @@
   } while (rc!=SQLITE_DONE);\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-        do {\
-                rc=(*proxy_sqlite3_step)(_stmt);\
-                if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-                        usleep(100);\
-                }\
-        } while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
-
 using std::vector;
 using std::pair;
 using std::string;

lib/ProxySQL_Statistics.cpp

@@ -32,16 +32,6 @@ extern MySQL_Threads_Handler *GloMTH;
 	} while (rc!=SQLITE_DONE );\
 } while (0)
 
-#define SAFE_SQLITE3_STEP2(_stmt) do {\
-	do {\
-		rc=(*proxy_sqlite3_step)(_stmt);\
-		if (rc==SQLITE_LOCKED || rc==SQLITE_BUSY) {\
-			usleep(100);\
-		}\
-	} while (rc==SQLITE_LOCKED || rc==SQLITE_BUSY);\
-} while (0)
-
-
 ProxySQL_Statistics::ProxySQL_Statistics() {
 	statsdb_mem = new SQLite3DB();
 	statsdb_mem->open((char *)"file:statsdb_mem?mode=memory&cache=shared", SQLITE_OPEN_READWRITE | SQLITE_OPEN_CREATE | SQLITE_OPEN_FULLMUTEX);

lib/debug.cpp

@@ -1,6 +1,8 @@
 #include "proxysql.h"
 #include "proxysql_atomic.h"
 
+#include "proxysql_admin.h"
+
 #include "sqlite3db.h"
 #include "prometheus_helpers.h"
 
@@ -24,16 +26,20 @@ using std::unordered_map;
 #endif // CLOCK_MONOTONIC
 
 #ifdef DEBUG
-static unsigned long long pretime=0;
+__thread unsigned long long pretime=0;
 static pthread_mutex_t debug_mutex;
+static bool debugdb_disk_init = false;
+sqlite3_stmt *statement1=NULL;
+extern ProxySQL_Admin *GloAdmin;
 #endif /* DEBUG */
 
+/*
 static inline unsigned long long debug_monotonic_time() {
 	struct timespec ts;
 	clock_gettime(CLOCK_MONOTONIC, &ts);
 	return (((unsigned long long) ts.tv_sec) * 1000000) + (ts.tv_nsec / 1000);
 }
-
+*/
 
 #define DEBUG_MSG_MAXSIZE	1024
 
@@ -111,26 +117,43 @@ void proxy_debug_load_filters(std::set<std::string>& f) {
 
 void proxy_debug_func(enum debug_module module, int verbosity, int thr, const char *__file, int __line, const char *__func, const char *fmt, ...) {
 	assert(module<PROXY_DEBUG_UNKNOWN);
+	if (pretime == 0) { // never initialized
+		pretime=realtime_time();
+	}
 	if (GloVars.global.gdbg_lvl[module].verbosity < verbosity)
 		return;
 	if (filter_debug_entry(__file, __line, __func)) // check if the entry must be filtered
 		return;
+	char origdebugbuff[DEBUG_MSG_MAXSIZE];
 	char debugbuff[DEBUG_MSG_MAXSIZE];
 	char longdebugbuff[DEBUG_MSG_MAXSIZE*8];
+	char longdebugbuff2[DEBUG_MSG_MAXSIZE*8];
 	longdebugbuff[0]=0;
-	if (GloVars.global.foreground) {
+	longdebugbuff2[0]=0;
+	unsigned long long curtime=realtime_time();
+	pthread_mutex_lock(&debug_mutex);
+	bool write_to_disk = false;
+	if (debugdb_disk_init == true && (GloAdmin->debug_output == 2 || GloAdmin->debug_output == 3)) {
+		write_to_disk = true;
+	}
+	if (
+		GloVars.global.foreground
+		||
+		write_to_disk == true
+	) {
 		va_list ap;
 		va_start(ap, fmt);
-		vsnprintf(debugbuff, DEBUG_MSG_MAXSIZE,fmt,ap);
+		vsnprintf(origdebugbuff, DEBUG_MSG_MAXSIZE,fmt,ap);
 		va_end(ap);
-		pthread_mutex_lock(&debug_mutex);
-		unsigned long long curtime=debug_monotonic_time();
 		//fprintf(stderr, "%d:%s:%d:%s(): MOD#%d LVL#%d : %s" , thr, __file, __line, __func, module, verbosity, debugbuff);
-		sprintf(longdebugbuff, "%llu(%llu): %d:%s:%d:%s(): MOD#%d#%s LVL#%d : %s" , curtime, curtime-pretime, thr, __file, __line, __func, module, GloVars.global.gdbg_lvl[module].name, verbosity, debugbuff);
-		pretime=curtime;
+		sprintf(longdebugbuff, "%llu(%llu): %d:%s:%d:%s(): MOD#%d#%s LVL#%d : %s" , curtime, curtime-pretime, thr, __file, __line, __func, module, GloVars.global.gdbg_lvl[module].name, verbosity, origdebugbuff);
 	}
 #ifdef __GLIBC__
-	if (GloVars.global.gdbg_lvl[module].verbosity>=10) {
+	if (
+		(GloVars.global.gdbg_lvl[module].verbosity>=10)
+		||
+		write_to_disk == true
+	) {
 		void *arr[20];
 		char **strings;
 		int s;
@@ -150,18 +173,66 @@ void proxy_debug_func(enum debug_module module, int verbosity, int thr, const ch
 			realname=abi::__cxa_demangle(debugbuff, 0, 0, &status);
 			if (realname) {
 				sprintf(debugbuff," ---- %s : %s\n", strings[i], realname);
-				strcat(longdebugbuff,debugbuff);
+				strcat(longdebugbuff2,debugbuff);
 			}
 		}
 		//printf("\n");
-		strcat(longdebugbuff,"\n");
+		//strcat(longdebugbuff2,"\n");
 		free(strings);
 //	} else {
 //		fprintf(stderr, "%s", longdebugbuff);
 	}
 #endif
-	if (strlen(longdebugbuff)) fprintf(stderr, "%s", longdebugbuff);
+	if (debugdb_disk_init == false) {
+		// default behavior
+		if (longdebugbuff[0] != 0) {
+			fprintf(stderr, "%s", longdebugbuff);
+		}
+		if (longdebugbuff2[0] != 0) {
+			if (GloVars.global.gdbg_lvl[module].verbosity>=10) {
+				fprintf(stderr, "%s\n", longdebugbuff2);
+			}
+		}
+	} else {
+		assert (GloAdmin != NULL);
+		SQLite3DB *db = GloAdmin->debugdb_disk;
+		assert(db != NULL);
+		int rc = 0;
+		if (statement1==NULL) {
+			const char *a = "INSERT INTO debug_log (id, time, lapse, thread, file, line, funct, modnum, modname, verbosity, message, note, backtrace) VALUES (NULL, ?1, ?2, ?3, ?4, ?5, ?6, ?7, ?8, ?9, ?10, NULL, ?11)";
+			rc=db->prepare_v2(a, &statement1);
+			ASSERT_SQLITE_OK(rc, db);
+		}
+		if (GloAdmin->debug_output == 1 || GloAdmin->debug_output == 3) {
+			// to stderr
+			if (longdebugbuff[0] != 0) {
+				fprintf(stderr, "%s", longdebugbuff);
+			}
+			if (longdebugbuff2[0] != 0) {
+				fprintf(stderr, "%s", longdebugbuff2);
+			}
+		}
+		if (write_to_disk == true) {
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 1, curtime); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 2, curtime-pretime); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 3, thr); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_text)(statement1,  4, __file, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 5, __line); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_text)(statement1,  6, __func, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 7, module); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_text)(statement1,  8, GloVars.global.gdbg_lvl[module].name, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_int64)(statement1, 9, verbosity); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_text)(statement1, 10, origdebugbuff, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_bind_text)(statement1, 11, longdebugbuff2, -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db);
+			SAFE_SQLITE3_STEP2(statement1);
+			rc=(*proxy_sqlite3_clear_bindings)(statement1); ASSERT_SQLITE_OK(rc, db);
+			rc=(*proxy_sqlite3_reset)(statement1); ASSERT_SQLITE_OK(rc, db);
+			//(*proxy_sqlite3_finalize)(statement1);
+		}
+	}
 	pthread_mutex_unlock(&debug_mutex);
+	if (curtime != 0)
+		pretime=curtime;
 };
 #endif
 
@@ -376,7 +447,6 @@ void print_backtrace(void)
 void init_debug_struct() {	
 	int i;
 	pthread_mutex_init(&debug_mutex,NULL);
-	pretime=debug_monotonic_time();
 	GloVars.global.gdbg_lvl= (debug_level *) malloc(PROXY_DEBUG_UNKNOWN*sizeof(debug_level));
 	for (i=0;i<PROXY_DEBUG_UNKNOWN;i++) {
 		GloVars.global.gdbg_lvl[i].module=(enum debug_module)i;
@@ -418,4 +488,9 @@ void init_debug_struct_from_cmdline() {
 		GloVars.global.gdbg_lvl[i].verbosity=GloVars.__cmd_proxysql_gdbg;
 	}
 }
+
+
+void proxysql_set_status_admin_debugdb_disk(bool status) {
+	debugdb_disk_init = status;
+}
 #endif /* DEBUG */