Random hang in logd

[sidepipe]

I'm seeing a random lockup in logd. Unfortunately this renders the system pretty much unusable, since then anything that writes to the log also freezes ( including login ).

I haven't been able to reliably replicate it, but it occasionally happens during system boot, so I changed the startup to detect the lock and reboot if it didn't happen... this would trigger the issue after many reboots. That way I managed to get a core dump by sending SIGABRT, and found that the lock was in read() called from ustream_fd_read_pending() from uloop_run_events().

A cursory look, without really understanding all of the pieces involved, leads me to think that the code is written assuming that the pipe opened in read_log() is set as non blocking, though the lock in read() suggests that it actually isn't, so just as a test I tried:

--- ubox.orig/log/logd.c        2025-10-30 11:10:12.000000000 +0000
+++ ubox/log/logd.c     2026-06-29 11:44:06.873768158 +0100
@@ -14,8 +14,8 @@
 #include <sys/types.h>
 #include <pwd.h>
 #include <stdio.h>
-#include <unistd.h>
 #include <syslog.h>
+#include <fcntl.h>
 #include <unistd.h>
 
 #include <linux/types.h>
@@ -122,7 +122,8 @@ read_log(struct ubus_context *ctx, struc
 
        l = log_list(count, NULL);
        if (stream) {
-               if (pipe(fds) == -1) {
+               if ((pipe(fds) == -1) || (fcntl(fds[0], F_SETFL, fcntl(fds[0], F_GETFL, 0) | O_NONBLOCK) == -1) ||
+                       (fcntl(fds[1], F_SETFL, fcntl(fds[1], F_GETFL, 0) | O_NONBLOCK) == -1)) {
                        fprintf(stderr, "logd: failed to create pipe: %m\n");
                        return -1;
                }

I've now rebooted my test box many times and not seen the lock, and AFAICT there doesn't seem to be any adverse effect from doing this ( such as increased CPU use, implying that the theory about the code expecting non blocking operation is probably true ).

Whilst the above seems to work, as I say I don't know enough about all of the various parts, and honestly don't have the time to work it all out. Seems odd that code written for a non-blocking socket doesn't actually set the socket non-blocking, so I'm assuming that the above fix isn't "correct" in that sense, but if the socket is meant to be blocking then the implication is that poll() is called before read() somewhere and there's a race which means that occasionally the data is eaten up between the two ( which would explain the randomness here ).

Anyway - hopefully someone who knows the code can investigate further.

I'm using:
ubox PKG_SOURCE_DATE:=2025-10-30
libubox PKG_SOURCE_DATE:=2025-07-23
ustream-ssl PKG_SOURCE_DATE:=2024-07-28

Note that I've been testing against 24.10.5, hence the older ustream, so it's possible that something has changed in there to fix this issue, but I don't think the ustream code is really involved too much with this and anyway has hardly changed in the last couple of years.

[sidepipe]

Hmm... I think I spoke too soon - it might be that the change makes very little difference, in that I've now seen a lock with it in place, and the core indicates control still in read(). I'm not really sure how that can be given that I'm specifically setting non block mode on the pipe sockets - unless it's reset again somewhere else in the code.

I've now tested with 100 reboots both with and without the non block change. With the change NOT in place, out of 100 boots I saw freezes on boot 12, 33, 53, 55, 91 and 96, snd with the change in place freezes on boots 24, 56 and 76. Whilst this shows that there are half as many freezes with the change in place, they're so infrequent and seemingly random I'm not sure that the sample size is actually big enough at this point.

[sidepipe]

I think I'm getting somewhere with this ( and might have a workaround ), but it's not great. Essentially, read() is blocking despite O_NONBLOCK being set on the file descriptor, which shouldn't be possible. It's waiting in syslog_print, and I think that ultimately /proc/kmsg is buggy and there's a race condition which is the result of reading the final data from the kernel log buffer at the same time as something else writes new data, and it gets stuck around wait_event_interruptible() in the kernel. I think it's a long shot to get /proc/kmsg fixed at this point. I don't think /dev/kmsg would have the same issues, and is a newer interface ( I think ) so the ultimate fix would be to use that instead ( but that would mean reformatting the returned data, since it's not really human readable as is ).

I'm currently testing a workaround which uses a poll() with timeout to try to prevent the race being triggered, but as I've found even running for an hour or so constantly rebooting doesn't really guarantee that it's fixed, so I'll leave it as long as I have patience for and if it works I'll post my patch here.

I'm unsure if this is actually the same issue as #6 - I did see one kernel panic during testing ( that I was watching ) but didn't get a chance to compare it with that one.

[sidepipe]

No matter what I've tried, logd falls foul of the ( I assume ) /proc/kmsg lock bug, which as I say locks any process that writes to the log also, such as dropbear, login, etc. I've given up trying to work around this, so instead have switched to using /dev/kmsg thus:

diff -rupN ubox.orig/log/logd.c ubox/log/logd.c
--- ubox.orig/log/logd.c        2026-06-30 09:23:59.000000000 +0100
+++ ubox/log/logd.c     2026-07-01 12:01:38.326354077 +0100
@@ -182,7 +182,7 @@ write_log(struct ubus_context *ctx, stru
                                event[len - 1] = 0;
                        }
 
-                       log_add(event, len, SOURCE_SYSLOG);
+                       log_add(event, len, -1, SOURCE_SYSLOG, NULL);
                }
        }
 
