MEDIUM: log: slightly refine the output format of alerts/warnings/etc

For about 20 years we've been emitting cryptic messages on warnings and
alerts, that nobody knows how to parse:

  [NOTICE] 126/080118 (3115) : haproxy version is 2.4-dev18-0b7c78-49
  [NOTICE] 126/080118 (3115) : path to executable is ./haproxy
  [WARNING] 126/080119 (3115) : Server default/srv1 is DOWN via static/srv1. 0 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
  [ALERT] 126/080119 (3115) : backend 'default' has no server available!

Hint: the first 3-digit number is the day of year, and the 6 digits
after it represent the time of day in format HHMMSS, then the pid in
parenthesis. These are not quite user-friendly and such cryptic into
are not useful at all.

This patch slightly adjusts the output by performing these minimal changes:
  - removing the date/time, as they were added very early when haproxy
    was meant to be used in foreground as a debugging tool, and they're
    provided in more details in logs nowadays ;

  - better aligning the fields by padding the severity tag to 10 chars.
    The diag output was renamed to "DIAG" only.

Now the output provides this:

  [NOTICE]   (4563) : haproxy version is 2.4-dev18-75a428-51
  [NOTICE]   (4563) : path to executable is ./haproxy
  [WARNING]  (4563) : Server default/srv1 is DOWN via static/srv1. 0 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.
  [ALERT]    (4563) : backend 'default' has no server available!

The useless space before the colon was kept so as not to confuse any
possible output parser.

The few entries in the doc referring to this format were adjusted to
reflect the new one.

The change was tagged "MEDIUM" as it may have visible consequences on
home-grown monitoring tools, though it is extremely unlikely due to the
limited extent of these changes.

diff --git a/doc/lua.txt b/doc/lua.txt
index 9bf9f144d9b0eb2e96716cfcf271f6a31ff7f39e..d05ff1de176a8c3401edc33440a64c4445cb48d9 100644 (file)
--- a/doc/lua.txt
+++ b/doc/lua.txt
@@ -642,7 +642,7 @@ the associated error.
 
    open("./luac/concat.so", O_RDONLY|O_CLOEXEC) = 4
 
-       [ALERT] 293/175822 (22806) : parsing [commonstats.conf:15] : lua runtime
+       [ALERT]    (22806) : parsing [commonstats.conf:15] : lua runtime
        error: error loading module 'luac/concat' from file './luac/concat.so':
                ./luac/concat.so: undefined symbol: luaopen_luac/concat
 

diff --git a/doc/regression-testing.txt b/doc/regression-testing.txt
index 1b6c21d10bb71aa056023f36c7299756dd39f862..aac312cde877d9a4943b54329d9796b2231f689e 100644 (file)
--- a/doc/regression-testing.txt
+++ b/doc/regression-testing.txt
@@ -228,9 +228,9 @@ as expected (verbose mode execution):
     **** h1    0.0 macro def h1_name=/tmp/vtc.25540.59b6ec5d/h1
     **   h1    0.0 Wait
     **   h1    0.0 Stop HAproxy pid=25558
-    ***  h1    0.0 debug|[ALERT] 157/135318 (25558) : parsing [/tmp/vtc.25540.59b6ec5d/h1/cfg:10] : 'filter' : ''spoe' : missing config file'
-    ***  h1    0.0 debug|[ALERT] 157/135318 (25558) : Error(s) found in configuration file : /tmp/vtc.25540.59b6ec5d/h1/cfg
-    ***  h1    0.0 debug|[ALERT] 157/135318 (25558) : Fatal errors found in configuration.
+    ***  h1    0.0 debug|[ALERT]    (25558) : parsing [/tmp/vtc.25540.59b6ec5d/h1/cfg:10] : 'filter' : ''spoe' : missing config file'
+    ***  h1    0.0 debug|[ALERT]    (25558) : Error(s) found in configuration file : /tmp/vtc.25540.59b6ec5d/h1/cfg
+    ***  h1    0.0 debug|[ALERT]    (25558) : Fatal errors found in configuration.
     **** h1    0.0 STDOUT poll 0x10
     **   h1    0.0 WAIT4 pid=25558 status=0x0100 (user 0.000000 sys 0.000000)
     **   h1    0.0 Found expected ''

diff --git a/src/log.c b/src/log.c
index fe0e3a2ea837aea95abfafb774cbef71ca523390..f760bacba7e7778339940b2406795ed266e69a58 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -1081,14 +1081,19 @@ int parse_logsrv(char **args, struct list *logsrvs, int do_del, const char *file
 /* Generic function to display messages prefixed by a label */
 static void print_message(const char *label, const char *fmt, va_list argp)
 {
-       struct tm tm;
        char *head, *msg;
+       char prefix[11]; // '[' + 8 chars + ']' + 0.
 
-       head = msg = NULL;
+       *prefix = '[';
+       strncpy(prefix + 1, label, sizeof(prefix) - 2);
+       msg = prefix + strlen(prefix);
+       *msg++ = ']';
+       while (msg < prefix + sizeof(prefix) - 1)
+               *msg++ = ' ';
+       *msg = 0;
 
-       get_localtime(date.tv_sec, &tm);
-       memprintf(&head, "[%s] %03d/%02d%02d%02d (%d) : ",
-                 label, tm.tm_yday, tm.tm_hour, tm.tm_min, tm.tm_sec, (int)getpid());
+       head = msg = NULL;
+       memprintf(&head, "%s (%u) : ", prefix, (uint)getpid());
        memvprintf(&msg, fmt, argp);
 
        if (global.mode & MODE_STARTING) {
@@ -1160,7 +1165,7 @@ void ha_warning(const char *fmt, ...)
  */
 void _ha_vdiag_warning(const char *fmt, va_list argp)
 {
-       print_message("DIAG/WARNING", fmt, argp);
+       print_message("DIAG", fmt, argp);
 }
 
 /*