MEDIUM: log: consider log-steps proxy setting for existing log origins

During tcp/http transaction processing, haproxy may produce logs at
different steps during the processing (accept, connect, request,
response, close). But the behavior is hardly configurable because
haproxy will only emit a single log per transaction, and by default
it will try to produce the log once all log aliases or fetches used
in the logformat could be satisfied, which means the log is often
emitted during connection teardown, unless "option logasap" is used.

We were often asked to have a way to emit multiple logs for a single
transaction, like for instance emit log during accept, then request,
response and close for instance, see GH #401 for more context.

Thanks to "log-steps" keyword introduced by commit "MINOR: log:
introduce "log-steps" proxy keyword", it is now possible to explictly
configure when logs should be generated by haproxy when processing a
transaction. This commit adds the required checks so that log-steps
proxy option is properly considered for existing logs generated by
haproxy. If "log-steps" is not specified on the proxy, the old behavior
is preserved.

Note: a slight cpu overhead should only be visible when "log-steps"
keyword will be used due to the implementation relying on eb32 lookup
instead of basic bitfield check as described in "MINOR: proxy: add
log_steps struct member". However, the default behavior shouldn't be
affected.

When combining log-steps with log-profiles, user has the ability to
explicitly control how and when haproxy should generate logs during
requests handling.