diff -rupN ubox.orig/log/syslog.c ubox/log/syslog.c
--- ubox.orig/log/syslog.c      2025-10-30 11:10:12.000000000 +0000
+++ ubox/log/syslog.c   2026-07-01 12:58:46.843536840 +0100
@@ -30,7 +30,6 @@
 
 #include <libubox/uloop.h>
 #include <libubox/usock.h>
-#include <libubox/ustream.h>
 #include <libubox/utils.h>
 
 #include "syslog.h"
@@ -39,7 +38,7 @@
 #define LOG_DEFAULT_SOCKET     "/dev/log"
 #define SYSLOG_PADDING         16
 
-#define KLOG_DEFAULT_PROC      "/proc/kmsg"
+#define KLOG_DEFAULT_PROC      "/dev/kmsg"
 
 #define PAD(x) (x % 4) ? (((x) - (x % 4)) + 4) : (x)
 
@@ -144,11 +143,10 @@ log_add_udebug(int priority, char *buf,
 
 
 void
-log_add(char *buf, int size, int source)
+log_add(char *buf, int size, int priority, int source, struct timespec *ts)
 {
        regmatch_t matches[3];
        struct log_head *next;
-       int priority = 0;
        int ret;
        char *c;
 
@@ -171,12 +169,15 @@ log_add(char *buf, int size, int source)
 
        buf[size - 1] = 0;
 
-       /* strip the priority */
-       ret = regexec(&pat_prio, buf, 3, matches, 0);
-       if (!ret) {
-               priority = atoi(&buf[matches[1].rm_so]);
-               size -= matches[2].rm_so;
-               buf += matches[2].rm_so;
+       if (priority < 0) {
+               priority = LOG_INFO;    /* Default if regex doesn't match. */
+               /* strip the priority */
+               ret = regexec(&pat_prio, buf, 3, matches, 0);
+               if (!ret) {
+                       priority = atoi(&buf[matches[1].rm_so]);
+                       size -= matches[2].rm_so;
+                       buf += matches[2].rm_so;
+               }
        }
 
        /* strip syslog timestamp */
@@ -210,7 +211,11 @@ log_add(char *buf, int size, int source)
        newest->id = current_id++;
        newest->priority = priority;
        newest->source = source;
-       clock_gettime(CLOCK_REALTIME, &newest->ts);
+       if (ts) {
+               newest->ts = *ts;
+       } else {
+               clock_gettime(CLOCK_REALTIME, &newest->ts);
+       }
        strcpy(newest->data, buf);
 
        ubus_notify_log(newest);
@@ -237,39 +242,77 @@ syslog_handle_fd(struct uloop_fd *fd, un
 
                buf[len] = 0;
 
-               log_add(buf, strlen(buf) + 1, SOURCE_SYSLOG);
+               log_add(buf, strlen(buf) + 1, -1, SOURCE_SYSLOG, NULL);
        }
 }
 
-static void
-klog_cb(struct ustream *s, int bytes)
-{
-       struct ustream_buf *buf = s->r.head;
-       char *newline, *str;
-       int len;
-
-       do {
-               str = ustream_get_read_buf(s, NULL);
-               if (!str)
-                       break;
-               newline = strchr(buf->data, '\n');
-               if (!newline)
-                       break;
-               *newline = 0;
-               len = newline + 1 - str;
-               log_add(buf->data, len, SOURCE_KLOG);
-               ustream_consume(s, len);
-       } while (1);
-}
-
 static struct uloop_fd syslog_fd = {
        .cb = syslog_handle_fd
 };
 
-static struct ustream_fd klog = {
-       .stream.string_data = true,
-       .stream.notify_read = klog_cb,
-};
+static struct uloop_fd klog_fd = { 0 };
+
+static void klog_devkmsg_read_cb(struct uloop_fd *u, unsigned int events)
+{
+       static char raw_buf[4096];
+       ssize_t res;
+       char *msg_start;
+       int priority = 0;
+       unsigned long long ktime_usec = 0;
+       struct timespec realtime, monotonic, msg_ts;
+
+       /* read() will read a single record from /dev/kmsg */
+       retry_read:
+       res = read(u->fd, raw_buf, sizeof(raw_buf) - 1);
+       if (res <= 0) {
+               /* /dev/kmsg read returns EPIPE if buffer looped */
+               if (errno == EAGAIN || errno == EWOULDBLOCK)
+                       return;
+
+               /*
+               * EPIPE indicates that the buffer has looped, so we should retry the read to
+               * prevent nothing being read ( subsequent reads proceed as normal ). Similarly,
+               * EINTR should be silently ignored.
+               */
+               if (errno == EPIPE || errno == EINTR)
+                       goto retry_read;
+
+               return;
+       }
+       raw_buf[res] = '\0';
+
+       /* Parse /dev/kmsg metadata */
+       if (sscanf(raw_buf, "%d,%*d,%llu,", &priority, &ktime_usec) == 2) {
+               int msg_len;
+
+               msg_start = strchr(raw_buf, ';');
+               if (!msg_start)
+                       return;
+
+               msg_start++; /* Step past semicolon */
+               msg_len = strlen(msg_start);
+               if (msg_len > 0 && msg_start[msg_len - 1] == '\n') {
+                       msg_start[msg_len - 1] = '\0';
+                       msg_len--;
+               }
+
+               if (msg_len <= 0)
+                       return;
+
+               /* Calculate the exact wall-clock timestamp of when this log happened */
+               if (clock_gettime(CLOCK_REALTIME, &realtime) == 0 &&
+                               clock_gettime(CLOCK_MONOTONIC, &monotonic) == 0) {
+                       long long log_ns_since_boot = ktime_usec * 1000LL;
+                       long long current_mono_ns = (monotonic.tv_sec * 1000000000LL) + monotonic.tv_nsec;
+                       long long delta_ns = current_mono_ns - log_ns_since_boot;
+                       long long real_ns = (realtime.tv_sec * 1000000000LL) + realtime.tv_nsec - delta_ns;
+
+                       msg_ts.tv_sec = real_ns / 1000000000LL;
+                       msg_ts.tv_nsec = real_ns % 1000000000LL;
+                       log_add(msg_start, msg_len + 1, priority & 7, SOURCE_KLOG, &msg_ts);
+               }
+       }
+}
 
 static int
 klog_open(void)
@@ -282,7 +325,9 @@ klog_open(void)
                return -1;
        }
        fcntl(fd, F_SETFD, fcntl(fd, F_GETFD) | FD_CLOEXEC);
-       ustream_fd_init(&klog, fd);
+       klog_fd.fd = fd;
+       klog_fd.cb = klog_devkmsg_read_cb;
+       uloop_fd_add(&klog_fd, ULOOP_READ);
        return 0;
 }
 
