From: Christos Tsantilas <christos@chtsanti.net>
Date: Sat, 14 Apr 2018 02:14:46 +0000 (+0000)
Subject: Add timestamps to (most) FATAL messages (#179)
X-Git-Tag: SQUID_4_0_25~19
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=32ce6085a51fb7183197a43cce03b0a440dd0464;p=thirdparty%2Fsquid.git

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 3fb9003253..ccb3111bed 100644
--- 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 f727165ce9..82ae61560e 100644
--- 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 a50d37b255..f5da9b3f7c 100644
--- 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 adc9428342..9ddaf949c8 100644
--- 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 daf057528b..0fe5aadc48 100644
--- 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 *