openshift / openshift/microshift

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

Open
#7,301 0 comments 0 reactions 0 assignees View on GitHub

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.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=500M16G 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.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.