@@ -397,8 +442,7 @@ log_shutdown(void)
                close(syslog_fd.fd);
        }
 
-       ustream_free(&klog.stream);
-       close(klog.fd.fd);
+       close(klog_fd.fd);
        free(log);
        regfree(&pat_prio);
        regfree(&pat_tstamp);
diff -rupN ubox.orig/log/syslog.h ubox/log/syslog.h
--- ubox.orig/log/syslog.h      2025-10-30 11:10:12.000000000 +0000
+++ ubox/log/syslog.h   2026-07-01 12:01:58.059678308 +0100
@@ -40,7 +40,7 @@ void log_shutdown(void);
 typedef void (*log_list_cb)(struct log_head *h);
 struct log_head* log_list(int count, struct log_head *h);
 int log_buffer_init(int size);
-void log_add(char *buf, int size, int source);
+void log_add(char *buf, int size, int priority, int source, struct timespec *ts);
 void ubus_notify_log(struct log_head *l);
 void log_udebug_config(struct udebug_ubus *ctx, struct blob_attr *data,
                       bool enabled);

This completely fixes the issue, and anyway /dev/kmsg is a much better interface to be using ( honestly /proc/kmsg needs to be put out of its misery! ) I'm not going to create a pull request for this - partly lack of time, but also because as I've said, I really don't know how all the pieces fit so there may be a "better" way.

