DEV Community: The Homelab Postmortem

Pi pwm-ir-tx on kernel 6.18 sends nothing, and ir-ctl still reports success

The Homelab Postmortem — Mon, 12 Oct 2026 01:11:12 +0000

TL;DR: On Raspberry Pi OS's 6.18 kernel, an IR transmitter on dtoverlay=pwm-ir-tx sends nothing usable. A test code of 100 ms pulse, 100 ms space, 100 ms pulse was applied to the PWM as four state changes within 7 microseconds, all from one timer interrupt, so the LED was on for a few microseconds in total. ir-ctl --send still exited 0, and it still took about 350 ms, because the LIRC core waits for the length of the signal before returning. So neither the exit code nor the timing gives it away. The cause is a 6.18 cleanup, described as switching to "an equivalent higher-level helper", that inverted the loop condition in the driver's timer callback. Switching to dtoverlay=gpio-ir-tx on the same pin sent correctly timed 100 ms bursts. The toolkit's check-ir-tx.sh finds the affected transmitters and can measure one. Upstream report: raspberrypi/linux#7678.

The symptom

Raspberry Pi 4B, Raspberry Pi OS (Debian 13, arm64), kernel 6.18.34+rpt-rpi-v8. One line added to /boot/firmware/config.txt:

dtoverlay=pwm-ir-tx

After a reboot everything looks right:

rc rc0: PWM IR Transmitter as /devices/platform/pwm-ir-transmitter/rc/rc0
rc rc0: lirc_dev: driver pwm-ir-tx registered at minor = 0, no receiver, raw IR transmitter

$ pinctrl get 18
18: a5    pd | lo // GPIO18 = PWM0_0

$ ir-ctl -d /dev/lirc0 -f
Send features /dev/lirc0:
 - Device can send raw IR
 - IR scancode encoder
 - Set carrier
 - Set duty cycle

A test signal of 100 ms on, 100 ms off, 100 ms on, at 38 kHz:

$ printf 'pulse 100000\nspace 100000\npulse 100000\n' > ir300.txt
$ ir-ctl -d /dev/lirc0 --carrier=38000 --send=ir300.txt
send 1: rc=0 elapsed_ms=359
send 2: rc=0 elapsed_ms=345
send 3: rc=0 elapsed_ms=349

Exit 0, about the length of the signal, nothing in dmesg. The kernel's pwm_apply trace event shows what the PWM was actually told to do:

ir-ctl-1230 [002] d.h1.  42.847753: pwm_apply: pwmchip0.0: period=26316 duty_cycle=13158 polarity=0 enabled=1 err=0
ir-ctl-1230 [002] d.h1.  42.847758: pwm_apply: pwmchip0.0: period=26316 duty_cycle=13158 polarity=0 enabled=0 err=0
ir-ctl-1230 [002] d.h1.  42.847759: pwm_apply: pwmchip0.0: period=26316 duty_cycle=13158 polarity=0 enabled=1 err=0
ir-ctl-1230 [002] d.h1.  42.847760: pwm_apply: pwmchip0.0: period=26316 duty_cycle=13158 polarity=0 enabled=0 err=0

The carrier settings are right (a 26,316 ns period is 38 kHz, at 50% duty). The timing is not: the two 100 ms pulses were on for 5 µs and 1 µs, and the whole code was over in 7 µs. The h in d.h1. means all four were applied in hard interrupt context, from the same callback. After a reboot the same test gave the same four edges within 6 µs.

The report upstream is from a Pi 3B+ on the 32-bit kernel (6.18.50+rpt-rpi-v7), with an LED that stayed dark. Here it is a Pi 4B on the 64-bit kernel, so it isn't limited to one model or architecture.

Why it's easy to miss

Every check you'd normally do passes. The overlay loads, /dev/lirc0 appears with the right features, the pin is in PWM mode, and ir-ctl returns 0.

Timing doesn't help either. It is tempting to think a transmission that collapses into microseconds would make ir-ctl return instantly, and that measuring it would catch the problem. It doesn't: the LIRC core (lirc_transmit() in lirc_dev.c) sleeps until the full duration of the signal has passed before the write returns, whatever the driver did. ir-ctl took 345 to 359 ms for a 300 ms signal, which looks perfectly healthy.

And IR is invisible. Unless you point a phone camera at the LED, the only symptom is that the TV or amplifier doesn't react, which looks like a wrong code, a weak LED, or a bad angle. People who have had a working IR blaster for years will update the kernel and start debugging their codes.

One more trap if you test with long signals: a 600 ms test code (three 200 ms segments) was refused outright with failed to send: Invalid argument (exit 74), because LIRC limits one transmission to 500 ms in total (IR_MAX_DURATION). That's an honest error, but it sends you looking in the wrong place.

What's really going on

pwm-ir-tx has two ways of sending. If the PWM driver can be called from atomic context, it programs each edge from an hrtimer callback; otherwise it sleeps between edges. The Pi's PWM driver is atomic, and dmesg shows no "TX will not be accurate as PWM device might sleep" line, so the Pi uses the timer path.

The timer callback applies one edge, schedules the next expiry, and loops if it has fallen behind, to catch up after a latency spike. Up to 6.17 the loop condition was:

        now = timer->base->get_time();
    } while (hrtimer_get_expires_tv64(timer) < now);

that is, keep going while the next expiry is already in the past. Commit 44d7fb8acdf8 ("media: pwm-ir-tx: Avoid direct access to hrtimer clockbase", first in v6.18) replaced it with what its message calls "an equivalent higher-level helper":

    } while (hrtimer_expires_remaining(timer) > 0);

hrtimer_expires_remaining() is the expiry time minus now. It is positive when the next expiry is in the future, which is always the case right after adding the next edge's duration. So the loop that used to run only when behind now runs whenever it is on time: the first callback applies every edge, one after another, completes the transmission and stops the timer. That is exactly the trace above. The same line is in rpi-6.18.y and in mainline today.

The fix

Until the condition is put back, use the bit-banged driver on the same pin:

dtoverlay=gpio-ir-tx,gpio_pin=18

instead of dtoverlay=pwm-ir-tx, and reboot. Same test signal, traced through the gpio_value event:

rc=0 elapsed_ms=331
burst length_ms=105.98 toggles=7604
burst length_ms=99.99  toggles=7600
gap between bursts ms=100.01

Two bursts of about 100 ms, 100 ms apart, each with 7,600 toggles, which is 38 kHz for 100 ms. gpio-ir-tx generates the carrier by busy-waiting on the CPU, so it costs CPU time while a code is being sent and its timing can be disturbed by other load. For an IR blaster that sends a code now and then, that is a fair trade against sending nothing.

To check a machine, check-ir-tx.sh lists the IR transmitters, flags pwm-ir-tx on a 6.18 or later kernel, and with --probe (as root) sends a 30 ms test code and measures the spread of its PWM edges in the trace. On this Pi with pwm-ir-tx it reported 4 edges in 7 µs. With gpio-ir-tx it passed.

The generalisable habit

When a change is described as equivalent, check the one thing that would make it not equivalent. Here it was the direction of a comparison: "expiry is before now" and "time remaining is positive" sound like the same question and are opposites. A refactor that only swaps how a value is obtained can still flip what the condition means, and the commit message and the review both read it as a no-op.

The other habit is about what counts as a test. An exit code and a duration are both claims the software makes about itself. For anything that leaves the machine, an IR code, a packet, a write to a disk, measure what actually happened: a trace event, a camera, a capture on the other end.

This is the second time the Pi's 6.18 kernel has quietly taken away something that worked on 6.12: legacy iptables modules stopped being built while the config still said they were enabled.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

Rootful Podman restarts a --uidmap container once on an AppArmor host, then gives up

The Homelab Postmortem — Sun, 11 Oct 2026 01:09:12 +0000

TL;DR: On a host with AppArmor enabled, a rootful Podman container that has its own ID mapping (--uidmap/--gidmap) and a restart policy is restarted once at most. When it exits the second time it stays exited. podman events shows died, restart, and then nothing, and RestartCount stops at 1. The process that should restart it, podman container cleanup, fails with profile "containers-default-0.62.2" specified but AppArmor is disabled on the host. AppArmor is enabled, and the error is logged only if the container was created with podman --syslog. Reproduced on Debian 13 with Debian's podman 5.4.2. The upstream report is on Ubuntu 26.04 with 5.7.0 and 6.1.3, so it isn't Ubuntu-specific or new. The same container without the mapping, or with --security-opt apparmor=unconfined, kept restarting. A Quadlet unit with UIDMap= and Restart=always was restarted by systemd every time. The toolkit's check-podman-restart-userns.sh lists containers that are stuck or will get stuck. Upstream report: podman-container-tools/podman#29925.

The symptom

A disposable Debian 13.7 VM (kernel 6.12.111, AppArmor enabled: /sys/module/apparmor/parameters/enabled is Y), apt install podman: podman 5.4.2, crun 1.21, conmon 2.1.12, containers-common 0.62.2. All as root. Three containers that exit after four seconds, each with --restart always:

podman run -d --name rtest-userns --restart always \
  --uidmap 0:200000:65536 --gidmap 0:200000:65536 alpine:3.22 sleep 4
podman run -d --name rtest-unconfined --restart always \
  --uidmap 0:200000:65536 --gidmap 0:200000:65536 \
  --security-opt apparmor=unconfined alpine:3.22 sleep 4
podman run -d --name rtest-plain --restart always alpine:3.22 sleep 4

Twenty-five seconds later:

rtest-userns:     exited  restarts=1  apparmor=containers-default-0.62.2
rtest-unconfined: running restarts=5  apparmor=unconfined
rtest-plain:      running restarts=5  apparmor=containers-default-0.62.2

The events for the mapped container:

create init start died restart

and nothing after that. podman start rtest-userns from a shell started it without complaint. --restart on-failure:3 on a mapped container whose command exits 1 stopped the same way, at restarts=1.

Created with podman --syslog run ... instead, the same container left this in the journal when it stopped:

/usr/bin/podman[5105]: level=error msg="Cleaning up container: failed to clean up container 75c416f9...:
  profile \"containers-default-0.62.2\" specified but AppArmor is disabled on the host"

from the process podman ... --syslog container cleanup --stopped-only <id>, which conmon runs when the container exits.

Why it's easy to miss

Everything you'd look at says the restart policy is working. The event stream has a restart event. podman inspect shows the policy as always. The first crash is handled, so a quick test that kills the container once and watches it come back passes.

The error itself goes nowhere by default. Without --syslog on the command that created the container, the cleanup process has no place to report it, so it isn't in the journal, in podman logs, or in the events. When you do find it, it says AppArmor is disabled on a host where it plainly isn't, which points at the host configuration rather than at Podman.

And the combination is narrow enough that most setups don't have it. Rootless Podman doesn't use AppArmor profiles. Fedora and RHEL use SELinux. Containers without their own mapping restart fine. It takes rootful Podman, an AppArmor distribution, and --uidmap/--gidmap, which is exactly what people reach for when they want rootful containers to run as unprivileged host IDs. Other ways of giving a container its own mapping, such as --userns=auto, weren't tested here.

What's really going on

