Now that init_log_module() is called earlier, call show_version()
[privoxy.git] / errlog.c
index 96de4e1..138d7e9 100644 (file)
--- a/errlog.c
+++ b/errlog.c
@@ -1,4 +1,4 @@
-const char errlog_rcs[] = "$Id: errlog.c,v 1.57 2007/10/27 13:02:26 fabiankeil Exp $";
+const char errlog_rcs[] = "$Id: errlog.c,v 1.85 2009/02/06 17:51:38 fabiankeil Exp $";
 /*********************************************************************
  *
  * File        :  $Source: /cvsroot/ijbswa/current/errlog.c,v $
@@ -6,7 +6,7 @@ const char errlog_rcs[] = "$Id: errlog.c,v 1.57 2007/10/27 13:02:26 fabiankeil E
  * Purpose     :  Log errors to a designated destination in an elegant,
  *                printf-like fashion.
  *
- * Copyright   :  Written by and Copyright (C) 2001-2007 the SourceForge
+ * Copyright   :  Written by and Copyright (C) 2001-2009 the SourceForge
  *                Privoxy team. http://www.privoxy.org/
  *
  *                Based on the Internet Junkbuster originally written
@@ -33,6 +33,113 @@ const char errlog_rcs[] = "$Id: errlog.c,v 1.57 2007/10/27 13:02:26 fabiankeil E
  *
  * Revisions   :
  *    $Log: errlog.c,v $
+ *    Revision 1.85  2009/02/06 17:51:38  fabiankeil
+ *    Be prepared if I break the log module initialization again.
+ *
+ *    Revision 1.84  2008/12/14 15:46:22  fabiankeil
+ *    Give crunched requests their own log level.
+ *
+ *    Revision 1.83  2008/12/04 18:14:32  fabiankeil
+ *    Fix some cparser warnings.
+ *
+ *    Revision 1.82  2008/11/23 16:06:58  fabiankeil
+ *    Update a log message I missed in 1.80.
+ *
+ *    Revision 1.81  2008/11/23 15:59:27  fabiankeil
+ *    - Update copyright range.
+ *    - Remove stray line breaks in a log message
+ *      nobody is supposed to see anyway.
+ *
+ *    Revision 1.80  2008/11/23 15:49:49  fabiankeil
+ *    In log_error(), don't surround the thread id with "Privoxy(" and ")".
+ *
+ *    Revision 1.79  2008/10/20 17:09:25  fabiankeil
+ *    Update init_error_log() description to match reality.
+ *
+ *    Revision 1.78  2008/09/07 16:59:31  fabiankeil
+ *    Update a comment to reflect that we
+ *    have mutex support on mingw32 now.
+ *
+ *    Revision 1.77  2008/09/07 12:43:44  fabiankeil
+ *    Move the LogPutString() call in log_error() into the locked
+ *    region so the Windows GUI log is consistent with the logfile.
+ *
+ *    Revision 1.76  2008/09/07 12:35:05  fabiankeil
+ *    Add mutex lock support for _WIN32.
+ *
+ *    Revision 1.75  2008/09/04 08:13:58  fabiankeil
+ *    Prepare for critical sections on Windows by adding a
+ *    layer of indirection before the pthread mutex functions.
+ *
+ *    Revision 1.74  2008/08/06 18:33:36  fabiankeil
+ *    If the "close fd first" workaround doesn't work,
+ *    the fatal error message will be lost, so we better
+ *    explain the consequences while we still can.
+ *
+ *    Revision 1.73  2008/08/04 19:06:55  fabiankeil
+ *    Add a lame workaround for the "can't open an already open
+ *    logfile on OS/2" problem reported by Maynard in #2028842
+ *    and describe what a real solution would look like.
+ *
+ *    Revision 1.72  2008/07/27 12:04:28  fabiankeil
+ *    Fix a comment typo.
+ *
+ *    Revision 1.71  2008/06/28 17:17:15  fabiankeil
+ *    Remove another stray semicolon.
+ *
+ *    Revision 1.70  2008/06/28 17:10:29  fabiankeil
+ *    Remove stray semicolon in get_log_timestamp().
+ *    Reported by Jochen Voss in #2005221.
+ *
+ *    Revision 1.69  2008/05/30 15:55:25  fabiankeil
+ *    Declare variable "debug" static and complain about its name.
+ *
+ *    Revision 1.68  2008/04/27 16:50:46  fabiankeil
+ *    Remove an incorrect assertion. The value of debug may change if
+ *    the configuration is reloaded in another thread. While we could
+ *    cache the initial value, the assertion doesn't seem worth it.
+ *
+ *    Revision 1.67  2008/03/27 18:27:23  fabiankeil
+ *    Remove kill-popups action.
+ *
+ *    Revision 1.66  2008/01/31 15:38:14  fabiankeil
+ *    - Make the logfp assertion more strict. As of 1.63, the "||" could
+ *      have been an "&&", which means we can use two separate assertions
+ *      and skip on of them on Windows.
+ *    - Break a long commit message line in two.
+ *
+ *    Revision 1.65  2008/01/31 14:44:33  fabiankeil
+ *    Use (a != b) instead of !(a == b) so the sanity check looks less insane.
+ *
+ *    Revision 1.64  2008/01/21 18:56:46  david__schmidt
+ *    Swap #def from negative to positive, re-joined it so it didn't
+ *    span an assertion (compilation failure on OS/2)
+ *
+ *    Revision 1.63  2007/12/15 19:49:32  fabiankeil
+ *    Stop overloading logfile to control the mingw32 log window as well.
+ *    It's no longer necessary now that we disable all debug lines by default
+ *    and at least one user perceived it as a regression (added in 1.55).
+ *
+ *    Revision 1.62  2007/11/30 15:33:46  fabiankeil
+ *    Unbreak LOG_LEVEL_FATAL. It wasn't fatal with logging disabled
+ *    and on mingw32 fatal log messages didn't end up in the log file.
+ *
+ *    Revision 1.61  2007/11/04 19:03:01  fabiankeil
+ *    Fix another deadlock Hal spotted and that mysteriously didn't affect FreeBSD.
+ *
+ *    Revision 1.60  2007/11/03 19:03:31  fabiankeil
+ *    - Prevent the Windows GUI from showing the version two times in a row.
+ *    - Stop using the imperative in the "(Re-)Open logfile" message.
+ *    - Ditch the "Switching to daemon mode" message as the detection
+ *      whether or not we're already in daemon mode doesn't actually work.
+ *
+ *    Revision 1.59  2007/11/01 12:50:56  fabiankeil
+ *    Here's looking at you, deadlock.
+ *
+ *    Revision 1.58  2007/10/28 19:04:21  fabiankeil
+ *    Don't mention daemon mode in "Logging disabled" message. Some
+ *    platforms call it differently and it's not really relevant anyway.
+ *
  *    Revision 1.57  2007/10/27 13:02:26  fabiankeil
  *    Relocate daemon-mode-related log messages to make sure
  *    they aren't shown again in case of configuration reloads.
@@ -355,8 +462,8 @@ const char errlog_h_rcs[] = ERRLOG_H_VERSION;
 /* where to log (default: stderr) */
 static FILE *logfp = NULL;
 
