MAJOR: log: implement proper postparsing for logformat expressions

This patch tries to address a design flaw with how logformat expressions
are parsed from config. Indeed, some parse_logformat_string() calls are
performed during config parsing when the proxy mode is not yet known.

Here's a config example that illustrates the issue:

  defaults
     mode tcp

  listen test
     bind :8888
     http-response set-header custom-hdr "%trl" # needs http
     mode http

The above config should work, because the effective proxy mode is http,
yet haproxy fails with this error:

  [ALERT]    (99051) : config : parsing [repro.conf:6] : error detected in proxy 'test' while parsing 'http-response set-header' rule : format tag 'trl' is reserved for HTTP mode.

To fix the issue once and for all, let's implement smart postparsing for
logformat expressions encountered during config parsing:

  - split parse_logformat_string() (and subfonctions) in order to create a
    new lf_expr_postcheck() function that must be called to finish
    preparing and checking the logformat expression once the proxy type is
    known.
  - save some config hints info during parse_logformat_string() to
    generate more precise error messages during lf_expr_postcheck(), if
    needed, we rely on curpx->conf.args.{file,line} hints for that because
    parse_logformat_string() doesn't know about current file and line
    number.
  - lf_expr_postcheck() uses PR_FL_CHECKED proxy flag to know if the
    function may try to make the proxy compatible with the expression, or
    if it should simply fail as soon as an incompatibility is detected.
  - if parse_logformat_string() is called from an unchecked proxy, then
    schedule the expression for postparsing, else (ie: during runtime),
    run the postcheck right away.

This change will also allow for some logformat expression error handling
simplifications in the future.
This commit is contained in:
Aurelien DARRAGON 2024-02-23 17:26:32 +01:00
parent 56d8074798
commit 7a21c3a4ef
10 changed files with 197 additions and 96 deletions

View File

@ -170,7 +170,12 @@ struct logformat_node {
/* a full logformat expr made of one or multiple logformat nodes */
struct lf_expr {
struct list nodes; /* logformat_node list */
struct list list; /* to store lf_expr inside a list */
struct list nodes; /* logformat_node list */
struct {
char *file; /* file where the lft appears */
int line; /* line where the lft appears */
} conf; // parsing hints
};
/* Range of indexes for log sampling. */

View File

@ -71,6 +71,7 @@ static inline int lf_expr_isempty(const struct lf_expr *expr)
{
return LIST_ISEMPTY(&expr->nodes);
}
int lf_expr_postcheck(struct lf_expr *lf_expr, struct proxy *px, char **err);
/* Deinitialize log buffers used for syslog messages */
void free_logformat_list(struct list *fmt);

View File

@ -439,6 +439,7 @@ struct proxy {
char *error_logformat_string;
char *elfs_file;
int elfs_line;
struct list lf_checks; /* list of logformats found in the proxy section that needs to be checked during postparse */
} conf; /* config information */
struct http_ext *http_ext; /* http ext options */
struct eb_root used_server_addr; /* list of server addresses in use */

View File

@ -1522,10 +1522,6 @@ static enum act_parse_ret parse_http_set_header(const char **args, int *orig_arg
return ACT_RET_PRS_ERR;
}
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
/* some characters are totally forbidden in header names and
* may happen by accident when writing configs, causing strange
* failures in field. Better catch these ones early, nobody will
@ -1654,10 +1650,6 @@ static enum act_parse_ret parse_http_replace_header(const char **args, int *orig
return ACT_RET_PRS_ERR;
}
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
*orig_arg = cur_arg + 1;
return ACT_RET_PRS_OK;
}
@ -1975,10 +1967,6 @@ static enum act_parse_ret parse_http_set_map(const char **args, int *orig_arg, s
}
}
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
*orig_arg = cur_arg + 1;
return ACT_RET_PRS_OK;
}

View File

@ -1335,13 +1335,34 @@ err:
*/
static int httpclient_precheck()
{
int err_code = ERR_NONE;
char *errmsg = NULL;
/* initialize the default httpclient_proxy which is used for the CLI and the lua */
httpclient_proxy = httpclient_create_proxy("<HTTPCLIENT>");
if (!httpclient_proxy)
return ERR_RETRYABLE;
if (httpclient_proxy->conf.logformat_string) {
httpclient_proxy->conf.args.ctx = ARGC_LOG;
if (!parse_logformat_string(httpclient_proxy->conf.logformat_string,
httpclient_proxy, &httpclient_proxy->logformat,
LOG_OPT_MANDATORY|LOG_OPT_MERGE_SPACES,
SMP_VAL_FE_LOG_END, &errmsg)) {
memprintf(&errmsg, "failed to parse log-format : %s.", errmsg);
err_code |= ERR_ALERT | ERR_FATAL;
goto err;
}
httpclient_proxy->conf.args.file = NULL;
httpclient_proxy->conf.args.line = 0;
}
return ERR_NONE;
err:
if (err_code & ERR_CODE) {
ha_alert("httpclient: failed to initialize: %s\n", errmsg);
free(errmsg);
}
return err_code;
}
/* Initialize the logs for every proxy dedicated to the httpclient */
@ -1372,18 +1393,6 @@ static int httpclient_postcheck_proxy(struct proxy *curproxy)
}
LIST_APPEND(&curproxy->loggers, &node->list);
}
if (curproxy->conf.logformat_string) {
curproxy->conf.args.ctx = ARGC_LOG;
if (!parse_logformat_string(curproxy->conf.logformat_string, curproxy, &curproxy->logformat,
LOG_OPT_MANDATORY|LOG_OPT_MERGE_SPACES,
SMP_VAL_FE_LOG_END, &errmsg)) {
memprintf(&errmsg, "failed to parse log-format : %s.", errmsg);
err_code |= ERR_ALERT | ERR_FATAL;
goto err;
}
curproxy->conf.args.file = NULL;
curproxy->conf.args.line = 0;
}
#ifdef USE_OPENSSL
/* initialize the SNI for the SSL servers */

