journal: fix log filtering for syslog message (#38372)

Fixes #38361.

src/journal/journald-syslog.c

@@ -392,9 +392,6 @@ void manager_process_syslog_message(
         if (!client_context_test_priority(context, priority))
                 return;
 
-        if (client_context_check_keep_log(context, msg, strlen(msg)) <= 0)
-                return;
-
         syslog_ts = msg;
         syslog_ts_len = syslog_skip_timestamp(&msg);
         if (syslog_ts_len == 0)
@@ -403,6 +400,9 @@ void manager_process_syslog_message(
 
         syslog_parse_identifier(&msg, &identifier, &pid);
 
+        if (client_context_check_keep_log(context, msg, strlen(msg)) <= 0)
+                return;
+
         if (m->config.forward_to_syslog)
                 forward_syslog_raw(m, priority, buf, raw_len, ucred, tv);
 

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/delegated-cgroup-filtering.service

@@ -3,7 +3,7 @@ Description=Test service for delegated logs filtering
 
 [Service]
 Type=oneshot
-ExecStart=/usr/lib/systemd/tests/testdata/units/delegated_cgroup_filtering_payload.sh
+ExecStart=/usr/lib/systemd/tests/testdata/TEST-04-JOURNAL.units/delegated_cgroup_filtering_payload.sh
 Delegate=yes
 SyslogLevel=notice
 LogLevelMax=info

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/delegated_cgroup_filtering_payload.sh

@@ -2,7 +2,7 @@
 # SPDX-License-Identifier: LGPL-2.1-or-later
 
 mkdir /sys/fs/cgroup/system.slice/delegated-cgroup-filtering.service/the_child
-/bin/sh /usr/lib/systemd/tests/testdata/units/delegated_cgroup_filtering_payload_child.sh
+/usr/lib/systemd/tests/testdata/TEST-04-JOURNAL.units/delegated_cgroup_filtering_payload_child.sh
 
 echo "parent_process: hello, world!"
 echo "parent_process: hello, people!"

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/delegated_cgroup_filtering_payload_child.sh

@@ -1,4 +1,4 @@
-#!/bin/sh
+#!/bin/bash
 # SPDX-License-Identifier: LGPL-2.1-or-later
 
 echo $$ >/sys/fs/cgroup/system.slice/delegated-cgroup-filtering.service/the_child/cgroup.procs

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/logs-filtering-syslog.py

@@ -0,0 +1,14 @@
+#!/usr/bin/python3
+# SPDX-License-Identifier: LGPL-2.1-or-later
+
+import subprocess
+import syslog
+
+if __name__ == '__main__':
+    syslog.openlog(ident="logs-filtering", logoption=syslog.LOG_PID)
+    syslog.syslog(syslog.LOG_NOTICE, "Logging from the service, and ~more~ foo bar")
+
+    subprocess.check_output(
+        ['journalctl', '--sync'],
+        stdin=subprocess.DEVNULL,
+        text=True)

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/logs-filtering-syslog.service

@@ -0,0 +1,8 @@
+[Unit]
+Description=Log filtering unit
+
+[Service]
+Type=oneshot
+ExecStart=/usr/lib/systemd/tests/testdata/TEST-04-JOURNAL.units/logs-filtering-syslog.py
+SyslogLevel=notice
+LogLevelMax=info

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/silent-success.service

@@ -5,7 +5,6 @@ Description=Silent successful service
 [Service]
 Type=oneshot
 LogLevelMax=notice
-ExecStart=/bin/true
 # If the service finishes extremely fast, journald cannot find the source of the
 # stream. Hence, we need to call 'journalctl --sync' before service finishes.
 ExecStart=journalctl --sync

test/integration-tests/TEST-04-JOURNAL/TEST-04-JOURNAL.units/verbose-success.service

@@ -4,10 +4,7 @@ Description=Verbose successful service
 
 [Service]
 Type=oneshot
-ExecStart=echo success
 # If the service finishes extremely fast, journald cannot find the source of the
 # stream. Hence, we need to call 'journalctl --sync' before service finishes.
-ExecStart=journalctl --sync
+ExecStart=bash -c 'echo success; journalctl --sync'
-# Suppress debugging logs from PID1 or sd-executor. Otherwise, the client context
-# may be outdated when the stream from 'echo' command in the above comes.
 LogLevelMax=info

test/units/TEST-04-JOURNAL.LogFilterPatterns.sh

@@ -47,67 +47,79 @@ at_exit() {
 
 trap at_exit EXIT
 
-# Accept all log messages
+test_service() {
-add_logs_filtering_override "logs-filtering.service" "00-reset" ""
+    service="${1:?}"
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "01-allow-all" ".*"
+    # Accept all log messages
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    add_logs_filtering_override "$service" "00-reset" ""
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
+
+    add_logs_filtering_override "$service" "01-allow-all" ".*"
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
     # Discard all log messages
-add_logs_filtering_override "logs-filtering.service" "02-discard-all" "~.*"
+    add_logs_filtering_override "$service" "02-discard-all" "~.*"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
     # Accept all test messages
-add_logs_filtering_override "logs-filtering.service" "03-reset" ""
+    add_logs_filtering_override "$service" "03-reset" ""
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
     # Discard all test messages
-add_logs_filtering_override "logs-filtering.service" "04-discard-gg" "~.*gg.*"
+    add_logs_filtering_override "$service" "04-discard-gg" "~.*gg.*"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
     # Deny filter takes precedence
-add_logs_filtering_override "logs-filtering.service" "05-allow-all-but-too-late" ".*"
+    add_logs_filtering_override "$service" "05-allow-all-but-too-late" ".*"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
     # Use tilde in a deny pattern
-add_logs_filtering_override "logs-filtering.service" "06-reset" ""
+    add_logs_filtering_override "$service" "06-reset" ""
-add_logs_filtering_override "logs-filtering.service" "07-prevent-tilde" "~~more~"
+    add_logs_filtering_override "$service" "07-prevent-tilde" "~~more~"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
     # Only allow a pattern that won't be matched
-add_logs_filtering_override "logs-filtering.service" "08-reset" ""
+    add_logs_filtering_override "$service" "08-reset" ""
-add_logs_filtering_override "logs-filtering.service" "09-allow-only-non-existing" "non-existing string"
+    add_logs_filtering_override "$service" "09-allow-only-non-existing" "non-existing string"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
     # Allow a pattern starting with a tilde
-add_logs_filtering_override "logs-filtering.service" "10-allow-with-escape-char" "\\\\x7emore~"
+    add_logs_filtering_override "$service" "10-allow-with-escape-char" "\\\\x7emore~"
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "11-reset" ""
+    add_logs_filtering_override "$service" "11-reset" ""
-add_logs_filtering_override "logs-filtering.service" "12-allow-with-spaces" "foo bar"
+    add_logs_filtering_override "$service" "12-allow-with-spaces" "foo bar"
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "13-reset" ""
+    add_logs_filtering_override "$service" "13-reset" ""
-add_logs_filtering_override "logs-filtering.service" "14-exclude-head" "~^Logging"
+    add_logs_filtering_override "$service" "14-exclude-head" "~^Logging"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "15-reset" ""
+    add_logs_filtering_override "$service" "15-reset" ""
-add_logs_filtering_override "logs-filtering.service" "16-exclude-head-no-match" "~^foo"
+    add_logs_filtering_override "$service" "16-exclude-head-no-match" "~^foo"
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "17-reset" ""
+    add_logs_filtering_override "$service" "17-reset" ""
-add_logs_filtering_override "logs-filtering.service" "18-include-head" "^Logging"
+    add_logs_filtering_override "$service" "18-include-head" "^Logging"
-[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
 
-add_logs_filtering_override "logs-filtering.service" "19-reset" ""
+    add_logs_filtering_override "$service" "19-reset" ""
-add_logs_filtering_override "logs-filtering.service" "20-include-head-no-match" "^foo"
+    add_logs_filtering_override "$service" "20-include-head-no-match" "^foo"
-[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
+}
 
-add_logs_filtering_override "delegated-cgroup-filtering.service" "00-allow-all" ".*"
+test_delegate() {
-[[ -n $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]
+    local service="${1:?}"
 
-add_logs_filtering_override "delegated-cgroup-filtering.service" "01-discard-hello" "~hello"
+    add_logs_filtering_override "$service" "00-allow-all" ".*"
-[[ -z $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]
+    [[ -n $(run_service_and_fetch_logs "$service") ]]
+
+    add_logs_filtering_override "$service" "01-discard-hello" "~hello"
+    [[ -z $(run_service_and_fetch_logs "$service") ]]
+}
+
+test_service logs-filtering.service
+test_service logs-filtering-syslog.service
+test_delegate delegated-cgroup-filtering.service
 
 systemctl log-level "$SAVED_LOG_LEVEL"

test/units/TEST-04-JOURNAL.journal.sh

@@ -109,10 +109,10 @@ systemctl start silent-success
 # Test syslog identifiers exclusion
 systemctl start verbose-success.service
 [[ -n "$(journalctl -b -q -u verbose-success.service -t systemd)" ]]
-[[ -n "$(journalctl -b -q -u verbose-success.service -t echo)" ]]
+[[ -n "$(journalctl -b -q -u verbose-success.service -t bash)" ]]
 [[ -n "$(journalctl -b -q -u verbose-success.service -T systemd)" ]]
-[[ -n "$(journalctl -b -q -u verbose-success.service -T echo)" ]]
+[[ -n "$(journalctl -b -q -u verbose-success.service -T bash)" ]]
-[[ -z "$(journalctl -b -q -u verbose-success.service -T echo -T '(echo)' -T sleep -T '(sleep)' -T systemd -T '(systemd)' -T systemd-executor)" ]]
+[[ -z "$(journalctl -b -q -u verbose-success.service -T bash -T '(bash)' -T systemd -T '(systemd)')" ]]
 
 # Exercise the matching machinery
 SYSTEMD_LOG_LEVEL=debug journalctl -b -n 1 /dev/null /dev/zero /dev/null /dev/null /dev/null

test/units/TEST-87-AUX-UTILS-VM.coredump.sh

@@ -23,7 +23,8 @@ at_exit() {
 
 trap at_exit EXIT
 
-# To make all coredump entries stored in system.journal.
+# Sync and rotate journal to make all coredump entries stored in system.journal.
+journalctl --sync
 journalctl --rotate
 
 # Check that we're the ones to receive coredumps
@@ -109,6 +110,16 @@ EOF
     unset CONTAINER
 fi
 
+# Sync and rotate journals (again) to make coredumps stored in archived journal. Otherwise, the main active
+# journal file may be already mostly filled with the coredumps, and may trigger rotation during the sanity
+# checks below. If coredumpctl accesses the main journal currently rotationg, then it warns the following and
+# skips reading the main journal, and cannot find the recent coredumps:
+# TEST-87-AUX-UTILS-VM.sh[839]: + coredumpctl -n 1
+# TEST-87-AUX-UTILS-VM.sh[1172]: Journal file /var/log/journal/a8285330872602d1377cbaaf68869946/system.journal is truncated, ignoring file.
+# TEST-87-AUX-UTILS-VM.sh[1172]: No coredumps found.
+journalctl --sync
+journalctl --rotate
+
 coredumpctl
 SYSTEMD_LOG_LEVEL=debug coredumpctl
 coredumpctl --help