From 1a6f2331597ac1d8164bcc96de771a27ee94e6ff Mon Sep 17 00:00:00 2001 From: Alexey Romanov Date: Sun, 12 Oct 2014 20:32:56 +0400 Subject: [PATCH] Improved logging --- c_src/sqlite3_drv.c | 123 ++++++++++++++++++++++++-------------------- 1 file changed, 67 insertions(+), 56 deletions(-) diff --git a/c_src/sqlite3_drv.c b/c_src/sqlite3_drv.c index baed6bf..9bf9c12 100644 --- a/c_src/sqlite3_drv.c +++ b/c_src/sqlite3_drv.c @@ -13,8 +13,16 @@ static int DEBUG = 1; static int DEBUG = 0; #endif -#define TRACE(x) do { if (DEBUG) debug_printf x; } while (0) -#define LOG_ERROR(x) debug_printf x; +#define LOG_DEBUG(M, ...) do { \ + if (DEBUG && drv->log) \ + fprintf(drv->log, "[DEBUG] (%s:%d) " M "\n", __FILE__, __LINE__, __VA_ARGS__); \ + } while (0) +#define LOG_ERROR(M, ...) do { \ + if (drv->log) \ + fprintf(drv->log, "[ERROR] (%s:%d) " M "\n", __FILE__, __LINE__, __VA_ARGS__); \ + if (drv->log != stderr) \ + fprintf(stderr, "[ERROR] (%s:%d) " M "\n", __FILE__, __LINE__, __VA_ARGS__); \ + } while(0) #define EXTEND_DATASET(n, term_count, term_allocated, dataset) \ term_count += n; \ @@ -91,36 +99,37 @@ static void driver_free_binary_fun(void *ptr) { // Driver Start static ErlDrvData start(ErlDrvPort port, char* cmd) { - sqlite3_drv_t* retval = (sqlite3_drv_t*) driver_alloc(sizeof(sqlite3_drv_t)); + sqlite3_drv_t* drv = (sqlite3_drv_t*) driver_alloc(sizeof(sqlite3_drv_t)); struct sqlite3 *db = NULL; int status = 0; char *db_name = strstr(cmd, " "); #ifdef DEBUG + errno_t file_open_errno; #ifdef _MSC_VER const char *log_file = _tempnam(NULL, "erlang-sqlite3-log-"); - retval->log = - fopen_s(log_file, "a"); + file_open_errno = fopen_s(drv->log, log_file, "a+"); #else const char *log_file = tempnam(NULL, "erlang-sqlite3-log-"); - retval->log = + drv->log = fopen(log_file, "ax"); + file_open_errno = errno; #endif - if (!retval->log) { - fprintf(stderr, "Error creating log file: %s\n", log_file); + if (file_open_errno) { + fprintf(stderr, "Error creating log file %s; reason %s\n", log_file, strerror(file_open_errno)); // if we can't open the log file we shouldn't hide the data or the problem - retval->log = stderr; // noisy + drv->log = stderr; // noisy } free(log_file); #else - retval->log = NULL; + drv->log = NULL; #endif #if defined(_MSC_VER) #pragma warning(disable: 4306) #endif if (!db_name) { - driver_free(retval); + driver_free(drv); return ERL_DRV_ERROR_BADARG; } else { ++db_name; // move to first character after ' ' @@ -130,41 +139,40 @@ static ErlDrvData start(ErlDrvPort port, char* cmd) { status = sqlite3_open(db_name, &db); if (status != SQLITE_OK) { - TRACE((retval->log, "ERROR: Unable to open file: %s because %s\n\n", - db_name, sqlite3_errmsg(db))); + LOG_ERROR("Unable to open file: %s because %s\n\n", db_name, sqlite3_errmsg(db)); // We don't do this because there's no way to pass the error to Erlang // sqlite3_close(db); - // driver_free(retval); + // driver_free(drv); // return ERL_DRV_ERROR_GENERAL; } else { - TRACE((retval->log, "Opened file %s\n", db_name)); + LOG_DEBUG("Opened file %s\n", db_name); } #if defined(_MSC_VER) #pragma warning(default: 4306) #endif // Set the state for the driver - retval->port = port; - retval->db = db; - retval->key = 42; + drv->port = port; + drv->db = db; + drv->key = 42; // FIXME Any way to get canonical path to the DB? // We need to ensure equal keys for different paths to the same file - retval->async_handle = 0; - retval->prepared_stmts = NULL; - retval->prepared_count = 0; - retval->prepared_alloc = 0; + drv->async_handle = 0; + drv->prepared_stmts = NULL; + drv->prepared_count = 0; + drv->prepared_alloc = 0; - retval->atom_blob = driver_mk_atom("blob"); - retval->atom_error = driver_mk_atom("error"); - retval->atom_columns = driver_mk_atom("columns"); - retval->atom_rows = driver_mk_atom("rows"); - retval->atom_null = driver_mk_atom("null"); - retval->atom_rowid = driver_mk_atom("rowid"); - retval->atom_ok = driver_mk_atom("ok"); - retval->atom_done = driver_mk_atom("done"); - retval->atom_unknown_cmd = driver_mk_atom("unknown_command"); + drv->atom_blob = driver_mk_atom("blob"); + drv->atom_error = driver_mk_atom("error"); + drv->atom_columns = driver_mk_atom("columns"); + drv->atom_rows = driver_mk_atom("rows"); + drv->atom_null = driver_mk_atom("null"); + drv->atom_rowid = driver_mk_atom("rowid"); + drv->atom_ok = driver_mk_atom("ok"); + drv->atom_done = driver_mk_atom("done"); + drv->atom_unknown_cmd = driver_mk_atom("unknown_command"); - return (ErlDrvData) retval; + return (ErlDrvData) drv; } // Driver Stop @@ -345,7 +353,7 @@ static inline int sql_exec_statement( sqlite3_drv_t *drv, sqlite3_stmt *statement) { async_sqlite3_command *async_command = make_async_command_statement(drv, statement, 1); - TRACE((drv->log, "Driver async: %d %p\n", SQLITE_VERSION_NUMBER, async_command->statement)); + LOG_DEBUG("Driver async: %d %p\n", SQLITE_VERSION_NUMBER, async_command->statement); if (sqlite3_threadsafe()) { drv->async_handle = driver_async(drv->port, &drv->key, sql_exec_async, @@ -362,7 +370,7 @@ static int sql_exec(sqlite3_drv_t *drv, char *command, int command_size) { const char *rest; sqlite3_stmt *statement; - TRACE((drv->log, "Preexec: %.*s\n", command_size, command)); + LOG_DEBUG("Preexec: %.*s\n", command_size, command); result = sqlite3_prepare_v2(drv->db, command, command_size, &statement, &rest); if (result != SQLITE_OK) { return output_db_error(drv); @@ -375,7 +383,7 @@ static int sql_exec(sqlite3_drv_t *drv, char *command, int command_size) { static int sql_exec_script(sqlite3_drv_t *drv, char *command, int command_size) { async_sqlite3_command *async_command = make_async_command_script(drv, command, command_size); - TRACE((drv->log, "Driver async: %d %p\n", SQLITE_VERSION_NUMBER, async_command->statement)); + LOG_DEBUG("Driver async: %d %p\n", SQLITE_VERSION_NUMBER, async_command->statement); if (sqlite3_threadsafe()) { drv->async_handle = driver_async(drv->port, &drv->key, sql_exec_async, @@ -577,7 +585,7 @@ static void get_columns( char *column_name_copy = driver_alloc(sizeof(char) * (column_name_length + 1)); strcpy(column_name_copy, column_name); *p_ptrs = add_to_ptr_list(*p_ptrs, column_name_copy); - TRACE((drv->log, "Column: %s\n", column_name_copy)); + LOG_DEBUG("Column: %s\n", column_name_copy); (*dataset_p)[base + (i * 3)] = ERL_DRV_STRING; (*dataset_p)[base + (i * 3) + 1] = (ErlDrvTermData) column_name_copy; @@ -597,7 +605,7 @@ static int sql_bind_and_exec(sqlite3_drv_t *drv, char *buffer, int buffer_size) long bin_size; char *command; - TRACE((drv->log, "Preexec: %.*s\n", buffer_size, buffer)); + LOG_DEBUG("Preexec: %.*s\n", buffer_size, buffer); ei_decode_version(buffer, &index, NULL); result = ei_decode_tuple_header(buffer, &index, &size); @@ -682,11 +690,11 @@ static int sql_exec_one_statement( ERL_DRV_TUPLE, (ErlDrvTermData) 2, ERL_DRV_ATOM, drv->atom_rows); } - TRACE((drv->log, "Exec: %s\n", sqlite3_sql(statement))); + LOG_DEBUG("Exec: %s\n", sqlite3_sql(statement)); while ((next_row = sqlite3_step(statement)) == SQLITE_ROW) { for (i = 0; i < column_count; i++) { - TRACE((drv->log, "Column %d type: %d\n", i, sqlite3_column_type(statement, i))); + LOG_DEBUG("Column %d type: %d\n", i, sqlite3_column_type(statement, i)); switch (sqlite3_column_type(statement, i)) { case SQLITE_INTEGER: { ErlDrvSInt64 *int64_ptr = driver_alloc(sizeof(ErlDrvSInt64)); @@ -788,7 +796,8 @@ static int sql_exec_one_statement( append_to_dataset(2, *dataset_p, *term_count_p, ERL_DRV_ATOM, drv->atom_ok); } - TRACE((drv->log, "Total term count: %p %d, rows count: %dx%d\n", statement, *term_count_p, column_count, row_count)); + LOG_DEBUG("Total term count: %p %d, rows count: %dx%d\n", + statement, *term_count_p, column_count, row_count); async_command->finalize_statement_on_free = 1; return has_error; @@ -881,7 +890,7 @@ static void sql_step_async(void *_async_command) { append_to_dataset(2, dataset, term_count, ERL_DRV_PORT, driver_mk_port(drv->port)); for (i = 0; i < column_count; i++) { - TRACE((drv->log, "Column %d type: %d\n", i, sqlite3_column_type(statement, i))); + LOG_DEBUG("Column %d type: %d\n", i, sqlite3_column_type(statement, i)); switch (sqlite3_column_type(statement, i)) { case SQLITE_INTEGER: { ErlDrvSInt64 *int64_ptr = driver_alloc(sizeof(ErlDrvSInt64)); @@ -973,7 +982,7 @@ POPULATE_COMMAND: async_command->ptrs = ptrs; async_command->binaries = binaries; async_command->row_count = 1; - TRACE((drv->log, "Total term count: %p %d, columns count: %d\n", statement, term_count, column_count)); + LOG_DEBUG("Total term count: %p %d, columns count: %d\n", statement, term_count, column_count); } static void ready_async(ErlDrvData drv_data, ErlDrvThreadData thread_data) { @@ -986,13 +995,13 @@ static void ready_async(ErlDrvData drv_data, ErlDrvThreadData thread_data) { async_command->term_count); (void) res; // suppress unused warning if (res != 1) { - TRACE((drv->log, "driver_output_term returned %d\n", res)); + LOG_DEBUG("driver_output_term returned %d\n", res); #ifdef DEBUG fprint_dataset(drv->log, async_command->dataset, async_command->term_count); #endif } - TRACE((drv->log, "Total term count: %p %d, rows count: %d (%d)\n", async_command->statement, async_command->term_count, async_command->row_count, res)); + LOG_DEBUG("Total term count: %p %d, rows count: %d (%d)\n", async_command->statement, async_command->term_count, async_command->row_count, res); sql_free_async(async_command); } @@ -1002,7 +1011,7 @@ static int prepare(sqlite3_drv_t *drv, char *command, int command_size) { sqlite3_stmt *statement; ErlDrvTermData spec[6]; - TRACE((drv->log, "Preparing statement: %.*s\n", command_size, command)); + LOG_DEBUG("Preparing statement: %.*s\n", command_size, command); result = sqlite3_prepare_v2(drv->db, command, command_size, &statement, &rest); if (result != SQLITE_OK) { return output_db_error(drv); @@ -1036,7 +1045,7 @@ static int prepared_bind(sqlite3_drv_t *drv, char *buffer, int buffer_size) { int index = 0, type, size; sqlite3_stmt *statement; - TRACE((drv->log, "Finalizing prepared statement: %.*s\n", buffer_size, buffer)); + LOG_DEBUG("Finalizing prepared statement: %.*s\n", buffer_size, buffer); ei_decode_version(buffer, &index, NULL); ei_decode_tuple_header(buffer, &index, &size); @@ -1072,13 +1081,13 @@ static int prepared_columns(sqlite3_drv_t *drv, char *buffer, int buffer_size) { prepared_index = (unsigned int) long_prepared_index; if (prepared_index >= drv->prepared_count) { - TRACE((drv->log, "Tried to get columns for prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1)); + LOG_DEBUG("Tried to get columns for prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1); return output_error(drv, SQLITE_MISUSE, "Trying to reset non-existent prepared statement"); } - TRACE((drv->log, "Getting the columns for prepared statement #%d\n", prepared_index)); + LOG_DEBUG("Getting the columns for prepared statement #%d\n", prepared_index); statement = drv->prepared_stmts[prepared_index]; @@ -1111,12 +1120,12 @@ static int prepared_step(sqlite3_drv_t *drv, char *buffer, int buffer_size) { prepared_index = (unsigned int) long_prepared_index; if (prepared_index >= drv->prepared_count) { - TRACE((drv->log, "Tried to make a step in prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1)); + LOG_DEBUG("Tried to make a step in prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1); return output_error(drv, SQLITE_MISUSE, "Trying to evaluate non-existent prepared statement"); } - TRACE((drv->log, "Making a step in prepared statement #%d\n", prepared_index)); + LOG_DEBUG("Making a step in prepared statement #%d\n", prepared_index); statement = drv->prepared_stmts[prepared_index]; async_command = make_async_command_statement(drv, statement, 0); @@ -1142,12 +1151,13 @@ static int prepared_reset(sqlite3_drv_t *drv, char *buffer, int buffer_size) { prepared_index = (unsigned int) long_prepared_index; if (prepared_index >= drv->prepared_count) { - TRACE((drv->log, "Tried to reset prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1)); + LOG_DEBUG("Tried to reset prepared statement #%d, but maximum possible is #%d\n", + prepared_index, drv->prepared_count - 1); return output_error(drv, SQLITE_MISUSE, "Trying to reset non-existent prepared statement"); } - TRACE((drv->log, "Resetting prepared statement #%d\n", prepared_index)); + LOG_DEBUG("Resetting prepared statement #%d\n", prepared_index); // don't bother about error code, any errors should already be shown by step statement = drv->prepared_stmts[prepared_index]; sqlite3_reset(statement); @@ -1165,12 +1175,12 @@ static int prepared_clear_bindings(sqlite3_drv_t *drv, char *buffer, int buffer_ prepared_index = (unsigned int) long_prepared_index; if (prepared_index >= drv->prepared_count) { - TRACE((drv->log, "Tried to clear bindings of prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1)); + LOG_DEBUG("Tried to clear bindings of prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1); return output_error(drv, SQLITE_MISUSE, "Trying to clear bindings of non-existent prepared statement"); } - TRACE((drv->log, "Clearing bindings of prepared statement #%d\n", prepared_index)); + LOG_DEBUG("Clearing bindings of prepared statement #%d\n", prepared_index); statement = drv->prepared_stmts[prepared_index]; sqlite3_clear_bindings(statement); return output_ok(drv); @@ -1186,12 +1196,13 @@ static int prepared_finalize(sqlite3_drv_t *drv, char *buffer, int buffer_size) prepared_index = (unsigned int) long_prepared_index; if (prepared_index >= drv->prepared_count) { - TRACE((drv->log, "Tried to finalize prepared statement #%d, but maximum possible is #%d\n", prepared_index, drv->prepared_count - 1)); + LOG_DEBUG("Tried to finalize prepared statement #%d, but maximum possible is #%d\n", + prepared_index, drv->prepared_count - 1); return output_error(drv, SQLITE_MISUSE, "Trying to finalize non-existent prepared statement"); } - TRACE((drv->log, "Finalizing prepared statement #%d\n", prepared_index)); + LOG_DEBUG("Finalizing prepared statement #%d\n", prepared_index); // finalize the statement and make sure it isn't accidentally executed again sqlite3_finalize(drv->prepared_stmts[prepared_index]); drv->prepared_stmts[prepared_index] = NULL;