Skip to content

Latest commit

 

History

History
511 lines (381 loc) · 22.2 KB

File metadata and controls

511 lines (381 loc) · 22.2 KB

Failure modes

Production container problems, reproduced deliberately, with the evidence read from the kernel rather than inferred from a runtime's error message.

Each entry follows the same shape: the symptom as it appears in production, the reproduction, what the kernel says, and the actual cause.


docker stop hangs for ten seconds, then the container dies anyway

Symptom in production. docker stop or a Kubernetes pod deletion appears to do nothing. After exactly the grace period the container disappears. Application shutdown hooks never ran, in-flight requests were dropped, and the logs contain no shutdown message.

Reproduction. Two containers, identical except for whether PID 1 installs a signal handler.

# PID 1 with no handler
jq '.process.args = ["/bin/sleep","30"]' config.json | sponge config.json
mars run --pid-file /tmp/bare.pid demo &
kill -TERM $!                       # ask the runtime to forward SIGTERM
sleep 1
kill -0 "$(cat /tmp/bare.pid)" && echo "still alive"
still alive
# PID 1 with a handler
jq '.process.args = ["/bin/sh","-c","trap \"exit 42\" TERM; while true; do sleep 0.2; done"]' \
  config.json | sponge config.json
mars run demo &
kill -TERM $!
wait $!; echo "exit=$?"
exit=42

What the kernel says. From man 7 pid_namespaces:

a process in an ancestor namespace can — subject to the usual permission checks — send signals to the "init" process of a child PID namespace only if the "init" process has established a handler for that signal. […] SIGKILL or SIGSTOP are treated exceptionally: these signals are forcibly delivered when sent from an ancestor PID namespace.

Cause. PID 1 of a namespace does not get default signal actions. The kernel discards any signal with no installed handler, deliberately, so that a stray kill cannot destroy a namespace's init. The runtime forwarded SIGTERM correctly; the kernel dropped it on the floor.

So the ten second wait is not a timeout being hit — it is docker stop sending SIGTERM, the kernel discarding it, and Docker then falling back to SIGKILL, which is forcibly delivered.

What this means when it is your service. ENTRYPOINT ["python", "app.py"] makes the interpreter PID 1. If it never registers a SIGTERM handler, it cannot shut down gracefully — no amount of increasing terminationGracePeriodSeconds helps, because nothing is waiting on that grace period. Either handle the signal in the application, or run a real init as PID 1 (docker run --init, or tini) so signals reach your process as a normal child with normal default actions.

Evidence of correct translation. SIGKILL from an ancestor namespace is delivered, and the runtime reports it the way a shell does:

  ok   SIGKILL is forcibly delivered, reported as 128+9

137 = 128 + 9. The same arithmetic behind every OOMKilled exit code.


Mounting /sys/fs/cgroup fails with EPERM, and it is not a permission problem

Symptom in production. An older image, or an older runtime, or a hand-written OCI bundle fails to start on a current host. The error is EPERM on a mount, while running as root with full capabilities. Everything about the message points at permissions, and permissions are fine.

Reproduction. The default OCI spec asks for the legacy cgroup filesystem:

{ "destination": "/sys/fs/cgroup", "type": "cgroup",
  "options": ["nosuid","noexec","nodev","relatime","ro"] }

Run it on Ubuntu 24.04 with kernel 6.8:

mars: container init failed: mount cgroup type=cgroup at /sys/fs/cgroup
      flags=MsFlags(MS_RDONLY | MS_NOSUID | MS_NODEV | MS_NOEXEC | MS_RELATIME)
      data="": EPERM: Operation not permitted

What the kernel says. The host is running a pure cgroup v2 unified hierarchy:

$ stat -fc %T /sys/fs/cgroup
cgroup2fs
$ cat /sys/fs/cgroup/cgroup.controllers
cpuset cpu io memory hugetlb pids rdma misc

cgroup2fs, not tmpfs with v1 hierarchies underneath. There is no v1 hierarchy to join, and the kernel refuses to create one.

