#include "proxysql.h" #include "proxysql_atomic.h" #include "sqlite3db.h" #include "prometheus_helpers.h" #include "gen_utils.h" #include #include #include #include #include using std::string; using std::unordered_map; #ifdef DEBUG __thread unsigned long long pretime=0; static pthread_mutex_t debug_mutex; static pthread_rwlock_t filters_rwlock; static SQLite3DB * debugdb_disk = NULL; sqlite3_stmt *statement1=NULL; static unsigned int debug_output = 1; #define DEBUG_MSG_MAXSIZE 1024 struct DebugLogEntry { unsigned long long time; unsigned long long lapse; int thr; std::string file; int line; std::string funct; int module; std::string modname; int verbosity; std::string message; std::string backtrace; }; static const size_t limitSize = 100; static std::vector log_buffer = {}; /** * @brief Synchronizes the log buffer to the SQLite database. * * This function writes the contents of the shared log buffer to the SQLite database * in a single transaction. It assumes that the log buffer is protected by a mutex * and that the prepared statement `statement1` has already been prepared. * This happens in proxy_debug_func() * * @param db A pointer to the SQLite3DB object. */ void sync_log_buffer_to_disk(SQLite3DB *db) { int rc; db->execute("BEGIN TRANSACTION"); for (const auto& entry : log_buffer) { rc=(*proxy_sqlite3_bind_int64)(statement1, 1, entry.time); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_int64)(statement1, 2, entry.lapse);ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_int64)(statement1, 3, entry.thr); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_text)(statement1, 4, entry.file.c_str(), -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_int64)(statement1, 5, entry.line); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_text)(statement1, 6, entry.funct.c_str(), -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_int64)(statement1, 7, entry.module); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_text)(statement1, 8, entry.modname.c_str(), -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_int64)(statement1, 9, entry.verbosity); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_text)(statement1, 10, entry.message.c_str(), -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); rc=(*proxy_sqlite3_bind_text)(statement1, 11, entry.backtrace.c_str(), -1, SQLITE_TRANSIENT); ASSERT_SQLITE_OK(rc, db); SAFE_SQLITE3_STEP2(statement1); rc=(*proxy_sqlite3_clear_bindings)(statement1); ASSERT_SQLITE_OK(rc, db); // Note: no assert() in proxy_debug_func() after sqlite3_reset() because it is possible that we are in shutdown rc=(*proxy_sqlite3_reset)(statement1); // ASSERT_SQLITE_OK(rc, db); } db->execute("COMMIT"); log_buffer.clear(); } /** * @brief Contains all filters related to debug. * @details The convention for key value is `filename:line:function`. This key structure also applies also * applies if the line is `0` or function is empty, the `filename` is always mandatory. * * IMPORTANT: This structure is a pointer to avoid race conditions during process termination, otherwise the * destruction of the object may be performed before working threads have exited. This structure will leak, * this is intentional, since we can't synchronize the exit of the working threads with its destruction. */ std::set* debug_filters = nullptr; static bool filter_debug_entry(const char *__file, int __line, const char *__func) { pthread_rwlock_rdlock(&filters_rwlock); bool to_filter = false; if (debug_filters && debug_filters->size()) { // if the set is empty we aren't performing any filter, so we won't search std::string key(__file); key += ":" + std::to_string(__line); key += ":"; key += __func; // we start with a full search if (debug_filters->find(key) != debug_filters->end()) { to_filter = true; } else { // we now search filename + line key = __file; key += ":" + std::to_string(__line); // remember to add the final ":" key += ":"; if (debug_filters->find(key) != debug_filters->end()) { to_filter = true; } else { // we now search filename + function key = __file; // no line = 0 key += ":0:"; key += __func; if (debug_filters->find(key) != debug_filters->end()) { to_filter = true; } else { // we now search filename only key = __file; // remember to add ":" even if no line key += ":0:"; if (debug_filters->find(key) != debug_filters->end()) { to_filter = true; } else { // if we reached here, we couldn't find any filter } } } } } pthread_rwlock_unlock(&filters_rwlock); return to_filter; } // we use this function to sent the filters to Admin // we hold here the lock on filters_rwlock void proxy_debug_get_filters(std::set& f) { pthread_rwlock_rdlock(&filters_rwlock); if (debug_filters) { f = *debug_filters; } pthread_rwlock_unlock(&filters_rwlock); } // we use this function to get the filters from Admin // we hold here the lock on filters_rwlock void proxy_debug_load_filters(std::set& f) { pthread_rwlock_wrlock(&filters_rwlock); if (debug_filters) { debug_filters->erase(debug_filters->begin(), debug_filters->end()); *debug_filters = f; } else { debug_filters = new std::set(f); } pthread_rwlock_unlock(&filters_rwlock); } // REMINDER: This function should always save/restore 'errno', otherwise it could influence error handling. void proxy_debug_func( enum debug_module module, int verbosity, int thr, const char *__file, int __line, const char *__func, const char *fmt, ... ) { int saved_errno = errno; assert(module=10) { void *arr[20]; char **strings; int s; s = backtrace(arr, 20); strings=backtrace_symbols(arr,s); if (strings == NULL) { perror("backtrace_symbols"); exit(EXIT_FAILURE); } for (int i=0; i=10) { fprintf(stderr, "%s\n", longdebugbuff2); } } } else { SQLite3DB *db = debugdb_disk; 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 (debug_output == 1 || 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) { // Create a DebugLogEntry DebugLogEntry entry; entry.time = curtime; entry.lapse = curtime - pretime; entry.thr = thr; entry.file = __file; entry.line = __line; entry.funct = __func; entry.module = module; entry.modname = GloVars.global.gdbg_lvl[module].name; entry.verbosity = verbosity; entry.message = origdebugbuff; entry.backtrace = longdebugbuff2; log_buffer.push_back(entry); // we now batch writes // note1: in case of crash, the database will have some missing entries, // but the entries can be read in `log_buffer` in the core dump // note2: also in case of shutdown , `log_buffer` will have entries that won't be saved. // if we really want *all* entries, we could just call sync_log_buffer_to_disk() on shutdown if ( (log_buffer.size() >= limitSize) || (entry.file == "ProxySQL_Admin.cpp" && entry.funct == "flush_logs") ) { sync_log_buffer_to_disk(db); } } } pthread_mutex_unlock(&debug_mutex); if (curtime != 0) pretime=curtime; errno = saved_errno; }; #endif using metric_name = std::string; using metric_help = std::string; using metric_tags = std::map; using debug_dyn_counter_tuple = std::tuple; using debug_dyn_counter_vector = std::vector; const std::tuple debug_metrics_map = std::make_tuple( debug_dyn_counter_vector { std::make_tuple ( p_debug_dyn_counter::proxysql_message_count, "proxysql_message_count_total", "Number of times a particular message has been logged by ProxySQL.", metric_tags {} ) } ); std::map p_proxysql_messages_map {}; std::array*, p_debug_dyn_counter::__size> p_debug_dyn_counter_array {}; std::mutex msg_stats_mutex {}; const int ProxySQL_MSG_STATS_FIELD_NUM = 7; class ProxySQL_messages_stats { public: const int32_t message_id = 0; const char* filename = nullptr; const int32_t line = 0; const char* func = nullptr; uint64_t count_star = 0; time_t first_seen = 0; time_t last_seen = 0; ProxySQL_messages_stats( const int32_t message_id_, const char* filename_, const int32_t line_, const char* func_, time_t first_seen_, time_t last_seen_, uint64_t count_star_ ) : message_id(message_id_), filename(filename_), line(line_), func(func_), count_star(count_star_), first_seen(first_seen_), last_seen(last_seen_) { assert(message_id_); assert(filename_); assert(line_); assert(func_); } char** get_row() const { char buf[128]; char** pta = static_cast(malloc(sizeof(char *)*ProxySQL_MSG_STATS_FIELD_NUM)); sprintf(buf,"%d",message_id); pta[0]=strdup(buf); pta[1]=strdup(filename); sprintf(buf,"%d",line); pta[2]=strdup(buf); pta[3]=strdup(func); sprintf(buf,"%lu",count_star); pta[4]=strdup(buf); sprintf(buf,"%ld", first_seen); pta[5]=strdup(buf); sprintf(buf,"%ld", last_seen); pta[6]=strdup(buf); return pta; } void add_time(uint64_t n) { count_star++; if (first_seen == 0) { first_seen = n; } last_seen=n; } void free_row(char **pta) const { for (int i=0; i < ProxySQL_MSG_STATS_FIELD_NUM; i++) { assert(pta[i]); free(pta[i]); } free(pta); } }; unordered_map umap_msg_stats {}; /** * @brief Handles ProxySQL message logging. * @details The extra variadic arguments are expected to be received in the following order: * ``` * proxy_error_func(msgid, fmt_message, time_buf, __FILE__, __LINE__, __func__ , ## __VA_ARGS__); * ``` * Any other use of the function is UNSAFE. And will result in unespecified behavior. * @param msgid The message id of the message to be logged, when non-zero, stats about the message are updated in * 'umap_msg_stats'. * @param fmt The formatted string to be pass to 'vfprintf'. * @param ... The variadic list of arguments to be passed to 'vfprintf'. */ void proxy_error_func(int msgid, const char *fmt, ...) { va_list ap; va_start(ap, fmt); if (msgid != 0) { va_list stats_params; va_copy(stats_params, ap); // ignore 'time' buffer argument va_arg(stats_params, const char*); // collect arguments '__FILE__', '__LINE__' and '__func__' const char* file = va_arg(stats_params, const char*); const int32_t line = va_arg(stats_params, int32_t); const char* func = va_arg(stats_params, const char*); std::lock_guard msg_stats_guard { msg_stats_mutex }; string msg_stats_id { string { file } + ":" + std::to_string(line) + ":" + string { func } }; auto msg_stats = umap_msg_stats.find(msg_stats_id); time_t tn = time(NULL); const std::map m_labels { { "message_id", std::to_string(msgid) }, { "filename", file }, { "line", std::to_string(line) }, { "func", func } }; prometheus::Family* m_family = p_debug_dyn_counter_array[p_debug_dyn_counter::proxysql_message_count]; p_inc_map_counter(p_proxysql_messages_map, m_family, msg_stats_id, m_labels); if (msg_stats != umap_msg_stats.end()) { msg_stats->second.add_time(tn); } else { umap_msg_stats.insert( { msg_stats_id, ProxySQL_messages_stats(msgid, file, line, func, tn, tn, 1) } ); } } vfprintf(stderr, fmt, ap); va_end(ap); }; SQLite3_result* proxysql_get_message_stats(bool reset) { std::lock_guard msg_stats_guard { msg_stats_mutex }; SQLite3_result* result = new SQLite3_result(ProxySQL_MSG_STATS_FIELD_NUM); result->add_column_definition(SQLITE_TEXT,"message_id"); result->add_column_definition(SQLITE_TEXT,"filename"); result->add_column_definition(SQLITE_TEXT,"line"); result->add_column_definition(SQLITE_TEXT,"func"); result->add_column_definition(SQLITE_TEXT,"count_star"); result->add_column_definition(SQLITE_TEXT,"first_seen"); result->add_column_definition(SQLITE_TEXT,"last_seen"); for (const auto& msg_stats : umap_msg_stats) { char** pta = msg_stats.second.get_row(); result->add_row(pta); msg_stats.second.free_row(pta); } if (reset) { umap_msg_stats.clear(); } return result; } void proxysql_init_debug_prometheus_metrics() { init_prometheus_dyn_counter_array(debug_metrics_map, p_debug_dyn_counter_array); } static void full_write(int fd, const char *buf, size_t len) { while (len > 0) { ssize_t ret = write(fd, buf, len); if ((ret == -1) && (errno != EINTR)) break; buf += (size_t) ret; len -= (size_t) ret; } } void print_backtrace(void) { static const char start[] = "BACKTRACE ------------\n"; static const char end[] = "----------------------\n"; void *bt[1024]; int bt_size; char **bt_syms; int i; bt_size = backtrace(bt, 1024); bt_syms = backtrace_symbols(bt, bt_size); full_write(STDERR_FILENO, start, strlen(start)); for (i = 1; i < bt_size; i++) { size_t len = strlen(bt_syms[i]); full_write(STDERR_FILENO, bt_syms[i], len); full_write(STDERR_FILENO, "\n", 1); } full_write(STDERR_FILENO, end, strlen(end)); free(bt_syms); } #ifdef DEBUG void init_debug_struct() { int i; pthread_mutex_init(&debug_mutex,NULL); pthread_rwlock_init(&filters_rwlock, NULL); GloVars.global.gdbg_lvl= (debug_level *) malloc(PROXY_DEBUG_UNKNOWN*sizeof(debug_level)); for (i=0;i