View File

@ -1718,9 +1718,6 @@ struct http_reply *http_parse_http_reply(const char **args, int *orig_arg, struc
if (!parse_logformat_string(args[cur_arg+1], px, &hdr->value, LOG_OPT_HTTP, cap, errmsg))
goto error;
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
cur_arg += 2;
}
else
@ -1804,10 +1801,6 @@ struct http_reply *http_parse_http_reply(const char **args, int *orig_arg, struc
}
if (!parse_logformat_string(obj, px, &reply->body.fmt, LOG_OPT_HTTP, cap, errmsg))
goto error;
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
}
free(obj);

View File

@ -466,9 +466,6 @@ struct redirect_rule *http_parse_redirect_rule(const char *file, int linenum, st
if (!parse_logformat_string(destination, curproxy, &rule->rdr_fmt, LOG_OPT_HTTP, cap, errmsg)) {
goto err;
}
free(curproxy->conf.lfs_file);
curproxy->conf.lfs_file = strdup(curproxy->conf.args.file);
curproxy->conf.lfs_line = curproxy->conf.args.line;
}
}

213
src/log.c
View File

@ -304,9 +304,11 @@ struct logformat_tag_args tag_args_list[] = {
*/
int prepare_addrsource(struct logformat_node *node, struct proxy *curproxy)
{
curproxy->options2 |= PR_O2_SRC_ADDR;
if ((curproxy->flags & PR_FL_CHECKED))
return 0;
return 0;
curproxy->options2 |= PR_O2_SRC_ADDR;
return 1;
}
@ -379,40 +381,29 @@ int parse_logformat_tag(char *arg, int arg_len, char *name, int name_len, int ty
for (j = 0; logformat_tags[j].name; j++) { // search a log type
if (strlen(logformat_tags[j].name) == tag_len &&
strncmp(tag, logformat_tags[j].name, tag_len) == 0) {
if (logformat_tags[j].mode != PR_MODE_HTTP || curproxy->mode == PR_MODE_HTTP) {
node = calloc(1, sizeof(*node));
if (!node) {
memprintf(err, "out of memory error");
goto error_free;
}
node->type = LOG_FMT_TAG;
node->tag = &logformat_tags[j];
node->typecast = typecast;
if (name)
node->name = my_strndup(name, name_len);
node->options = *defoptions;
if (arg_len) {
node->arg = my_strndup(arg, arg_len);
if (!parse_logformat_tag_args(node->arg, node, err))
goto error_free;
}
if (node->tag->type == LOG_FMT_GLOBAL) {
*defoptions = node->options;
free_logformat_node(node);
} else {
if (logformat_tags[j].config_callback &&
logformat_tags[j].config_callback(node, curproxy) != 0) {
goto error_free;
}
curproxy->to_log |= logformat_tags[j].lw;
LIST_APPEND(list_format, &node->list);
}
return 1;
} else {
memprintf(err, "format tag '%s' is reserved for HTTP mode",
logformat_tags[j].name);
node = calloc(1, sizeof(*node));
if (!node) {
memprintf(err, "out of memory error");
goto error_free;
}
node->type = LOG_FMT_TAG;
node->tag = &logformat_tags[j];
node->typecast = typecast;
if (name)
node->name = my_strndup(name, name_len);
node->options = *defoptions;
if (arg_len) {
node->arg = my_strndup(arg, arg_len);
if (!parse_logformat_tag_args(node->arg, node, err))
goto error_free;
}
if (node->tag->type == LOG_FMT_GLOBAL) {
*defoptions = node->options;
free_logformat_node(node);
} else {
LIST_APPEND(list_format, &node->list);
}
return 1;
}
}
@ -527,17 +518,6 @@ int add_sample_to_logformat_list(char *text, char *name, int name_len, int typec
curpx->conf.args.file, curpx->conf.args.line, text);
}
/* check if we need to allocate an http_txn struct for HTTP parsing */
/* Note, we may also need to set curpx->to_log with certain fetches */
curpx->http_needed |= !!(expr->fetch->use & SMP_USE_HTTP_ANY);
/* FIXME: temporary workaround for missing LW_XPRT and LW_REQ flags
* needed with some sample fetches (eg: ssl*). We always set it for
* now on, but this will leave with sample capabilities soon.
*/
curpx->to_log |= LW_XPRT;
if (curpx->http_needed)
curpx->to_log |= LW_REQ;
LIST_APPEND(list_format, &node->list);
return 1;
@ -547,7 +527,10 @@ int add_sample_to_logformat_list(char *text, char *name, int name_len, int typec
}
/*
* Parse the log_format string and fill a linked list.
* Parse the log_format string and fill a logformat expression. The logformat
* expression will be scheduled for postcheck on the proxy unless the proxy was
* already checked, in which case all checks will be performed right away.
*
* Tag name are preceded by % and composed by characters [a-zA-Z0-9]* : %tagname
* You can set arguments using { } : %{many arguments}tagname.
* The curproxy->conf.args.ctx must be set by the caller.
@ -579,11 +562,18 @@ int parse_logformat_string(const char *fmt, struct proxy *curproxy, struct lf_ex
memprintf(err, "out of memory error");
return 0;
}
curproxy->to_log |= LW_INIT;
/* reset the old expr first (if previously defined) */
lf_expr_deinit(lf_expr);
/* Save some parsing infos to raise relevant error messages during
* postparsing if needed.
*/
if (curproxy->conf.args.file) {
lf_expr->conf.file = strdup(curproxy->conf.args.file);
lf_expr->conf.line = curproxy->conf.args.line;
}
for (cformat = LF_INIT; cformat != LF_END; str++) {
pformat = cformat;
@ -760,14 +750,123 @@ int parse_logformat_string(const char *fmt, struct proxy *curproxy, struct lf_ex
memprintf(err, "truncated line after '%s'", tag ? tag : arg ? arg : "%");
goto fail;
}
free(backfmt);
ha_free(&backfmt);
if (!(curproxy->flags & PR_FL_CHECKED)) {
/* add the lf_expr to the proxy checks to delay postparsing
* since config-related proxy properties are not stable yet
*/
LIST_APPEND(&curproxy->conf.lf_checks, &lf_expr->list);
}
else {
/* probably called during runtime or with proxy already checked,
* perform the postcheck right away
*/
if (!lf_expr_postcheck(lf_expr, curproxy, err))
goto fail;
}
return 1;
fail:
free(backfmt);
ha_free(&backfmt);
return 0;
}
/* Performs a postparsing check on logformat expression <expr> for a given <px>
* proxy. The function will behave differently depending on the proxy state
* (during parsing we will try to adapt proxy configuration to make it
* compatible with logformat expression, but once the proxy is checked, we fail
* as soon as we face incompatibilities)
*
* It returns 1 on success and 0 on error, <err> will be set in case of error.
*/
int lf_expr_postcheck(struct lf_expr *lf_expr, struct proxy *px, char **err)
{
struct logformat_node *lf;
if (!(px->flags & PR_FL_CHECKED))
px->to_log |= LW_INIT;
list_for_each_entry(lf, &lf_expr->nodes, list) {
if (lf->type == LOG_FMT_EXPR) {
struct sample_expr *expr = lf->expr;
uint8_t http_needed = !!(expr->fetch->use & SMP_USE_HTTP_ANY);
if ((px->flags & PR_FL_CHECKED)) {
/* fail as soon as proxy properties are not compatible */
if (http_needed && !px->http_needed) {
memprintf(err, "sample fetch '%s' requires HTTP enabled proxy which is not available here",
expr->fetch->kw);
goto fail;
}
continue;
}
/* check if we need to allocate an http_txn struct for HTTP parsing */
/* Note, we may also need to set curpx->to_log with certain fetches */
px->http_needed |= http_needed;
/* FIXME: temporary workaround for missing LW_XPRT and LW_REQ flags
* needed with some sample fetches (eg: ssl*). We always set it for
* now on, but this will leave with sample capabilities soon.
*/
px->to_log |= LW_XPRT;
if (px->http_needed)
px->to_log |= LW_REQ;
}
else if (lf->type == LOG_FMT_TAG) {
if (lf->tag->mode == PR_MODE_HTTP && px->mode != PR_MODE_HTTP) {
memprintf(err, "format tag '%s' is reserved for HTTP mode",
lf->tag->name);
goto fail;
}
if (lf->tag->config_callback &&
!lf->tag->config_callback(lf, px)) {
memprintf(err, "cannot configure format tag '%s' in this context",
lf->tag->name);
goto fail;
}
if (!(px->flags & PR_FL_CHECKED))
px->to_log |= lf->tag->lw;
}
}
if ((px->to_log & (LW_REQ | LW_RESP)) &&
(px->mode != PR_MODE_HTTP && !(px->options & PR_O_HTTP_UPG))) {
memprintf(err, "logformat expression not usable here (at least one node depends on HTTP mode)");
goto fail;
}
return 1;
fail:
return 0;
}
/* postparse logformats defined at <px> level */
static int postcheck_logformat_proxy(struct proxy *px)
{
char *err = NULL;
struct lf_expr *lf_expr, *back_lf;
int err_code = ERR_NONE;
list_for_each_entry_safe(lf_expr, back_lf, &px->conf.lf_checks, list) {
if (!lf_expr_postcheck(lf_expr, px, &err))
err_code |= ERR_FATAL | ERR_ALERT;
/* check performed, ensure it doesn't get checked twice */
LIST_DEL_INIT(&lf_expr->list);
if (err_code & ERR_CODE)
break;
}
if (err) {
memprintf(&err, "error detected while postparsing logformat expression used by %s '%s' : %s", proxy_type_str(px), px->id, err);
if (lf_expr->conf.file)
memprintf(&err, "parsing [%s:%d] : %s.\n", lf_expr->conf.file, lf_expr->conf.line, err);
ha_alert("%s", err);
ha_free(&err);
}
return err_code;
}
/*
* Parse the first range of indexes from a string made of a list of comma separated
* ranges of indexes. Note that an index may be considered as a particular range
@ -2599,12 +2698,19 @@ void free_logformat_list(struct list *fmt)
void lf_expr_init(struct lf_expr *expr)
{
LIST_INIT(&expr->nodes);
LIST_INIT(&expr->list);
expr->conf.file = NULL;
expr->conf.line = 0;
}
/* Releases and resets a log-format expression */
void lf_expr_deinit(struct lf_expr *expr)
{
free_logformat_list(&expr->nodes);
free(expr->conf.file);
/* remove from parent list (if any) */
LIST_DEL_INIT(&expr->list);
lf_expr_init(expr);
}
@ -2619,11 +2725,19 @@ void lf_expr_xfer(struct lf_expr *src, struct lf_expr *dst)
lf_expr_deinit(dst);
/* then proceed with transfer between <src> and <dst> */
dst->conf.file = src->conf.file;
dst->conf.line = src->conf.line;
list_for_each_entry_safe(lf, lfb, &src->nodes, list) {
LIST_DELETE(&lf->list);
LIST_APPEND(&dst->nodes, &lf->list);
}
/* replace <src> with <dst> in <src>'s list by first adding
* <dst> after <src>, then removing <src>...
*/
LIST_INSERT(&src->list, &dst->list);
LIST_DEL_INIT(&src->list);
/* src is now empty, perform an explicit reset */
lf_expr_init(src);
}
@ -4654,6 +4768,7 @@ static int postresolve_loggers()
REGISTER_CONFIG_SECTION("log-forward", cfg_parse_log_forward, NULL);
REGISTER_POST_CHECK(postresolve_loggers);
REGISTER_POST_PROXY_CHECK(postcheck_log_backend);
REGISTER_POST_PROXY_CHECK(postcheck_logformat_proxy);
REGISTER_PER_THREAD_ALLOC(init_log_buffers);
REGISTER_PER_THREAD_FREE(deinit_log_buffers);

View File

@ -1279,12 +1279,6 @@ int proxy_cfg_ensure_no_http(struct proxy *curproxy)
ha_warning("Layer 7 hash not possible for %s '%s' (needs 'mode http'). Falling back to round robin.\n",
proxy_type_str(curproxy), curproxy->id);
}
if (curproxy->to_log & (LW_REQ | LW_RESP)) {
curproxy->to_log &= ~(LW_REQ | LW_RESP);
ha_warning("parsing [%s:%d] : HTTP log/header format not usable with %s '%s' (needs 'mode http').\n",
curproxy->conf.lfs_file, curproxy->conf.lfs_line,
proxy_type_str(curproxy), curproxy->id);
}
if (curproxy->conf.logformat_string == default_http_log_format ||
curproxy->conf.logformat_string == clf_http_log_format) {
/* Note: we don't change the directive's file:line number */
@ -1356,6 +1350,7 @@ void init_new_proxy(struct proxy *p)
LIST_INIT(&p->conf.listeners);
LIST_INIT(&p->conf.errors);
LIST_INIT(&p->conf.args.list);
LIST_INIT(&p->conf.lf_checks);
LIST_INIT(&p->filter_configs);
LIST_INIT(&p->tcpcheck_rules.preset_vars);

View File

@ -1022,11 +1022,6 @@ static enum act_parse_ret parse_store(const char **args, int *arg, struct proxy
return ACT_RET_PRS_ERR;
(*arg)++;
/* for late error reporting */
free(px->conf.lfs_file);
px->conf.lfs_file = strdup(px->conf.args.file);
px->conf.lfs_line = px->conf.args.line;
} else {
/* set-var */
rule->arg.vars.expr = sample_parse_expr((char **)args, arg, px->conf.args.file,
@ -1065,6 +1060,7 @@ static int vars_parse_global_set_var(char **args, int section_type, struct proxy
struct proxy px = {
.id = "CFG",
.conf.args = { .file = file, .line = line, },
.flags = PR_FL_CHECKED,
};
struct act_rule rule = {
.arg.vars.scope = SCOPE_PROC,
@ -1185,6 +1181,7 @@ static int vars_parse_cli_set_var(char **args, char *payload, struct appctx *app
struct proxy px = {
.id = "CLI",
.conf.args = { .file = "CLI", .line = 0, },
.flags = PR_FL_CHECKED,
};
struct act_rule rule = {
.arg.vars.scope = SCOPE_PROC,