14. A starved proxymous: trixie passes, rocky does not

14.1. The symptom

The test reported a file transfer refused:

FAILED: everything at once, 600s
  scp up in the storm: cloonix refused the leg to 'bfB': KO_name_not_found

bfB was not missing by accident. The syslog of the toy showed the net destroying itself a moment before, in three steps:

cloonix-ovs-nat:     nat bfnat: proxymous said nothing for 3000 ms, stopping
cloonix-main-server: ERROR IMPOSSIBLE CTRL CONNECTION TO PROXYMOUS
cloonix-main-server: net stopping, asked by: a client asking for kil (llid=0 tid=0)

The main server had lost its proxymous, deleted every item, bfB with them, and doorways then answered the scp with KO_name_not_found. The last line was wrong: no client had asked, the server had decided alone.

One net is two halves in a toy. The servers run inside the crun container; cloonix-proxymous runs outside it, on the machine, because it holds what must be on the machine: the two tcp ports, passt, the udp relay of the c2c. Each half watches the other by a heartbeat. The failure was always the inside half no longer hearing the outside one.

14.2. Seven runs

Each run of the suite lasts about forty minutes, so each build carried several instruments at once. The table gives what each run added to the picture.

14.3. The cause

On the left, the toy as it was. crun --cgroup-manager=systemd asks the systemd of the user for a cgroup, crun-nemo.scope, and every process of the net lives in it: the servers, the switch, and during the storm the packet generators and the qemu, all of them asking for cpu without pause. proxymous is started by nemocmd before crun and stays where the shell was, in session-c1.scope.

A linux scheduler shares the cpus first between cgroups, then between the processes of each. With kernel 6.12.0-211.54.1.el10_2 of rocky, a busy cgroup beside a nearly idle one left the process of the idle one without a cpu for tens of seconds. proxymous needs a few milliseconds per second; it did not get them, its heartbeat stopped, and the net did what it must do when its proxymous is gone.

On the right, the toy as it is now: no cgroup of its own, one cgroup for both halves, as the bundle always was. The same kernel then shares between processes only, and proxymous is served within a second.

The kernel lists describe this family of defects in the scheduler of the 6.12 line (EEVDF with group scheduling: a process outside a cgroup that holds a cpu hog, the weight of that cgroup recomputed often). Which corrections a given distribution kernel carries was not established; the observation is that trixie's 6.12 did not show it and rocky's did.

14.4. What differs between the machines

The seven autotest machines are made by debug/autotest/kvm_autotest_<distro>.sh. The columns are what the investigation looked at; measured means read in a log of these runs, the rest comes from the builders.

Four differences between trixie and rocky were suspected and each was cleared by a measure:

• /tmp on a disk: the storm writes 64 MB files in /tmp. iowait was 0% during every stall.

• the log chain: syslog(3) blocks when the log daemon does not read /dev/log. KERR was given a socket that never blocks and counts what it drops; it dropped nothing.

• the outer host: the two kvm run side by side. steal was 0%.

• memory: no major fault, no swap, 2.1 GB free at the failure.

What remained was the only thing the toy has and the bundle has not: a cgroup of its own.

14.5. What was changed

For the cause:

• toy_targz/tools_crun/setup.sh: crun create with --cgroup-manager=disabled by default. CLOONIX_TOY_CGROUPM=systemd asks for the former behaviour; the start prints which is used.

• cloonixsbininit: with CLOONIX_WITH_SYSTEMD=1, a mkdir is tried in /sys/fs/cgroup. When it fails the container starts without systemd and /run/cloonix_no_systemd holds the reason. The chapter Things set aside describes what would give this back.

Defects met on the way, each corrected where it was:

• The beat (lib_io_clownix/src/channel.c): 100 beats lasted 1029 ms idle, 502 ms under a flood, 625 ms with sparse events. A beat is now two heartbeat periods of the monotonic clock in every case: 1000 ms measured in all three.

• Two watchdogs on one proxymous (uml_cloonix_switch/src/proxymous.c): the older one counted beats and fired at 10 s under load. It now covers only the time before the connection exists; proxycrun.c alone judges a silent proxymous, 30 s on the wall clock.

• The nat's watchdog (ovs_nat_passt.c): 3 s, and fed only when the main server sent a pid request, so it measured the server as well. It sends its own beat every second and allows 20 s, as ctrl_link does.

• The c2c verdicts on the peer (ovs_c2c.c): counted in beats, 9 s nominal. On the wall clock, 20 s.

• The reason of a stop: asked by names the server when no client asked.

• The del_all pass on an a2b: asking again while a delete is in flight is the pass waiting, no longer an ERROR per second.

• A close forced on a slow client (doorways/src/llid_traffic.c): a session asked to close with bytes still queued was cut after 30 s whatever the queue did. On fedora44 the storm left more than 30 s of a 64 MB scp in that queue and the transfer was cut. The 30 s now count only while nothing leaves the queue.

• Dead code: nat_tcp.c, nat_udp.c, nat_icmp.c, nat_utils.c of proxymous, about 1500 lines no request reached since passt; removed.

14.6. The instruments that stay

Four lines now exist in every daemon and need nothing to be switched on.

A stall says what the process did and what the machine did:

WARNING this loop did not beat for 5615 ms (cpu 16 ms, 222 voluntary and
27 forced switches, 0 major faults; the machine over the last 6015 ms:
user 27% system 55% softirq 16% irq 0% steal 0% iowait 0% idle 0%)

The loop says where a late turn lost its time, at most once per ten seconds and only above 2 s:

WARNING late loop, 1053 turns in 37743 ms: epoll_wait came back late by
11007 ms in all, 8046 ms at worst (the cpu was not given); the callbacks
took 21764 ms in all, one turn 21752 ms at worst with 1 ms of cpu, ...

KERR says when lines were lost:

WARNING 2989 line(s) before this one were dropped: the log daemon did
not read /dev/log for 5005 ms

testitalltoy.sh prints at its start the cgroup of each proxymous and of each main server, with the kernel version; a failed autotest trace ends with the last 200 lines of kerr1_outputs.log, free, the swap and fault counters, the pressure files, df -T and the dmesg lines about stalls.

To look at a machine by hand:

cat /proc/$(pgrep -f cloonix-proxymous-nemo | head -1)/cgroup
cat /proc/$(pgrep -f "cloonix-main-server.* nemo" | head -1)/cgroup
grep -H . /proc/pressure/cpu
grep -E "did not beat|late loop|dropped" /var/log/syslog | tail