Do not die silently when dying early. (#43)

Report (to stderr) various problems (e.g., unhandled exceptions) that
may occur very early in Squid lifetime, before stderr-logging is forced
by SquidMain() and way before proper logging is configured by the first
_db_init() call.

To enable such early reporting, we started with a trivial change:
  -FILE *debug_log = NULL;
  +FILE *debug_log = stderr;
... but realized that debug_log may not be assigned early enough! The
resulting (larger) changes ensure that we can log (to stderr if
necessary) as soon as stderr itself is initialized. They also polish
related logging code, including localization of stderr checks and
elimination of double-closure during log rotation on Windows.

These reporting changes do not bypass or eliminate any failures.

diff --git a/src/Debug.h b/src/Debug.h
index 86289b26e2c79b23387652bc9b172250f63e47f4..b32a9603d7354dd88b2070d4f8061a38f9d911a0 100644 (file)
--- a/src/Debug.h
+++ b/src/Debug.h
@@ -99,7 +99,17 @@ private:
     static Context *Current; ///< deepest active context; nil outside debugs()
 };
 
-extern FILE *debug_log;
+/// cache.log FILE or, as the last resort, stderr stream;
+/// may be nil during static initialization and destruction!
+FILE *DebugStream();
+/// change-avoidance macro; new code should call DebugStream() instead
+#define debug_log DebugStream()
+
+/// start logging to stderr (instead of cache.log, if any)
+void StopUsingDebugLog();
+
+/// a hack for low-level file descriptor manipulations in ipcCreate()
+void ResyncDebugLog(FILE *newDestination);
 
 size_t BuildPrefixInit();
 const char * SkipBuildPrefix(const char* path);

diff --git a/src/debug.cc b/src/debug.cc
index 3d420801434b7da388b2243a4e45d7e24ad1f9c2..133675842cd3afe064f3f25643f4a3436591c27b 100644 (file)
--- a/src/debug.cc
+++ b/src/debug.cc
@@ -26,8 +26,6 @@ bool Debug::log_syslog = false;
 int Debug::Levels[MAX_DEBUG_SECTIONS];
 char *Debug::cache_log = NULL;
 int Debug::rotateNumber = -1;
-FILE *debug_log = NULL;
-static char *debug_log_file = NULL;
 static int Ctx_Lock = 0;
 static const char *debugLogTime(void);
 static const char *debugLogKid(void);
@@ -46,6 +44,70 @@ extern LPCRITICAL_SECTION dbg_mutex;
 typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
 #endif
 
+/// a (FILE*, file name) pair that uses stderr FILE as the last resort
+class DebugFile
+{
+public:
+    DebugFile() {}
+    ~DebugFile() { clear(); }
+    DebugFile(DebugFile &&) = delete; // no copying or moving of any kind
+
+    /// switches to the new pair, absorbing FILE and duping the name
+    void reset(FILE *newFile, const char *newName);
+
+    /// go back to the initial state
+    void clear() { reset(nullptr, nullptr); }
+
+    /// logging stream; the only method that uses stderr as the last resort
+    FILE *file() { return file_ ? file_ : stderr; }
+
+    char *name = nullptr;
+
+private:
+    friend void ResyncDebugLog(FILE *newFile);
+
+    FILE *file_ = nullptr; ///< opened "real" file or nil; never stderr
+};
+
+/// configured cache.log file or stderr
+/// safe during static initialization, even if it has not been constructed yet
+static DebugFile TheLog;
+
+FILE *
+DebugStream() {
+    return TheLog.file();
+}
+
+void
+StopUsingDebugLog()
+{
+    TheLog.clear();
+}
+
+void
+ResyncDebugLog(FILE *newFile)
+{
+    TheLog.file_ = newFile;
+}
+
+void
+DebugFile::reset(FILE *newFile, const char *newName)
+{
+    // callers must use nullptr instead of the used-as-the-last-resort stderr
+    assert(newFile != stderr || !stderr);
+
+    if (file_)
+        fclose(file_);
+    file_ = newFile; // may be nil
+
+    xfree(name);
+    name = newName ? xstrdup(newName) : nullptr;
+
+    // all open files must have a name
+    // all cleared files must not have a name
+    assert(!file_ == !name);
+}
+
 void
 _db_print(const char *format,...)
 {
@@ -210,18 +272,10 @@ static void
 debugOpenLog(const char *logfile)
 {
     if (logfile == NULL) {
-        debug_log = stderr;
+        TheLog.clear();
         return;
     }
 
-    if (debug_log_file)
-        xfree(debug_log_file);
-
-    debug_log_file = xstrdup(logfile);  /* keep a static copy */
-
-    if (debug_log && debug_log != stderr)
-        fclose(debug_log);
-
     // Bug 4423: ignore the stdio: logging module name if present
     const char *logfilename;
     if (strncmp(logfile, "stdio:",6) == 0)
@@ -229,19 +283,18 @@ debugOpenLog(const char *logfile)
     else
         logfilename = logfile;
 
-    debug_log = fopen(logfilename, "a+");
-
-    if (!debug_log) {
+    if (auto log = fopen(logfilename, "a+")) {
+#if _SQUID_WINDOWS_
+        setmode(fileno(log), O_TEXT);
+#endif
+        TheLog.reset(log, logfilename);
+    } else {
         fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile);
         perror(logfile);
         fprintf(stderr, "         messages will be sent to 'stderr'.\n");
         fflush(stderr);
-        debug_log = stderr;
+        TheLog.clear();
     }
-
-#if _SQUID_WINDOWS_
-    setmode(fileno(debug_log), O_TEXT);
-#endif
 }
 
 #if HAVE_SYSLOG
@@ -445,12 +498,12 @@ _db_init(const char *logfile, const char *options)
 void
 _db_rotate_log(void)
 {
-    if (debug_log_file == NULL)
+    if (!TheLog.name)
         return;
 
 #ifdef S_ISREG
     struct stat sb;
-    if (stat(debug_log_file, &sb) == 0)
+    if (stat(TheLog.name, &sb) == 0)
         if (S_ISREG(sb.st_mode) == 0)
             return;
 #endif
@@ -469,8 +522,8 @@ _db_rotate_log(void)
     /* Rotate numbers 0 through N up one */
     for (int i = Debug::rotateNumber; i > 1;) {
         --i;
-        snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1);
-        snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i);
+        snprintf(from, MAXPATHLEN, "%s.%d", TheLog.name, i - 1);
+        snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, i);
 #if _SQUID_WINDOWS_
         remove
         (to);