Cause. type: "cgroup" names the v1 filesystem. On a unified host the correct filesystem is cgroup2, which is a different fstype with different semantics — one hierarchy for all controllers instead of one mount per controller. The kernel reports this refusal as EPERM, which is misleading: nothing about the request was a permissions question.

The fix, and what real runtimes do. Detect the host's hierarchy and translate:

pub fn unified_cgroup_host() -> bool {
    nix::sys::statfs::statfs("/sys/fs/cgroup")
        .map(|stat| stat.filesystem_type() == nix::sys::statfs::CGROUP2_SUPER_MAGIC)
        .unwrap_or(false)
}

pub fn effective_fstype(requested: &str, unified_host: bool) -> &str {
    if requested == "cgroup" && unified_host { "cgroup2" } else { requested }
}

runc does the same thing. This is why a bundle that names cgroup still works under Docker on a v2 host: the runtime quietly rewrote the request. A hand-rolled bundle gets no such courtesy.

Debugging lesson. The original error was just EPERM: Operation not permitted with no indication of which of the seven mounts failed. Adding the mount target, fstype, flags, and data to the error message turned a guessing game into a one-line diagnosis. For a runtime whose purpose is troubleshooting, an error that does not name the syscall and its arguments is a bug in its own right.


OOMKilled with exit 137, and no idea how close you were

Symptom in production. A pod restarts. kubectl describe says OOMKilled, exit code 137. The application logged nothing — no exception, no shutdown. Raising the memory limit fixes it, but by how much is a guess, and the same pod ran fine for weeks.

Reproduction. A 32 MiB limit and a process that allocates without bound:

jq '.linux.resources.memory.limit = 33554432
  | .process.args = ["/usr/bin/awk","BEGIN{s=\"\";while(1){s = s sprintf(\"%1000000s\",\"\")}}"]' \
  config.json | sponge config.json

mars run oomtest; echo "exit=$?"
WARN container was OOM killed: a process exceeded memory.max
     exit_code=137 oom_kill=1 max_events=35
exit=137

What the kernel says. memory.events, in the container's cgroup, while it still exists:

low 0
high 0
max 45
oom 1
oom_kill 1
oom_group_kill 0

memory.peak in the same cgroup reads 33554432 — exactly the limit, to the byte. The container did not overshoot; it was held at the ceiling until the kernel gave up.

Cause. 137 = 128 + 9: killed by signal 9. The application logged nothing because SIGKILL cannot be caught — there is no handler, no unwinding, no last log line. This is why the exit code alone can never tell you it was an OOM kill rather than any other kill -9; docker inspect carries a separate OOMKilled boolean precisely because 137 is ambiguous.

The number that actually matters is max. It counts how many times the cgroup reached its limit and survived, because reclaim managed to free something. Here: 35 times. The container had been fighting its limit continuously, and the kill was the end of that fight rather than a sudden spike.

That distinction changes the fix:

  • max high, oom_kill 1 — chronic pressure. The limit is genuinely too low; raise it.
  • max 0 or 1, oom_kill 1 — one allocation blew straight through the ceiling. Raising the limit a little will not help. Look for an unbounded allocation.

oom and oom_kill are also not the same counter. oom counts reclaim failures; oom_kill counts processes actually killed. A cgroup can accumulate oom events with nothing dying.

Why this evidence is usually gone. The cgroup is removed when the container exits, taking memory.events with it. By the time a human looks, only the 137 survives. A runtime that reads it before cleanup — as above — is the difference between "OOMKilled, again" and "chronic pressure, the limit is 20% too low".

The variant that reports success

Change one thing — make PID 1 a shell that outlives the allocation — and the same OOM kill produces a zero exit code:

jq '.linux.resources.memory.limit = 33554432
  | .process.args = ["/bin/sh","-c","awk \"BEGIN{s=\\\"\\\";for(i=0;i<28;i++){s = s sprintf(\\\"%1000000s\\\",\\\"\\\")}}\"; sleep 3"]' \
  config.json | sponge config.json
