syslogd: cover the two windows forwarding still missed - #2417
Merged
Conversation
widgetii
requested review from
cronyx,
flyrouter and
viktorxda
as code owners
September 14, 2026 08:30
PR Summary by QodoCover failsafe and sysupgrade syslog forwarding gaps
AI Description
Diagram
High-Level Assessment
Files changed (2)
|
Code Review by Qodo
1.
|
![qodo-free-for-open-source-projects[bot]](https://avatars.githubusercontent.com/in/1068000?s=60&v=4){kind=small}
#2415 gave a camera a way to send its log somewhere that outlives it. Two windows it does not reach, both found reviewing that change, and both the kind of moment the log is worth having. Failsafe mode started syslogd and not klogd. klogd is the only thing that pumps the kernel ring buffer into /dev/log, so the one boot mode built for post-mortem -- reached after repeated failed boots -- carried no kernel lines at all: no panic, no mmc timeouts, none of what usually explains why the boots failed. It goes directly after S01syslogd, which owns /dev/log. sysupgrade stopped syslogd and said nothing first. A forwarded log therefore just stopped mid-flash, and a clean stop read exactly like a death -- on the operation most likely to produce the latter. busybox emits no shutdown marker of its own on the remote path: it forwards each line unmodified and logs "syslogd exiting" only locally. So the breadcrumb has to be explicit, and has to go before syslogd does, with a moment for the datagram to leave, because forwarding is UDP and nothing retries it. The image is not known yet -- free_resources runs before the download -- so it names what is about to be written and what it is being written over. Tested on two boards, each for the half it can actually exercise. gk7205v200 (gk7205v200_lite, the family that ships openipc-failsafe), running the real failsafe-rescue script with klogd stopped beforehand: *** FAILSAFE: bringing up network + SSH only, services skipped *** Starting syslogd: OK (already running) Starting klogd: OK ... # echo failsafe-klogd-probe > /dev/kmsg Sep 14 07:47:09 gk7205v200-imx307 user.emerg kernel: failsafe-klogd-probe A kernel message reaches syslog only once klogd is in the list. "Starting dropbear: FAIL" and "bootcount-clear: not found" in that run are artifacts of invoking the script by hand on a booted camera carrying an older local image, not of this change. hi3516av300 (nightly-20260912-d87dae1), the breadcrumb, forwarded to a collector: # local sysupgrade: flashing now (kernel=1 rootfs=1 overlay=0) over nightly-20260912-d87dae1; this log stops here until the camera comes back # on the collector 2026-09-14T08:39:29+01:00 10.216.128.39 notice sysupgrade flashing now (kernel=1 rootfs=1 overlay=0) over nightly-20260912-d87dae1; this log stops here until the camera comes back test_sysupgrade.sh, test_shell_parse.sh and test_strip_shell_comments.sh all pass.
Two reviews landed on the same defect, and hardware found a third. The breadcrumb claimed a flash that had not started. free_resources() runs before check_sdcard, before the download and before any write, so a failed download or a bad checksum left a collector holding "flashing now, logging stops until the camera returns" for a camera that was never touched. It now says "preparing to flash", and restore_resources() logs the retraction when the camera stays up -- an abort or a deliberate --no_reboot -- so the two cases stop looking identical. It also gained -s (the operator watching the transcript is exactly who needs it) and user.warning (a collector filtering at >= warning should not lose the one line explaining the silence), and the second it spends letting a datagram out is now gated on forwarding actually being enabled, rather than charged to every camera for a feature most have off. Failsafe started logging before the network, which is the mistake this whole change exists to fix, made again one layer down. etc/default/syslogd already documents that busybox drops rather than queues while the network is down, and klogd's read CONSUMES the ring buffer, so those lines are gone rather than delayed. Measured on a gk7205v200: exactly one of 154 replayed kernel lines reached the collector. The list is hand-written, so the order was free to fix -- S31hostname and S40network now precede S01syslogd and S02klogd, since syslogd also samples the hostname once at startup. And an address is not reachability. S40network's udhcpc forks to the background, so the reordering alone still raced the lease. There is now a bounded wait for an IPv4 address plus a short settle -- on that board lines stamped 00:00:08 were still lost while 00:00:10 arrived, so something after the lease is worth a couple of seconds. Bounded because failsafe must come up where there is no DHCP server at all. What that reliably buys is the local log: `logread` in failsafe now carries the kernel, where it carried nothing, and every kernel message from then on is forwarded. The replayed backlog gets its best chance, not a guarantee, and the comment says so rather than claiming otherwise. Smaller things from the same pass: a /dev/log readiness wait between syslogd and klogd, because start-stop-daemon -b returns before the socket exists and a consuming read cannot be retried; get_build_id() beside get_system_build() instead of a third spelling of the same os-release read; and the claim that failsafe now carries "no panic" removed, because klogd replays this boot's ring buffer and a boot that reached failsafe has no crash in it -- the oops is in /sys/fs/pstore, which this mode deliberately leaves intact. test_sysupgrade.sh gains three assertions, including that the breadcrumb precedes the syslogd stop. That ordering is the whole mechanism and nothing else in the suite protected it; the check was confirmed to fail against a deliberately reordered copy.
widgetii
force-pushed
the
syslog-forward-gaps
branch
from
September 14, 2026 11:05
1f7ac71 to
d5efceb
Compare
7 tasks
widgetii
added a commit
that referenced
this pull request
Sep 14, 2026
…rn (#2419) Two loose ends from #2417, both of them a camera left in a state nobody can see from outside. check_sdcard kept everything it had been given. It runs after create_lock and free_resources, and a recovery file on the card exited straight out of it, so the lock stayed in /tmp and every later run answered "Another sysupgrade process is already running!" until a reboot cleared it; syslogd, klogd, ntpd and crond stayed stopped; and majestic stayed gutted by the SIGQUIT free_resources sends. Since #2417 it also left a collector holding "logging stops here until this camera returns" for a camera that was never touched. Nothing is written at that point, so die() already does the right thing -- no-reboot branch, services restarted, lock dropped. Use it. Measured on an hi3516av300 (nightly-20260913-910e724), all three stoplist files on the card, kernel path deliberately nonexistent so nothing could be written even if the check were skipped. Before: syslogd, klogd, ntpd and crond all down, lock leaked, and the next run refusing outright. After: all four back, lock gone, and the #2417 retraction sent -- "still here on nightly-20260913-910e724", the first time that line has been confirmed on hardware rather than in the suite. majestic reports "up" either way, and that is the trap: pidof finds it because SIGQUIT is majestic's "release the SDK and keep serving" signal. In the broken state a snapshot returns HTTP 200 with 0 bytes and the log says "stop_sdk: Stop sdk Ok!". The camera looks alive and has no video. The second half is the other end of that sentence. free_resources tells a collector the log stops "until this camera returns"; nothing ever said it had. S41bootmsg logs "this camera is up on <BUILD_ID>" once the network can carry it. The build id is the payload: it is the only word from the camera itself that the flash took, or that the bootloader fell back to what it had. Gated on SYSLOG_REMOTE, so a camera that forwards nothing sources a file it does not have and exits -- 672 bytes once comments are stripped. Backgrounded, so the boot pays nothing: the script returns in 0.00s and the waiting happens in a subshell, which matters because it can wait a good while and blocking would put that in front of majestic and the video behind it. What it waits FOR took two corrections, both from the same mistake of assuming a signal meant what it looked like. A two-second settle after the address -- failsafe-rescue's -- is not enough: the marker went out at 13:28:10 and the first line the collector received that boot was majestic's at 13:28:11. It missed by one second, and forwarding is UDP with nothing to retry it. It now sends one ICMP packet at the collector first, which resolves the ARP entry the datagram needs instead of guessing how long that takes. And an IP is not a hostname. Every measurement above was taken against a literal IP; busybox resolves a name once, when syslogd starts at S01 before the network, and retries only every 120 s -- etc/default/syslogd has said so since #2415 and tells people to prefer an IP for exactly this reason. So on a name the marker was dropped outright: reproduced on the same board, present locally at 12:49:55 and absent at the collector, while 48 other lines from that window arrived once the daemon had re-resolved. The marker now waits that window out on a name. Late and delivered beats punctual and dropped, and the build id is no less true two minutes on. Not by restarting syslogd to force a re-resolve, which is the obvious repair: its buffer is in RAM and dies with it, so that trades the whole local record of the boot -- the copy that still exists when forwarding does not -- for one forwarded line. Delivered on both destination forms, same board and collector: 2026-09-14T13:33:52+01:00 10.216.128.39 warning boot this camera is up on nightly-20260913-910e724 2026-09-14T13:34:49+01:00 10.216.128.39 warning boot this camera is up on nightly-20260913-910e724 2026-09-14T13:55:39+01:00 10.216.128.39 warning boot this camera is up on nightly-20260913-910e724 test_sysupgrade.sh gains four behaviour checks and six drift checks, and the mount/umount stubs are now stateful so check_sdcard's unmount loop can be driven at all. The two assertions that encode the abort fix were confirmed to fail against the pre-fix script while the two unrelated ones stayed green, so they pin the fix rather than the weather.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
#2415 gave a camera a way to send its log somewhere that outlives it. Two windows it does not reach, both found reviewing that change, and both the kind of moment the log is most worth having.
Failsafe mode started syslogd and not klogd. The rescue list was:
klogd is the only thing that pumps the kernel ring buffer into
/dev/log, so the one boot mode built for post-mortem — reached after repeated failed boots — carried no kernel lines at all. No panic, no mmc timeouts, none of what usually explains why the boots failed. It goes directly afterS01syslogd, which owns/dev/log.sysupgrade stopped syslogd and said nothing first. A forwarded log therefore just stopped mid-flash, and a clean stop read exactly like a death — on the operation most likely to produce the latter. busybox emits no shutdown marker of its own on the remote path: it forwards each line unmodified and logs
syslogd exitingonly locally. So the breadcrumb has to be explicit, has to go before syslogd does, and needs a moment for the datagram to leave, because forwarding is UDP and nothing retries it. The image is not known yet —free_resourcesruns before the download — so it names what is about to be written and what it is being written over.What review and hardware changed
Two reviews landed independently on the same defect: the breadcrumb claimed a flash before the download or checksum had happened, so a failed download left a collector holding a death notice for a camera that was never written to. It now says
preparing to flash, andrestore_resources()logs a retraction when the camera stays up. It also gained-sanduser.warning, and its one-second datagram drain is gated on forwarding actually being enabled rather than charged to every camera.Then the board found something neither review did, and it was my own mistake repeated one layer down. The first version of the failsafe fix started logging before the network — exactly the trap
etc/default/syslogddocuments, and exactly what this PR exists to fix. busybox drops rather than queues, and klogd's read consumes the ring buffer, so those lines are gone rather than delayed.Measured on a gk7205v200, forwarding to a live collector:
Ordering alone was not enough:
S40network's udhcpc forks to the background, so the reorder still raced the lease. And an address is not reachability — lines stamped00:00:08were still lost while00:00:10arrived — hence the bounded wait plus a short settle. Bounded, because failsafe has to come up where there is no DHCP server at all.I tested and discarded two other explanations before landing on that one: burst loss (100/100 forwarded lines arrived) and unresolved ARP (100/100 after an
ip neigh flush all).Hardware tested on
Two boards, each for the half it can exercise.
gk7205v200_lite) — the family that shipsopenipc-failsafe. Flashed with a build of this branch (kernel + rootfs), then booted into real failsafe mode via the kernel command line, which is the second triggerrcSdocuments.nightly-20260912-d87dae1, for the sysupgrade breadcrumb, forwarded to a live collector.Evidence
Failsafe, on a real failsafe boot
Not the script invoked by hand:
rcSdispatched it, on a camera running this branch.The contrast, on the same board, with klogd stopped and then started in the order the new list uses:
The board was returned to a normal boot afterwards: no
failsafein/proc/cmdline, majestic running.The sysupgrade breadcrumb, reaching a collector
Checks that need no board
Size
gk7205v200_liteis one of the tighter boards — the build of this branch printedheadroom warning: rootfs.squashfs has 28KB left of 5120KB. Measured againstorigin/master, comment-stripped as the build ships them:Note
Flashing for this test ran into a separate, pre-existing problem with
sysupgrade -x, which leaves a camera with no shell, no SSH and no console until it reboots. That is unrelated to this change and is filed as #2416.Scope
general/package/all-patches/linux/(those go to OpenIPC/linux)general/overlay/or in a sharedload_<vendor>script hardcodes a value specific to my boardLD_PRELOAD, and no binaries that cannot be rebuilt from source