@@ -482,36 +535,31 @@ _db_rotate_log(void)
         }
     }
 
-    /*
-     * You can't rename open files on Microsoft "operating systems"
-     * so we close before renaming.
-     */
-#if _SQUID_WINDOWS_
-    if (debug_log != stderr)
-        fclose(debug_log);
-#endif
     /* Rotate the current log to .0 */
     if (Debug::rotateNumber > 0) {
-        snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, 0);
+        // form file names before we may clear TheLog below
+        snprintf(from, MAXPATHLEN, "%s", TheLog.name);
+        snprintf(to, MAXPATHLEN, "%s.%d", TheLog.name, 0);
+
 #if _SQUID_WINDOWS_
         errno = 0;
         if (remove(to) == -1) {
             const auto saved_errno = errno;
             debugs(0, DBG_IMPORTANT, "removal of log file " << to << " failed: " << xstrerr(saved_errno));
         }
+        TheLog.clear(); // Windows cannot rename() open files
 #endif
         errno = 0;
-        if (rename(debug_log_file, to) == -1) {
+        if (rename(from, to) == -1) {
             const auto saved_errno = errno;
-            debugs(0, DBG_IMPORTANT, "renaming file " << debug_log_file << " to "
+            debugs(0, DBG_IMPORTANT, "renaming file " << from << " to "
                    << to << "failed: " << xstrerr(saved_errno));
         }
     }
 
-    /* Close and reopen the log.  It may have been renamed "manually"
-     * before HUP'ing us. */
-    if (debug_log != stderr)
-        debugOpenLog(Debug::cache_log);
+    // Close (if we have not already) and reopen the log because
+    // it may have been renamed "manually" before HUP'ing us.
+    debugOpenLog(Debug::cache_log);
 }
 
 static const char *

diff --git a/src/ipc.cc b/src/ipc.cc
index 8fd9f45e45e71ce37e9f8b7d55bf24bdfa8c6a87..90f8eed2596f93b3b0a5100c8e97a946bfe25638 100644 (file)
--- a/src/ipc.cc
+++ b/src/ipc.cc
@@ -416,7 +416,7 @@ ipcCreate(int type, const char *prog, const char *const args[], const char *name
     execvp(prog, (char *const *) args);
     xerrno = errno;
 
-    debug_log = fdopen(2, "a+");
+    ResyncDebugLog(fdopen(2, "a+"));
 
     debugs(54, DBG_CRITICAL, "ipcCreate: " << prog << ": " << xstrerr(xerrno));
 

diff --git a/src/main.cc b/src/main.cc
index fbc833be74b22593e6d372c8c9064a59d164bb88..c42e0be0fe800f12f495e162d95ae509943c9056 100644 (file)
--- a/src/main.cc
+++ b/src/main.cc
@@ -1457,7 +1457,6 @@ SquidMain(int argc, char **argv)
     ConfigureCurrentKid(argv[0]);
 
     Debug::parseOptions(NULL);
-    debug_log = stderr;
 
 #if defined(SQUID_MAXFD_LIMIT)
 
@@ -1717,7 +1716,7 @@ SquidMain(int argc, char **argv)
 static void
 sendSignal(void)
 {
-    debug_log = stderr;
+    StopUsingDebugLog();
 
 #if USE_WIN32_SERVICE
     // WIN32_sendSignal() does not need the PID value to signal,

diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc
index ce9fc5d81ec2179422a94bb699d45aba78cc6507..c1b698473fa78fc8c265fea56160220a9e3c0481 100644 (file)
--- a/src/tests/stub_debug.cc
+++ b/src/tests/stub_debug.cc
@@ -16,7 +16,8 @@
 #include "squid.h"
 #include "Debug.h"
 
-FILE *debug_log = NULL;
+#define STUB_API "debug.cc"
+#include "tests/STUB.h"
 
 char *Debug::debugOptions;
 char *Debug::cache_log= NULL;
@@ -26,6 +27,15 @@ int Debug::override_X = 0;
 int Debug::log_stderr = 1;
 bool Debug::log_syslog = false;
 
+void StopUsingDebugLog() STUB
+void ResyncDebugLog(FILE *) STUB
+
+FILE *
+DebugStream()
+{
+    return stderr;
+}
+
 Ctx
 ctx_enter(const char *)
 {