From 9f903af510771fc47525c7161c0c94763dff9e0d Mon Sep 17 00:00:00 2001 From: Willy Tarreau Date: Fri, 7 May 2021 08:42:39 +0200 Subject: [PATCH] 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. --- doc/lua.txt | 2 +- doc/regression-testing.txt | 6 +++--- src/log.c | 17 +++++++++++------ 3 files changed, 15 insertions(+), 10 deletions(-) diff --git a/doc/lua.txt b/doc/lua.txt index 9bf9f144d..d05ff1de1 100644 --- 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 1b6c21d10..aac312cde 100644 --- 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 fe0e3a2ea..f760bacba 100644 --- 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. + + *prefix = '['; + strncpy(prefix + 1, label, sizeof(prefix) - 2); + msg = prefix + strlen(prefix); + *msg++ = ']'; + while (msg < prefix + sizeof(prefix) - 1) + *msg++ = ' '; + *msg = 0; head = msg = NULL; - - 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()); + 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); } /*