From c46c8ac083b851d35137ae455eef0c8622dc07c7 Mon Sep 17 00:00:00 2001 From: Christopher Powell Date: Tue, 2 Apr 2002 20:19:30 +0000 Subject: This is a "pre" snapshot of 1.15. Numerous changes emphasizing how SQL errors are reported and handled. Any missed queries during SQL downtime are written out to a textfile. --- CHANGELOG | 17 ++++- INSTALL | 4 +- mod_log_sql.c | 195 +++++++++++++++++++++++++++++++++++++++++----------------- 3 files changed, 155 insertions(+), 61 deletions(-) diff --git a/CHANGELOG b/CHANGELOG index b0da0a2..34aed54 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -1,14 +1,27 @@ -$Id: CHANGELOG,v 1.6 2002/02/24 20:17:16 helios Exp $ +$Id: CHANGELOG,v 1.7 2002/04/02 20:19:30 helios Exp $ TODO: * Full commenting of the code. * Rethink documentation flow and rewrite? -* Message queueing during server downtime? +* Config directives for proxy clients +* Port connection portion to other DBMS? Genericize the module? CHANGES: +1.15: +* Vastly improved error reporting is a lot clearer about lost db + connections, etc. Some unreachable code has been corrected. +* The way that query-retries and openlink-retries are handled has + been tweaked and improved. +* Missed database entries are now preserved for later inclusion. This + file is not held open but is closed after each use, so it's safe + to delete while Apache is running. +* Now each child instantiates its MySQL link upon birth rather than + waiting for its first request. + + 1.14: * Improved the apxs instructions based on user feedback, including the mysql.sock define issue. diff --git a/INSTALL b/INSTALL index 0391e88..3226e89 100644 --- a/INSTALL +++ b/INSTALL @@ -1,4 +1,4 @@ -$Id: INSTALL,v 1.5 2002/02/24 20:17:16 helios Exp $ +$Id: INSTALL,v 1.6 2002/04/02 20:19:30 helios Exp $ Requirements @@ -126,7 +126,7 @@ Installation (as a static module compiled into httpd) 6a) Edit Configuration.apaci as follows... * Append the following string to the EXTRA_LIBS= line. (/usr/lib/mysql is where your libmysqlclient.a file lives): - -L/usr/lib/mysql -lmysqlclient -lm + -L/usr/lib/mysql -lmysqlclient -lm -lz * Add this line at the end of the file: Module mysql_log_module mod_log_mysql.o diff --git a/mod_log_sql.c b/mod_log_sql.c index 6780b74..61c1ed9 100644 --- a/mod_log_sql.c +++ b/mod_log_sql.c @@ -1,10 +1,13 @@ -/* $Id: mod_log_sql.c,v 1.5 2002/01/15 18:40:14 helios Exp $ */ +/* $Id: mod_log_sql.c,v 1.6 2002/04/02 20:19:30 helios Exp $ */ /* DEFINES */ #define MYSQL_ERROR(mysql) ((mysql)?(mysql_error(mysql)):"MySQL server has gone away") #define ERRLEVEL APLOG_ERR|APLOG_NOERRNO +#define WARNINGLEVEL APLOG_WARNING|APLOG_NOERRNO +#define NOTICELEVEL APLOG_NOTICE|APLOG_NOERRNO #define DEBUGLEVEL APLOG_INFO|APLOG_NOERRNO +#define PRESERVEFILE "/tmp/mysql-preserve" /* (MYSQLSOCKET, DEBUG and WANT_SSL_LOGGING are defined in the Makefile DEFS line.) */ @@ -463,15 +466,35 @@ const char *mysql_escape_log(const char *str, pool *p) } } -void open_logdb_link() +int open_logdb_link() { - if (mysql_log != NULL) { /* virtual database link shared with main server */ - return; + if (mysql_log != NULL) { + return 2; } - if (db_name) { /* open an SQL link */ + + if (db_name) { mysql_init(&sql_server); mysql_log = mysql_real_connect(&sql_server, db_host, db_user, db_pwd, db_name, 0, MYSQLSOCKET, 0); + + if (mysql_log != NULL) { + return 1; + } else { + return 0; + } } + return 0; +} + +void preserve_entry(request_rec *r, const char *query) +{ + FILE *fp; + + fp = fopen(PRESERVEFILE, "a"); + if (fp == NULL) + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: attempted append of local offline file but failed."); + else + fprintf(fp,"%s\n", query); + fclose(fp); } int safe_mysql_query(request_rec *r, const char *query) @@ -481,57 +504,61 @@ int safe_mysql_query(request_rec *r, const char *query) int ret; char *str; void (*handler) (int); + /* A failed mysql_query() may send a SIGPIPE, so we ignore that signal momentarily. */ handler = signal(SIGPIPE, SIG_IGN); - /* If there's no DB link, or if we run the query and it gacks, try to be graceful */ - if ( !mysql_log || - ( - (retval = mysql_query(mysql_log, query)) && - (mysql_errno(mysql_log) != 0) - ) - ) - - { /* We need to restart the server link */ - mysql_log = NULL; - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: connection lost, attempting reconnect"); + /* First attempt for the query */ + retval = mysql_query(mysql_log, query); + + /* If we ran the query and it returned an error, try to be graceful. + * We only reach this point if the module thinks it has a valid connection to the + * database (i.e. mysql_log is non-null). But that connection could go sour + * at any time, hence the check. */ + if ( retval != 0 ) + { + /* Something went wrong, so start by trying to restart the db link. */ + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: attempting reconnect because API said: %s", MYSQL_ERROR(mysql_log)); + mysql_log = NULL; open_logdb_link(); if (mysql_log == NULL) { /* still unable to link */ signal(SIGPIPE, handler); - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: reconnect failed"); + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: httpd child reconnect failed, unable to reach database. SQL logging stopped until an httpd child regains a db connection."); + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: log entries are being preserved in %s",PRESERVEFILE); return retval; - } + } else { + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: reconnect successful."); + } - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: reconnect successful"); - retval = mysql_query(mysql_log, query); + /* Attempt a single re-try... First sleep for a tiny amount of time. */ + delay.tv_sec = 0; + delay.tv_nsec = 500000000; /* max is 999999999 (nine nines) */ + ret = nanosleep(&delay, &remainder); + if (ret && errno != EINTR) + perror("nanosleep"); + + /* Now make our second attempt */ + retval = mysql_query(mysql_log,query); + + /* If this one also failed, log that and append to our local offline file */ + if ( retval != 0 ) + { + str = pstrcat(r->pool, "MySQL delayed insert attempt failed, API said: ", MYSQL_ERROR(mysql_log), NULL); + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,str); + + preserve_entry(r, query); + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: entry preserved in %s",PRESERVEFILE); + } else { + ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: insert successful after a delayed retry."); + } } /* Restore SIGPIPE to its original handler function */ signal(SIGPIPE, handler); - - if (retval) { - /* Attempt a single re-try... First sleep for a tiny amount of time. */ - delay.tv_sec = 0; - delay.tv_nsec = 500000000; /* max is 999999999 (nine nines) */ - ret = nanosleep(&delay, &remainder); - if (ret && errno != EINTR) - perror("nanosleep"); - - /* Now re-attempt */ - retval = mysql_query(mysql_log,query); - - if (retval) { - str = pstrcat(r->pool, "MySQL insert failed: ", query, NULL); - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,str); - str = pstrcat(r->pool, "MySQL failure reason: ", MYSQL_ERROR(mysql_log), NULL); - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,str); - } else { - ap_log_error(APLOG_MARK,ERRLEVEL,r->server,"MySQL: insert successful after a delayed retry."); - } - } + return retval; } @@ -657,7 +684,7 @@ void *log_mysql_make_state(pool *p, server_rec *s) /* Setup of the available httpd.conf configuration commands. - * command, function called, NULL, where available, how many arguments, verbose description + * Structure: command, function called, NULL, where available, how many arguments, verbose description */ command_rec log_mysql_cmds[] = { {"MySQLRefererLogTable", set_referer_log_mysql_table, NULL, RSRC_CONF, TAKE1, @@ -708,7 +735,8 @@ int log_mysql_transaction(request_rec *orig) request_rec *r; int retvalue = DECLINED; int referer_needed, agent_needed, transfer_needed; - + + /* Are there configuration directives for these SQL logs? For each found * config directive that is found, mark that type as 'needed'. */ @@ -719,13 +747,7 @@ int log_mysql_transaction(request_rec *orig) if (!referer_needed && !agent_needed && !transfer_needed) { return OK; } - - if (mysql_log == NULL) { /* mysql link not up, hopefully we can do something about it */ - open_logdb_link(); - if (mysql_log == NULL) { - return OK; - } - } + for (r = orig; r->next; r = r->next) { continue; @@ -750,7 +772,20 @@ int log_mysql_transaction(request_rec *orig) } } str = pstrcat(orig->pool, "insert into ", cls->referer_table_name, " (referer,url,time_stamp) values ('", mysql_escape_log(referer, orig->pool), "','", mysql_escape_log(r->uri, orig->pool), "',unix_timestamp(now()) )", NULL); - safe_mysql_query(orig, str); + + if (mysql_log == NULL) { /* child's mysql link not up, re-establish it */ + open_logdb_link(); + if (mysql_log == NULL) { + preserve_entry(r, str); + return OK; + } else { + ap_log_error(APLOG_MARK,NOTICELEVEL,orig->server,"MySQL: httpd child established database connection"); + safe_mysql_query(orig, str); + } + } else { + safe_mysql_query(orig, str); + } + } } @@ -763,7 +798,19 @@ int log_mysql_transaction(request_rec *orig) if (agent != NULL) { str = pstrcat(orig->pool, "insert into ", cls->agent_table_name, "(agent,time_stamp) values ('", mysql_escape_log(agent, orig->pool), "',unix_timestamp(now()) )", NULL); - safe_mysql_query(orig, str); + + if (mysql_log == NULL) { /* child's mysql link not up, re-establish it */ + open_logdb_link(); + if (mysql_log == NULL) { + preserve_entry(r, str); + return OK; + } else { + ap_log_error(APLOG_MARK,NOTICELEVEL,orig->server,"MySQL: httpd child established database connection"); + safe_mysql_query(orig, str); + } + } else { + safe_mysql_query(orig, str); + } } } @@ -771,7 +818,7 @@ int log_mysql_transaction(request_rec *orig) if (transfer_needed) { const char *thehost; - char *fields = "", *values = "", *query; + char *fields = "", *values = ""; const char *formatted_item; int i, j, length; @@ -840,8 +887,29 @@ int log_mysql_transaction(request_rec *orig) } /* Set up the actual INSERT statement and execute it. */ - query = pstrcat(orig->pool, "insert into ", cls->transfer_table_name, " (", fields, ") values (", values, ")", NULL); - safe_mysql_query(orig, query); + str = pstrcat(orig->pool, "insert into ", cls->transfer_table_name, " (", fields, ") values (", values, ")", NULL); + + + /* How's our mysql link integrity? */ + if (mysql_log == NULL) { + + /* Try to regain the link */ + open_logdb_link(); + + if (mysql_log == NULL) { + /* Unable to re-establish a DB link, so assume that it's really + * gone and send the entry to the preserve file instead. */ + preserve_entry(r, str); + return OK; + } else { + /* Whew, we got the DB link back */ + ap_log_error(APLOG_MARK,NOTICELEVEL,orig->server,"MySQL: httpd child established database connection"); + safe_mysql_query(orig, str); + } + } else { + /* Everything was fine */ + safe_mysql_query(orig, str); + } } return retvalue; @@ -851,7 +919,20 @@ int log_mysql_transaction(request_rec *orig) /* Called on the exit of an httpd child process */ static void log_mysql_child_exit(server_rec *s, pool *p) { - mysql_close(mysql_log); + mysql_close(mysql_log); +} + +/* Called on the init of an httpd child process */ +static void log_mysql_child_init(server_rec *s, pool *p) +{ + int retval; + + retval = open_logdb_link(); + #ifdef DEBUG + if (retval > 0) { + ap_log_error(APLOG_MARK,DEBUGLEVEL,s,"MySQL: open_logdb_link successful"); + } + #endif } @@ -874,7 +955,7 @@ module mysql_log_module = { log_mysql_transaction, /* logger */ NULL, /* header parser */ #if MODULE_MAGIC_NUMBER >= 19970728 /* 1.3-dev or later support these additionals... */ - NULL, /* child_init */ + log_mysql_child_init, /* child_init */ log_mysql_child_exit, /* process exit/cleanup */ NULL /* [#0] post read-request */ #endif -- cgit