Killed
WARN container was OOM killed: a process exceeded memory.max
     exit_code=0 oom_kill=1 max_events=45

oom_kill=1 — a process really was killed. exit_code=0 — the container reports success.

The OOM killer picks its victim by badness score, largely proportional to memory used. That is usually the process doing the allocating, which is often not PID 1. Here awk was killed, sh carried on to sleep 3, and exited cleanly.

Everything downstream reads the exit code. Kubernetes marks a pod OOMKilled when PID 1 dies of signal 9; when a child dies instead, the pod is Completed and nothing restarts. This is the mechanism behind "a worker disappeared and no alert fired" — a Celery worker, a forked request handler, a build step in a wrapper script.

Which is why mars reports OOM kills from memory.events rather than inferring them from the exit code. The exit code cannot see this case at all.

To make the whole container die together, cgroup v2 offers memory.oom.group: set it to 1 and the kernel kills every process in the cgroup as a unit, so the failure is at least visible. The oom_group_kill counter above is how you confirm it fired.


CPU throttling while utilisation looks low

Symptom in production. Latency is bad. CPU utilisation graphs sit at 25%. Adding replicas does not help much, and the node is not busy.

Reproduction. A quota of 10% of one core, running a tight loop:

jq '.linux.resources.cpu.quota = 10000 | .linux.resources.cpu.period = 100000' \
  config.json | sponge config.json
INFO container was CPU throttled by cpu.max
     nr_periods=37 nr_throttled=37 throttled_usec=3314146

Cause. cpu.max is "quota period" — here 10ms of CPU per 100ms window. Once the quota is spent, every task in the cgroup is stopped until the next period begins, even on a completely idle machine. All 37 periods ended throttled, with 3.3 seconds spent frozen out of 3.7 seconds of wall clock — the workload was stopped roughly 90% of the time, which is the arithmetic complement of the 10% quota.

Average utilisation reads 10% because 10% is the ceiling, not because the application is idle. The metric and the symptom are the same number seen from opposite sides.

The distinction to hold onto. Two things both get called "CPU limits":

file behaviour
shares / weight cpu.weight relative, only bites under contention; an idle machine gives you everything
quota cpu.max absolute, bites regardless of what else is running

In Kubernetes, requests.cpu becomes cpu.weight and limits.cpu becomes cpu.max. Which is why removing a CPU limit can improve latency dramatically while removing a CPU request does nothing until the node is contended.

Where to look. cpu.stat, specifically nr_throttled against nr_periods. A ratio near 1 means the workload is quota-bound, whatever the utilisation graph says.


Zombie processes pile up, and the runtime is not at fault

Symptom in production. ps inside a long-running container fills with Z state processes. Eventually fork() starts failing with EAGAIN because the pid limit is reached, and the application cannot start subprocesses any more.

Reproduction. A PID 1 that is an ordinary program, with an orphan below it:

jq '.process.args = ["/bin/sh","-c","{ sleep 0.3; } & exec sleep 4"]' config.json | sponge config.json
mars run --pid-file /tmp/z.pid zombietest &
sleep 1.2
ps -o stat= --ppid "$(cat /tmp/z.pid)" | grep -c '^Z'
1

Cause. exec sleep 4 replaces the shell, so PID 1 is sleep. When the backgrounded child exits, its parent is PID 1 — and PID 1 of a namespace inherits every orphan in it. sleep never calls wait(), so the child's exit status is never collected and the process table entry stays forever.

Nothing here is the runtime's job. After execve the runtime is not in the container at all; PID 1 is the application. A container's init duties — reaping orphans, forwarding signals — belong to whatever the image chose to put at PID 1.

Note this is the same root cause as the SIGTERM case above. Both are the consequence of an application being PID 1 when it was never written to be an init. docker run --init and Kubernetes' shareProcessNamespace pause container both exist to insert a real init — tini reaps orphans and forwards signals in about 200 lines.


Files written inside a container are gone after it is recreated

