journald: include socket cookie in stream state file names (#44521)

journald keeps track of stream metadata in files identified by dev and
inode numbers. However for sockets, the kernel returns a number that's
truncated to 32 bits. On busy systems, that number can overflow and be
attributed to another service, which will remove the file on exit. When
journald gets restarted, when trying to restore objects, it will see
that the file is missing and emit an error: `systemd-journald[228270]: 1
unknown file descriptors passed, closing`. PID 1 will then retain the fd
and future writes from the daemon that was using that stream will end up
being stuck in the socket that nothing drains.

This PR fixes this by appending `SO_COOKIE` to the name of the stream.
If supports old style streams so that upgrades work and older builds
will load the stream by looking only at the dev and inode, so that
rollbacks work.

src/journal/journald-stream.c

@@ -123,15 +123,27 @@ static int stdout_stream_save(StdoutStream *s) {
 
         if (!s->state_file) {
                 struct stat st;
+                uint64_t cookie;
 
                 r = fstat(s->fd, &st);
                 if (r < 0)
                         return log_ratelimit_warning_errno(errno, JOURNAL_LOG_RATELIMIT,
                                                            "Failed to stat connected stream: %m");
 
-                /* We use device and inode numbers as identifier for the stream */
-                r = asprintf(&s->state_file, "%s/streams/%lu:%lu", s->manager->runtime_directory, (unsigned long) st.st_dev, (unsigned long) st.st_ino);
+                /* Identify the stream by device, inode and socket cookie: socket inode numbers are 32-bit
+                 * and get reused, the cookie never is. Device and inode come first so that older versions
+                 * can still parse the name. */
+                r = socket_get_cookie(s->fd, &cookie);
                 if (r < 0)
+                        return log_ratelimit_warning_errno(r, JOURNAL_LOG_RATELIMIT,
+                                                           "Failed to get cookie of connected stream: %m");
+
+                s->state_file = asprintf_safe("%s/streams/%lu:%lu:%" PRIu64,
+                                              s->manager->runtime_directory,
+                                              (unsigned long) st.st_dev,
+                                              (unsigned long) st.st_ino,
+                                              cookie);
+                if (!s->state_file)
                         return log_oom();
         }
 
@@ -833,6 +845,56 @@ static int stdout_stream_restore(Manager *m, const char *fname, int fd) {
         return 0;
 }
 
+static int restore_stream_from_file(Manager *m, DIR *d, const char *path, const char *fname, FDSet *fds, bool with_cookie) {
+        unsigned long st_dev, st_ino;
+        uint64_t cookie = 0;
+        int fd, n, r;
+
+        assert(m);
+        assert(d);
+        assert(path);
+        assert(fname);
+        /* fds may be NULL if no stream fds were passed in, in which case all state files are removed */
+
+        /* Older versions named state files without the socket cookie, see stdout_stream_save() */
+        n = sscanf(fname, "%lu:%lu:%" SCNu64, &st_dev, &st_ino, &cookie);
+        if (n != (with_cookie ? 3 : 2))
+                return 0;
+
+        FDSET_FOREACH(fd, fds) {
+                struct stat st;
+
+                if (fstat(fd, &st) < 0)
+                        return log_error_errno(errno, "Failed to stat %s: %m", fname);
+
+                if (!S_ISSOCK(st.st_mode) || st.st_dev != st_dev || st.st_ino != st_ino)
+                        continue;
+
+                /* Socket inode numbers are reused, so match the cookie too if we have one */
+                if (with_cookie) {
+                        uint64_t c;
+
+                        if (socket_get_cookie(fd, &c) < 0 || c != cookie)
+                                continue;
+                }
+
+                fdset_remove(fds, fd);
+
+                r = stdout_stream_restore(m, fname, fd);
+                if (r < 0)
+                        safe_close(fd);
+
+                return 0;
+        }
+
+        /* No file descriptor? Then let's delete the state file */
+        log_debug("Cannot restore stream file %s", fname);
+        if (unlinkat(dirfd(d), fname, 0) < 0)
+                log_warning_errno(errno, "Failed to remove %s/%s: %m", path, fname);
+
+        return 0;
+}
+
 int manager_restore_streams(Manager *m, FDSet *fds) {
         _cleanup_closedir_ DIR *d = NULL;
         const char *path;
@@ -847,39 +909,21 @@ int manager_restore_streams(Manager *m, FDSet *fds) {
                 return log_warning_errno(errno, "Failed to enumerate %s: %m", path);
         }
 
+        /* Restore streams from state files with socket cookie first, so that state files named without
+         * cookie can only take the fds that are left over: socket inode numbers are reused, and the fd of
+         * a stream with a state file of its own has to stay with that stream. */
         FOREACH_DIRENT(de, d, goto fail) {
-                unsigned long st_dev, st_ino;
-                bool found = false;
-                int fd;
-
-                if (sscanf(de->d_name, "%lu:%lu", &st_dev, &st_ino) != 2)
-                        continue;
-
-                FDSET_FOREACH(fd, fds) {
-                        struct stat st;
-
-                        if (fstat(fd, &st) < 0)
-                                return log_error_errno(errno, "Failed to stat %s: %m", de->d_name);
-
-                        if (S_ISSOCK(st.st_mode) && st.st_dev == st_dev && st.st_ino == st_ino) {
-                                found = true;
-                                break;
-                        }
-                }
-
-                if (!found) {
-                        /* No file descriptor? Then let's delete the state file */
-                        log_debug("Cannot restore stream file %s", de->d_name);
-                        if (unlinkat(dirfd(d), de->d_name, 0) < 0)
-                                log_warning_errno(errno, "Failed to remove %s/%s: %m", path, de->d_name);
-                        continue;
-                }
-
-                fdset_remove(fds, fd);
-
-                r = stdout_stream_restore(m, de->d_name, fd);
+                r = restore_stream_from_file(m, d, path, de->d_name, fds, /* with_cookie= */ true);
                 if (r < 0)
-                        safe_close(fd);
+                        return r;
+        }
+
+        rewinddir(d);
+
+        FOREACH_DIRENT(de, d, goto fail) {
+                r = restore_stream_from_file(m, d, path, de->d_name, fds, /* with_cookie= */ false);
+                if (r < 0)
+                        return r;
         }
 
         return 0;

test/units/TEST-04-JOURNAL.stream-restore.sh

@@ -0,0 +1,108 @@
+#!/usr/bin/env bash
+# SPDX-License-Identifier: LGPL-2.1-or-later
+set -eux
+set -o pipefail
+
+# Check that stdout streams are restored from the right state file on journald restart: state files include
+# the socket cookie, state files named without it by older versions are still used, and state files of other
+# streams with the same inode number, with or without cookie, are not used.
+
+STREAMS=/run/systemd/journal/streams
+
+start_logger() {
+    local id="${1:?}"
+
+    systemd-run --unit="$id.service" -p SyslogIdentifier="$id" \
+                bash -c "i=0; while :; do echo \"$id \$((i++))\"; sleep .2; done"
+}
+
+# Print the state file of the stream with the given identifier, once PID 1 has the stream in its fd store
+state_file_of() {
+    local id="${1:?}"
+    local f ino
+
+    f="$(timeout 30 bash -c "until grep -lx 'IDENTIFIER=$id' $STREAMS/* 2>/dev/null; do sleep .2; done")"
+    [[ "$(wc -l <<<"$f")" -eq 1 ]]
+
+    ino="$(basename "$f" | cut -d: -f2)"
+    for _ in {1..150}; do
+        if find /proc/1/fd -lname "socket:\[$ino\]" | grep . >/dev/null; then
+            echo "$f"
+            return 0
+        fi
+        sleep .2
+    done
+
+    return 1
+}
+
+# Restart journald and wait until new lines matching the given journalctl arguments are logged
+restart_and_wait_for_logs() {
+    local cursor
+
+    # Reset the start-limit counters, as we're going to restart journald a couple of times
+    systemctl reset-failed systemd-journald.service
+    systemctl restart systemd-journald
+    journalctl --sync
+    cursor="$(journalctl -q "$@" -n 1 -o export | sed -n 's/^__CURSOR=//p')"
+    [[ -n "$cursor" ]]
+
+    for _ in {1..150}; do
+        journalctl --sync
+        if journalctl -q "$@" --after-cursor="$cursor" | grep .; then
+            return 0
+        fi
+        sleep .2
+    done
+
+    return 1
+}
+
+at_exit() {
+    systemctl stop stream-restore-cookie.service \
+                   stream-restore-legacy.service \
+                   stream-restore-other.service \
+                   stream-restore-legacy-other.service || :
+    systemctl reset-failed systemd-journald.service || :
+}
+
+trap at_exit EXIT
+
+# State files include the socket cookie, and the stream is restored from them with its identifier
+start_logger stream-restore-cookie
+F="$(state_file_of stream-restore-cookie)"
+[[ "$(basename "$F")" =~ ^[0-9]+:[0-9]+:[0-9]+$ ]]
+restart_and_wait_for_logs -t stream-restore-cookie
+[[ -e "$F" ]]
+systemctl stop stream-restore-cookie.service
+
+# A state file named without cookie, as written by older versions, is used and left as it is
+start_logger stream-restore-legacy
+F="$(state_file_of stream-restore-legacy)"
+mv "$F" "${F%:*}"
+restart_and_wait_for_logs -t stream-restore-legacy
+grep -x IDENTIFIER=stream-restore-legacy "${F%:*}"
+[[ ! -e "$F" ]]
+systemctl stop stream-restore-legacy.service
+
+# A state file with the same inode number but another cookie, i.e. of another stream after the inode number
+# was reused, is not used for the stream and removed
+start_logger stream-restore-other
+F="$(state_file_of stream-restore-other)"
+sed 's/^IDENTIFIER=.*/IDENTIFIER=stream-restore-other-bogus/' "$F" >"${F%:*}:1"
+restart_and_wait_for_logs -t stream-restore-other
+[[ ! -e "${F%:*}:1" ]]
+[[ -e "$F" ]]
+[[ -z "$(journalctl -q -t stream-restore-other-bogus)" ]]
+systemctl stop stream-restore-other.service
+
+# A state file without cookie with the same inode number, e.g. of a stream from before the upgrade, does not
+# take the fd of a stream that has a state file with cookie, and is removed
+start_logger stream-restore-legacy-other
+F="$(state_file_of stream-restore-legacy-other)"
+sed 's/^IDENTIFIER=.*/IDENTIFIER=stream-restore-legacy-other-bogus/' "$F" >"${F%:*}"
+restart_and_wait_for_logs -t stream-restore-legacy-other
+[[ ! -e "${F%:*}" ]]
+[[ -e "$F" ]]
+[[ -z "$(journalctl -q -t stream-restore-legacy-other-bogus)" ]]
+systemctl stop stream-restore-legacy-other.service