The message comes from containers/common's AppArmor package. IsEnabled() there returns whether IsSupported() succeeds, and IsSupported() (v0.62.2, the version in Debian) checks three things in order: that the process isn't rootless, that the kernel reports AppArmor as enabled, and that the apparmor_parser binary can be found.

The upstream report doesn't explain the failure. The obvious guess is that the cleanup process thinks it is rootless. Here it isn't. Traced with strace -f on conmon as the container exited, the cleanup process ran as root, in the host's user namespace, with no Podman user-namespace variable in its environment, and it didn't re-execute itself or call unshare. conmon's capabilities were the same for the mapped and the plain container (CapEff: 000001ffffffffff, host user namespace). So whichever check fails, it fails for a process that looks the same as the one that successfully restarts the plain container. Which of the other two checks fails in that path wasn't pinned down here.

What is clear is the shape: the restart decision happens in the cleanup process, the cleanup process fails before it restarts the container, and the failure is reported only to syslog when asked for.

The fix

Until Podman fixes it:

Let systemd do the restarting. A Quadlet unit with the same mapping:

  [Container]
  Image=docker.io/library/alpine:3.22
  Exec=sleep 4
  UIDMap=0:200000:65536
  GIDMap=0:200000:65536

  [Service]
  Restart=always
  RestartSec=1

restarted 4 times in 25 seconds, with no AppArmor error in its journal. Quadlet runs the container with --rm and no --restart, so each restart is a new podman run from systemd, and Podman's own restart path isn't used.

--security-opt apparmor=unconfined also avoids it, as the table shows. That removes the container's AppArmor confinement, so it is a trade, not a fix.
Create containers with podman --syslog if you depend on Podman's restart policy. It doesn't fix anything, but the failure is then in the journal instead of nowhere.

To find containers already in this state, check-podman-restart-userns.sh lists every container with a restart policy that is exited without having been stopped by the user (STUCK), and every running one that is rootful, mapped, confined and set to restart on an AppArmor host (AT RISK, because it will stop the same way next time). On the test VM it reported the stuck and the at-risk containers, and passed one stopped by the user, one that exited 0 under on-failure, and the unconfined one.

The generalisable habit

A restart policy is only tested when the thing has stopped more than once. The common test, kill it and see it come back, exercises the first restart, which here worked. The question to ask is "what does the second exit look like", and the place to look is the restart count after a few cycles, not whether the container is up right now.

The same goes for a supervisor's error reporting. When the component that does the restarting is a short-lived helper process, find out where its errors go before you need them. Here they went to syslog only on request. Podman's compat API resetting the restart policy to no was the same kind of failure: the container looks configured to come back, and after the next crash it doesn't.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

llama-server's prompt cache reuses KV computed under a different LoRA scale

The Homelab Postmortem — Fri, 09 Oct 2026 01:54:03 +0000

TL;DR: llama-server's RAM prompt cache (--cache-ram, on by default) saves a slot's KV when another request takes the slot, and restores it when the same prompt comes back. The saved entry doesn't record which LoRA adapters and scales the KV was computed with. The server does check for a LoRA change, but it compares the new request with the slot's previous request, not with the entry it has just restored. So: send a prompt with an adapter at scale 0, send something else that takes the slot, send the first prompt again at scale 1, and the answer is decoded on the scale-0 KV. On b11514, the current release, that happened on 10 of 10 prompts: cache_n showed the whole prompt reused, prompt_n was 1, and the answer differed from the same request without the cache. Changing the scale globally with POST /lora-adapters did the same. b10703 from August behaved the same way. --cache-ram 0, or cache_prompt: false on every request, gave the right answers. The toolkit's check-lora-cache.sh tests a running server. Upstream: ggml-org/llama.cpp#30129, and #26207 for the global path.

The symptom

Debian 13 LXC, CPU only, llama.cpp b11514 from the release tarball. The models are the ones llama.cpp's own server tests use for LoRA: stories15M_MOE-F16.gguf (a 15M-parameter story model) and its moe_shakespeare15M.gguf adapter, both checked against the SHA-256 on Hugging Face. The server:

llama-server -m stories15M_MOE-F16.gguf --lora moe_shakespeare15M.gguf \
  --lora-init-without-apply -np 1 -c 4096

Ten prompts, each about 116 tokens, at temperature 0, 48 tokens out. First, the reference answers from a separate server started with --cache-ram 0: each prompt at scale 1 and at scale 0. The two scales gave different answers on all ten. Then, on a fresh default server, the sequence from the report, for each prompt P:

1. P  with "lora": [{"id": 0, "scale": 0}]
2. Q  with "lora": [{"id": 0, "scale": 1}]     (another prompt; it takes the only slot)
3. P  with "lora": [{"id": 0, "scale": 1}]

Step 3 for the first prompt:

scale 1, no cache:   ' loved to watch the time.\nBut that I in that bears that I want to keep,\nThe neither of you'
scale 0, no cache:   ' is very far away. The farmer and his family who is very far away. The farmer and his fami'
step 3:              ' had many:\nThe old men who had used it to sell,\nThe old men and men who had gone out to se'
                     timings: cache_n=116 prompt_n=1

The whole prompt came from the cache and one token was evaluated. The answer is neither the scale-1 answer nor the scale-0 one: the prompt was read under scale 0 and the continuation generated under scale 1. Across the ten prompts:

default server                                    differs from the scale-1 answer 10/10
--cache-ram 0                                     0/10
step 3 sent with cache_prompt: false              0/10
step 1 also at scale 1 (KV and request match)     1/10
scale changed with POST /lora-adapters instead    10/10
b10703 (August), default                          10/10

The 1 in the matching-scale row was the same prompt each time the ten ran in sequence. Re-run on its own three times, it matched. The KV there was built in a different order from the reference, so a floating-point difference is the likely cause, but that wasn't proven. It is a different thing from the 10 out of 10.

Why it's easy to miss

The request is honoured on its face. It names an adapter and a scale, the server accepts it, and the generated tokens are produced with that adapter applied. Only the part of the context that came from the cache was computed differently, and nothing in the response says which part that was. cache_n tells you that something was reused, not under what.

It needs a particular pattern to show up: the same prompt prefix sent under two different LoRA settings, with another request in between that takes the slot. That is exactly what a server that switches adapters per request does all day, with a shared system prompt and different personas or tasks per adapter. A test that sends one request per setting, or sends the two settings back to back, never sees it, because then the slot still holds the KV and the slot-level check works. With -np 4 and the same ten-prompt sequence, every answer was right: each prompt kept its own slot.

And the output from a contaminated request is plausible. On a 15M story model the difference is easy to see. On a real model with a style or persona adapter, a request that is half one adapter and half the other looks like a slightly off answer.

What's really going on

The unit the cache stores, in tools/server/server-task.h at b11514:

struct server_prompt {
    server_tokens tokens;

    std::list<common_prompt_checkpoint> checkpoints;
    ...
};

Tokens and checkpoints, nothing about adapters. When a request is assigned a slot, get_available_slot saves the slot's current prompt to the cache and loads the entry with the longest matching prefix for the new request (prompt_save, then prompt_load). Matching is by tokens only.

The LoRA check comes after that, in launch_slot_with_task:

