openshift / openshift/microshift
Embedded etcd logs every unary request as a `warn` (`request stats`), flooding the journal
Nobody has claimed this yet.
- Dominant language
- Go
- Stars
- 843
- Forks
- 233
- Avg merge
- 1d 8h
- Merged PRs (30d)
- 101
Description
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.logLevelonly goes in the more-verbose direction (Normal/Debug/Trace).microshift-etcdis registered as a scope unit, not a service. Scopes have no
exec context, soLogRateLimitIntervalSec=/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:
themicroshift-etcdbinary contains noETCD_*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 etcd3.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 OCP4.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.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start by tracing where MicroShift constructs the embedded etcd embed.Config, using server/etcdserver/api/v3rpc/interceptor.go to confirm how WarningUnaryRequestDuration controls request-stats logging. The change is done when the threshold defaults to 300 ms, any exposed etcd configuration is consistent, and routine requests no longer appear as warnings while genuinely slow requests still do.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- backend, distributed-systems
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 72/100