diff --git a/src/cli.c b/src/cli.c
index e2ae2eb7004d1edb2109492e5f82945dee404813..1d80b760238bd32526dd418b5049bbad5898afa8 100644 (file)
--- a/src/cli.c
+++ b/src/cli.c
@@ -3112,6 +3112,8 @@ int pcli_wait_for_response(struct stream *s, struct channel *rep, int an_bit)
        }
 
        if (s->scb->flags & (SC_FL_ABRT_DONE|SC_FL_EOS)) {
+               uint8_t do_log = 0;
+
                /* stream cleanup */
 
                pcli_write_prompt(s);
@@ -3145,7 +3147,14 @@ int pcli_wait_for_response(struct stream *s, struct channel *rep, int an_bit)
                pendconn_free(s);
 
                /* let's do a final log if we need it */
-               if (!lf_expr_isempty(&fe->logformat) && s->logs.logwait &&
+               if (fe->to_log == LW_LOGSTEPS) {
+                       if (log_orig_proxy(LOG_ORIG_TXN_CLOSE, fe))
+                               do_log = 1;
+               }
+               else if (!lf_expr_isempty(&fe->logformat) && s->logs.logwait)
+                       do_log = 1;
+
+               if (do_log &&
                    !(s->flags & SF_MONITOR) &&
                    (!(fe->options & PR_O_NULLNOLOG) || s->req.total)) {
                        s->do_log(s, log_orig(LOG_ORIG_TXN_CLOSE, LOG_ORIG_FL_NONE));

diff --git a/src/frontend.c b/src/frontend.c
index 3d18db94abd47c9003ea89cdaf53e8ee01bc3b69..22270f28721d20636b9bb32c6bd636b9caf2f8e7 100644 (file)
--- a/src/frontend.c
+++ b/src/frontend.c
@@ -55,7 +55,11 @@ int frontend_accept(struct stream *s)
 
        if ((fe->mode == PR_MODE_TCP || fe->mode == PR_MODE_HTTP)
            && (!LIST_ISEMPTY(&fe->loggers))) {
-               if (likely(!lf_expr_isempty(&fe->logformat))) {
+               if (fe->to_log == LW_LOGSTEPS) {
+                       if (log_orig_proxy(LOG_ORIG_TXN_ACCEPT, fe))
+                               s->do_log(s, log_orig(LOG_ORIG_TXN_ACCEPT, LOG_ORIG_FL_NONE));
+               }
+               else if (likely(!lf_expr_isempty(&fe->logformat))) {
                        /* we have the client ip */
                        if (s->logs.logwait & LW_CLIP)
                                if (!(s->logs.logwait &= ~(LW_CLIP|LW_INIT)))

diff --git a/src/http_ana.c b/src/http_ana.c
index 175c01cba76f64f35c5c9e4fe93772160a1d1ee2..a8d1b18fc37e3092b5a5028a31d6b69e06e1a754 100644 (file)
--- a/src/http_ana.c
+++ b/src/http_ana.c
@@ -82,6 +82,7 @@ static int http_reply_100_continue(struct stream *s);
  */
 int http_wait_for_request(struct stream *s, struct channel *req, int an_bit)
 {
+       uint8_t do_log = 0;
 
        /*
         * We will analyze a complete HTTP request to check the its syntax.
@@ -264,7 +265,20 @@ int http_wait_for_request(struct stream *s, struct channel *req, int an_bit)
         * Note: we cannot log anymore if the request has been
         * classified as invalid.
         */
-       if (unlikely(s->logs.logwait & LW_REQ)) {
+       if (unlikely(sess->fe->to_log == LW_LOGSTEPS)) {
+               if (log_orig_proxy(LOG_ORIG_TXN_REQUEST, sess->fe))
+                       do_log = 1; /* forced log (through "log-steps") */
+       }
+       else if (unlikely(s->logs.logwait & LW_REQ)) {
+               /* default behavior when log-steps isn't specified:
+                * don't log systematically, but only if conditions are
+                * met, ie: not log emitted yet for this txn, all data available
+                * (unless "option logasap" is used)
+                */
+               do_log = 2;
+       }
+
+       if (do_log) {
                /* we have a complete HTTP request that we must log */
                if ((txn->uri = pool_alloc(pool_head_requri)) != NULL) {
                        size_t len;
@@ -272,7 +286,7 @@ int http_wait_for_request(struct stream *s, struct channel *req, int an_bit)
                        len = http_fmt_req_line(sl, txn->uri, global.tune.requri_len - 1);
                        txn->uri[len] = 0;
 
-                       if (!(s->logs.logwait &= ~(LW_REQ|LW_INIT)))
+                       if (do_log == 1 || !(s->logs.logwait &= ~(LW_REQ|LW_INIT)))
                                s->do_log(s, log_orig(LOG_ORIG_TXN_REQUEST, LOG_ORIG_FL_NONE));
                } else {
                        ha_alert("HTTP logging : out of memory.\n");
@@ -1682,6 +1696,7 @@ int http_process_res_common(struct stream *s, struct channel *rep, int an_bit, s
        struct htx *htx;
        struct proxy *cur_proxy;
        enum rule_result ret = HTTP_RULE_RES_CONT;
+       uint8_t do_log = 0;
 
        if (unlikely(msg->msg_state < HTTP_MSG_BODY))   /* we need more data */
                return 0;
@@ -1904,11 +1919,18 @@ int http_process_res_common(struct stream *s, struct channel *rep, int an_bit, s
        rep->analysers &= ~AN_RES_FLT_XFER_DATA;
        rep->analysers |= AN_RES_HTTP_XFER_BODY;
 
+       if (sess->fe->to_log == LW_LOGSTEPS) {
+               if (log_orig_proxy(LOG_ORIG_TXN_RESPONSE, sess->fe))
+                       do_log = 1;
+       }
+       else if ((!lf_expr_isempty(&sess->fe->logformat) && !(s->logs.logwait & LW_BYTES)))
+               do_log = 1;
+
        /* if the user wants to log as soon as possible, without counting
         * bytes from the server, then this is the right moment. We have
         * to temporarily assign bytes_out to log what we currently have.
         */
-       if (!lf_expr_isempty(&sess->fe->logformat) && !(s->logs.logwait & LW_BYTES)) {
+       if (do_log) {
                s->logs.t_close = s->logs.t_data; /* to get a valid end date */
                s->logs.bytes_out = htx->data;
                s->do_log(s, log_orig(LOG_ORIG_TXN_RESPONSE, LOG_ORIG_FL_NONE));

diff --git a/src/stream.c b/src/stream.c
index f955b81297a14b60232d31ad9dd7ca16afe608b5..9b48e7d78977d3d4e069a67721b3bb1b05ca863e 100644 (file)
--- a/src/stream.c
+++ b/src/stream.c
@@ -896,6 +896,7 @@ void back_establish(struct stream *s)
        struct connection *conn = sc_conn(s->scb);
        struct channel *req = &s->req;
        struct channel *rep = &s->res;
+       uint8_t do_log = 0;
 
        DBG_TRACE_ENTER(STRM_EV_STRM_PROC|STRM_EV_CS_ST, s);
        /* First, centralize the timers information, and clear any irrelevant
@@ -916,19 +917,28 @@ void back_establish(struct stream *s)
        if (objt_server(s->target))
                health_adjust(__objt_server(s->target), HANA_STATUS_L4_OK);
 
+       if (strm_fe(s)->to_log == LW_LOGSTEPS) {
+               if (log_orig_proxy(LOG_ORIG_TXN_CONNECT, strm_fe(s)))
+                       do_log = 1;
+       }
+
        if (!IS_HTX_STRM(s)) { /* let's allow immediate data connection in this case */
                /* if the user wants to log as soon as possible, without counting
                 * bytes from the server, then this is the right moment. */
-               if (!lf_expr_isempty(&strm_fe(s)->logformat) && !(s->logs.logwait & LW_BYTES)) {
-                       /* note: no pend_pos here, session is established */
-                       s->logs.t_close = s->logs.t_connect; /* to get a valid end date */
-                       s->do_log(s, log_orig(LOG_ORIG_TXN_CONNECT, LOG_ORIG_FL_NONE));
-               }
+               if (strm_fe(s)->to_log != LW_LOGSTEPS &&
+                   !lf_expr_isempty(&strm_fe(s)->logformat) && !(s->logs.logwait & LW_BYTES))
+                       do_log = 1;
        }
        else {
                s->scb->flags |= SC_FL_RCV_ONCE; /* a single read is enough to get response headers */
        }
 
+       if (do_log) {
+               /* note: no pend_pos here, session is established */
+               s->logs.t_close = s->logs.t_connect; /* to get a valid end date */
+               s->do_log(s, log_orig(LOG_ORIG_TXN_CONNECT, LOG_ORIG_FL_NONE));
+       }
+
        rep->analysers |= strm_fe(s)->fe_rsp_ana | s->be->be_rsp_ana;
 
        se_have_more_data(s->scb->sedesc);
@@ -2564,6 +2574,8 @@ struct task *process_stream(struct task *t, void *context, unsigned int state)
        }
 
        if (!(s->flags & SF_IGNORE)) {
+               uint8_t do_log = 0;
+
                s->logs.t_close = ns_to_ms(now_ns - s->logs.accept_ts);
 
                stream_process_counters(s);
@@ -2586,7 +2598,14 @@ struct task *process_stream(struct task *t, void *context, unsigned int state)
                }
 
                /* let's do a final log if we need it */
-               if (!lf_expr_isempty(&sess->fe->logformat) && s->logs.logwait &&
+               if (sess->fe->to_log == LW_LOGSTEPS) {
+                       if (log_orig_proxy(LOG_ORIG_TXN_CLOSE, sess->fe))
+                               do_log = 1;
+               }
+               else if (!lf_expr_isempty(&sess->fe->logformat) && s->logs.logwait)
+                       do_log = 1;
+
+               if (do_log &&
                    !(s->flags & SF_MONITOR) &&
                    (!(sess->fe->options & PR_O_NULLNOLOG) || req->total)) {
                        /* we may need to know the position in the queue */