Add timestamps to (most) FATAL messages (#179)

Reliable timestamp information is often critical for triage. We can use
the existing debugs() interface to add timestamps to FATAL messages. The
affected code already calls such risky functions as
storeDirWriteCleanLogs() so calling debugs() instead of printing
directly to files/syslog should not make things worse.

FATAL messages that were also logged to syslog (at LOG_ALERT level) are
still logged to syslog (at that same level, but now with the usual
Squid-generated prefix). Such syslog alerts can now be easily triggered
via a new ForceAlert() API.

Also treat segmentation faults, bus errors, and other signal-based
sudden deaths the same as most other FATAL errors -- log them to syslog.

This is a Measurement Factory project.

diff --git a/src/Debug.h b/src/Debug.h
index 3fb9003253243d037083245f28b2d7dbf272ae6b..ccb3111bedc54795a469685f9a8107a18e58e330 100644 (file)
--- a/src/Debug.h
+++ b/src/Debug.h
@@ -68,6 +68,7 @@ public:
         void formatStream();
         Context *upper; ///< previous or parent record in nested debugging calls
         std::ostringstream buf; ///< debugs() output sink
+        bool forceAlert; ///< the current debugs() will be a syslog ALERT
     };
 
     /// whether debugging the given section and the given level produces output
@@ -96,6 +97,8 @@ public:
     /// logs output buffer created in Start() and closes debugging context
     static void Finish();
 
+    /// configures the active debugging context to write syslog ALERT
+    static void ForceAlert();
 private:
     static Context *Current; ///< deepest active context; nil outside debugs()
 };
@@ -132,6 +135,11 @@ void ResyncDebugLog(FILE *newDestination);
         } \
    } while (/*CONSTCOND*/ 0)
 
+/// Does not change the stream being manipulated. Exists for its side effect:
+/// In a debugs() context, forces the message to become a syslog ALERT.
+/// Outside of debugs() context, has no effect and should not be used.
+std::ostream& ForceAlert(std::ostream& s);
+
 /** stream manipulator which does nothing.
  * \deprecated Do not add to new code, and remove when editing old code
  *
@@ -166,7 +174,6 @@ inline std::ostream& operator <<(std::ostream &os, const uint8_t d)
 
 /* Legacy debug function definitions */
 void _db_init(const char *logfile, const char *options);
-void _db_print(const char *,...) PRINTF_FORMAT_ARG1;
 void _db_set_syslog(const char *facility);
 void _db_rotate_log(void);
 

diff --git a/src/debug.cc b/src/debug.cc
index f727165ce99058824e6b2e598303cf002eebf5c7..82ae61560e6dc3bbca46006efceecc900b347cd1 100644 (file)
--- a/src/debug.cc
+++ b/src/debug.cc
@@ -34,7 +34,7 @@ static void ctx_print(void);
 #ifdef LOG_LOCAL4
 static int syslog_facility = 0;
 #endif
-static void _db_print_syslog(const char *format, va_list args);
+static void _db_print_syslog(const bool forceAlert, const char *format, va_list args);
 #endif
 static void _db_print_stderr(const char *format, va_list args);
 static void _db_print_file(const char *format, va_list args);
@@ -108,8 +108,9 @@ DebugFile::reset(FILE *newFile, const char *newName)
     assert(!file_ == !name);
 }
 
+static
 void