Symptom in production. Someone fixes a problem by execing into a running container — installs a package, edits a config, drops a certificate in place. It works. The pod restarts, or the deployment is rolled, and the fix is gone. Or: a container writes logs to a path nobody mounted, the disk fills up, and after docker rm the space comes back but the logs are unrecoverable.

Reproduction. Three runs of the same bundle. The first writes a file, the second keeps the same upperdir, the third gets a fresh one:

$ jq '.process.args = ["/bin/sh","-c","echo important >/data.txt; cat /data.txt"]' …
$ mars run first
important
$ find diff -mindepth 1 -exec stat -c '%n  %F' {} \;
/var/tmp/fm-overlay/bundle/diff/data.txt  regular file
$ ls lower/base/data.txt
ls: cannot access 'lower/base/data.txt': No such file or directory

The write went to upperdir. The lower layer — the image — never saw it. Run it again with the same upperdir and the file is still there:

$ jq '.process.args = ["/bin/sh","-c","cat /data.txt 2>&1"]' …
$ mars run second
important

Now discard upperdir and workdir, which is exactly what docker rm followed by docker run does, and what a Kubernetes pod restart does to a container's writable layer:

$ rm -rf diff work && mkdir diff work
$ mars run third
cat: can't open '/data.txt': No such file or directory

Cause. upperdir is the container. It is not part of the image and not part of any volume; it is a scratch directory whose lifetime is the container's lifetime. Every write that does not land on a mounted volume lands there, and is deleted with the container.

This is the mechanism behind a specific and common misdiagnosis. When a fix survives a docker restart (same container, same upperdir) but not a docker rm && docker run (new container, new upperdir), the natural conclusion is that something is wrong with the image or the restart policy. Nothing is wrong. The two operations differ in exactly one way, and it is this one.

The corollary is the reason docker diff exists: it is a listing of upperdir, and therefore a listing of everything that will be lost. Anything in it that matters belongs in a volume.

Note also what did not happen: the lower layer is byte-identical after all three runs. That is guaranteed, not incidental — OverlayFS never writes below the upper layer. It is why one image directory can back a thousand containers, and why deleting files inside a container frees no disk space (see phase 3).


mount: special device overlay does not exist, and the layer count is the real cause

Symptom in production. An image with many layers fails to start with an error naming a device that does not exist and was never supposed to. Rebuilding the same image with fewer, larger layers fixes it, which makes no sense.

Reproduction. 41 lower layers with long directory names — 4223 bytes of lowerdir=:

$ mount -t overlay overlay -o "lowerdir=$ABS,upperdir=$B/diff,workdir=$B/work" $B/merged
mount: /var/tmp/mars-long/merged: special device overlay does not exist.
$ dmesg | tail -1
overlayfs: failed to resolve '/var/tmp/mars-long/layer-with-a-deliberately-long-dire': -2

Cause. mount(2)'s data argument is copied by copy_mount_options, which copies at most one page — 4096 bytes. A longer option string is not rejected. It is truncated, and the kernel then tries to resolve whatever partial path it was left holding.

The evidence is in the dmesg line. That directory is really named layer-with-a-deliberately-long-directory-name-to-blow-the-page-limit-…; it appears cut off mid-word because that is where byte 4096 fell. And the errno is ENOENT attributed to overlay — the mount source, a placeholder string that was never a path and was never the problem.

Nothing in that output says "too many layers". The dmesg line is the only clue, and only if you notice that the path in it is truncated rather than merely missing.

This is why /var/lib/docker/overlay2 contains a l/ directory full of short symlinks like l/BSHXFN2… pointing at the real layer directories. It looks like obfuscation. It is Docker keeping the option string under 4096 bytes.

mars measures the string before the syscall, and if it is over the limit, chdirs to the deepest common parent of the layers and passes relative paths instead:

DEBUG overlay option string exceeded one page, using paths relative to a common parent
      base=/tmp/mars-it bytes=3742

If even that does not fit, it is reported as a configuration error naming the byte count — never handed to the kernel to cut in half.


permission denied on a volume at mode 0777

