From 0c7e529e20c71bc534b62813e0b6c33bb03944c1 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Mon, 21 Aug 2017 19:09:23 -0600 Subject: [PATCH] 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. --- src/Debug.h | 12 +++- src/debug.cc | 124 ++++++++++++++++++++++++++++------------ src/ipc.cc | 2 +- src/main.cc | 3 +- src/tests/stub_debug.cc | 12 +++- 5 files changed, 110 insertions(+), 43 deletions(-) diff --git a/src/Debug.h b/src/Debug.h index 86289b26e2..b32a9603d7 100644 --- 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 930ac55e0e..9d79a5fe58 100644 --- 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 8fd9f45e45..90f8eed259 100644 --- 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 7a7e7aa2aa..99bd564390 100644 --- a/src/main.cc +++ b/src/main.cc @@ -1471,7 +1471,6 @@ SquidMain(int argc, char **argv) ConfigureCurrentKid(argv[0]); Debug::parseOptions(NULL); - debug_log = stderr; #if defined(SQUID_MAXFD_LIMIT) @@ -1731,7 +1730,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 ce9fc5d81e..c1b698473f 100644 --- 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 *) { -- 2.47.2