-/* logging detail level.  */
-int debug = (LOG_LEVEL_FATAL | LOG_LEVEL_ERROR | LOG_LEVEL_INFO);  
+/* logging detail level. XXX: stupid name. */
+static int debug = (LOG_LEVEL_FATAL | LOG_LEVEL_ERROR | LOG_LEVEL_INFO);  
 
 /* static functions */
 static void fatal_error(const char * error_message);
@@ -367,24 +474,24 @@ static char *w32_socket_strerr(int errcode, char *tmp_buf);
 static char *os2_socket_strerr(int errcode, char *tmp_buf);
 #endif
 
-#ifdef FEATURE_PTHREAD
+#ifdef MUTEX_LOCKS_AVAILABLE
 static inline void lock_logfile(void)
 {
-   pthread_mutex_lock(&log_mutex);
+   privoxy_mutex_lock(&log_mutex);
 }
 static inline void unlock_logfile(void)
 {
-   pthread_mutex_unlock(&log_mutex);
+   privoxy_mutex_unlock(&log_mutex);
 }
 static inline void lock_loginit(void)
 {
-   pthread_mutex_lock(&log_init_mutex);
+   privoxy_mutex_lock(&log_init_mutex);
 }
 static inline void unlock_loginit(void)
 {
-   pthread_mutex_unlock(&log_init_mutex);
+   privoxy_mutex_unlock(&log_init_mutex);
 }