-_db_print(const char *format,...)
+_db_print(const bool forceAlert, const char *format,...)
 {
     char f[BUFSIZ];
     f[0]='\0';
@@ -167,7 +168,7 @@ _db_print(const char *format,...)
     _db_print_stderr(f, args2);
 
 #if HAVE_SYSLOG
-    _db_print_syslog(format, args3);
+    _db_print_syslog(forceAlert, format, args3);
 #endif
 
 #if _SQUID_WINDOWS_
@@ -207,15 +208,17 @@ _db_print_stderr(const char *format, va_list args)
 
 #if HAVE_SYSLOG
 static void
-_db_print_syslog(const char *format, va_list args)
+_db_print_syslog(const bool forceAlert, const char *format, va_list args)
 {
     /* level 0,1 go to syslog */
 
-    if (Debug::Level() > 1)
-        return;
+    if (!forceAlert) {
+        if (Debug::Level() > 1)
+            return;
 
-    if (!Debug::log_syslog)
-        return;
+        if (!Debug::log_syslog)
+            return;
+    }
 
     char tmpbuf[BUFSIZ];
     tmpbuf[0] = '\0';
@@ -224,7 +227,7 @@ _db_print_syslog(const char *format, va_list args)
 
     tmpbuf[BUFSIZ - 1] = '\0';
 
-    syslog(Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
+    syslog(forceAlert ? LOG_ALERT : (Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE), "%s", tmpbuf);
 }
 #endif /* HAVE_SYSLOG */
 
@@ -744,10 +747,10 @@ ctx_print(void)
 
     if (Ctx_Valid_Level < Ctx_Reported_Level) {
         if (Ctx_Reported_Level != Ctx_Valid_Level + 1)
-            _db_print("ctx: exit levels from %2d down to %2d\n",
+            _db_print(false, "ctx: exit levels from %2d down to %2d\n",
                       Ctx_Reported_Level, Ctx_Valid_Level + 1);
         else
-            _db_print("ctx: exit level %2d\n", Ctx_Reported_Level);
+            _db_print(false, "ctx: exit level %2d\n", Ctx_Reported_Level);
 
         Ctx_Reported_Level = Ctx_Valid_Level;
     }
@@ -756,7 +759,7 @@ ctx_print(void)
     while (Ctx_Reported_Level < Ctx_Current_Level) {
         ++Ctx_Reported_Level;
         ++Ctx_Valid_Level;
-        _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
+        _db_print(false, "ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
                   ctx_get_descr(Ctx_Reported_Level));
     }
 
@@ -779,7 +782,8 @@ Debug::Context *Debug::Current = nullptr;
 Debug::Context::Context(const int aSection, const int aLevel):
     level(aLevel),
     sectionLevel(Levels[aSection]),
-    upper(Current)
+    upper(Current),
+    forceAlert(false)
 {
     formatStream();
 }
@@ -836,7 +840,8 @@ void
 Debug::Finish()
 {
     // TODO: Optimize to remove at least one extra copy.
-    _db_print("%s\n", Current->buf.str().c_str());
+    _db_print(Current->forceAlert, "%s\n", Current->buf.str().c_str());
+    Current->forceAlert = false;
 
     Context *past = Current;
     Current = past->upper;
@@ -845,6 +850,21 @@ Debug::Finish()
     // else it was a static topContext from Debug::Start()
 }
 
+void
+Debug::ForceAlert()
+{
+    //  the ForceAlert(ostream) manipulator should only be used inside debugs()
+    if (Current)
+        Current->forceAlert = true;
+}
+
+std::ostream&
+ForceAlert(std::ostream& s)
+{
+    Debug::ForceAlert();
+    return s;
+}
+
 /// print data bytes using hex notation
 void
 Raw::printHex(std::ostream &os) const

diff --git a/src/fatal.cc b/src/fatal.cc
index a50d37b255709544093595576ee2c80075928a10..f5da9b3f7c2429f4a68e37c088fd3e0e3afb296d 100644 (file)
--- a/src/fatal.cc
+++ b/src/fatal.cc
@@ -16,19 +16,8 @@
 static void
 fatal_common(const char *message)
 {
-#if HAVE_SYSLOG
-    syslog(LOG_ALERT, "%s", message);
-#endif
-
-    fprintf(debug_log, "FATAL: %s\n", message);
-
-    if (Debug::log_stderr > 0 && debug_log != stderr)
-        fprintf(stderr, "FATAL: %s\n", message);
-
-    fprintf(debug_log, "Squid Cache (Version %s): Terminated abnormally.\n",
-            version_string);
-
-    fflush(debug_log);
+    debugs(1, DBG_CRITICAL, ForceAlert << "FATAL: " << message);
+    debugs(1, DBG_CRITICAL, "Squid Cache (Version " << version_string << "): Terminated abnormally.");
 
     PrintRusage();
 

diff --git a/src/tests/stub_debug.cc b/src/tests/stub_debug.cc
index adc942834243c5c930612425bf53ffaf86a3fa2b..9ddaf949c8db9ff2ff681e56fbcf238a73dfda1c 100644 (file)
--- a/src/tests/stub_debug.cc
+++ b/src/tests/stub_debug.cc
@@ -26,6 +26,7 @@ int Debug::Levels[MAX_DEBUG_SECTIONS];
 int Debug::override_X = 0;
 int Debug::log_stderr = 1;
 bool Debug::log_syslog = false;
+void Debug::ForceAlert() STUB
 
 void StopUsingDebugLog() STUB
 void ResyncDebugLog(FILE *) STUB
@@ -125,6 +126,12 @@ Debug::Finish()
     }
 }
 
+std::ostream&
+ForceAlert(std::ostream& s)
+{
+    return s;
+}
+
 std::ostream &
 Raw::print(std::ostream &os) const
 {

diff --git a/src/tools.cc b/src/tools.cc
index daf057528b87e51c6da06e1a4c90b5e4d91cca95..0fe5aadc48464e6e87163d23bca9e30800d86b82 100644 (file)
--- a/src/tools.cc
+++ b/src/tools.cc
@@ -291,11 +291,11 @@ void
 death(int sig)
 {
     if (sig == SIGSEGV)
-        fprintf(debug_log, "FATAL: Received Segment Violation...dying.\n");
+        debugs(1, DBG_CRITICAL, ForceAlert << "FATAL: Received Segment Violation...dying.");
     else if (sig == SIGBUS)
-        fprintf(debug_log, "FATAL: Received Bus Error...dying.\n");
+        debugs(1, DBG_CRITICAL, ForceAlert << "FATAL: Received Bus Error...dying.");
     else
-        fprintf(debug_log, "FATAL: Received signal %d...dying.\n", sig);
+        debugs(1, DBG_CRITICAL, ForceAlert << "FATAL: Received signal " << sig << "...dying.");
 
 #if PRINT_STACK_TRACE
 #if _SQUID_HPUX_
@@ -405,7 +405,7 @@ debug_trap(const char *message)
     if (!opt_catch_signals)
         fatal_dump(message);
 
-    _db_print("WARNING: %s\n", message);
+    debugs(50, DBG_CRITICAL, "WARNING: " << message);
 }
 
 const char *