The ring forwarder applet (used by "ring" sections, and by "log" backends, to
forward buffered events to a remote server) closed its session immediately as
soon as a soft-stop was requested:
/* if stopping was requested, close immediately */
if (unlikely(stopping))
goto soft_close;
This was meant to let the worker exit quickly, since the forwarder is a job
the soft-stop waits for. But it does not only abandon the messages still
present in the ring at that instant: it also stops forwarding the messages
that in-flight streams keep producing for the rest of the soft-stop window.
As a consequence, on every reload a leaving worker loses all the log/event
lines generated between the moment stopping is requested and the moment its
data plane is fully drained.
This is easy to observe with a typical access-log pipeline
(frontend -> ring -> log-forward/log backend -> remote collector). At 3000
req/s with a reload every 10s, about 3400 access-log lines out of ~120000
never reach the collector per run; with no reload during the same load, none
are lost. Instrumentation shows the lost lines correspond to requests that
complete a few hundred milliseconds *after* the reload, i.e. while the old
worker is still draining - exactly the window during which the forwarder had
already closed.
Instead of closing immediately, keep the forwarder attached and flushing
during the soft-stop, and only close once no message has been forwarded for
SINK_FWD_QUIET_MS. Every forwarded message pushes that deadline back, so the
forwarder stays attached exactly as long as the data plane keeps feeding the
ring and closes shortly after it drains. The same deadline bounds the
shutdown when the downstream is wedged or unreachable (no progress is made),
so a stuck downstream can never hold the process up to "hard-stop-after". If
the downstream connection was never established there is nothing to flush to,
so we still close right away. A task wake-up is scheduled at the deadline
because, the ring being empty, no incoming message would otherwise wake the
applet to notice that the data plane has gone quiet.
Using the number of active front connections (actconn) as a more direct
"data plane drained" signal was considered but is not usable: in
master-worker mode the worker keeps a permanent connection to the master CLI,
so actconn never reaches zero and the worker would then hang until
"hard-stop-after".
With this change the same test loses 0 line, and the old worker exits about
520 ms after the reload (the quiet window plus scheduling), both with a
healthy downstream and with a down or wedged one (no hard-stop-after
fallback).
The trade-off is that a worker now lingers up to SINK_FWD_QUIET_MS after its
last forwarded message on each soft-stop, and a message produced after a
quiet period longer than SINK_FWD_QUIET_MS could still be missed.
SINK_FWD_QUIET_MS (300ms) balances both and could be made configurable later.
This should be backported to stable branches that still close the forwarder
immediately on soft-stop, at least as far back as 3.2. Note that older
branches use the previous applet API in this function (se_fl_test() on the
sedesc, sc_opposite(sc)->state for the connection state, and se_fl_set() in
soft_close()), so the backport needs a small adaptation of the
not-established test and of the close path; the rest is identical.
---
include/haproxy/sink-t.h | 1 +
src/sink.c | 47 +++++++++++++++++++++++++++++++++++++---
2 files changed, 45 insertions(+), 3 deletions(-)
diff --git a/include/haproxy/sink-t.h b/include/haproxy/sink-t.h
index a9db336..955263c 100644
--- a/include/haproxy/sink-t.h
+++ b/include/haproxy/sink-t.h
@@ -41,6 +41,7 @@ struct sink_forward_target {
struct server *srv; // used server
struct appctx *appctx; // appctx of current session
uint last_conn; // copy of now_ms for last session establishment
attempt
+ int flush_exp; // soft-stop: close when no message forwarded by
this tick; TICK_ETERNITY/0 = unset
size_t ofs; // ring buffer reader offset
size_t e_processed; // processed events
struct sink *sink; // the associated sink
diff --git a/src/sink.c b/src/sink.c
index ec0eb9d..a91e98c 100644
--- a/src/sink.c
+++ b/src/sink.c
@@ -422,6 +422,18 @@ void sink_setup_proxy(struct proxy *px)
sink_proxies_list = px;
}
+/* During a soft-stop the ring forwarder must keep flushing the messages that
+ * in-flight streams are still producing instead of closing immediately (which
+ * loses e.g. access logs on every reload). It keeps forwarding and closes once
+ * no message has been forwarded for SINK_FWD_QUIET_MS: every forwarded message
+ * pushes that deadline back, so the forwarder stays attached exactly as long
as
+ * logs keep flowing (i.e. while the data plane is still draining) and then
+ * closes promptly. The same deadline bounds the shutdown if the downstream is
+ * wedged (no progress is made), so a stuck downstream cannot hold the process
+ * up to hard-stop-after.
+ */
+#define SINK_FWD_QUIET_MS 300
+
static void _sink_forward_io_handler(struct appctx *appctx,
ssize_t (*msg_handler)(void *ctx, struct
ist v1, struct ist v2, size_t ofs, size_t len, char delim))
{
@@ -435,9 +447,23 @@ static void _sink_forward_io_handler(struct appctx *appctx,
if (unlikely(applet_fl_test(appctx, APPCTX_FL_EOS|APPCTX_FL_ERROR)))
goto out;
- /* if stopping was requested, close immediately */
- if (unlikely(stopping))
- goto soft_close;
+ /* If stopping was requested, we used to close immediately. That dropped
+ * not only the messages still buffered in the ring, but also every
+ * message that in-flight streams keep producing during the soft-stop
+ * window (e.g. access logs lost on every reload). Instead we keep the
+ * forwarder flushing and only close once no message has been forwarded
+ * for SINK_FWD_QUIET_MS (deadline maintained after dispatch below): the
+ * forwarder thus stays attached as long as the data plane keeps feeding
+ * the ring, and closes shortly after it drains. If the downstream
+ * connection is not established there is nothing to flush to, so we
+ * close right away.
+ */
+ if (unlikely(stopping)) {
+ if (se_fl_test(appctx->sedesc, SE_FL_APPLET_NEED_CONN))
+ goto soft_close;
+ if (tick_isset(sft->flush_exp) &&
tick_is_expired(sft->flush_exp, now_ms))
+ goto soft_close;
+ }
/* if the connection is not established, inform the stream that we want
* to be notified whenever the connection completes.
@@ -493,6 +519,21 @@ static void _sink_forward_io_handler(struct appctx *appctx,
} else
applet_have_no_more_data(appctx);
}
+ /* During a soft-stop, keep forwarding whatever in-flight streams are
+ * still producing and only close once nothing has been forwarded for
+ * SINK_FWD_QUIET_MS. Every forwarded message (processed > 0) pushes the
+ * deadline back, so we stay attached exactly as long as logs keep
+ * flowing (the data plane is still draining); when they stop -- or
when a
+ * wedged downstream stops making progress -- the deadline fires and the
+ * close is performed at the top of this handler. The task wake-up at
the
+ * deadline is needed because, the ring being empty, no message would
+ * otherwise wake us to notice the data plane has gone quiet.
+ */
+ if (unlikely(stopping)) {
+ if (processed || !tick_isset(sft->flush_exp))
+ sft->flush_exp = tick_add(now_ms, SINK_FWD_QUIET_MS);
+ task_schedule(appctx->t, sft->flush_exp);
+ }
HA_SPIN_UNLOCK(SFT_LOCK, &sft->lock);
out:
--
2.47.3