-#else /* ! FEATURE_PTHREAD */
+#else /* ! MUTEX_LOCKS_AVAILABLE */
 /*
  * FIXME we need a cross-platform locking mechanism.
  * The locking/unlocking functions below should be 
@@ -418,11 +525,13 @@ static void fatal_error(const char * error_message)
 
    /* Cleanup - remove taskbar icon etc. */
    TermLogWindow();
-
-#else /* if !defined(_WIN32) || defined(_WIN_CONSOLE) */
-   fputs(error_message, logfp);
 #endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */
 
+   if (logfp != NULL)
+   {
+      fputs(error_message, logfp);
+   }
+
 #if defined(unix)
    if (pidfile)
    {
@@ -446,7 +555,7 @@ static void fatal_error(const char * error_message)
  * Returns     :  Nothing.
  *
  *********************************************************************/
-static void show_version(const char *prog_name)
+void show_version(const char *prog_name)
 {
    log_error(LOG_LEVEL_INFO, "Privoxy version " VERSION);
    if (prog_name != NULL)
@@ -470,13 +579,12 @@ static void show_version(const char *prog_name)
  * Returns     :  Nothing.
  *
  *********************************************************************/
-void init_log_module(const char *prog_name)
+void init_log_module(void)
 {
    lock_logfile();
    logfp = stderr;
    unlock_logfile();
    set_debug_level(debug);
-   show_version(prog_name);
 }
 
 
@@ -488,7 +596,7 @@ void init_log_module(const char *prog_name)
  *                plus LOG_LEVEL_MINIMUM.
  *
  *                XXX: we should only use the LOG_LEVEL_MINIMUM
- *                until the frist time the configuration file has
+ *                until the first time the configuration file has
  *                been parsed.
  *                
  * Parameters  :  1: debug_level = The debug level to set.
@@ -515,14 +623,15 @@ void set_debug_level(int debug_level)
  *********************************************************************/
 void disable_logging(void)
 {
-   lock_logfile();
    if (logfp != NULL)
    {
-      log_error(LOG_LEVEL_INFO, "No logfile configured. Logging disabled.");
+      log_error(LOG_LEVEL_INFO,
+         "No logfile configured. Please enable it before reporting any problems.");
+      lock_logfile();
       fclose(logfp);
       logfp = NULL;
+      unlock_logfile();
    }
-   unlock_logfile();
 }
 
 
@@ -536,8 +645,7 @@ void disable_logging(void)
  *
  * Parameters  :
  *          1  :  prog_name  = The program name.
- *          2  :  logfname   = The logfile name, or NULL for stderr.
- *          3  :  debuglevel = The debugging level.
+ *          2  :  logfname   = The logfile to (re)open.
  *
  * Returns     :  N/A
  *
@@ -549,20 +657,45 @@ void init_error_log(const char *prog_name, const char *logfname)
    assert(NULL != logfname);
 
    lock_loginit();
-   lock_logfile();
 
-   if (logfp == stderr)
-   {
-      log_error(LOG_LEVEL_INFO,
-         "Switching to daemon mode. Log messages will be written to: %s", logfname);
-   }
-   else if (logfp != NULL)
+   if (logfp != NULL)
    {
-      log_error(LOG_LEVEL_INFO, "(Re-)Open logfile \'%s\'", logfname ? logfname : "none");
+      log_error(LOG_LEVEL_INFO, "(Re-)Opening logfile \'%s\'", logfname);
    }
 
    /* set the designated log file */
    fp = fopen(logfname, "a");
+   if ((NULL == fp) && (logfp != NULL))
+   {
+      /*
+       * Some platforms (like OS/2) don't allow us to open
+       * the same file twice, therefore we give it another
+       * shot after closing the old file descriptor first.
+       *
+       * We don't do it right away because it prevents us
+       * from logging the "can't open logfile" message to
+       * the old logfile.
+       *
+       * XXX: this is a lame workaround and once the next
+       * release is out we should stop bothering reopening
+       * the logfile unless we have to.
+       *
+       * Currently we reopen it every time the config file
+       * has been reloaded, but actually we only have to
+       * reopen it if the file name changed or if the
+       * configuration reloas was caused by a SIGHUP.
+       */
+      log_error(LOG_LEVEL_INFO, "Failed to reopen logfile: \'%s\'. "
+         "Retrying after closing the old file descriptor first. If that "
+         "doesn't work, Privoxy will exit without being able to log a message.",
+         logfname);
+      lock_logfile();
+      fclose(logfp);
+      logfp = NULL;
+      unlock_logfile();
+      fp = fopen(logfname, "a");
+   }
+
    if (NULL == fp)
    {
       log_error(LOG_LEVEL_FATAL, "init_error_log(): can't open logfile: \'%s\'", logfname);
@@ -571,6 +704,7 @@ void init_error_log(const char *prog_name, const char *logfname)
    /* set logging to be completely unbuffered */
    setbuf(fp, NULL);
 
+   lock_logfile();
    if (logfp != NULL)
    {
       fclose(logfp);
@@ -578,7 +712,18 @@ void init_error_log(const char *prog_name, const char *logfname)
    logfp = fp;
    unlock_logfile();
 
+#if !defined(_WIN32)
+   /*
+    * Prevent the Windows GUI from showing the version two
+    * times in a row on startup. It already displayed the show_version()
+    * call from main() that other systems write to stderr.
+    *
+    * This means mingw32 users will never see the version in their
+    * log file, but I assume they wouldn't look for it there anyway
+    * and simply use the "Help/About Privoxy" menu.
+    */
    show_version(prog_name);
+#endif /* def unix */
 
    unlock_loginit();
 
@@ -661,15 +806,15 @@ static inline size_t get_log_timestamp(char *buffer, size_t buffer_size)
 #ifdef HAVE_LOCALTIME_R
    tm_now = *localtime_r(&now, &tm_now);
 #elif FEATURE_PTHREAD
-   pthread_mutex_lock(&localtime_mutex);
+   privoxy_mutex_lock(&localtime_mutex);
    tm_now = *localtime(&now); 
-   pthread_mutex_unlock(&localtime_mutex);
+   privoxy_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);
+   if (length > (size_t)0)
    {
       msecs_length = snprintf(buffer+length, buffer_size - length, ".%.3ld", msecs);               
    }
@@ -719,18 +864,18 @@ static inline size_t get_clf_timestamp(char *buffer, size_t buffer_size)
 #ifdef HAVE_GMTIME_R
    gmt = *gmtime_r(&now, &gmt);
 #elif FEATURE_PTHREAD
-   pthread_mutex_lock(&gmtime_mutex);
+   privoxy_mutex_lock(&gmtime_mutex);
    gmt = *gmtime(&now);
-   pthread_mutex_unlock(&gmtime_mutex);
+   privoxy_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);
+   privoxy_mutex_lock(&localtime_mutex);
    tm_now = localtime(&now); 
-   pthread_mutex_unlock(&localtime_mutex);
+   privoxy_mutex_unlock(&localtime_mutex);
 #else
    tm_now = localtime(&now); 
 #endif
@@ -740,7 +885,7 @@ static inline size_t get_clf_timestamp(char *buffer, size_t buffer_size)
 
    length = strftime(buffer, buffer_size, "%d/%b/%Y:%H:%M:%S ", tm_now);
 
-   if (length > 0);
+   if (length > (size_t)0)
    {
       tz_length = snprintf(buffer+length, buffer_size-length,
                      "%+03d%02d", mins / 60, abs(mins) % 60);
@@ -815,11 +960,9 @@ static inline const char *get_log_level_string(int loglevel)
       case LOG_LEVEL_DEANIMATE:
          log_level_string = "Gif-Deanimate";
          break;
-#ifdef FEATURE_KILL_POPUPS
-      case LOG_LEVEL_POPUPS:
-         log_level_string = "Kill-Popups";
+      case LOG_LEVEL_CRUNCH:
+         log_level_string = "Crunch";
          break;
-#endif /* def FEATURE_KILL_POPUPS */
       case LOG_LEVEL_CGI:
          log_level_string = "CGI";
          break;
@@ -870,7 +1013,7 @@ void log_error(int loglevel, const char *fmt, ...)
     * the taskbar icon animate.  (There is an option to disable
     * this but checking that is handled inside LogShowActivity()).
     */
-   if (loglevel == LOG_LEVEL_GPC)
+   if ((loglevel == LOG_LEVEL_GPC) || (loglevel == LOG_LEVEL_CRUNCH))
    {
       LogShowActivity();
    }
@@ -881,8 +1024,17 @@ void log_error(int loglevel, const char *fmt, ...)
     * settings and that logging is enabled.
     * Bail out otherwise.
     */
-   if ((0 == (loglevel & debug)) || (logfp == NULL))
+   if ((0 == (loglevel & debug))
+#ifndef _WIN32
+      || (logfp == NULL)
+#endif
+      )
    {
+      if (loglevel == LOG_LEVEL_FATAL)
+      {
+         fatal_error("Fatal error. You're not supposed to"
+            "see this message. Please file a bug report.");
+      }
       return;
    }
 
@@ -898,11 +1050,8 @@ void log_error(int loglevel, const char *fmt, ...)
       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);
-         assert(NULL != logfp);
-         fputs(tempbuf, logfp);
-         unlock_logfile();
+            "%s %08lx Fatal error: Out of memory in log_error().",
+            timestamp, thread_id);
          fatal_error(tempbuf); /* Exit */
       }
    }