A couple of things to note:

• I'm decoding timestamps from the kernel log records rather than just stamping based on the time they're read. /dev/kmsg isn't consuming in the way /proc/kmsg is, so if you restart logd you'll see all of the old messages still in the kernel buffer - this is an improvement on the old behaviour but without decoding the timestamps they'd all show as logd startup time, not the time they actually happened. Haven't looked at how the other paths for logs to be sourced handle this ( I suspect not at all ) and for now any other source does what it used to do,
• This no longer uses ustream at all for these logs... /dev/kmsg is record based and I don't think it's really compatible,

[rabbitrogi]

Confirming this on a production system, with a full evidence set — and what looks like a reliable, high-frequency reproduction environment: OpenWrt running as Docker containers sharing the host kernel's printk ring buffer.

Environment

• OpenWrt 24.10.6 (ubox 2024.04.26~85f10530-r1), x86_64, running as a Docker container — two such OpenWrt containers on the same host
• The containers are privileged enough to open /proc/kmsg, so logd reads the host's printk buffer (host kernel 6.17), which is far from quiet: audit/apparmor profile reloads, perf, etc.

Symptoms (identical to this issue)

logd became permanently wedged, and everything calling syslog() then blocked:

• dropbear child processes stuck before sending the SSH banner — clients died with Connection timed out during banner exchange (TCP handshake completed, banner never arrived), while ping kept working (pure kernel path)
• procd itself blocked — every ubus call service ... timed out, so even /etc/init.d/log restart was impossible
• logger and logread blocked as well
• SIGKILL on logd brought instant full recovery: the /dev/log queue drained, blocked processes completed, procd respawned logd

Evidence collected during the incident

logd's kernel stack (two samples 3 s apart, identical):

[<0>] syslog_print+0x17c/0x3f0
[<0>] do_syslog+0xde/0x450
[<0>] kmsg_read+0x43/0x60
[<0>] proc_reg_read+0x2e/0xa0
[<0>] vfs_read+0xb7/0x390
[<0>] ksys_read+0x71/0xf0

• dropbear children: wchan = unix_wait_for_peer (blocked sending to /dev/log)
• /dev/log unix dgram socket: 19 datagrams queued, never drained
• TCP connections to port 22 sat in ESTABLISHED with unread client data (banner blocked pre-auth)

Analysis

Matches your diagnosis, confirmed against kernel 6.6 sources (fs/proc/kmsg.c, kernel/printk/printk.c):

• kmsg_read() honors O_NONBLOCK only through the SYSLOG_ACTION_SIZE_UNREAD pre-check; the subsequent SYSLOG_ACTION_READ → syslog_print() → wait_event_interruptible(log_wait, prb_read_valid(...)) path has no non-blocking handling at all.
• The race window between the pre-check and the wait is where a printk flood laps the ring buffer. (The same code is present unchanged in current kernels — no kernel-side fix to expect.)

Two factors make this container setup a near-perfect repro:

1. Multiple /proc/kmsg readers share the global syslog_seq — two OpenWrt containers on one host run two logds advancing the same global cursor, invalidating each other's pre-checks.
2. Host printk traffic flows through the same ring buffer, so the lap-race is dramatically more probable than on a quiet router.

Fix direction

+1 for /dev/kmsg from us as well. We prepared a minimal downstream patch for OpenWrt 24.10 that converts logd's klog reader to /dev/kmsg (keeping the exact line format log_add() already expects, SEEK_END on open to skip the backlog replay, EPIPE resync on lap) and have it running in production on the affected machine: logd now holds /dev/kmsg (instead of /proc/kmsg), kernel messages reach logread with correct timestamps, and userland syslog flows normally. Happy to share the patch or help shape it into a PR if there is maintainer interest.