Embedded etcd logs every unary request as a `warn` (`request stats`), flooding the journal

[mkocustos]

What happens

microshift-etcd emits a "level":"warn" / "msg":"request stats" line for every
unary etcd request, not just slow ones. On an idle single-node install this is
30,544 lines/hour and accounts for 99.8 % of all etcd output (30,544 of 30,615
lines in a one-hour sample) and roughly 91 % of the entire systemd journal on the
host.

This is not a transient regression: the behaviour is unchanged across four months of
nightlies, from 4.22.0_202604200420 (April 2026) to 4.22.0_202608270614
(August 2026), measured on the same host.

Sample line — a routine Range on an empty key, served in 118 µs and logged as a
warning:

{"level":"warn","ts":"2026-09-02T09:19:07.119668+0200","caller":"v3rpc/interceptor.go:202",
 "msg":"request stats","start time":"2026-09-02T09:19:07.119529+0200","time spent":"117.678µs",
 "remote":"[::1]:46076","response type":"/etcdserverpb.KV/Range","request count":0,
 "request size":31,"response count":0,"response size":31,
 "request content":"key:\"/kubernetes.io/podtemplates\" limit:1 "}

Why this is wrong

logUnaryRequestStats (etcd server/etcdserver/api/v3rpc/interceptor.go) only logs at
warn when the request exceeded warning-unary-request-duration; otherwise it logs at
debug or not at all. etcd's default for that threshold is 300 ms.

Measured distribution over a 30-minute sample of 15,415 warned requests:

min	p25	median	p95	max
0.021 ms	0.103 ms	0.146 ms	3.234 ms	305.7 ms

The median is 2,049× below the default threshold. That only happens if
WarningUnaryRequestDuration is left at its zero value when MicroShift builds the
embedded embed.Config, so duration > warnLatency is true for every request.

The diagnostic cost is concrete. In that same 30-minute sample, exactly one
request — 305.7 ms — actually exceeded etcd's 300 ms default and genuinely deserved a
warning. It is buried under 15,414 that did not:

warned requests in 30 min	of those, actually > 300 ms	signal-to-noise
15,415	1	1 : 15,415

So the feature does not merely produce noise, it destroys the signal it exists to
provide: the one real slow-request warning is indistinguishable from the flood. On top
of that it dominates the host's journal.

Why it can't be worked around on the host

• MicroShift's config exposes only etcd.memoryLimitMB; there is no knob for the
  warning threshold or for etcd's log level.
• debugging.logLevel only goes in the more-verbose direction (Normal/Debug/Trace).
• microshift-etcd is registered as a scope unit, not a service. Scopes have no
  exec context, so LogRateLimitIntervalSec= / LogRateLimitBurst= / LogNamespace=
  drop-ins do not apply to it.
• A global journald rate limit low enough to catch etcd would indiscriminately drop
  bursts from every other unit.
• Setting etcd's own ETCD_* environment variables on the unit does not work either:
  the microshift-etcd binary contains no ETCD_* variable names at all
  (strings /usr/bin/microshift-etcd | grep -cE '^ETCD_[A-Z_]+$' → 0), because the
  config is built programmatically and etcd's environment-parsing layer is not linked
  in. This closes the most obvious operator-side workaround.

The only remaining option for operators is to spend disk on journal retention, which is
what we did (SystemMaxUse=500M → 16G just to keep ~4 weeks of history).

Prior art: k3s hit the same bug and fixed it

k3s embeds etcd the same way and ran into the identical zero-threshold problem. Their
etcd fork carries a patch titled server/embed: default WarningUnaryRequestDuration,
shipped in every recent release — including
v3.6.5-k3s1, which is the
same etcd base version MicroShift uses here, and continuing through
v3.6.12-k3s1.

That patch is both the precedent and a reference implementation for the fix suggested
below.

Suggested fix

Set WarningUnaryRequestDuration to etcd's default (300 ms) when constructing the
embedded config, and ideally surface it in the MicroShift config's etcd: section
alongside memoryLimitMB.

Environment

• MicroShift 4.22.0_202608270614_gaed751f15_4.22.0_okd_scos.ec.16
• Base OCP 4.22.0-0.nightly-2026-08-23-191303, base etcd 3.6.5
• Fedora release 43, kernel 7.1.12-100.fc43.x86_64, systemd 258, single node
• Also reproduced on 4.22.0_202604200420_g4ce2befbd_4.22.0_okd_scos.ec.11
  (base OCP 4.22.0-0.nightly-2026-04-01-223038) — four months earlier, same behaviour

Reproduce

# share of etcd output that is "request stats"
journalctl _SYSTEMD_UNIT=microshift-etcd.scope -S "1 hour ago" -o cat \
  | grep -c '"msg":"request stats"'

# durations of the warned requests
journalctl _SYSTEMD_UNIT=microshift-etcd.scope -S "30 min ago" -o cat \
  | grep '"msg":"request stats"' | grep -o '"time spent":"[^"]*"'

# no ETCD_* environment variables are linked into the binary
strings /usr/bin/microshift-etcd | grep -cE '^ETCD_[A-Z_]+$'

Use the indexed _SYSTEMD_UNIT= field match rather than -u: on a journal this
large a full-text scan takes minutes, the field match milliseconds.