Symptom in production. A rootless container — Podman, or Docker in rootless mode, or anything running under a user namespace — cannot write to a bind-mounted host directory. chmod 777 on the host does not help. ls -l inside the container shows the files owned by nobody, and the numbers do not match anything in /etc/passwd.

Reproduction. A container in a user namespace mapping container 0..65535 onto host 100000..165535, looking at a device node that belongs to host root:

$ mars run uns
0                              # id -u: root, as far as the container knows
         0     100000      65536
$ stat -c %u /dev/null         # inside the container
65534

65534 is the overflow uid/proc/sys/kernel/overflowuid. It is what the kernel shows when a file's owner has no mapping in the calling process's user namespace. Host uid 0 is not inside [100000, 165536), so root-owned files have no name inside the container at all.

Cause. File ownership is stored as a number, and a user namespace changes what that number means. The container's uid 0 is host uid 100000. A file owned by host uid 0 maps to nothing, so it reads as nobody, and the container's root — which is host 100000 — has only "other" permissions on it.

chmod 777 does work, for that reason. What usually does not work is chmod 755, which is what people actually try, and what makes this look like a permission bug rather than a mapping one.

Three things follow:

  1. The fix is ownership, not mode. chown 100000:100000 on the host, or podman unshare chown 0:0 which does the same arithmetic for you. Newer kernels can do it per-mount with an idmapped mount (mount_setattr with MOUNT_ATTR_IDMAP), which is what mounts[].uidMappings in the runtime-spec is for.
  2. nobody in ls -l is the diagnostic. If a rootless container shows nobody on files you own, you are looking at an unmapped id, not a broken ACL.
  3. The same rule breaks the runtime itself, one step earlier. mkdir inside the rootfs failed with EOVERFLOW before any container started, because the runtime's own uid was unmapped — see phase 5. Same mechanism, different victim.

Starting a container is slow, and nothing in the image is to blame

Symptom in production. Short-lived containers have a floor on startup latency that image size and registry caching do not move. A CI job that runs a hundred one-second containers spends a visible fraction of its wall clock somewhere unaccounted for. Kubernetes pod startup has a similar floor.

Reproduction. Trace the runtime's own startup path — mars exports one span per phase over OTLP:

trace 10a2ae966c82f09af3c6d2282991b79c  25 spans  11892us total
     458us    279us  cgroup             ← create the cgroup, write every limit
    1012us    895us  intermediate.unshare.net
    2358us   7065us  cgroup.attach      ← write one pid to cgroup.procs
    9438us    492us  init.rootfs.mount
    9931us    232us  init.pivot_root

Across three runs cgroup.attach was 6.6ms, 9.5ms and 14.7ms of totals of 11.9ms, 14.2ms and 18.5ms — 55% to 79% of cold start, to write one number to one file.

Measured on its own, moving the same process in and out of a freshly created cgroup:

  move into a new cgroup: 11268us     ← first migration
  move back to root:        770us
  move into the same one:   702us     ← second migration
  move back to root:        639us
  move into the same one:   615us

Cause. The first process migration into a newly created cgroup pays a one-time cost the later ones do not: the kernel allocating and initialising per-cgroup controller state, and taking cgroup_threadgroup_rwsem as a writer, which needs an RCU grace period across every CPU. Roughly 11ms here, then ~650µs for every migration after it.

Which is precisely the wrong shape for containers, because every container gets a fresh cgroup, so every container pays the first-touch cost and nothing is ever amortised.

The practical consequences:

  • Nothing about the image is involved. Assembling the rootfs, pivot_root, masking paths and loading the seccomp filter came to under 900µs combined — two orders of magnitude below the cgroup migration.
  • The runner-up is unshare(CLONE_NEWNET) at ~900µs, ten times any other namespace, because the kernel builds a whole network stack: a fresh loopback device, routing tables, per-namespace state. That is the mechanism behind --network=host making short-lived containers measurably faster.
  • If you are chasing container startup latency, measure before optimising. I assumed the 7ms was an instrumentation bug, which is why the standalone measurement above exists.

Still to come

  • nothing outstanding; the remaining gaps are listed per phase in the writeups