X-Git-Url: http://www.privoxy.org/gitweb/?p=privoxy.git;a=blobdiff_plain;f=errlog.c;h=9b9fd5005b9ac059206bf8b80af0027c304155b3;hp=59ea1d8741e5566aea34738875853e122587074e;hb=fffab6e6ee7719edef26f9cced06f3797be11312;hpb=683fe3fb293c8836f4887905b38098cba7ba932c diff --git a/errlog.c b/errlog.c index 59ea1d87..9b9fd500 100644 --- a/errlog.c +++ b/errlog.c @@ -1,4 +1,4 @@ -const char errlog_rcs[] = "$Id: errlog.c,v 1.9 2001/05/28 16:15:17 jongfoster Exp $"; +const char errlog_rcs[] = "$Id: errlog.c,v 1.49 2007/04/08 16:44:15 fabiankeil Exp $"; /********************************************************************* * * File : $Source: /cvsroot/ijbswa/current/errlog.c,v $ @@ -6,8 +6,8 @@ const char errlog_rcs[] = "$Id: errlog.c,v 1.9 2001/05/28 16:15:17 jongfoster Ex * Purpose : Log errors to a designated destination in an elegant, * printf-like fashion. * - * Copyright : Written by and Copyright (C) 2001 the SourceForge - * IJBSWA team. http://ijbswa.sourceforge.net + * Copyright : Written by and Copyright (C) 2001-2007 the SourceForge + * Privoxy team. http://www.privoxy.org/ * * Based on the Internet Junkbuster originally written * by and Copyright (C) 1997 Anonymous Coders and @@ -33,6 +33,169 @@ const char errlog_rcs[] = "$Id: errlog.c,v 1.9 2001/05/28 16:15:17 jongfoster Ex * * Revisions : * $Log: errlog.c,v $ + * Revision 1.49 2007/04/08 16:44:15 fabiankeil + * We need for gettimeofday(), not . + * + * Revision 1.48 2007/03/31 13:33:28 fabiankeil + * Add alternative log_error() with timestamps + * that contain milliseconds and without using + * strcpy(), strcat() or sprintf(). + * + * Revision 1.47 2006/11/28 15:25:15 fabiankeil + * Only unlink the pidfile if it's actually used. + * + * Revision 1.46 2006/11/13 19:05:51 fabiankeil + * Make pthread mutex locking more generic. Instead of + * checking for OSX and OpenBSD, check for FEATURE_PTHREAD + * and use mutex locking unless there is an _r function + * available. Better safe than sorry. + * + * Fixes "./configure --disable-pthread" and should result + * in less threading-related problems on pthread-using platforms, + * but it still doesn't fix BR#1122404. + * + * Revision 1.45 2006/08/21 11:15:54 david__schmidt + * MS Visual C++ build updates + * + * Revision 1.44 2006/08/18 16:03:16 david__schmidt + * Tweak for OS/2 build happiness. + * + * Revision 1.43 2006/08/03 02:46:41 david__schmidt + * Incorporate Fabian Keil's patch work: + * http://www.fabiankeil.de/sourcecode/privoxy/ + * + * Revision 1.42 2006/07/18 14:48:46 david__schmidt + * Reorganizing the repository: swapping out what was HEAD (the old 3.1 branch) + * with what was really the latest development (the v_3_0_branch branch) + * + * Revision 1.40.2.4 2005/04/03 20:10:50 david__schmidt + * Thanks to Jindrich Makovicka for a race condition fix for the log + * file. The race condition remains for non-pthread implementations. + * Reference patch #1175720. + * + * Revision 1.40.2.3 2003/03/07 03:41:04 david__schmidt + * Wrapping all *_r functions (the non-_r versions of them) with mutex + * semaphores for OSX. Hopefully this will take care of all of those pesky + * crash reports. + * + * Revision 1.40.2.2 2002/09/28 00:30:57 david__schmidt + * Update error logging to give sane values for thread IDs on Mach kernels. + * It's still a hack, but at least it looks farily normal. We print the + * absolute value of the first 4 bytes of the pthread_t modded with 1000. + * + * Revision 1.40.2.1 2002/09/25 12:47:42 oes + * Make log_error safe against NULL string arguments + * + * Revision 1.40 2002/05/22 01:27:27 david__schmidt + * + * Add os2_socket_strerr mirroring w32_socket_strerr. + * + * Revision 1.39 2002/04/03 17:15:27 gliptak + * zero padding thread ids in log + * + * Revision 1.38 2002/03/31 17:18:59 jongfoster + * Win32 only: Enabling STRICT to fix a VC++ compile warning. + * + * Revision 1.37 2002/03/27 14:32:43 david__schmidt + * More compiler warning message maintenance + * + * Revision 1.36 2002/03/26 22:29:54 swa + * we have a new homepage! + * + * Revision 1.35 2002/03/24 15:23:33 jongfoster + * Name changes + * + * Revision 1.34 2002/03/24 13:25:43 swa + * name change related issues + * + * Revision 1.33 2002/03/13 00:27:04 jongfoster + * Killing warnings + * + * Revision 1.32 2002/03/07 03:46:17 oes + * Fixed compiler warnings + * + * Revision 1.31 2002/03/06 23:02:57 jongfoster + * Removing tabs + * + * Revision 1.30 2002/03/05 22:43:45 david__schmidt + * - Better error reporting on OS/2 + * - Fix double-slash comment (oops) + * + * Revision 1.29 2002/03/04 23:45:13 jongfoster + * Printing thread ID if using Win32 native threads + * + * Revision 1.28 2002/03/04 17:59:59 oes + * Deleted deletePidFile(), cosmetics + * + * Revision 1.27 2002/03/04 02:08:01 david__schmidt + * Enable web editing of actions file on OS/2 (it had been broken all this time!) + * + * Revision 1.26 2002/01/09 19:05:45 steudten + * Fix big memory leak. + * + * Revision 1.25 2002/01/09 14:32:08 oes + * Added support for gmtime_r and localtime_r. + * + * Revision 1.24 2001/12/30 14:07:32 steudten + * - Add signal handling (unix) + * - Add SIGHUP handler (unix) + * - Add creation of pidfile (unix) + * - Add action 'top' in rc file (RH) + * - Add entry 'SIGNALS' to manpage + * - Add exit message to logfile (unix) + * + * Revision 1.23 2001/11/07 00:02:13 steudten + * Add line number in error output for lineparsing for + * actionsfile and configfile. + * Special handling for CLF added. + * + * Revision 1.22 2001/11/05 23:43:05 steudten + * Add time+date to log files. + * + * Revision 1.21 2001/10/25 03:40:47 david__schmidt + * Change in porting tactics: OS/2's EMX porting layer doesn't allow multiple + * threads to call select() simultaneously. So, it's time to do a real, live, + * native OS/2 port. See defines for __EMX__ (the porting layer) vs. __OS2__ + * (native). Both versions will work, but using __OS2__ offers multi-threading. + * + * Revision 1.20 2001/09/16 23:04:34 jongfoster + * Fixing a warning + * + * Revision 1.19 2001/09/13 20:08:06 jongfoster + * Adding support for LOG_LEVEL_CGI + * + * Revision 1.18 2001/09/10 11:27:24 oes + * Declaration of w32_socket_strerr now conditional + * + * Revision 1.17 2001/09/10 10:17:13 oes + * Removed unused variable; Fixed sprintf format + * + * Revision 1.16 2001/07/30 22:08:36 jongfoster + * Tidying up #defines: + * - All feature #defines are now of the form FEATURE_xxx + * - Permanently turned off WIN_GUI_EDIT + * - Permanently turned on WEBDAV and SPLIT_PROXY_ARGS + * + * Revision 1.15 2001/07/29 17:41:10 jongfoster + * Now prints thread ID for each message (pthreads only) + * + * Revision 1.14 2001/07/19 19:03:48 haroon + * - Added case for LOG_LEVEL_POPUPS + * + * Revision 1.13 2001/07/13 13:58:58 oes + * - Added case for LOG_LEVEL_DEANIMATE + * - Removed all #ifdef PCRS + * + * Revision 1.12 2001/06/09 10:55:28 jongfoster + * Changing BUFSIZ ==> BUFFER_SIZE + * + * Revision 1.11 2001/06/01 18:14:49 jongfoster + * Changing the calls to strerr() to check HAVE_STRERR (which is defined + * in config.h if appropriate) rather than the NO_STRERR macro. + * + * Revision 1.10 2001/05/29 11:52:21 oes + * Conditional compilation of w32_socket_error + * * Revision 1.9 2001/05/28 16:15:17 jongfoster * Improved reporting of errors under Win32. * @@ -109,28 +272,48 @@ const char errlog_rcs[] = "$Id: errlog.c,v 1.9 2001/05/28 16:15:17 jongfoster Ex #include "config.h" +#include "miscutil.h" #include #include #include #include -#ifndef _WIN32 +#if defined(HAVE_STRLCPY) && defined(HAVE_GETTIMEOFDAY) +#define USE_NEW_LOG_ERROR +/* For gettimeofday() */ +#include +#endif /* defined(HAVE_STRLCPY) && defined(HAVE_GETTIMEOFDAY) */ + +#if !defined(_WIN32) && !defined(__OS2__) #include -#endif /* ndef _WIN32 */ +#endif /* !defined(_WIN32) && !defined(__OS2__) */ #include -/* #include */ +#include #ifdef _WIN32 +#ifndef STRICT +#define STRICT +#endif #include #ifndef _WIN_CONSOLE #include "w32log.h" #endif /* ndef _WIN_CONSOLE */ #endif /* def _WIN32 */ +#ifdef _MSC_VER +#define inline __inline +#endif /* def _MSC_VER */ + +#ifdef __OS2__ +#include /* For sock_errno */ +#define INCL_DOS +#include +#endif #include "errlog.h" #include "project.h" +#include "jcc.h" const char errlog_h_rcs[] = ERRLOG_H_VERSION; @@ -145,16 +328,46 @@ const char errlog_h_rcs[] = ERRLOG_H_VERSION; /* where to log (default: stderr) */ static FILE *logfp = NULL; -/* where to log (NULL == stderr) */ -static char * logfilename = NULL; - /* logging detail level. */ -static int debug = (LOG_LEVEL_FATAL | LOG_LEVEL_ERROR | LOG_LEVEL_INFO); +int debug = (LOG_LEVEL_FATAL | LOG_LEVEL_ERROR | LOG_LEVEL_INFO); /* static functions */ static void fatal_error(const char * error_message); -static char * w32_socket_strerr(int errcode, char * tmp_buf); +#ifdef _WIN32 +static char *w32_socket_strerr(int errcode, char *tmp_buf); +#endif +#ifdef __OS2__ +static char *os2_socket_strerr(int errcode, char *tmp_buf); +#endif +#ifdef FEATURE_PTHREAD +static inline void lock_logfile() +{ + pthread_mutex_lock(&log_mutex); +} +static inline void unlock_logfile() +{ + pthread_mutex_unlock(&log_mutex); +} +static inline void lock_loginit() +{ + pthread_mutex_lock(&log_init_mutex); +} +static inline void unlock_loginit() +{ + pthread_mutex_unlock(&log_init_mutex); +} +#else /* ! FEATURE_PTHREAD */ +/* + * FIXME we need a cross-platform locking mechanism. + * The locking/unlocking functions below should be + * fleshed out for non-pthread implementations. + */ +static inline void lock_logfile() {} +static inline void unlock_logfile() {} +static inline void lock_loginit() {} +static inline void unlock_loginit() {} +#endif /********************************************************************* * @@ -173,7 +386,7 @@ static char * w32_socket_strerr(int errcode, char * tmp_buf); static void fatal_error(const char * error_message) { #if defined(_WIN32) && !defined(_WIN_CONSOLE) - MessageBox(g_hwndLogFrame, error_message, "Internet JunkBuster Error", + MessageBox(g_hwndLogFrame, error_message, "Privoxy Error", MB_OK | MB_ICONERROR | MB_TASKMODAL | MB_SETFOREGROUND | MB_TOPMOST); /* Cleanup - remove taskbar icon etc. */ @@ -183,13 +396,20 @@ static void fatal_error(const char * error_message) fputs(error_message, stderr); #endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */ +#if defined(unix) + if(pidfile) + { + unlink(pidfile); + } +#endif /* unix */ + exit(1); } /********************************************************************* * - * Function : init_errlog + * Function : init_error_log * * Description : Initializes the logging module. Must call before * calling log_error. @@ -206,41 +426,310 @@ void init_error_log(const char *prog_name, const char *logfname, int debuglevel) { FILE *fp; - /* FIXME RACE HAZARD: should start critical section error_log_use here */ + lock_loginit(); /* set the logging detail level */ debug = debuglevel | LOG_LEVEL_MINIMUM; if ((logfp != NULL) && (logfp != stderr)) { + log_error(LOG_LEVEL_INFO, "(Re-)Open logfile %s", logfname ? logfname : "none"); + lock_logfile(); fclose(logfp); + } else { + lock_logfile(); } logfp = stderr; + unlock_logfile(); /* set the designated log file */ if( logfname ) { - if( !(fp = fopen(logfname, "a")) ) + if( NULL == (fp = fopen(logfname, "a")) ) { - log_error(LOG_LEVEL_FATAL, "init_errlog(): can't open logfile: %s", logfname); + log_error(LOG_LEVEL_FATAL, "init_error_log(): can't open logfile: %s", logfname); } /* set logging to be completely unbuffered */ setbuf(fp, NULL); + lock_logfile(); logfp = fp; + unlock_logfile(); } - log_error(LOG_LEVEL_INFO, "Internet JunkBuster version " VERSION); + log_error(LOG_LEVEL_INFO, "Privoxy version " VERSION); if (prog_name != NULL) { log_error(LOG_LEVEL_INFO, "Program name: %s", prog_name); } - /* FIXME RACE HAZARD: should end critical section error_log_use here */ + unlock_loginit(); } /* init_error_log */ +#if defined(USE_NEW_LOG_ERROR) +/* + * Use an alternative log_error version and its helper functions. + * + * The code is mostly copied from the old log_error + * function but it's divided into multiple functions, + * doesn't use strcpy, strcat or sprintf and compiles + * with gcc43 without warnings (on FreeBSD that is). + * + * It should behave like the old log_error function with + * two exceptions: + * + * - too long format strings are logged truncated instead + * of completely replaced with the truncation warning, + * - its time stamps contain milliseconds. + */ + +/********************************************************************* + * + * Function : get_thread_id + * + * Description : Returns a number that is different for each thread. + * + * XXX: Should be moved elsewhere (miscutil.c?) + * + * Parameters : None + * + * Returns : thread_id + * + *********************************************************************/ +long get_thread_id(void) +{ + long this_thread = 1; /* was: pthread_t this_thread;*/ + +#ifdef __OS2__ + PTIB ptib; + APIRET ulrc; /* XXX: I have no clue what this does */ +#endif /* __OS2__ */ + + /* FIXME get current thread id */ +#ifdef FEATURE_PTHREAD + this_thread = (long)pthread_self(); +#ifdef __MACH__ + /* + * Mac OSX (and perhaps other Mach instances) doesn't have a debuggable + * value at the first 4 bytes of pthread_self()'s return value, a pthread_t. + * pthread_t is supposed to be opaque... but it's fairly random, though, so + * we make it mostly presentable. + */ + this_thread = abs(this_thread % 1000); +#endif /* def __MACH__ */ +#elif defined(_WIN32) + this_thread = GetCurrentThreadId(); +#elif defined(__OS2__) + ulrc = DosGetInfoBlocks(&ptib, NULL); + if (ulrc == 0) + this_thread = ptib -> tib_ptib2 -> tib2_ultid; +#endif /* def FEATURE_PTHREAD */ + + return this_thread; +} + + +/********************************************************************* + * + * Function : get_log_timestamp + * + * Description : Generates the time stamp for the log message prefix. + * + * Parameters : + * 1 : buffer = Storage buffer + * 2 : buffer_size = Size of storage buffer + * + * Returns : Number of written characters or 0 for error. + * + *********************************************************************/ +static inline size_t get_log_timestamp(char *buffer, size_t buffer_size) +{ + size_t length; + time_t now; + struct tm tm_now; + struct timeval tv_now; /* XXX: stupid name */ + gettimeofday(&tv_now, NULL); + long msecs = tv_now.tv_usec / 1000; + int msecs_length = 0; + + time(&now); + +#ifdef HAVE_LOCALTIME_R + tm_now = *localtime_r(&now, &tm_now); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&localtime_mutex); + tm_now = *localtime(&now); + pthread_mutex_unlock(&localtime_mutex); +#else + tm_now = *localtime(&now); +#endif + + length = strftime(buffer, buffer_size, "%b %d %H:%M:%S", &tm_now); + if (length > 0); + { + msecs_length = snprintf(buffer+length, buffer_size - length, ".%.3ld", msecs); + } + if (msecs_length > 0) + { + length += (size_t)msecs_length; + } + else + { + length = 0; + } + + return length; +} + + +/********************************************************************* + * + * Function : get_clf_timestamp + * + * Description : Generates a Common Log Format time string. + * + * Parameters : + * 1 : buffer = Storage buffer + * 2 : buffer_size = Size of storage buffer + * + * Returns : Number of written characters or 0 for error. + * + *********************************************************************/ +static inline size_t get_clf_timestamp(char *buffer, size_t buffer_size) +{ + /* + * Complex because not all OSs have tm_gmtoff or + * the %z field in strftime() + */ + time_t now; + struct tm *tm_now; + struct tm gmt; +#ifdef HAVE_LOCALTIME_R + struct tm dummy; +#endif + int days, hrs, mins; + size_t length; + int tz_length = 0; + + time (&now); +#ifdef HAVE_GMTIME_R + gmt = *gmtime_r(&now, &gmt); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&gmtime_mutex); + gmt = *gmtime(&now); + pthread_mutex_unlock(&gmtime_mutex); +#else + gmt = *gmtime(&now); +#endif +#ifdef HAVE_LOCALTIME_R + tm_now = localtime_r(&now, &dummy); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&localtime_mutex); + tm_now = localtime(&now); + pthread_mutex_unlock(&localtime_mutex); +#else + tm_now = localtime(&now); +#endif + days = tm_now->tm_yday - gmt.tm_yday; + hrs = ((days < -1 ? 24 : 1 < days ? -24 : days * 24) + tm_now->tm_hour - gmt.tm_hour); + mins = hrs * 60 + tm_now->tm_min - gmt.tm_min; + + length = strftime(buffer, buffer_size, "%d/%b/%Y:%H:%M:%S ", tm_now); + + if (length > 0); + { + tz_length = snprintf(buffer+length, buffer_size-length, + "%+03d%02d", mins / 60, abs(mins) % 60); + } + if (tz_length > 0) + { + length += (size_t)tz_length; + } + else + { + length = 0; + } + + return length; +} + + +/********************************************************************* + * + * Function : get_log_level_string + * + * Description : Translates a numerical loglevel into a string. + * + * Parameters : + * 1 : loglevel = LOG_LEVEL_FOO + * + * Returns : Log level string. + * + *********************************************************************/ +inline const char *get_log_level_string(int loglevel) +{ + char *log_level_string = NULL; + + assert(0 < loglevel); + + switch (loglevel) + { + case LOG_LEVEL_ERROR: + log_level_string = "Error"; + break; + case LOG_LEVEL_FATAL: + log_level_string = "Fatal error"; + break; + case LOG_LEVEL_GPC: + log_level_string = "Request"; + break; + case LOG_LEVEL_CONNECT: + log_level_string = "Connect"; + break; + case LOG_LEVEL_LOG: + log_level_string = "Writing"; + break; + case LOG_LEVEL_HEADER: + log_level_string = "Header"; + break; + case LOG_LEVEL_INFO: + log_level_string = "Info"; + break; + case LOG_LEVEL_RE_FILTER: + log_level_string = "Re-Filter"; + break; +#ifdef FEATURE_FORCE_LOAD + case LOG_LEVEL_FORCE: + log_level_string = "Force"; + break; +#endif /* def FEATURE_FORCE_LOAD */ +#ifdef FEATURE_FAST_REDIRECTS + case LOG_LEVEL_REDIRECTS: + log_level_string = "Redirect"; + break; +#endif /* def FEATURE_FAST_REDIRECTS */ + case LOG_LEVEL_DEANIMATE: + log_level_string = "Gif-Deanimate"; + break; +#ifdef FEATURE_KILL_POPUPS + case LOG_LEVEL_POPUPS: + log_level_string = "Kill-Popups"; + break; +#endif /* def FEATURE_KILL_POPUPS */ + case LOG_LEVEL_CGI: + log_level_string = "CGI"; + break; + default: + log_level_string = "Unknown log level"; + break; + } + assert(NULL != log_level_string); + + return log_level_string; +} + /********************************************************************* * @@ -256,13 +745,330 @@ void init_error_log(const char *prog_name, const char *logfname, int debuglevel) * Returns : N/A * *********************************************************************/ -void log_error(int loglevel, char *fmt, ...) +void log_error(int loglevel, const char *fmt, ...) { va_list ap; - char outbuf[BUFSIZ]; - char * src = fmt; + char *outbuf = NULL; + static char *outbuf_save = NULL; + char tempbuf[BUFFER_SIZE]; + size_t length = 0; + const char * src = fmt; + long thread_id; + char timestamp[30]; + /* + * XXX: Make this a config option, + * why else do we allocate instead of using + * an array? + */ + size_t log_buffer_size = BUFFER_SIZE; + +#if defined(_WIN32) && !defined(_WIN_CONSOLE) + /* + * Irrespective of debug setting, a GET/POST/CONNECT makes + * the taskbar icon animate. (There is an option to disable + * this but checking that is handled inside LogShowActivity()). + */ + if (loglevel == LOG_LEVEL_GPC) + { + LogShowActivity(); + } +#endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */ + + /* verify if loglevel applies to current settings and bail out if negative */ + if ((loglevel & debug) == 0) + { + return; + } + + thread_id = get_thread_id(); + get_log_timestamp(timestamp, sizeof(timestamp)); + + /* protect the whole function because of the static buffer (outbuf) */ + lock_logfile(); + + if (NULL == outbuf_save) + { + outbuf_save = (char*)zalloc(log_buffer_size + 1); /* +1 for paranoia */ + if (NULL == outbuf_save) + { + snprintf(tempbuf, sizeof(tempbuf), + "%s Privoxy(%08lx) Fatal error: log_error() failed to allocate buffer memory.\n" + "\nExiting.", timestamp, thread_id); + if( !logfp ) + { + logfp = stderr; + } + fputs(tempbuf, logfp); + unlock_logfile(); + fatal_error(tempbuf); /* Exit */ + } + } + outbuf = outbuf_save; + + /* + * Memsetting the whole buffer to zero (in theory) + * makes things easier later on. + */ + memset(outbuf, 0, log_buffer_size); + + /* Add prefix for everything but Common Log Format messages */ + if (loglevel != LOG_LEVEL_CLF) + { + length = (size_t)snprintf(outbuf, log_buffer_size, "%s Privoxy(%08lx) %s: ", + timestamp, thread_id, get_log_level_string(loglevel)); + } + + /* get ready to scan var. args. */ + va_start(ap, fmt); + + /* build formatted message from fmt and var-args */ + while ((*src) && (length < log_buffer_size-2)) + { + const char *sval = NULL; /* %N string */ + int ival; /* %N string length or an error code */ + unsigned uval; /* %u value */ + long lval; /* %l value */ + unsigned long ulval; /* %ul value */ + char ch; + const char *format_string = tempbuf; + + ch = *src++; + if (ch != '%') + { + outbuf[length++] = ch; + /* + * XXX: Only necessary on platforms which don't use pthread + * mutexes (mingw32 for example), where multiple threads can + * write to the buffer at the same time. + */ + outbuf[length] = '\0'; + continue; + } + outbuf[length] = '\0'; + ch = *src++; + switch (ch) { + case '%': + tempbuf[0] = '%'; + tempbuf[1] = '\0'; + break; + case 'd': + ival = va_arg( ap, int ); + snprintf(tempbuf, sizeof(tempbuf), "%d", ival); + break; + case 'u': + uval = va_arg( ap, unsigned ); + snprintf(tempbuf, sizeof(tempbuf), "%u", uval); + break; + case 'l': + /* this is a modifier that must be followed by u or d */ + ch = *src++; + if (ch == 'd') + { + lval = va_arg( ap, long ); + snprintf(tempbuf, sizeof(tempbuf), "%ld", lval); + } + else if (ch == 'u') + { + ulval = va_arg( ap, unsigned long ); + snprintf(tempbuf, sizeof(tempbuf), "%lu", ulval); + } + else + { + snprintf(tempbuf, sizeof(tempbuf), "Bad format string: \"%s\"", fmt); + loglevel = LOG_LEVEL_FATAL; + } + break; + case 'c': + /* + * Note that char paramaters are converted to int, so we need to + * pass "int" to va_arg. (See K&R, 2nd ed, section A7.3.2, page 202) + */ + tempbuf[0] = (char) va_arg(ap, int); + tempbuf[1] = '\0'; + break; + case 's': + format_string = va_arg(ap, char *); + if (format_string == NULL) + { + format_string = "[null]"; + } + break; + case 'N': + /* + * Non-standard: Print a counted unterminated string. + * Takes 2 parameters: int length, const char * string. + */ + ival = va_arg(ap, int); + sval = va_arg(ap, char *); + if (sval == NULL) + { + format_string = "[null]"; + } + else if (ival <= 0) + { + if (0 == ival) + { + /* That's ok (but stupid) */ + tempbuf[0] = '\0'; + } + else + { + /* + * That's not ok (and even more stupid) + */ + assert(ival >= 0); + format_string = "[counted string lenght < 0]"; + } + } + else if (ival >= sizeof(tempbuf)) + { + /* + * String is too long, copy as much as possible. + * It will be further truncated later. + */ + memcpy(tempbuf, sval, sizeof(tempbuf)-1); + tempbuf[sizeof(tempbuf)-1] = '\0'; + } + else + { + memcpy(tempbuf, sval, (size_t) ival); + tempbuf[ival] = '\0'; + } + break; + case 'E': + /* Non-standard: Print error code from errno */ +#ifdef _WIN32 + ival = WSAGetLastError(); + format_string = w32_socket_strerr(ival, tempbuf); +#elif __OS2__ + ival = sock_errno(); + if (ival != 0) + { + format_string = os2_socket_strerr(ival, tempbuf); + } + else + { + ival = errno; + format_string = strerror(ival); + } +#else /* ifndef _WIN32 */ + ival = errno; +#ifdef HAVE_STRERROR + format_string = strerror(ival); +#else /* ifndef HAVE_STRERROR */ + format_string = NULL; +#endif /* ndef HAVE_STRERROR */ + if (sval == NULL) + { + snprintf(tempbuf, sizeof(tempbuf), "(errno = %d)", ival); + } +#endif /* ndef _WIN32 */ + break; + case 'T': + /* Non-standard: Print a Common Log File timestamp */ + get_clf_timestamp(tempbuf, sizeof(tempbuf)); + break; + default: + snprintf(tempbuf, sizeof(tempbuf), "Bad format string: \"%s\"", fmt); + loglevel = LOG_LEVEL_FATAL; + break; + } /* switch( p ) */ + + assert(length < log_buffer_size); + length += strlcpy(outbuf + length, format_string, log_buffer_size - length); + + if (length >= log_buffer_size-2) + { + static char warning[] = "... [too long, truncated]"; + + length = log_buffer_size - sizeof(warning) - 1; + length += strlcpy(outbuf + length, warning, log_buffer_size - length); + assert(length < log_buffer_size); + + break; + } + } /* for( p ... ) */ + + /* done with var. args */ + va_end(ap); + + assert(length < log_buffer_size); + length += strlcpy(outbuf + length, "\n", log_buffer_size - length); + + /* Some sanity checks */ + if (!(length < log_buffer_size) + || !(outbuf[log_buffer_size-1] == '\0') + || !(outbuf[log_buffer_size] == '\0') + ) + { + /* Repeat as assertions */ + assert(length < log_buffer_size); + assert(outbuf[log_buffer_size-1] == '\0'); + /* + * outbuf's real size is log_buffer_size+1, + * so while this looks like an off-by-one, + * we're only checking our paranoia byte. + */ + assert(outbuf[log_buffer_size] == '\0'); + + snprintf(outbuf, log_buffer_size, + "%s Privoxy(%08lx) Fatal error: log_error()'s sanity checks failed. length: %u\n" + "Exiting.", timestamp, thread_id, length); + loglevel = LOG_LEVEL_FATAL; + } + + /* deal with glibc stupidity - it won't let you initialize logfp */ + /* XXX: Still necessary? */ + if(NULL == logfp) + { + logfp = stderr; + } + + fputs(outbuf_save, logfp); + + if (loglevel == LOG_LEVEL_FATAL) + { + fatal_error(outbuf_save); + /* Never get here */ + } + + unlock_logfile(); + +#if defined(_WIN32) && !defined(_WIN_CONSOLE) + /* Write to display */ + LogPutString(outbuf_save); +#endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */ + +} + +#else /* use traditional log_error version */ + +/********************************************************************* + * + * Function : log_error + * + * Description : This is the error-reporting and logging function. + * + * Parameters : + * 1 : loglevel = the type of message to be logged + * 2 : fmt = the main string we want logged, printf-like + * 3 : ... = arguments to be inserted in fmt (printf-like). + * + * Returns : N/A + * + *********************************************************************/ +void log_error(int loglevel, const char *fmt, ...) +{ + va_list ap; + char *outbuf= NULL; + static char *outbuf_save = NULL; + const char * src = fmt; int outc = 0; long this_thread = 1; /* was: pthread_t this_thread;*/ +#ifdef __OS2__ + PTIB ptib; + APIRET ulrc; +#endif /* __OS2__ */ #if defined(_WIN32) && !defined(_WIN_CONSOLE) /* @@ -282,53 +1088,115 @@ void log_error(int loglevel, char *fmt, ...) return; } + /* protect the whole function because of the static buffer (outbuf) */ + lock_logfile(); + /* FIXME get current thread id */ - /* this_thread = (long)pthread_self(); */ +#ifdef FEATURE_PTHREAD + this_thread = (long)pthread_self(); +#ifdef __MACH__ + /* + * Mac OSX (and perhaps other Mach instances) doesn't have a debuggable + * value at the first 4 bytes of pthread_self()'s return value, a pthread_t. + * pthread_t is supposed to be opaque... but it's fairly random, though, so + * we make it mostly presentable. + */ + this_thread = abs(this_thread % 1000); +#endif /* def __MACH__ */ +#elif defined(_WIN32) + this_thread = GetCurrentThreadId(); +#elif defined(__OS2__) + ulrc = DosGetInfoBlocks(&ptib, NULL); + if (ulrc == 0) + this_thread = ptib -> tib_ptib2 -> tib2_ultid; +#endif /* def FEATURE_PTHREAD */ + + if ( !outbuf_save ) + { + outbuf_save = outbuf = (char*)malloc(BUFFER_SIZE); + if (NULL == outbuf_save) + { + fatal_error("Privoxy failed to allocate log buffer."); + } + } + outbuf = outbuf_save; + { + /* + * Write timestamp into tempbuf. + * + * Complex because not all OSs have tm_gmtoff or + * the %z field in strftime() + */ + time_t now; + struct tm tm_now; + time (&now); +#ifdef HAVE_LOCALTIME_R + tm_now = *localtime_r(&now, &tm_now); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&localtime_mutex); + tm_now = *localtime (&now); + pthread_mutex_unlock(&localtime_mutex); +#else + tm_now = *localtime (&now); +#endif + strftime(outbuf, BUFFER_SIZE-6, "%b %d %H:%M:%S ", &tm_now); + outbuf += strlen( outbuf ); + } switch (loglevel) { case LOG_LEVEL_ERROR: - outc = sprintf(outbuf, "IJB(%d) Error: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Error: ", this_thread); break; case LOG_LEVEL_FATAL: - outc = sprintf(outbuf, "IJB(%d) Fatal error: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Fatal error: ", this_thread); break; case LOG_LEVEL_GPC: - outc = sprintf(outbuf, "IJB(%d) Request: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Request: ", this_thread); break; case LOG_LEVEL_CONNECT: - outc = sprintf(outbuf, "IJB(%d) Connect: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Connect: ", this_thread); break; case LOG_LEVEL_LOG: - outc = sprintf(outbuf, "IJB(%d) Writing: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Writing: ", this_thread); break; case LOG_LEVEL_HEADER: - outc = sprintf(outbuf, "IJB(%d) Header: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Header: ", this_thread); break; case LOG_LEVEL_INFO: - outc = sprintf(outbuf, "IJB(%d) Info: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Info: ", this_thread); break; -#ifdef PCRS case LOG_LEVEL_RE_FILTER: - outc = sprintf(outbuf, "IJB(%d) Re-Filter: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Re-Filter: ", this_thread); break; -#endif /* def PCRS */ -#ifdef FORCE_LOAD +#ifdef FEATURE_FORCE_LOAD case LOG_LEVEL_FORCE: - outc = sprintf(outbuf, "IJB(%d) Force: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Force: ", this_thread); break; -#endif /* def FORCE_LOAD */ -#ifdef FAST_REDIRECTS +#endif /* def FEATURE_FORCE_LOAD */ +#ifdef FEATURE_FAST_REDIRECTS case LOG_LEVEL_REDIRECTS: - outc = sprintf(outbuf, "IJB(%d) Redirect: ", this_thread); + outc = sprintf(outbuf, "Privoxy(%08lx) Redirect: ", this_thread); + break; +#endif /* def FEATURE_FAST_REDIRECTS */ + case LOG_LEVEL_DEANIMATE: + outc = sprintf(outbuf, "Privoxy(%08lx) Gif-Deanimate: ", this_thread); break; -#endif /* def FAST_REDIRECTS */ case LOG_LEVEL_CLF: + outbuf = outbuf_save; outc = 0; outbuf[0] = '\0'; break; +#ifdef FEATURE_KILL_POPUPS + case LOG_LEVEL_POPUPS: + outc = sprintf(outbuf, "Privoxy(%08lx) Kill-Popups: ", this_thread); + break; +#endif /* def FEATURE_KILL_POPUPS */ + case LOG_LEVEL_CGI: + outc = sprintf(outbuf, "Privoxy(%08lx) CGI: ", this_thread); + break; default: - outc = sprintf(outbuf, "IJB(%d) UNKNOWN LOG TYPE(%d): ", this_thread, loglevel); + outc = sprintf(outbuf, "Privoxy(%08lx) UNKNOWN LOG TYPE(%d): ", this_thread, loglevel); break; } @@ -336,10 +1204,10 @@ void log_error(int loglevel, char *fmt, ...) va_start( ap, fmt ); /* build formatted message from fmt and var-args */ - while ((*src) && (outc < BUFSIZ-2)) + while ((*src) && (outc < BUFFER_SIZE-2)) { - char tempbuf[BUFSIZ]; - char *sval; + char tempbuf[BUFFER_SIZE]; + char *sval = NULL; int ival; unsigned uval; long lval; @@ -363,7 +1231,7 @@ void log_error(int loglevel, char *fmt, ...) ival = va_arg( ap, int ); oldoutc = outc; outc += sprintf(tempbuf, "%d", ival); - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, tempbuf); } @@ -376,7 +1244,7 @@ void log_error(int loglevel, char *fmt, ...) uval = va_arg( ap, unsigned ); oldoutc = outc; outc += sprintf(tempbuf, "%u", uval); - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, tempbuf); } @@ -403,21 +1271,19 @@ void log_error(int loglevel, char *fmt, ...) else { /* Error */ - sprintf(outbuf, "IJB(%d) Error: log_error(): Bad format string:\n" + sprintf(outbuf, "Privoxy(%08lx) Error: log_error(): Bad format string:\n" "Format = \"%s\"\n" "Exiting.", this_thread, fmt); - /* FIXME RACE HAZARD: should start critical section error_log_use here */ if( !logfp ) { logfp = stderr; } fputs(outbuf, logfp); - /* FIXME RACE HAZARD: should end critical section error_log_use here */ fatal_error(outbuf); /* Never get here */ break; } - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, tempbuf); } @@ -435,9 +1301,13 @@ void log_error(int loglevel, char *fmt, ...) break; case 's': sval = va_arg( ap, char * ); + if (sval == NULL) + { + sval = "[null]"; + } oldoutc = outc; outc += strlen(sval); - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, sval); } @@ -452,15 +1322,19 @@ void log_error(int loglevel, char *fmt, ...) */ ival = va_arg( ap, int ); sval = va_arg( ap, char * ); + if (sval == NULL) + { + sval = "[null]"; + } if (ival < 0) { ival = 0; } oldoutc = outc; outc += ival; - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { - memcpy(outbuf + oldoutc, sval, ival); + memcpy(outbuf + oldoutc, sval, (size_t) ival); } else { @@ -472,13 +1346,22 @@ void log_error(int loglevel, char *fmt, ...) #ifdef _WIN32 ival = WSAGetLastError(); sval = w32_socket_strerr(ival, tempbuf); +#elif __OS2__ + ival = sock_errno(); + if (ival != 0) + sval = os2_socket_strerr(ival, tempbuf); + else + { + ival = errno; + sval = strerror(ival); + } #else /* ifndef _WIN32 */ ival = errno; -#ifndef NOSTRERROR +#ifdef HAVE_STRERROR sval = strerror(ival); -#else /* def NOSTRERROR */ +#else /* ifndef HAVE_STRERROR */ sval = NULL; -#endif /* def NOSTRERROR */ +#endif /* ndef HAVE_STRERROR */ if (sval == NULL) { sprintf(tempbuf, "(errno = %d)", ival); @@ -487,7 +1370,7 @@ void log_error(int loglevel, char *fmt, ...) #endif /* ndef _WIN32 */ oldoutc = outc; outc += strlen(sval); - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, sval); } @@ -507,20 +1390,39 @@ void log_error(int loglevel, char *fmt, ...) */ time_t now; struct tm *tm_now; - struct tm gmt; + struct tm gmt; +#ifdef HAVE_LOCALTIME_R + struct tm dummy; +#endif int days, hrs, mins; time (&now); - gmt = *gmtime (&now); +#ifdef HAVE_GMTIME_R + gmt = *gmtime_r(&now, &gmt); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&gmtime_mutex); + gmt = *gmtime(&now); + pthread_mutex_unlock(&gmtime_mutex); +#else + gmt = *gmtime(&now); +#endif +#ifdef HAVE_LOCALTIME_R + tm_now = localtime_r(&now, &dummy); +#elif FEATURE_PTHREAD + pthread_mutex_lock(&localtime_mutex); tm_now = localtime (&now); + pthread_mutex_unlock(&localtime_mutex); +#else + tm_now = localtime (&now); +#endif days = tm_now->tm_yday - gmt.tm_yday; hrs = ((days < -1 ? 24 : 1 < days ? -24 : days * 24) + tm_now->tm_hour - gmt.tm_hour); mins = hrs * 60 + tm_now->tm_min - gmt.tm_min; - strftime (tempbuf, BUFSIZ-6, "%d/%b/%Y:%H:%M:%S ", tm_now); + strftime (tempbuf, BUFFER_SIZE-6, "%d/%b/%Y:%H:%M:%S ", tm_now); sprintf (tempbuf + strlen(tempbuf), "%+03d%02d", mins / 60, abs(mins) % 60); } oldoutc = outc; outc += strlen(tempbuf); - if (outc < BUFSIZ-1) + if (outc < BUFFER_SIZE-1) { strcpy(outbuf + oldoutc, tempbuf); } @@ -530,17 +1432,16 @@ void log_error(int loglevel, char *fmt, ...) } break; default: - sprintf(outbuf, "IJB(%d) Error: log_error(): Bad format string:\n" + sprintf(outbuf, "Privoxy(%08lx) Error: log_error(): Bad format string:\n" "Format = \"%s\"\n" "Exiting.", this_thread, fmt); - /* FIXME RACE HAZARD: should start critical section error_log_use here */ if( !logfp ) { logfp = stderr; } - fputs(outbuf, logfp); - /* FIXME RACE HAZARD: should end critical section error_log_use here */ - fatal_error(outbuf); + fputs(outbuf_save, logfp); + unlock_logfile(); + fatal_error(outbuf_save); /* Never get here */ break; @@ -551,20 +1452,20 @@ void log_error(int loglevel, char *fmt, ...) /* done with var. args */ va_end( ap ); - if (outc >= BUFSIZ-2) + if (outc >= BUFFER_SIZE-2) { /* insufficient room for newline and trailing null. */ static const char warning[] = "... [too long, truncated]\n"; - if (outc < BUFSIZ) + if (outc < BUFFER_SIZE) { /* Need to add terminating null in this case. */ outbuf[outc] = '\0'; } /* Truncate output */ - outbuf[BUFSIZ - sizeof(warning)] = '\0'; + outbuf[BUFFER_SIZE - sizeof(warning)] = '\0'; /* Append warning */ strcat(outbuf, warning); @@ -576,30 +1477,29 @@ void log_error(int loglevel, char *fmt, ...) outbuf[outc] = '\0'; } - /* FIXME RACE HAZARD: should start critical section error_log_use here */ - /* deal with glibc stupidity - it won't let you initialize logfp */ if( !logfp ) { logfp = stderr; } - fputs(outbuf, logfp); + fputs(outbuf_save, logfp); if (loglevel == LOG_LEVEL_FATAL) { - fatal_error(outbuf); + fatal_error(outbuf_save); /* Never get here */ } - /* FIXME RACE HAZARD: should end critical section error_log_use here */ + unlock_logfile(); #if defined(_WIN32) && !defined(_WIN_CONSOLE) /* Write to display */ - LogPutString(outbuf); + LogPutString(outbuf_save); #endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */ } +#endif /* defined(USE_NEW_LOG_ERROR) */ #ifdef _WIN32 @@ -620,7 +1520,7 @@ void log_error(int loglevel, char *fmt, ...) * tmp_buf. * *********************************************************************/ -static char * w32_socket_strerr(int errcode, char * tmp_buf) +static char *w32_socket_strerr(int errcode, char *tmp_buf) { #define TEXT_FOR_ERROR(code,text) \ if (errcode == code) \ @@ -692,9 +1592,84 @@ static char * w32_socket_strerr(int errcode, char * tmp_buf) #endif /* def _WIN32 */ +#ifdef __OS2__ +/********************************************************************* + * + * Function : os2_socket_strerr + * + * Description : Translate the return value from sock_errno() + * into a string. + * + * Parameters : + * 1 : errcode = The return value from sock_errno(). + * 2 : tmp_buf = A temporary buffer that might be used to + * store the string. + * + * Returns : String representing the error code. This may be + * a global string constant or a string stored in + * tmp_buf. + * + *********************************************************************/ +static char *os2_socket_strerr(int errcode, char *tmp_buf) +{ +#define TEXT_FOR_ERROR(code,text) \ + if (errcode == code) \ + { \ + return #code " - " text; \ + } + + TEXT_FOR_ERROR(SOCEPERM , "Not owner.") + TEXT_FOR_ERROR(SOCESRCH , "No such process.") + TEXT_FOR_ERROR(SOCEINTR , "Interrupted system call.") + TEXT_FOR_ERROR(SOCENXIO , "No such device or address.") + TEXT_FOR_ERROR(SOCEBADF , "Bad file number.") + TEXT_FOR_ERROR(SOCEACCES , "Permission denied.") + TEXT_FOR_ERROR(SOCEFAULT , "Bad address.") + TEXT_FOR_ERROR(SOCEINVAL , "Invalid argument.") + TEXT_FOR_ERROR(SOCEMFILE , "Too many open files.") + TEXT_FOR_ERROR(SOCEPIPE , "Broken pipe.") + TEXT_FOR_ERROR(SOCEWOULDBLOCK , "Operation would block.") + TEXT_FOR_ERROR(SOCEINPROGRESS , "Operation now in progress.") + TEXT_FOR_ERROR(SOCEALREADY , "Operation already in progress.") + TEXT_FOR_ERROR(SOCENOTSOCK , "Socket operation on non-socket.") + TEXT_FOR_ERROR(SOCEDESTADDRREQ , "Destination address required.") + TEXT_FOR_ERROR(SOCEMSGSIZE , "Message too long.") + TEXT_FOR_ERROR(SOCEPROTOTYPE , "Protocol wrong type for socket.") + TEXT_FOR_ERROR(SOCENOPROTOOPT , "Protocol not available.") + TEXT_FOR_ERROR(SOCEPROTONOSUPPORT, "Protocol not supported.") + TEXT_FOR_ERROR(SOCESOCKTNOSUPPORT, "Socket type not supported.") + TEXT_FOR_ERROR(SOCEOPNOTSUPP , "Operation not supported.") + TEXT_FOR_ERROR(SOCEPFNOSUPPORT , "Protocol family not supported.") + TEXT_FOR_ERROR(SOCEAFNOSUPPORT , "Address family not supported by protocol family.") + TEXT_FOR_ERROR(SOCEADDRINUSE , "Address already in use.") + TEXT_FOR_ERROR(SOCEADDRNOTAVAIL , "Can't assign requested address.") + TEXT_FOR_ERROR(SOCENETDOWN , "Network is down.") + TEXT_FOR_ERROR(SOCENETUNREACH , "Network is unreachable.") + TEXT_FOR_ERROR(SOCENETRESET , "Network dropped connection on reset.") + TEXT_FOR_ERROR(SOCECONNABORTED , "Software caused connection abort.") + TEXT_FOR_ERROR(SOCECONNRESET , "Connection reset by peer.") + TEXT_FOR_ERROR(SOCENOBUFS , "No buffer space available.") + TEXT_FOR_ERROR(SOCEISCONN , "Socket is already connected.") + TEXT_FOR_ERROR(SOCENOTCONN , "Socket is not connected.") + TEXT_FOR_ERROR(SOCESHUTDOWN , "Can't send after socket shutdown.") + TEXT_FOR_ERROR(SOCETOOMANYREFS , "Too many references: can't splice.") + TEXT_FOR_ERROR(SOCETIMEDOUT , "Operation timed out.") + TEXT_FOR_ERROR(SOCECONNREFUSED , "Connection refused.") + TEXT_FOR_ERROR(SOCELOOP , "Too many levels of symbolic links.") + TEXT_FOR_ERROR(SOCENAMETOOLONG , "File name too long.") + TEXT_FOR_ERROR(SOCEHOSTDOWN , "Host is down.") + TEXT_FOR_ERROR(SOCEHOSTUNREACH , "No route to host.") + TEXT_FOR_ERROR(SOCENOTEMPTY , "Directory not empty.") + TEXT_FOR_ERROR(SOCEOS2ERR , "OS/2 Error.") + + sprintf(tmp_buf, "(error number %d)", errcode); + return tmp_buf; +} +#endif /* def __OS2__ */ + + /* Local Variables: tab-width: 3 end: */ -