BUG/MINOR: log: make "show startup-log" use a ring buffer instead

The copy of the startup logs used to rely on a re-allocated memory area
on the fly, that would attempt to be delivered at once over the CLI. But
if it's too large (too many warnings) it will take time to start up, and
may not even show up on the CLI as it doesn't fit in a buffer.

The ring buffer infrastructure solves all this with no more code, let's
switch to this instead. It simply requires a parsing function to attach
the ring via ring_attach_cli() and all the rest is automatically handled.

Initially this was imagined as a code cleanup, until a test with a config
involving 100k backends and just one occurrence of
"load-server-state-from-file global" in the defaults section took approx
20 minutes to parse due to the O(N^2) cost of concatenating the warnings
resulting in ~1 TB of data to be copied, while it took only 0.57s with
the ring.

Ideally this patch should be backported to 2.0 and 1.9, though it relies
on the ring infrastructure which will then also need to be backported.
Configs able to trigger the bug are uncommon, so another workaround for
older versions without backporting the rings would consist in simply
limiting the size of the error message in print_message() to something
always printable, which will only return the first errors.
This commit is contained in:
Willy Tarreau 2019-11-15 15:16:57 +01:00
parent fcf94981e4
commit 869efd5eeb
2 changed files with 31 additions and 19 deletions

View File

@ -36,6 +36,11 @@
#define SYSLOG_PORT 514 #define SYSLOG_PORT 514
#define UNIQUEID_LEN 128 #define UNIQUEID_LEN 128
/* 64kB to archive startup-logs seems way more than enough */
#ifndef STARTUP_LOG_SIZE
#define STARTUP_LOG_SIZE 65536
#endif
/* The array containing the names of the log levels. */ /* The array containing the names of the log levels. */
extern const char *log_levels[]; extern const char *log_levels[];

View File

@ -248,7 +248,7 @@ THREAD_LOCAL char *logline_rfc5424 = NULL;
/* A global buffer used to store all startup alerts/warnings. It will then be /* A global buffer used to store all startup alerts/warnings. It will then be
* retrieve on the CLI. */ * retrieve on the CLI. */
static char *startup_logs = NULL; static struct ring *startup_logs = NULL;
struct logformat_var_args { struct logformat_var_args {
char *name; char *name;
@ -1056,8 +1056,21 @@ static void print_message(const char *label, const char *fmt, va_list argp)
label, tm.tm_yday, tm.tm_hour, tm.tm_min, tm.tm_sec, (int)getpid()); label, tm.tm_yday, tm.tm_hour, tm.tm_min, tm.tm_sec, (int)getpid());
memvprintf(&msg, fmt, argp); memvprintf(&msg, fmt, argp);
if (global.mode & MODE_STARTING) if (global.mode & MODE_STARTING) {
memprintf(&startup_logs, "%s%s%s", (startup_logs ? startup_logs : ""), head, msg); if (unlikely(!startup_logs))
startup_logs = ring_new(STARTUP_LOG_SIZE);
if (likely(startup_logs)) {
struct ist m[2];
m[0] = ist(head);
m[1] = ist(msg);
/* trim the trailing '\n' */
if (m[1].len > 0 && m[1].ptr[m[1].len - 1] == '\n')
m[1].len--;
ring_write(startup_logs, ~0, 0, 0, m, 2);
}
}
fprintf(stderr, "%s%s", head, msg); fprintf(stderr, "%s%s", head, msg);
fflush(stderr); fflush(stderr);
@ -1901,20 +1914,15 @@ int init_log_buffers()
/* Deinitialize log buffers used for syslog messages */ /* Deinitialize log buffers used for syslog messages */
void deinit_log_buffers() void deinit_log_buffers()
{ {
void *tmp_startup_logs;
free(logheader); free(logheader);
free(logheader_rfc5424); free(logheader_rfc5424);
free(logline); free(logline);
free(logline_rfc5424); free(logline_rfc5424);
tmp_startup_logs = _HA_ATOMIC_XCHG(&startup_logs, NULL); ring_free(_HA_ATOMIC_XCHG(&startup_logs, NULL));
free(tmp_startup_logs);
logheader = NULL; logheader = NULL;
logheader_rfc5424 = NULL; logheader_rfc5424 = NULL;
logline = NULL; logline = NULL;
logline_rfc5424 = NULL; logline_rfc5424 = NULL;
startup_logs = NULL;
} }
/* Builds a log line in <dst> based on <list_format>, and stops before reaching /* Builds a log line in <dst> based on <list_format>, and stops before reaching
@ -3027,23 +3035,22 @@ void app_log(struct list *logsrvs, struct buffer *tag, int level, const char *fo
__send_log(logsrvs, tag, level, logline, data_len, default_rfc5424_sd_log_format, 2); __send_log(logsrvs, tag, level, logline, data_len, default_rfc5424_sd_log_format, 2);
} }
static int cli_io_handler_show_startup_logs(struct appctx *appctx) /* parse the "show startup-logs" command, returns 1 if a message is returned, otherwise zero */
static int cli_parse_show_startup_logs(char **args, char *payload, struct appctx *appctx, void *private)
{ {
struct stream_interface *si = appctx->owner; if (!cli_has_level(appctx, ACCESS_LVL_OPER))
const char *msg = (startup_logs ? startup_logs : "No startup alerts/warnings.\n");
if (ci_putstr(si_ic(si), msg) == -1) {
si_rx_room_blk(si);
return 0;
}
return 1; return 1;
if (!startup_logs)
return cli_msg(appctx, LOG_INFO, "\n"); // nothing to print
return ring_attach_cli(startup_logs, appctx);
} }
/* register cli keywords */ /* register cli keywords */
static struct cli_kw_list cli_kws = {{ },{ static struct cli_kw_list cli_kws = {{ },{
{ { "show", "startup-logs", NULL }, { { "show", "startup-logs", NULL },
"show startup-logs : report logs emitted during HAProxy startup", "show startup-logs : report logs emitted during HAProxy startup", cli_parse_show_startup_logs, NULL, NULL },
NULL, cli_io_handler_show_startup_logs },
{{},} {{},}
}}; }};