@@ -917,8 +1066,8 @@ void log_error(int loglevel, const char *fmt, ...)
    /* 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));
+      length = (size_t)snprintf(outbuf, log_buffer_size, "%s %08lx %s: ",
+         timestamp, thread_id, get_log_level_string(loglevel));
    }
 
    /* get ready to scan var. args. */
@@ -940,9 +1089,9 @@ void log_error(int loglevel, const char *fmt, ...)
       {
          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.
+          * XXX: Only necessary on platforms where multiple threads
+          * can write to the buffer at the same time because we
+          * don't support mutexes (OS/2 for example).
           */
          outbuf[length] = '\0';
          continue;
@@ -1023,7 +1172,7 @@ void log_error(int loglevel, const char *fmt, ...)
                   format_string = "[counted string lenght < 0]";
                }
             }
-            else if (ival >= sizeof(tempbuf))
+            else if ((size_t)ival >= sizeof(tempbuf))
             {
                /*
                 * String is too long, copy as much as possible.
@@ -1099,9 +1248,9 @@ void log_error(int loglevel, const char *fmt, ...)
    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')
+   if ((length >= log_buffer_size)
+    || (outbuf[log_buffer_size-1] != '\0')
+    || (outbuf[log_buffer_size] != '\0')
       )
    {
       /* Repeat as assertions */
@@ -1115,27 +1264,37 @@ void log_error(int loglevel, const char *fmt, ...)
       assert(outbuf[log_buffer_size] == '\0');
 
       snprintf(outbuf, log_buffer_size,
-         "%s Privoxy(%08lx) Fatal error: log_error()'s sanity checks failed. length: %d\n"
-         "Exiting.", timestamp, thread_id, (int)length);
+         "%s %08lx Fatal error: log_error()'s sanity checks failed."
+         "length: %d. Exiting.",
+         timestamp, thread_id, (int)length);
       loglevel = LOG_LEVEL_FATAL;
    }
 
+#ifndef _WIN32
+   /*
+    * On Windows this is acceptable in case
+    * we are logging to the GUI window only.
+    */
    assert(NULL != logfp);
+#endif
 
    if (loglevel == LOG_LEVEL_FATAL)
    {
       fatal_error(outbuf_save);
       /* Never get here */
    }
-   fputs(outbuf_save, logfp);
-
-   unlock_logfile();
+   if (logfp != NULL)
+   {
+      fputs(outbuf_save, logfp);
+   }
 
 #if defined(_WIN32) && !defined(_WIN_CONSOLE)
    /* Write to display */
    LogPutString(outbuf_save);
 #endif /* defined(_WIN32) && !defined(_WIN_CONSOLE) */
 
+   unlock_logfile();
+
 }