if (!task.params.lora.empty()) {
    auto task_loras = construct_lora_list(task.params.lora);
    if (!are_lora_equal(task_loras, slot.lora)) {
        // if lora has changed, check to see if the cache should be cleared
        if (lora_should_clear_cache(slot.lora, task_loras)) {
            slot.prompt.clear();
        ...
        slot.lora = task_loras;
    }
} else {
    slot.lora = params_base.lora_adapters;
}

slot.lora is the LoRA setting of the slot's previous request. In the sequence above that is step 2 at scale 1, the new request is also scale 1, so nothing is cleared, and the KV that prompt_load just put in the slot, computed at scale 0, stays. When the prompt keeps its own slot, slot.lora really is the setting its KV was computed under, and the check clears it as intended. That is why -np 4 was fine here.

Requests with no lora field, which is what you send after changing the scale globally with POST /lora-adapters, take the else branch, which doesn't compare anything. That is the path in #26207, and it was 10 out of 10 here as well.

The fix

Until the cache records the adapters it was computed with:

Start the server with --cache-ram 0 if it serves more than one LoRA setting. All ten answers were right. You lose the RAM cache across slots, but each slot still reuses its own prefix, and the LoRA check works there.
Or send "cache_prompt": false on every request. Step 3 sent that way came back with cache_n=0 and the right answer on all ten. It has to be every request, because the entries are written whatever the flag says, and any request that doesn't opt out can read one computed under another setting.

Changing the scale globally through POST /lora-adapters is affected in the same way and is fixed the same way.

To test a running server, check-lora-cache.sh runs the same three steps with a probe prompt containing a random marker, after pushing it out of every slot, and compares the answer with an uncached request. On the default server it reported contamination with one slot and with four. With --cache-ram 0 it reported that the cache never restored the probe, which is the fixed state.

The generalisable habit

A cache key has to include everything that went into computing the value. Here the value is KV, and it depends on the tokens and on which adapters were applied. The key has only the tokens. The server knew about the second input, but checked it against the wrong thing: the slot's history instead of the cached entry's. The question to ask of any cache is "what else did this value depend on, and is it in the key?".

The test for it is the A, B, A sequence. Compute something under setting A, make the cache evict it, ask for it again under setting B, and compare with an uncached answer under B. Back-to-back requests won't find it, because nothing has been evicted yet.

The same RAM cache also has a "no limit" setting that keeps less than the default. In both cases the server gave no error, and the evidence was in cache_n.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

Ollama picks the Gemma 4 prompt template from the model's name

The Homelab Postmortem — Wed, 07 Oct 2026 08:36:39 +0000

TL;DR: Gemma 4 models in Ollama carry RENDERER gemma4, which Ollama 0.35.1 resolves per request to gemma4-small (the e2b/e4b template) or gemma4-large (12b, 26b, 31b). It decides by looking for e2b/e4b or 12b/26b/31b in the model's name, and if there is none, by parameter count against 12 billion. The 12B counts as 11.9B. So gemma4:12b itself gets the large template, but ollama cp gemma4:12b mygemma, or a Modelfile FROM gemma4:12b with your system prompt saved as assistant, gets the small one. The difference is an empty thought block the large template adds when thinking is off. ollama show prints the same thing for both. On the 12B Q4_K_M we tested, the model wrote the missing block itself: four extra generated tokens, the same answers on five of six prompts, and the same answer with different formatting on the sixth. If you want the template the model was trained with, put RENDERER gemma4-large in the Modelfile. The toolkit's check-gemma4-renderer.sh lists which of your models resolve to which. Upstream report: ollama/ollama#18824.

The symptom

Debian 13 LXC, CPU only, Ollama 0.35.1 (the current release) from the release tarball, gemma4:12b from the library (8.0 GB; ollama show says 11.9B parameters, RENDERER gemma4). The report used a third-party GGUF and the request below: "Hello", think: false, num_predict: 1, read prompt_eval_count. The same weights under different names:

gemma4:12b                                        think:false 14   think:true 17
ollama cp gemma4:12b mygemma                      think:false 10   think:true 17
FROM gemma4:12b, saved as assistant               think:false 10   think:true 17
FROM gemma4:12b, saved as assistant-12b           think:false 14   think:true 17
FROM gemma4:12b, saved as assistant:12b           think:false 14   think:true 17
FROM gemma4:12b + RENDERER gemma4-large           think:false 14   think:true 17
FROM gemma4:12b + SYSTEM + num_ctx, as helper     think:false 21   think:true 23
same Modelfile, saved as helper-12b               think:false 25   think:true 23

Four tokens go missing whenever the name has no size in it, including on a plain ollama cp. With thinking on, every variant gets the same prompt. The report says the official library tag is fine because its name contains 12b. That is true of the tag, but not of anything derived from it under another name, which is the usual thing to do with a library model once you add a system prompt.

Why it's easy to miss

Nothing you can look at shows it. ollama show assistant and ollama show gemma4:12b print the same model block, and ollama show --modelfile says RENDERER gemma4 for both. The resolution happens per request and isn't logged.

It only matters with thinking off. A request without a think field, including everything through /v1/chat/completions, ran with thinking on for this model, and both templates produced the same prompt there.

And the answers are nearly the same, as below, so a quick look at the output won't show a difference.

What's really going on

server/renderer_resolution.go in 0.35.1:

func resolveGemma4Renderer(m *Model) string {
    ...
    if renderer, ok := gemma4RendererFromName(m.ShortName); ok {
        return renderer
    }
    if renderer, ok := gemma4RendererFromName(m.Name); ok {
        return renderer
    }
    if parameterCount, ok := parseHumanParameterCount(m.Config.ModelType); ok {
        return gemma4RendererForParameterCount(parameterCount)
    }
    return gemma4RendererSmall
}

gemma4RendererFromName is a substring check: e2b or e4b gives small, 12b, 26b or 31b gives large. ShortName and Name are the name you asked for (n.DisplayShortest() and n.String() in GetModel), tag included, so assistant:12b counts. A copy or a derived model keeps the base model's config, RENDERER gemma4 and model_type 11.9B included, under the new name. With no size in the name, the count decides, and gemma4LargeMinParameterCount is exactly 12,000,000,000.

The two renderers are the same code with one flag:

case "gemma4", "gemma4-small":
    return &Gemma4Renderer{useImgTags: RenderImgTags}
case "gemma4-large":
    return &Gemma4Renderer{useImgTags: RenderImgTags, emptyBlockOnNothink: true}

With emptyBlockOnNothink, the generation prompt ends <|turn>model\n<|channel>thought\n<channel|> when thinking is off: an empty thought block. The report compared 50 rendered prompts with Google's chat template for the 12B and found the large renderer identical on all 50 and the small one missing this block on all 50. Without it, the prompt stops at <|turn>model\n. Those are the four tokens.

What it does to the answers

The report says it did not measure the effect on outputs. Six prompts, think: false, temperature 0, assistant (small) against assistant-12b (large):

17 * 23?                  small eval   8  '391'                 large eval   4  '391'
capital of Australia?     small eval   7  'Canberra'            large eval   3  'Canberra'
bat and ball              small eval 207  '...**$0.05**...'     large eval 205  '...**$0.05**...'
one sentence on autumn    small eval  25  identical             large eval  21
three primes over 50      small eval  34  identical             large eval  30
'good morning' in French  small eval  33  identical             large eval  29

Five answers are identical, with four more generated tokens on the small side. The bat-and-ball answer is the same answer with a bolded heading on one side and not the other. To see where the four tokens go, the two prompts, written out by hand as the renderers build them, were sent straight to the llama-server process Ollama runs for the model:

small prompt   raw tokens: '<|channel>' 'thought' '\n' '<channel|>' '3' '9' '1'
large prompt   raw tokens: '3' '9' '1'

The model writes the empty block itself, and Ollama's Gemma 4 parser removes it before the reply goes out. With a JSON schema in format and thinking off, the model can't write the block, since the grammar applies from the first token. The answers still had the same values (391, Canberra, 0.05, 53, 59, and 61, Bonjour), with different whitespace, and the bat-and-ball one came back as "The ball costs $0.05." instead of "0.05".

So on this model and these prompts, the cost is a few tokens and some formatting drift. That is one quantisation of one size on six prompts, not a quality evaluation. A smaller quantisation, a long multi-turn chat or a different task may react differently to a prompt the model wasn't trained on. The point is that whether it gets that prompt depends on what you named it.

The fix

Name the renderer in the Modelfile. An explicit gemma4-large is used as is, whatever the model is called:

FROM helper
RENDERER gemma4-large
PARSER gemma4

Re-created that way, helper (system prompt and num_ctx 8192 kept) went from 21 to 25 prompt tokens, the same as helper-12b.

Putting 12b in the name also works, but it is a substring match: a name containing both e4b and 12b resolves to small, because e2b/e4b is checked first. Setting the renderer doesn't depend on that.

To find affected models, check-gemma4-renderer.sh reads /api/tags and /api/show and applies the same rules without loading anything. On the eight models above it marked assistant, helper and mygemma as resolving to the small template and the others as large, which matches the measured token counts.

The generalisable habit

When a tool picks behaviour from a name, a copy is a different thing. ollama cp and FROM look like they produce the same model under another label, and for the weights and the config they do. But anything resolved from the label at request time is decided again for the copy, and the closer the model sits to a threshold, here 11.9B against 12B, the more likely that decision changes. The way to see it is to measure something the decision affects, here the prompt token count, on the original and the copy.

The template also decides what a Gemma 4 model does with your JSON schema when thinking is on, which is the other side of the same <|channel> block.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

llama-server's logprobs are placeholders when speculative decoding is on

The Homelab Postmortem — Tue, 06 Oct 2026 03:37:19 +0000

TL;DR: When llama-server runs with speculative decoding (a draft model with -md, MTP, or one of the n-gram types), every token that comes out of the speculative loop is sent with logprob: 0.0 and an empty top_logprobs list. The code sets the probability to 1.0 with the comment // set later and never sets it. With a draft model that is every token after the first. On b11430, the current release, the mean logprob of 64-token samples at temperature 1 was -0.48 without speculation and -0.0011 with it. The generated text looked normal, and nothing in the response or the log says the numbers are fill-ins. There is no per-request switch: the request fields that used to tune speculation are compiled out and ignored. Send logprob requests to an instance started without speculation. The tokens themselves are fine: on a small fixture, the server's speculative output had the same next-token distribution as plain sampling. The llama-speculative example program did not. The toolkit's check-spec-logprobs.sh checks a running server. Upstream: ggml-org/llama.cpp#27972 and #29975.

The symptom

Debian 13 LXC, CPU only, llama.cpp b11430 from the release tarball (the current release, SHA-256 matching the release digest), gemma-3-1b-it-Q4_K_M. A draft model normally has to be smaller than the target to save time; using the same file as its own draft is enough to put every token through the speculative path, and needs no extra download. The request is the one from the report:

curl -s http://127.0.0.1:8080/v1/chat/completions -H 'Content-Type: application/json' -d '{
  "messages": [{"role": "user", "content": "Explain how a CPU branch predictor works."}],
  "max_tokens": 24, "temperature": 1.0, "seed": 1, "logprobs": true, "top_logprobs": 3}'

Without speculation:

'Okay'    logprob=-0.00813608   top_logprobs=3
','       logprob=0             top_logprobs=3
' let'    logprob=-2.38419e-07  top_logprobs=3
'’'       logprob=-2.60903      top_logprobs=3
's'       logprob=0             top_logprobs=3
' break'  logprob=-0.0479959    top_logprobs=3

Same server started with -md gemma-3-1b-it-Q4_K_M.gguf --spec-type draft-simple:

'Okay'    logprob=-0.00813608   top_logprobs=3
','       logprob=0             top_logprobs=0
' let'    logprob=0             top_logprobs=0
"'"       logprob=0             top_logprobs=0
's'       logprob=0             top_logprobs=0
' break'  logprob=0             top_logprobs=0

All 23 tokens after the first came back as 0 with no alternatives, at temperature 0 and at 1, on /v1/chat/completions and on the native /completion with n_probs. With post_sampling_probs: true the native endpoint reported prob: 1.0 and an empty top_probs for every token after the first; the unspeculated run gave What 0.048, for example.

The effect on anything that aggregates logprobs is not subtle. Five seeds, 64 tokens each, "Write a short story about a lighthouse keeper." at temperature 1:

no speculation    -0.5158 -0.6775 -0.3832 -0.3360 -0.4898   mean -0.4805
draft model       -0.0055 -0.0    -0.0    -0.0    -0.0      mean -0.0011

The report saw the same shape on a Vulkan iGPU with Gemma 4 26B and an MTP drafter: a mean of -0.00107 with MTP against -0.38244 without, measured while trying to find out whether MTP changes the output. b10703, from August and before #27694, gave the same placeholders on the same probes.

Why it's easy to miss

The fields are all there. logprob is a number, top_logprobs is a list, and the response validates against any schema you have for it.

A logprob of exactly 0 is not suspicious either. In the run without speculation above, , and s came back as 0 with three alternatives: a 1B model is that certain of them. So you can't spot the placeholders by looking for zeros. The giveaway is the empty top_logprobs on a request that asked for three.

The text looks normal, so nothing seems wrong to anyone reading the output. And the server's own description doesn't help: /props reported "speculative.types": "none" in its default generation settings on servers started with -md and with --spec-type ngram-mod. /slots is the place that is right: "speculative": true.

With the n-gram types it is patchier still. Those only draft when the recent text repeats, so a single response mixes real values and placeholders. On a prompt asking the model to copy a repeated sentence, --spec-type ngram-mod with its default settings left 27 of the 30 tokens after the first correct and 3 as placeholders. With a shorter match length it was 26 placeholders out of 30.

What's really going on

tools/server/server-context.cpp at b11430 has two places that emit a generated token. The normal one:

result.prob         = 1.0f; // TODO: set it here instead of doing inside populate_token_probs

if (slot.task->params.sampling.n_probs > 0) {
    populate_token_probs(slot, result, slot.task->params.post_sampling_probs, params_base.special, tok_idx);
}

and the one after the target has verified a draft, which loops over the accepted tokens plus the one the target sampled itself:

for (size_t i = 0; i < ids.size(); ++i) {
    completion_token_output result;

    result.tok          = ids[i];
    result.text_to_send = common_token_to_piece(slot.ctx_tgt, result.tok, accept_special_token(slot, result.tok));
    result.prob         = 1.0f; // set later

    // TODO: set result.probs

Nothing sets it later. populate_token_probs is called in one place, the normal path. The first token of a response always comes from the normal path, because there is nothing to draft from yet, which is why it alone has real values. After that, with a draft model, every step goes through the speculative loop. That includes steps where the target rejected the whole draft: on a two-token native request the draft got 0 of 3 accepted, and the second token, sampled by the target itself, still came back empty.

Does speculation change the tokens too?

If the logprobs are wrong, the obvious next question is whether the output is. Speculative decoding is meant to be lossless: the target's verification should leave the distribution of sampled tokens exactly as if there were no draft. #27694, merged on 2026-10-02 and in b11430, made the server verify draft-simple and MTP drafts by rejection sampling at temperature above 0, and its description says the output distribution is preserved exactly.

#29975 reports that the llama-speculative example program does not preserve it, and ships a fixture to show it: two 24 KB GGUFs with an eight-letter vocabulary, a target and a noised copy as draft. After the prompt bcdbc and a first generated f, the target's own top-3 distribution for the next token is e 0.345, g 0.452, h 0.203. The archive's SHA-256 matched the one in the issue. Built from source at b11430 and run over seeds 1 to 1000 with the report's script:

seeds 1..1000; runs with first token 'f' (5): 820
  next token 4 ('e'): 1.000   target: 0.345
  next token 6 ('g'): 0.000   target: 0.452
  next token 7 ('h'): 0.000   target: 0.203

The report doesn't test the server. The same fixture through llama-server from the same build, same sampler settings (top-k 3, temperature 1), 1000 seeds, with and without -md draft.gguf:

no speculation    first token 'f': 840   next e 0.330  g 0.452  h 0.218
draft model       first token 'f': 840   next e 0.330  g 0.452  h 0.218   (2470 drafted, 884 accepted)

Both match the target distribution within sampling error (one standard deviation is about 0.016 at 840 samples). So the server's speculative path does what #27694 says: it changes which tokens it reports probabilities for, but not which tokens it picks. The example program, a natural place to look when learning how speculative decoding works or benchmarking it, always picks e. The report points at two lines: the example takes the draft's top candidate instead of the one it sampled, and on rejection it subtracts the two distributions position by position after sorting both, which pairs up different tokens when top-k leaves different sets. Those reasons are the report's; only the output above was measured here.

The fix

There is no way to turn speculation off for one request. The server used to accept speculative.n_max and related fields per request; on b11430 they are inside an #if 0 block in tools/server/server-schema.cpp ("we disable speculative parameter adjustments for now"), and unknown fields are ignored. Sending "speculative.n_max": 0 or 1 changed nothing: the same 17 tokens were drafted and the same 23 placeholders came back.

So:

Send requests that need logprobs to a server started without -md / --spec-type. The unspeculated runs above returned real values on every token. If you want speculation for everything else, that means a second instance.
Check /slots, not /props, to see whether a server speculates. curl -s localhost:8080/slots | jq '.[].speculative'.
Treat an empty top_logprobs on a request that asked for alternatives as a missing value, not a certain one. If you can't change the server, at least don't average over those tokens.
If you benchmark distributions, use llama-server rather than llama-speculative until #29975 is fixed.

The generalisable habit

When a measurement comes back too good, check the instrument before the thing you are measuring. The reporter's numbers said MTP made a model almost perfectly certain at temperature 1, which is physically implausible, and that is what made them look at the logprobs instead of the model. A cheap way to do that is to run the same measurement under a condition you know must differ, here with and without the draft, and see whether the instrument can tell them apart. Here it did, and the whole difference was the instrument's.

The second check is the one people skip: when an optimisation is meant to be invisible, test that it is, with something small enough to count. Two 24 KB models and 1000 seeds were enough to show that the server's speculation leaves the distribution alone and the example's doesn't.

The toolkit's check-spec-logprobs.sh reads /slots, sends one logprob request, and reports whether the tokens after the first came back with alternatives.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

Ollama skips your JSON schema when a thinking model answers without thinking

The Homelab Postmortem — Mon, 05 Oct 2026 02:34:15 +0000

TL;DR: Since 0.34.4, Ollama applies a format schema on a thinking model as a single grammar: anything until the thinking block closes, then the schema. That grammar also allows the response to end before the closing, and it treats everything up to the closing as thinking. So when a model like Gemma 4 decides not to think and answers straight away, its answer is "text before the closing" and nothing constrains it. On gemma4:e2b with think: true and a one-field schema, every answer that skipped thinking came back as bare text (391, Paris) with HTTP 200 and nothing in the log. Every answer that thought first matched the schema. With think: false the reply had the right shape every time. The open fix, ollama/ollama#18783, made all 16 replayed requests match the schema, though not by constraining the direct answer: the model thought first every time instead. Until a release includes it, validate format replies in the client. The toolkit's check-ollama-format-think.sh tells you whether a model on your server does this. Upstream report: ollama/ollama#18774.

The symptom

Debian 13 LXC, CPU only, Ollama 0.35.1 (the current release) from the release tarball, gemma4:e2b from the library. The report used gemma4:e4b; the smaller model is what a CPU-only LXC runs at a usable speed. The schema asks for one string field:

{"type": "object",
 "properties": {"answer": {"type": "string"}},
 "required": ["answer"]}

The report's request on /api/chat at temperature 0, with seeds 1 and 2, then with think: false:

{"think": true,  "eval_count": 4,   "thinking_chars": 0,   "content": "391"}
{"think": true,  "eval_count": 248, "thinking_chars": 607, "content": "{\n  \"answer\": \">391\"\n}"}
{"think": false, "eval_count": 11,  "thinking_chars": 0,   "content": "{ \"answer\": \")\"\n}"}

The first line is the bug. 391 parses as JSON, but it is a number, not an object with an answer field. The request returned HTTP 200 with done_reason: "stop" after four tokens, so it didn't run out of tokens. The second line is the same request with a different seed: the model thought first, and the reply has the right shape. /api/generate gave the same results.

To see how often it happens, three prompts went out eight times each at the default temperature, seeds 0 to 7, on /api/chat:

"What is 17 * 23? Answer with the number."   thought 5, valid 5    direct 3, valid 0   ("391")
"What is the capital of France? One word."   thought 3, valid 3    direct 5, valid 0   ("Paris")
"Is 91 prime? Answer yes or no."             thought 8, valid 8    direct 0

How often the model skips thinking depends on the question, but the result once it does is the same: 16 of 16 replies that thought first matched the schema, and 8 of 8 that skipped thinking didn't. In the report's think: false control, three requests on each endpoint at temperature 0, every reply had the right shape.

Why it's easy to miss

Whether you see it depends on the question. A test prompt that makes the model reason, which is what most people reach for when trying out a thinking model, never shows it. The prime question above went through thinking all eight times. The questions that trigger it are short and easy, which is also what most structured-output calls look like: classify this, extract that, yes or no.

Nothing reports it either. The status is 200, done_reason is stop, and the server log has no line about the format. A reply that is only a word or a number can even look like a parsing problem on the client side.

think: false working makes it look like think: true is just unsupported with format. It isn't: with thinking enabled the schema is enforced, but only on the part of the reply after the thinking.

What's really going on

#18479 ("apply structured outputs in a single pass on thinking models", merged 2026-09-22, first released in 0.34.4) made the format and the thinking one grammar. In llm/llama_server.go in 0.35.1, when the model's parser reports a thinking-close string and the request has a format, the schema is converted to a grammar and wrapped:

if len(req.ThinkingClose) > 0 && (lsReq.Grammar != "" || lsReq.JsonSchema != nil) {
    ...
    lsReq.Grammar = thinkingGrammar(req.ThinkingClose, lsReq.Grammar)
}

The docstring of thinkingGrammar in llm/gbnf.go says what that wrapper allows:

// thinkingGrammar returns a grammar that leaves the text before any of the
// closings unconstrained, then constrains what follows the first complete
// closing to the root of the format grammar. The response may end before any
// closing.

Gemma 4 opens thinking with <|channel> and closes it with <channel|>, and its parser reports <channel|> as the closing whenever thinking is enabled. The grammar assumes the response starts inside the thinking block. When the model starts with <|channel>, that holds: everything up to <channel|> is free, and the schema applies after it. When the model skips thinking and writes 391 followed by end of sequence, the grammar sees text before any closing, followed by an end the grammar allows. Nothing in it says the answer itself has to match the schema.

The #18479 description acknowledges the limitation: "A model that answers without thinking stays unconstrained."

With think: false the parser reports no closing, so the schema grammar is applied on its own from the first token, which is why that control always has the right shape.

What the open fix does

#18783 adds the opening string. For a model whose response can begin in content, the grammar becomes "either the schema, or <|channel>, then free thinking, then a required <channel|>, then the schema". The thinking branch can no longer end before the closing.

The PR head (4121ed65) and its merge base (42e911bc) were built in the same LXC, and each build got the eight prompt and seed pairs that had answered directly in the run above, on both endpoints:

                         0.35.1      merge base    PR #18783
answered directly        15 of 16    15 of 16      0 of 16
  ... schema violated    15          15            -
thought first            1           1             16
  ... schema matched     1           1             16
eval_count, direct       2 to 4      2 to 4        -
eval_count, thought      155         155           112 to 267

The one request that thought on 0.35.1 and the merge base (17 × 23, seed 1, /api/chat) had answered directly in the earlier run; at the default temperature the same seed doesn't always take the same branch. The merge base behaved exactly like the release.

On the PR build every request matched the schema. None of them was a constrained direct answer, though. The grammar no longer allows Paris as a first token, and of the two things it does allow, the start of the JSON object or <|channel>, the model picked <|channel> every time and thought for 260 to 634 characters. A capital-of-France call that took 2 tokens now takes about 113. That is a fair trade for getting the shape you asked for, but on a CPU box it is roughly fifty times the tokens for the questions that used to be the cheapest.

The fix also does nothing for what goes inside the field. Across the builds, the 17 × 23 answers that went through thinking came back as "$391", ">391", "))391" and ")), ". That is this small model under a grammar, not the bug, but it means a reply that matches the schema still needs checking.

The fix

Until a release includes #18783:

Validate the reply against the schema in the client. A reply that fails validation and has an empty thinking field is this case. On 0.35.1 every reply that thought first had the right shape, so a retry that lands in thinking will too; on prompts the model always answers directly, a retry won't help.
Send think: false for calls where you need the shape and don't need the thinking. It had the right shape every time here. On gemma4:e2b the content was poor (")", and in the report "\\text{391}"), so check whether your model's answers survive it.

Either way, don't assume that format guarantees the shape just because the request succeeded. With thinking enabled, it only covers the part of the reply after the thinking.

The generalisable habit

When a constraint is applied to "the part after X", find out what happens when X never appears. Here the constraint was written for responses that begin with thinking, and a response with no thinking at all fell through it. The test is the input that skips the step: a question easy enough that the model answers it straight away.

It is the second structured-output gap in Ollama 0.35 here in a week. On one of its two chat paths, your schema's keys are re-sorted alphabetically before the grammar sees them. Both times the reply was HTTP 200 and nothing in the log said anything was wrong.

Which template a Gemma 4 model gets in the first place depends on what the model is called: a copy of gemma4:12b under a name without 12b is prompted with the e2b/e4b template.

The toolkit's check-ollama-format-think.sh sends a few short prompts to a model with think: true and a schema, and reports how many replies skipped thinking and how many of those broke the schema.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

vLLM's weight cache can serve another checkpoint's weights when the tensor layout matches

The Homelab Postmortem — Sat, 03 Oct 2026 07:45:07 +0000

TL;DR: vLLM 0.30.0 can keep a model's weights in a long-running daemon so that engines restart without reloading them (load_format="ipc_cache"). Before an engine uses those weights, both sides compare a fingerprint, and the docs describe the checkpoint part of it as "checkpoint content". In the code it is a hash of each shard's file name and safetensors header: tensor names, shapes, dtypes and offsets, but no tensor values. Two checkpoints with the same layout, such as a base model and a fine-tune of it, or two training steps, get the same fingerprint. On an RTX 2070, a daemon holding Qwen3-0.6B served an engine started on a copy with model.norm.weight zeroed. On its own that copy answers '!!!!!!!!!!!!'. With the daemon running, it answered ' Paris. The capital of Italy is Rome. The capital of', exactly like the original, logged Mapped 339 tensors from the weight cache daemon, and warned about nothing. Upstream report: vllm-project/vllm#59647.

The symptom

RTX 2070 (8 GB) on Windows 11, WSL2 Ubuntu, driver 591.86, vLLM 0.30.0 with torch 2.13.0+cu130, everything in fp16 since the card has no bf16. Two checkpoints, following the report:

hf download Qwen/Qwen3-0.6B --local-dir q
cp -r q q_mod
# zero the 2,048 bytes of model.norm.weight in q_mod/model.safetensors, header untouched

The files differ, and loaded normally each behaves like itself. Greedy decoding, 12 tokens, "The capital of France is":

q      load_format=auto   ' Paris. The capital of Italy is Rome. The capital of'
q_mod  load_format=auto   '!!!!!!!!!!!!'

Then the daemon, preloaded with q. The report used vllm preload, which isn't in the 0.30.0 CLI. The module the docs point to is:

python -m vllm.model_executor.model_loader.weight_cache.daemon --model q --dtype float16
# ===== Weight cache daemon READY: node 0/1 serving 1 local rank(s) in the default socket dir =====

and an engine on q_mod with the cache:

q_mod  load_format=ipc_cache   ' Paris. The capital of Italy is Rome. The capital of'
  INFO [ipc_loader.py:203] Mapped 339 tensors from the weight cache daemon (zero_copy mode)

The engine was asked for q_mod and ran q, with no warning from either process. To confirm that the check itself works, an engine started with ipc_cache on a different model (a small random Qwen3 with different shapes) was turned away and fell back to disk, as documented:

WARNING [ipc_loader.py:139] Weight cache unusable (WeightCacheKey mismatch on fields: ['checkpoint']); falling back to disk loading

So the fallback works when the layout differs, and doesn't trigger when only the values do.

Why it's easy to miss

Everything you'd look at points at the checkpoint you asked for. The engine was started on q_mod, the only log line about weights says they were mapped successfully, and the output is fluent text from a working model. Only the weights are someone else's. In the realistic case, a base model and its fine-tune, or the same fine-tune at two steps, the wrong answers are plausible ones. Nothing points at the cache.

The documentation says this case can't happen. The feature's page on the main branch (docs/features/preload.md, which isn't in the 0.30.0 tag) lists a "Safe fallback" for cached weights that "don't match the engine's configuration". It describes the fingerprint as covering "checkpoint content (hashed from safetensors metadata, ...)". That parenthesis gives it away: metadata is all it hashes, and different weights can have identical metadata.

What's really going on

vllm/model_executor/model_loader/weight_cache/protocol.py in 0.30.0:

def hash_checkpoint(model: str) -> str | None:
    """Fingerprint checkpoint content from local safetensors metadata.

    Hashes each shard's safetensors header so a daemon and an engine pointing
    at identical weights in different directories produce the same key. ...
    """
    ...
    for path in sorted(files, key=os.path.basename):
        hasher.update(os.path.basename(path).encode())
        hasher.update(_safetensors_header(path))
    return hasher.hexdigest()

A safetensors header is a JSON index: for each tensor, its name, dtype, shape and byte offsets. Fine-tuning changes none of those. The design goal in the docstring, letting a copy of the same weights in another directory match, is met by hashing less than the content. The side effect is that different weights with the same layout match too. The rest of WeightCacheKey (architecture, dtype, quantization, TP rank, vLLM version) is the same for a local base model and its fine-tune as well.

A fix is proposed in #59648, titled "Fingerprint sampled tensor bytes, not headers only". It is open, and 0.30.0 is the current release.

The fix

Until that ships, the daemon's checkpoint and the engine's must be the same one, and nothing will tell you if they aren't. In practice:

Run a weight-cache daemon only for the checkpoint you serve. If you switch between a base model and fine-tunes of it, or between training checkpoints, either stop the daemon and start one for the new checkpoint, or load the others with the default load_format.
Treat "Mapped N tensors from the weight cache daemon" as a claim to check. After any switch, compare one deterministic prompt between load_format="ipc_cache" and "auto" for the checkpoint you think you're serving. Here that took one prompt and twelve tokens to show the difference.

Neither of those was needed for a different-shaped model, which the existing check caught.

The generalisable habit

A cache key decides what counts as the same thing. Whoever chose this one optimised for matching identical weights in different places, and in doing so it also matched different weights in the same layout. When a cache promises a safe fallback on mismatch, find out what the key covers before relying on it. The test is cheap: make two inputs that differ only in what the key leaves out, and see whether the cache tells them apart.

The same version of vLLM also loads a LoRA adapter's per-module scaling as one number and serves it without a warning. In both cases vLLM read less of what it was given than it reported using.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

vLLM ignores LoRA rank_pattern and alpha_pattern and serves the adapter at the wrong scale

The Homelab Postmortem — Sat, 03 Oct 2026 07:45:05 +0000

TL;DR: A PEFT LoRA adapter can give individual modules their own rank and alpha through rank_pattern and alpha_pattern in adapter_config.json, and PEFT scales each module by its own alpha_m / r_m. vLLM 0.30.0 reads r and lora_alpha only and applies lora_alpha / r to every module. The patterns are dropped without a warning. On an RTX 2070 under WSL2, with PEFT 0.21.2 and a small random Qwen3, an adapter with rank_pattern = {"q_proj": 4} gave prompt log-probabilities 0.0211 away from PEFT's on average, against 0.0003 for the same setup without a pattern. An adapter with only alpha_pattern set was off by 0.0168. Multiplying the affected modules' lora_B by the missing factor and clearing the pattern brought it back to 0.0003. The toolkit's check-lora-patterns.py reads an adapter's config and lists the modules vLLM will mis-scale, and by how much. Upstream report: vllm-project/vllm#59799.

The symptom

RTX 2070 (8 GB) on Windows 11, WSL2 Ubuntu, driver 591.86. vLLM 0.30.0 with torch 2.13.0+cu130, PEFT 0.21.2. The model is a randomly initialised two-layer Qwen3 (hidden size 256), so nothing has to be downloaded. The RTX 2070 has no bf16, so everything ran in fp16 (the report used bf16).

Four adapters on q_proj and v_proj, all r=16, lora_alpha=32, with lora_B scaled up so the adapter's effect stands well clear of fp16 noise. For each, PEFT's own prompt log-probabilities on four 48-token prompts are the reference, then vLLM serves the same adapter on the same base:

adapter                                   PEFT q_proj scale   mean |vLLM - PEFT|   max
none          no pattern                  2                   0.0003               0.0016
rank          rank_pattern {"q_proj": 4}  32/4   = 8          0.0211               0.1106
rank_folded   rank, q_proj lora_B x4,     2 (x4 in weights)   0.0003               0.0010
              rank_pattern {}
alpha         alpha_pattern {"q_proj":128} 128/16 = 8         0.0168               0.1046

The first row shows vLLM's LoRA path is fine: with no pattern it matches PEFT to within fp16 rounding. With a pattern on one module, the error is 70 times larger. The folded copy, which moves the factor PEFT applies into the weights themselves, matches again. alpha_pattern alone produces the same error, so this is about the scaling, not about the module having a different rank.

The vLLM log has nothing to say about any of it. No line in the run mentions rank_pattern or alpha_pattern.

Why it's easy to miss

vLLM accepts the adapter. It already turns some adapters away: _validate_features refuses DoRA and modules_to_save, so an adapter that loads without complaint looks supported. The output is still the adapter's output, only weaker or stronger in the patterned modules than it was trained to be. Nothing about the generated text flags that. You would have to compare against PEFT, or measure the quality you trained for, to see it.

The patterns aren't exotic, either. The report points out that PEFT's own LoRA documentation recommends rank_pattern for mixture-of-experts models, giving each expert a smaller rank (r // num_experts), and points to vLLM for serving. The reporter measured the consequence on OLMoE-1B-7B: a held-out perplexity of 10.06 in PEFT and 11.28 in vLLM, against 13.09 for the base model. That means vLLM gave up about 40% of what the adapter had gained. Those numbers are the reporter's, from hardware this lab doesn't have. The direction and size of the effect match the small model here.

What's really going on

vllm/lora/peft_helper.py in 0.30.0 defines the fields vLLM reads from adapter_config.json:

r: int
lora_alpha: int
target_modules: list[str] | str
bias: ...
modules_to_save: list[str] | None = ...
use_rslora: bool = field(default=False)
use_dora: bool = field(default=False)
vllm_lora_scaling_factor: float = field(default=1.0)

and computes one scale from them:

if self.use_rslora:
    self.vllm_lora_scaling_factor = self.lora_alpha / math.sqrt(self.r)
else:
    self.vllm_lora_scaling_factor = self.lora_alpha / self.r

There is no field for rank_pattern or alpha_pattern, and a code search of the repository finds no other reference to them. The rank of each module still comes out right, because it's taken from the tensor shapes in the safetensors file. Only the scale is shared, so any module whose pattern makes alpha_m / r_m differ from lora_alpha / r is scaled wrong by exactly that ratio. For q_proj above that is 8 against 2, a factor of 4.

Not every patterned adapter is affected. According to the report, PEFT's save_as_lora with a dynamic rank writes r=1, lora_alpha=1 and the same value in both patterns for each module. Every module's scale is then 1, and vLLM gets it right by coincidence.

A fix is proposed in #59801, which applies the scale per module. It is open and unmerged, and 0.30.0 is the current release.

The fix

Until a release includes it, fold each affected module's scale correction into its lora_B and remove the patterns. The factor is PEFT's scale for that module divided by vLLM's, and check-lora-patterns.py prints it. For the adapter above it was 4 for q_proj. This is the fold the rank_folded row used, written to a new directory:

import json, os
from safetensors.torch import load_file, save_file

sd = load_file("rank/adapter_model.safetensors")
sd = {k: v * 4 if "q_proj.lora_B" in k else v for k, v in sd.items()}   # 4 = (32/4) / (32/16)
os.makedirs("rank_folded")
save_file(sd, "rank_folded/adapter_model.safetensors")
cfg = json.load(open("rank/adapter_config.json"))
cfg["rank_pattern"] = {}
json.dump(cfg, open("rank_folded/adapter_config.json", "w"))

Two cautions:

Pattern keys are module-name patterns. According to the report, PEFT matches a key against the end of the module path, so q_proj applies to every layer's q_proj, and a key like layers.3.self_attn.q_proj applies to one. Fold the tensors the key actually covers.
Don't just delete alpha_pattern. That changes what PEFT does as well, and leaves vLLM where it was.

Run check-lora-patterns.py on the folded adapter afterwards. It should report every module as keeping lora_alpha / r.

The generalisable habit

An adapter config is a set of instructions, and a loader that recognises only some of them will quietly carry out a different set. vLLM rejects some unsupported adapter features outright, and that makes it easy to assume that whatever it accepts, it supports. It doesn't follow. Before you trust a server to reproduce a training setup, compare one batch of its outputs against the training framework's on the same inputs. Here that took four prompts and a single number.

This is the second LoRA case on this site where vLLM accepts an adapter and serves something else. The first was an adapter whose target modules it will never apply. Its weight cache, which can serve another checkpoint's weights, is the same pattern one level down: a check that passes on less than it claims to check.

The toolkit's check-lora-patterns.py reads adapter_config.json files, or every one under a directory. For each module whose pattern changes its scale, it prints PEFT's scale, vLLM's, and the factor between them. It doesn't flag save_as_lora-style adapters whose patterns keep every scale equal.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

A failing Docker swarm service cut healthy containers off the overlay network

The Homelab Postmortem — Sat, 03 Oct 2026 06:53:13 +0000

TL;DR: On a Docker swarm node, the overlay driver keeps a count of how many endpoints have joined each network there, and destroys the network's sandbox on that node when the count reaches zero. When a container start fails after the driver's Join (for example because the host port it publishes is taken), libnetwork rolls the join back by calling Leave twice, so every such failure takes one more off the count than it added. On Docker 29.8.2, a node with two healthy containers on an overlay network lost that network within 20 seconds of creating a swarm service that published a host port another container already held. Nobody touched anything: the service's own retries did it. Both containers went NO-CARRIER, could no longer reach anything on the overlay, and docker ps showed them running throughout. Restarting the containers didn't bring them back. Restarting the daemon did. The toolkit's check-overlay-sandbox.sh finds containers in that state. Upstream report: moby/moby#53834.

The symptom

A Debian 13 VM on Proxmox, Docker 29.8.2 from Docker's apt repository (the current release; the report was against 29.8.1), docker swarm init as a single-node swarm. An attachable overlay network with two long-running containers on it, and one more container on the default bridge holding host port 8080:

docker network create -d overlay --attachable ovs
docker run -d --name c1 --network ovs alpine sleep infinity
docker run -d --name c2 --network ovs alpine sleep infinity
docker run -d --name holder -p 8080:80 alpine sleep infinity

Then a service that wants port 8080 in host mode. Port conflicts happen easily, from a leftover container, a second compose project or a forgotten test:

docker service create -d --name web --network ovs \
  --publish mode=host,target=80,published=8080 alpine sleep infinity

The service's task fails, and swarm schedules a new one, again and again:

starting container failed: failed to set up container networking: ... endpoint join on GW Network
failed: driver failed programming external connectivity on endpoint gateway_8e90e46aa0fb (...):
Bind for 0.0.0.0:8080 failed: port is already allocated

Meanwhile, on the containers that had nothing to do with it (ping from each to the network's load-balancer endpoint):

baseline   c1 ping=0  c2 ping=0  netns=present  c1/c2 running
t+10 s     c1 ping=0  c2 ping=0  netns=present  (2 failed tasks)
t+20 s     c1 ping=1  c2 ping=1  netns=MISSING  c1/c2 running  (4 failed tasks)
t+45 s     c1 ping=1  c2 ping=1  netns=MISSING  c1/c2 running

Inside them the overlay interface had lost its carrier:

eth0: <NO-CARRIER,BROADCAST,MULTICAST,UP,M-DOWN> state DOWN

The same happens without swarm services, with plain docker run. With one container on the network, the second failed docker run --network ovp -p 8080:80 ... against the taken port cut it off. The report used an invalid endpoint sysctl as the failing step, which reproduced here the same way: two failures with one container on the network, three with two.

Why it's easy to miss

The damage lands on containers that did nothing wrong, and the error lands somewhere else. The failing service logs a port conflict, which looks like the whole story: fix the port, and the service starts. The containers that lost their network stay running and healthy by every check that doesn't send traffic over the overlay. Health checks that only test the process inside the container still pass. The symptom other services see is "can't reach c1", and docker ps and docker inspect still show it running.

The usual reflex doesn't work once it has gone far. After the service's retries had failed more times than there were joins, restarting c1 and c2 left the sandbox missing. Stopping both and starting them again recreated /run/docker/netns/1-…, but the ping still failed. Only restarting the daemon brought them back:

restart c1 and c2               ping=1 ping=1  netns=MISSING
stop both, start both           ping=1 ping=1  netns=present
systemctl restart docker        ping=0 ping=0  netns=present

(After only two manual failures on a one-container network, a plain docker restart c1 was enough. How much it takes depends on how far past zero the count went.)

What's really going on

The overlay driver, daemon/libnetwork/drivers/overlay/ov_network.go in 29.8.2:

if incJoinCount {
    n.joinCnt++
}
...
func (n *network) leaveSandbox() {
    n.joinCnt--
    if n.joinCnt != 0 {
        return
    }
    n.destroySandbox()

And the caller, Endpoint.sbJoin in daemon/libnetwork/endpoint.go, which sets up two rollbacks for one join:

defer func() {
    if retErr != nil {
        if err := ep.sbLeave(ctx, sb, n, true); err != nil { ... }   // calls d.Leave(...)
    }
}()
...
if err := d.Join(ctx, nid, epid, sb.Key(), ep, ep.generic, sb.Labels()); err != nil {
    return err
}
defer func() {
    if retErr != nil {
        if err := d.Leave(nid, epid); err != nil { ... }              // and so does this
    }
}()

If anything after d.Join fails, both deferred functions run, and the driver sees one Join and two Leaves. Each failed start therefore costs the network one join it never had. On a node, the count is the containers on the network plus the network's load-balancer endpoint, so a node with N containers on an overlay network loses it after N+1 such failures. These accumulate over the daemon's lifetime, so they don't have to come in a burst. Once the count reaches zero the sandbox is destroyed under the containers still attached. If it goes below zero, the bookkeeping is wrong for every later join on that network until the daemon restarts. That matches what the recovery attempts showed.

A swarm service is the efficient way to get there. Its restart policy turns one bad port into a stream of failed starts, a few per ten seconds, and every one takes another join off the count.

The fix

There is no release with a fix. The reporter has one ready, pending a maintainer's view. Until then:

Fix the failing start first. Anything that fails a container start on an overlay network after the driver has joined (a published host port in use, a bad endpoint option) counts against the healthy containers on that node. A service in a restart loop counts every few seconds. docker service ps <service> --no-trunc shows the error. Scale the service to zero or remove it while you fix it.

Then restart the daemon on that node if containers are already cut off:

systemctl restart docker
docker start <containers without a restart policy>

Restarting the affected containers may be enough if the count only just reached zero. Here it wasn't, once a service had been retrying.

Check, rather than trust docker ps. On each node, the sandbox for a network with local containers should exist, and each container's interface on it should have a carrier:

NET=ovs
ls /run/docker/netns/1-$(docker network inspect $NET -f '{{slice .Id 0 10}}')
docker exec c1 ip link show eth0      # NO-CARRIER = cut off

The generalisable habit

running describes the process, not its connections, and the errors are on the container that failed rather than on the ones that paid for it. When a failure can have side effects on shared state, here a per-node reference count, look at the bystanders as well as the thing that failed. A cheap way to cover this is a check that sends real traffic over the network a container depends on, not one that only asks whether the process is alive.

It is the second time on this site that Docker reported success over a broken state: docker logs stops at a NUL byte in a json-file log and exits 0. Both times, the command whose job was to tell you said nothing was wrong.

The toolkit's check-overlay-sandbox.sh (run as root on each swarm node) checks every overlay network with local containers: that its sandbox exists, and that each running container's interface on it has a carrier. It reads the interface flags from inside the container's network namespace. It also counts swarm tasks that failed during network setup and are still listed, since each of those may have taken a join off the count.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

Ollama's native chat path re-sorts your JSON schema keys alphabetically

The Homelab Postmortem — Sat, 03 Oct 2026 06:24:17 +0000

TL;DR: Ollama 0.35 runs chat through one of two paths. Models it renders with a Go TEMPLATE hand your format / response_format schema to llama-server as written. Models on the "native" path go through llamaServerChatResponseFormat(), which decodes the schema into a Go map[string]any and encodes it again. Go writes map keys in alphabetical order, and llama-server's grammar enforces the order it receives. A model takes the native path when it has no renderer, parser or usable Go template, when its GGUF chat template is preferred over the Go one, or when the server runs with OLLAMA_GO_TEMPLATE=false. With that setting, a schema declaring zeta_colour then alpha_animal came back as {"alpha_animal": "blue", "zeta_colour": "zebra"} from Gemma 3 1B: valid against the schema, HTTP 200, and the colour in the animal field. The four models tested on default settings, including two hf.co imports, kept the declared order. The open fix, ollama/ollama#18721, kept it on the native path too. Until a release includes it, name keys so their alphabetical order is the order you want. The toolkit's check-ollama-schema-order.sh tests each model on your server. Upstream report: ollama/ollama#18717.

The symptom

Debian 13 LXC, CPU only, Ollama 0.35.1 (the current release) from the release tarball. One schema, whose declared order is the reverse of alphabetical order:

{"type": "object",
 "properties": {"zeta_colour": {"type": "string"}, "alpha_animal": {"type": "string"}},
 "required": ["zeta_colour", "alpha_animal"]}

sent with "Name a colour and an animal." at temperature 0, through /api/chat (format) and /v1/chat/completions (response_format). Both endpoints gave the same answer wherever both returned one. qwen3:0.6b is a thinking model and only reasoned within the token limit on /v1, so its line is from /api/chat with think: false.

On the default server, all four models kept the declared order:

plain (FROM gemma-3-1b-it-Q4_K_M.gguf)          {"zeta_colour": "blue", "alpha_animal": "zebra"}
hf.co/bartowski/Qwen2.5-0.5B-Instruct-GGUF      { "zeta_colour": "blue", "alpha_animal": "lion" }
hf.co/LiquidAI/LFM2-350M-GGUF                   {"zeta_colour": "red", "alpha_animal": "lion"}
qwen3:0.6b (library)                            { "zeta_colour": "green", "alpha_animal": "lion" }

The same server restarted with OLLAMA_GO_TEMPLATE=false:

plain (FROM gemma-3-1b-it-Q4_K_M.gguf)          { "alpha_animal" : "blue", "zeta_colour" : "zebra" }
hf.co/bartowski/Qwen2.5-0.5B-Instruct-GGUF      { "alpha_animal": "red", "zeta_colour": "red" }
hf.co/LiquidAI/LFM2-350M-GGUF                   {   "alpha_animal": "Blue",   "zeta_colour": "Blue" }

The keys are in alphabetical order, and Gemma's answers are in the wrong fields. The model was answering "a colour and an animal" in the order the question asked, while the grammar made it fill in alpha_animal first. So "blue" went into the animal field and "zebra" into the colour field. The JSON is valid against the schema, nothing reports an error, and a client that reads fields by name gets wrong data.

The report itself came from 0.35.0 with a local model created FROM another, and says 0.33.2 behaved the same way.

Why it's easy to miss

Most of the time it doesn't happen. All four models above took the other path on a default install, including two pulled straight from Hugging Face. So the usual test, sending a schema and looking at the output, comes back clean, and the bug only shows up for a particular model or server setting.

When it does happen, nothing looks wrong. JSON objects are unordered as far as most parsers care, and every field is present and valid. The cost is in what the order was for. A common structured-output pattern declares reasoning before answer so the model works something out before it commits to an answer. Sorted alphabetically, answer comes first. The request and the response both look normal, and the only symptom is worse answers. The swapped fields above are the visible version of the same thing.

It is also a regression of something fixed before. In December 2024, #8002 ("preserve field order in user-defined JSON schemas") closed the same complaint. The llama-server runner brought back the step that loses the order.

What's really going on

llm/llama_server.go in 0.35.1 builds the native chat request's response_format like this:

func llamaServerChatResponseFormat(format json.RawMessage) (map[string]any, error) {
    ...
        var schema map[string]any
        if err := json.Unmarshal(format, &schema); err != nil { ... }
        return map[string]any{
            "type": "json_schema",
            "json_schema": map[string]any{ ..., "schema": schema },
        }, nil

Unmarshalling into a map[string]any throws the order away, and encoding/json writes map keys sorted. The same function and the same var schema map[string]any are in v0.30.0 (released 2026-05-13) and v0.32.0. The other path, used for models with a Go template, keeps the schema as json.RawMessage (lsReq.JsonSchema = req.Format) and passes it on unchanged.

Which path a model takes is decided in server/routes.go:

func chatModeForModel(m *Model) chatExecutionMode {
    if m.IsMLX() || usesOllamaRenderedChat(m) {
        return chatExecutionModeRendered
    }
    return chatExecutionModeNative
}

usesOllamaRenderedChat is true when the model has a renderer, a parser or the harmony format, or when shouldUseGoTemplate is true. That in turn is true when the model has a Go template, OLLAMA_GO_TEMPLATE is not false, and Ollama hasn't decided to prefer the GGUF's own chat template. It prefers that template when the GGUF template supports more than the Go one, tool calling for example. ollama create from a bare GGUF and the hf.co pulls tested here all came with a Go template, which is why they kept the order. That leaves three ways onto the native path: a model with no Go template at all, a model whose GGUF template wins, and a server running with OLLAMA_GO_TEMPLATE=false. Only the last was reproduced here.

The open fix, #18721, passes the trimmed raw bytes through as json.RawMessage instead of the decoded map. Built from 0.35.1 with that change, on the same OLLAMA_GO_TEMPLATE=false server:

plain (FROM gemma-3-1b-it-Q4_K_M.gguf)          { "zeta_colour": "blue", "alpha_animal": "dolphin"}
hf.co/bartowski/Qwen2.5-0.5B-Instruct-GGUF      { "zeta_colour": "Blue", "alpha_animal": "Bluebird" }

The declared order is back, and Gemma's colour and animal are in the right fields.

The fix

Until a release includes #18721, make the order you want and alphabetical order the same, and declare the keys in that order too. That way both paths produce it:

{"type": "object",
 "properties": {"a_colour": {"type": "string"}, "b_animal": {"type": "string"}},
 "required": ["a_colour", "b_animal"]}

On the stock native path that gave {"a_colour": "blue", "b_animal": "lion"} from Gemma and {"a_colour": "Red", "b_animal": "Red fox"} from Qwen2.5. For the reasoning pattern that means a_reasoning, b_answer, and so on.

To find out whether a model is affected, send it a two-key schema in reverse-alphabetical order and see which key comes out first. That takes one request and doesn't depend on reading Ollama's routing rules correctly. If you have set OLLAMA_GO_TEMPLATE=false, assume every model without a renderer is affected.

The generalisable habit

When a layer sits between your client and the engine, check whether it passes your request through or rebuilds it. A layer that decodes a structure into its own types and encodes it again keeps only what those types can represent. Here a Go map can't represent key order, so the order was gone before llama-server saw the schema. The test for that is a request that only means something if a property survives the trip: two keys declared in reverse alphabetical order, compared against the output.

This is the second time in a week that Ollama's translation into llama-server rewrote part of a request without saying so. The OpenAI-compatible API fills in temperature and top_p as 1.0 when the client leaves them out. Both times the reply was valid and well formed.

A third turned up two days later: with think enabled, a model that answers without thinking isn't held to the schema at all.

The toolkit's check-ollama-schema-order.sh sends that two-key schema to each installed model, or the ones you name, and reports which kept the order. It also reads OLLAMA_GO_TEMPLATE from the running server's environment.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

llama-server's sleep mode loses or crashes on a request that arrives just before it sleeps

The Homelab Postmortem — Sat, 03 Oct 2026 05:20:17 +0000

TL;DR: llama-server --sleep-idle-seconds N unloads the model after N idle seconds and is documented to reload it for "any new incoming task". A request handler checks that the server is awake when it starts, then tokenizes the prompt, then queues the task. If the idle timer fires in between, the server goes to sleep anyway. On llama.cpp b11368 (CPU, Gemma 3 1B), a 17,653-token prompt sent 46 to 34 ms before the server fell asleep sat in the queue with no reply until a second request woke the server, 32 times out of 32. Sent 34 to 3 ms before, it crashed the server with SIGSEGV inside the tokenizer, which was reading the vocabulary the sleep had just freed, 41 times out of 41. With a two-word prompt the window is too short to hit: 0 of 93. Sending a 1-token completion first and the real request right after it avoided both in 123 of 123 tries. The toolkit's check-llama-sleep-race.sh finds servers with sleep mode on and says whether a crash would be restarted. Upstream report (the hang): ggml-org/llama.cpp#29689.

The symptom

The report that led here was intermittent: a client that sends /health, /props, /tokenize and then POST /completion right after the server starts, with --sleep-idle-seconds 1, got no answer to the completion about one time in eight. The server log showed it going to sleep and never waking:

I que    start_loop: entering sleeping state
I srv  handle_sleep: server is entering sleeping state
W srv          stop: cancel task, id_task = 0          <- the client giving up 10 s later

To find where the window is, a Debian 13 LXC with 6 CPU cores, the llama.cpp b11368 release binary, gemma-3-1b-it-Q4_K_M, -np 1 --sleep-idle-seconds 1. Each trial starts a fresh server, takes the moment /health first returns 200 as zero, waits a chosen offset, sends one POST /completion, and timestamps every server log line as it arrives. The server fell asleep 0.978 to 1.000 s after zero, so every send can be placed relative to the moment it slept.

With the prompt "Say OK", 93 sends between 0.97 and 1.03 s gave 93 answers. The 61 that arrived after the server was asleep woke it as documented, at about 1.4 s latency for the reload.

Then the same with a 17,653-token prompt. To keep each trial fast, the context was -c 512, so a prompt that gets processed is rejected at once with HTTP 400 ("exceeds the available context size"). A 400 means the request reached a slot. Anything else means it didn't. 123 sends between 0.93 and 1.01 s, grouped by when they were sent relative to the moment the server fell asleep:

sent relative to sleep    result
early enough (> ~50 ms)    13  answered before the timer fired (400, ~45 ms)
46 .. 34 ms before         32  no answer; /props says is_sleeping: true
34 .. 3 ms before          41  connection closed with no response; server gone
2 ms before .. 29 ms after 37  woke the server, answered (~1.3 s)

The hung requests were still in the queue. After 3 s the harness checked /props ("is_sleeping": true) and sent a second, short completion. That woke the server, and the first request was answered right behind it:

first sent      0.935 s   (server fell asleep at 0.979 s)
/props at 3 s   is_sleeping: true
second sent     3.938 s   -> "exiting sleeping state" at 3.938 s
first answered  5.172 s   (4.2 s after it was sent)

Without the second request the first would have waited until the client's own timeout. For a single client that sends one request after a quiet period, which is how cron jobs, home automations and agent turns tend to look, that means no reply at all.

The other 41 were not hangs. The server process had exited with signal 11, and the client got RemoteDisconnected. Ten more sends between 0.970 and 0.990 s crashed it all ten times. Run under gdb, the faulting thread was an HTTP worker in the middle of tokenizing the prompt:

Thread 9 "llama-server" received signal SIGSEGV, Segmentation fault.
#1  llama_vocab::text_to_token(...)
#2  llm_tokenizer_spm_session::try_add_bigram(int, int)
#3  llama_vocab::impl::tokenize(...)
#6  common_tokenize(...)
#9  tokenize_input_prompts(...)
#10 server_routes::handle_completions_impl(...)

Why it's easy to miss

It happens in a few dozen milliseconds out of every idle period, so most requests never see it, and the ones that do look like unrelated faults. The hang leaves no error anywhere: the log's last word is "entering sleeping state", which is what an idle server should say, and /props correctly reports that the server is asleep. The crash leaves nothing in the server's own log either, because the process dies mid-request. If a supervisor restarts it, the outage can pass for a blip.

The documentation describes the opposite: "When the server enters sleep mode, the model and its associated memory (including the KV cache) are unloaded from RAM to conserve resources. Any new incoming task will automatically trigger the model to reload." That holds for a request that arrives after the server is asleep. It doesn't hold for one that arrives slightly before.

And it depends on the prompt. With a two-word prompt there was no window to hit in 93 tries. The reporter's server had a vision projector loaded (--mmproj) and speculative decoding on, and saw it one time in eight. What widened their window isn't stated, but an image is preprocessed in the same place a prompt is tokenized, so either would do it.

What's really going on

Every completion handler starts by building its response object, and that constructor is the wake check (tools/server/server-context.cpp):

server_res_generator(server_queue & queue_tasks, ...) {
    bypass_sleep |= sleep_idle_seconds < 0;
    if (!bypass_sleep) {
        queue_tasks.wait_until_no_sleep();
    }
}

wait_until_no_sleep() returns at once if the server is awake. Only if it is already asleep does it set req_stop_sleeping and wait for the wake-up. After that, handle_completions_impl tokenizes the prompt (or runs process_mtmd_prompt for an image), builds the tasks, and only then calls rd.post_tasks(...).

Meanwhile the queue's main loop (tools/server/server-queue.cpp), finding the queue empty and the idle timer expired, does this while holding the queue lock:

QUE_INF("%s", "entering sleeping state\n");
sleeping = true;
for (auto & cb : callback_sleeping_state) {
    cb(true);                       // unloads the model, vocabulary included
}
req_stop_sleeping = false;
condition_tasks.wait(lock, [&]{
    return (!running || req_stop_sleeping);
});

That gives two outcomes, depending on where the sleep lands:

During tokenization. The handler is still reading the vocabulary when cb(true) frees it. That is the SIGSEGV in text_to_token.
After tokenization, before post_tasks. The task is queued while the loop is asleep. The loop only wakes when req_stop_sleeping is set, and a queued task doesn't set it. The task waits for the next request that arrives while the server is asleep, since that one goes through wait_until_no_sleep()'s wake path.

The window is the time between the wake check and the post, which is mostly tokenization. On this CPU a 17,653-token prompt took about 45 ms end to end, and the dangerous span measured 46 ms to 3 ms before the sleep. It grows with prompt length and with image preprocessing.

The issue proposes two fixes. One is to also wake when the queue is not empty. As this code reads, that covers the hang but not the crash, which happens before anything is queued. The other is to count requests that are between the wake check and the post, and not sleep while that count is above zero. That would cover both.

The fix

There is no release with a fix yet. These are the options that were measured or are plain configuration:

Send a 1-token completion before the real request. A request whose prompt is a couple of tokens has almost no window: 0 hits in 93. When it is queued it resets the idle timer, so the real request that follows gets a full idle period of headroom instead of whatever was left. The same 123-send sweep with that in front:

curl -s localhost:8080/completion -d '{"prompt":"hi","n_predict":1}' >/dev/null
curl -s localhost:8080/completion -d @real-request.json

123 sends, 0.93 .. 1.01 s:  123 answered, 0 hung, 0 crashed

The two requests have to go out back to back, well within the idle period. With a real setting in minutes, that is easy. /health and /props don't work as the warm-up: the README says they "do not reset the idle timer". The reporter's workaround goes the other way: wait until /props reports is_sleeping: true, then send. That relies on the wake path, which handled all 37 sends here that arrived after the sleep (and 61 of 61 with the short prompt), at the cost of a model reload on every request.

Give the client a timeout and a retry. It doesn't prevent anything, but a hung request becomes a slow one. The retry also wakes the server, which releases the stuck request.

Make sure a crash is restarted. Under systemd that means Restart=on-failure on the unit. The request that triggered the crash is lost either way.

Or leave sleep mode off (the default, -1) on servers that take long prompts or images from a single client.

The generalisable habit

A "check, then act" sequence is only as good as what stops the state from changing between the two steps. Here the wake check and the queueing are separate steps with real work between them, and nothing keeps the sleep from happening in that gap. When a feature adds a background transition (sleep, eviction, reload, rotation), ask what a request that started just before the transition is still holding, and whether the transition can take it away. Then test the boundary on purpose. A sweep of send times against the moment of the transition found in an hour what the reporter saw one time in eight, and it also turned up the crash. Nobody had reported that one, because the process that could log it dies first.

The same server has other places where what a request was promised and what it gets come apart: a documented response_format that is accepted and ignored is the earlier one on this site.

The toolkit's check-llama-sleep-race.sh reads running llama-server command lines (and router preset files) for --sleep-idle-seconds. For a running process, it also asks systemd whether a crash would be restarted. It never sends a request to the server, because a probe of this race can crash it.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →

Rootless podman export of a keep-id container shifts every file owner, exit 0

The Homelab Postmortem — Wed, 30 Sep 2026 01:51:19 +0000

Update 2026-10-08. Fixed upstream for podman export, not yet released. podman-container-tools/podman#29899 ("fix: preserve ownership when exporting keep-id containers") was merged into main on 2026-10-06 and closed #29856. As the merged diff reads, the nil tar options quoted below are replaced by the container's own UID and GID mappings, so the archive gets the in-container owners back. Its new test exports a created, never-started --userns=keep-id container and checks that home/ comes out as 0/0 and the user's home and files as 1000/1000. The latest releases, v6.1.3 and v5.8.8 (both 2026-09-29), predate the merge, so Debian's 5.4.2 and every current release still behave as described below, and the commit-based export is still the way to get a correct archive. The pull request changes only the export path: podman cp ctr:/ -, which showed the same shift here, is not touched by it. This was read from the diff, not re-tested here.

TL;DR: podman export of a rootless container that was created with --userns=keep-id writes a tarball in which every file owner is shifted by the container's ID mapping. Inside the container the user's home is 1000/1000 and system files are 0/0. In the export, the home is 0/0, the 3257 root-owned files are 1/1, and su, passwd and the other setuid binaries are setuid to UID 1. The export exits 0 and prints nothing. Import that tarball and the user can't write to its own home directory. podman cp ctr:/ - produced the same shift. podman commit maps the owners back: commit the container, create a plain container from the image, and export that. The export code passes no ID mapping to its tar writer, in 5.4.2 and in current main. Reproduced on a Raspberry Pi with Debian's podman 5.4.2. The toolkit's check-podman-export-idmap.sh lists the containers at risk and checks an export without writing it. Upstream report: podman-container-tools/podman#29856.

The symptom

Raspberry Pi 4B, Raspberry Pi OS (Debian 13, arm64), podman 5.4.2 from Debian, rootless as the login user (UID 1000, subuids 100000:65536). An image with one ordinary user:

FROM docker.io/library/debian:13-slim
RUN useradd -m user && echo hello > /home/user/note.txt && chown user:user /home/user/note.txt

Both ways of running it agree about who owns what:

podman run --rm exporttest ls -lan /home/user
podman run --rm --userns=keep-id exporttest ls -lan /home/user
  drwx------ 1000 1000 .
  -rw-r--r-- 1000 1000 .bashrc
  -rw-r--r-- 1000 1000 note.txt

Then one container of each kind, exported:

c1=$(podman create exporttest);                    podman export "$c1" > e1.tar   # rc=0
c2=$(podman create --userns=keep-id exporttest);   podman export "$c2" > e2.tar   # rc=0

tar tvf e1.tar home                          tar tvf e2.tar home
drwxr-xr-x 0/0       home/                   drwxr-xr-x 1/1       home/
drwx------ 1000/1000 home/user/              drwx------ 0/0       home/user/
-rw-r--r-- 1000/1000 home/user/.bashrc       -rw-r--r-- 0/0       home/user/.bashrc
-rw-r--r-- 1000/1000 home/user/note.txt      -rw-r--r-- 0/0       home/user/note.txt

The report upstream showed the home/ lines, and the shift doesn't stop there. The owner counts across the whole archive:

e1 (plain):   3257 0/0      7 0/42     5 1000/1000   3 0/43   1 0/8
e2 (keep-id): 3257 1/1      7 1/43     5 0/0         3 1/44   1 1/9

Every owner and every group is off by the same mapping. The setuid binaries go with them:

e1: -rwsr-xr-x 0/0 usr/bin/su     e2: -rwsr-xr-x 1/1 usr/bin/su
    -rwsr-xr-x 0/0 usr/bin/passwd     -rwsr-xr-x 1/1 usr/bin/passwd
    ... (8 setuid files, all 0/0)     ... (all 1/1)

podman import e2.tar e2img succeeds, and the damage shows up only when the image is used:

podman run --rm e2img stat -c "%u:%g %A %n" /etc/passwd /etc/shadow /usr/bin/su
  1:1 -rw-r--r-- /etc/passwd
  1:43 -rw-r----- /etc/shadow
  1:1 -rwsr-xr-x /usr/bin/su

podman run --rm --user user e2img touch /home/user/x
  touch: cannot touch '/home/user/x': Permission denied
podman run --rm --user user exporttest touch /home/user/x      # original image: works

su and passwd are now setuid to UID 1, which is daemon, so they no longer do what they are for.

Why it's easy to miss

podman export is the documented way to get a container's filesystem out as a tarball, and --userns=keep-id is the standard answer to "my rootless container writes files my host user can't read". Both are common, and nothing in their output hints at a problem when they're combined. The export exits 0 and prints nothing to stderr. The man page doesn't mention owners, user namespaces or ID mappings at all. The tarball has the right files, the right sizes and the right permission bits. Only the numbers in the owner column are wrong, and hardly anyone lists a backup tarball with tar tv to read that column.

The problem only surfaces when the archive is restored, in a different container or on a different day, as a permission error that looks like something the image itself got wrong.

The upstream report came from podman running inside another container on an EL8 kernel, with an ID mapping unlike an ordinary host's. That made it easy to read as an edge case of nested containers. On an ordinary host, with podman as a normal user and the stock subuid range, it happens the same way.

What's really going on

podman inspect shows the difference between the two containers:

plain:   IDMappings null
keep-id: UsernsMode private
         UidMap ["0:1:1000", "1000:0:1", "1001:1001:64536"]

A keep-id container gets its own user namespace inside rootless podman's namespace. Container UID 0 maps to 1 there, container UID 1000 maps to 0 there (which is the host user), and the rest follows. Its files are stored on disk under those intermediate IDs. You can see it by mounting the container's storage from inside podman unshare:

podman unshare sh -c 'm=$(podman mount hpmkid); ls -ln $m/home/user/made-at-runtime.txt $m/root/made-by-root.txt'
  -rw-r--r-- 1 0 0 ... home/user/made-at-runtime.txt     <- written by UID 1000 in the container
  -rw-r--r-- 1 1 1 ... root/made-by-root.txt             <- written by root in the container

The export code (libpod/container_internal.go) mounts that storage and tars it:

input, err := chrootarchive.Tar(mountPoint, nil, mountPoint)

The nil is the tar options, which is where an ID mapping would go. None is given, so the archive gets the on-disk IDs, which are the container's IDs pushed through its mapping. For a container with no mapping of its own, on-disk and in-container IDs are the same and nothing is visible. The line is identical in 5.4.2, in 5.8.7 (the version in the report) and in current main.

podman cp ctr:/ - | tar tv on the keep-id container showed the same shift: files the container's user owns came out as root/root, and root's files as daemon/daemon. That makes podman cp no workaround here.

The fix

podman commit does apply the container's mapping. Committing the keep-id container, creating a plain container from the resulting image and exporting that gave correct owners, including for files written while the container ran:

podman commit mycontainer tmp-export
c=$(podman create tmp-export)
podman export "$c" > mycontainer.tar
podman rm "$c"; podman rmi tmp-export

(0) podman export hpmkid                      (a) commit -> create -> export
  0/0       home/user/made-at-runtime.txt       1000/1000 home/user/made-at-runtime.txt
  1/1       root/made-by-root.txt               0/0       root/made-by-root.txt
  1/1       usr/bin/su                          0/0       usr/bin/su

Check any export before trusting it. In a normal Linux image etc/passwd belongs to root, so one line is enough:

podman export mycontainer | tar tvf - etc/passwd

If that shows anything other than 0/0, the archive is shifted. An archive already made this way can't be repaired by adding a fixed offset to every owner, because the mapping isn't a single offset: 0 became 1, 1000 became 0, and IDs above 1000 stayed where they were. Re-export it through a commit instead.

This was measured with --userns=keep-id. Other options that give a container its own mapping (--userns=auto, --uidmap) go through the same export line, but they weren't tested here.

The generalisable habit

A tarball has two layers, the data and the metadata, and most checks only look at the first. The files are there, the sizes match and the restore succeeds, so it looks like a backup. Check the metadata that matters for a restore — owners, groups, setuid bits — against the source before you rely on the archive. tar tv on one file whose owner you know is cheap. Finding out from Permission denied after the original is gone is not.

The same program already had one case of a copy command that reads the wrong layer of storage without saying so: podman cp on a stopped container ignores a volume's subpath=. In both cases the copy succeeds, and it copies the storage as it sits on disk, not the view the container has.

The toolkit's check-podman-export-idmap.sh lists the current user's containers that have their own ID mapping, and with --verify <container> streams an export straight into tar tv and checks that etc/passwd and usr/bin/su are root's, writing nothing to disk. It prints the commit-based export for any container that fails.

Toolkit

This post's fix is available as a tested, ready-to-run script in the toolkit.

See the toolkit →