Merge pull request #33140 from yuwata/test-journal

test: sync journal in short-living services

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

@@ -6,3 +6,4 @@ Type=oneshot
 ExecStart=/usr/lib/systemd/tests/testdata/units/delegated_cgroup_filtering_payload.sh
 Delegate=yes
 SyslogLevel=notice
+LogLevelMax=info

test/TEST-04-JOURNAL/TEST-04-JOURNAL.units/logs-filtering.service

@@ -3,5 +3,9 @@ Description=Log filtering unit
 
 [Service]
 Type=oneshot
-ExecStart=sh -c 'echo "Logging from the service, and ~more~ foo bar" && sleep 2'
+ExecStart=sh -c 'echo "Logging from the service, and ~more~ foo bar"'
+# 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
 SyslogLevel=notice
+LogLevelMax=info

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

@@ -3,5 +3,9 @@
 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/TEST-04-JOURNAL/TEST-04-JOURNAL.units/verbose-success.service

@@ -4,8 +4,10 @@ Description=Verbose successful service
 
 [Service]
 Type=oneshot
-# Sleep so that the cgroup is still there when journald processes the log message which is required for
-# journald to add the expected fields to the log message.
-ExecStart=sleep 2
 ExecStart=echo success
-ExecStart=sleep 2
+# 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
+# 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

@@ -3,8 +3,15 @@
 set -eux
 set -o pipefail
 
+if ! cgroupfs_supports_user_xattrs; then
+    echo "CGroup does not support user xattrs, skipping LogFilterPatterns= tests."
+    exit 0
+fi
+
 # shellcheck source=test/units/util.sh
- . "$(dirname "$0")"/util.sh
+. "$(dirname "$0")"/util.sh
+
+NEEDS_RELOAD=
 
 add_logs_filtering_override() {
     local unit="${1:?}"
@@ -13,66 +20,74 @@ add_logs_filtering_override() {
 
     mkdir -p "/run/systemd/system/$unit.d/"
     echo -ne "[Service]\nLogFilterPatterns=$log_filter" >"/run/systemd/system/$unit.d/$override_name.conf"
-    systemctl daemon-reload
+    NEEDS_RELOAD=1
 }
 
 run_service_and_fetch_logs() {
     local unit="${1:?}"
     local start
 
+    if [[ -n "$NEEDS_RELOAD" ]]; then
+        systemctl daemon-reload
+        NEEDS_RELOAD=
+    fi
+
+    journalctl --sync
     start="$(date '+%Y-%m-%d %T.%6N')"
     systemctl start "$unit"
-    journalctl --sync
     journalctl -q -u "$unit" -S "$start" -p notice
 }
 
-if cgroupfs_supports_user_xattrs; then
-    # Accept all log messages
-    add_logs_filtering_override "logs-filtering.service" "00-reset" ""
-    [[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    add_logs_filtering_override "logs-filtering.service" "01-allow-all" ".*"
-    [[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Discard all log messages
-    add_logs_filtering_override "logs-filtering.service" "02-discard-all" "~.*"
-    [[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Accept all test messages
-    add_logs_filtering_override "logs-filtering.service" "03-reset" ""
-    [[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Discard all test messages
-    add_logs_filtering_override "logs-filtering.service" "04-discard-gg" "~.*gg.*"
-    [[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Deny filter takes precedence
-    add_logs_filtering_override "logs-filtering.service" "05-allow-all-but-too-late" ".*"
-    [[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Use tilde in a deny pattern
-    add_logs_filtering_override "logs-filtering.service" "06-reset" ""
-    add_logs_filtering_override "logs-filtering.service" "07-prevent-tilde" "~~more~"
-    [[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Only allow a pattern that won't be matched
-    add_logs_filtering_override "logs-filtering.service" "08-reset" ""
-    add_logs_filtering_override "logs-filtering.service" "09-allow-only-non-existing" "non-existing string"
-    [[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    # Allow a pattern starting with a tilde
-    add_logs_filtering_override "logs-filtering.service" "10-allow-with-escape-char" "\\\\x7emore~"
-    [[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    add_logs_filtering_override "logs-filtering.service" "11-reset" ""
-    add_logs_filtering_override "logs-filtering.service" "12-allow-with-spaces" "foo bar"
-    [[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
-
-    add_logs_filtering_override "delegated-cgroup-filtering.service" "00-allow-all" ".*"
-    [[ -n $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]
-
-    add_logs_filtering_override "delegated-cgroup-filtering.service" "01-discard-hello" "~hello"
-    [[ -z $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]
-
+at_exit() {
     rm -rf /run/systemd/system/{logs-filtering,delegated-cgroup-filtering}.service.d
-fi
+    systemctl daemon-reload
+}
+
+trap at_exit EXIT
+
+# Accept all log messages
+add_logs_filtering_override "logs-filtering.service" "00-reset" ""
+[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+add_logs_filtering_override "logs-filtering.service" "01-allow-all" ".*"
+[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Discard all log messages
+add_logs_filtering_override "logs-filtering.service" "02-discard-all" "~.*"
+[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Accept all test messages
+add_logs_filtering_override "logs-filtering.service" "03-reset" ""
+[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Discard all test messages
+add_logs_filtering_override "logs-filtering.service" "04-discard-gg" "~.*gg.*"
+[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Deny filter takes precedence
+add_logs_filtering_override "logs-filtering.service" "05-allow-all-but-too-late" ".*"
+[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Use tilde in a deny pattern
+add_logs_filtering_override "logs-filtering.service" "06-reset" ""
+add_logs_filtering_override "logs-filtering.service" "07-prevent-tilde" "~~more~"
+[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Only allow a pattern that won't be matched
+add_logs_filtering_override "logs-filtering.service" "08-reset" ""
+add_logs_filtering_override "logs-filtering.service" "09-allow-only-non-existing" "non-existing string"
+[[ -z $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+# Allow a pattern starting with a tilde
+add_logs_filtering_override "logs-filtering.service" "10-allow-with-escape-char" "\\\\x7emore~"
+[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+add_logs_filtering_override "logs-filtering.service" "11-reset" ""
+add_logs_filtering_override "logs-filtering.service" "12-allow-with-spaces" "foo bar"
+[[ -n $(run_service_and_fetch_logs "logs-filtering.service") ]]
+
+add_logs_filtering_override "delegated-cgroup-filtering.service" "00-allow-all" ".*"
+[[ -n $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]
+
+add_logs_filtering_override "delegated-cgroup-filtering.service" "01-discard-hello" "~hello"
+[[ -z $(run_service_and_fetch_logs "delegated-cgroup-filtering.service") ]]

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

@@ -104,12 +104,10 @@ diff /tmp/expected /tmp/output
 
 # test that LogLevelMax can also suppress logging about services, not only by services
 systemctl start silent-success
-journalctl --sync
 [[ -z "$(journalctl -b -q -u silent-success.service)" ]]
 
 # Test syslog identifiers exclusion
 systemctl start verbose-success.service
-journalctl --sync
 [[ -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 systemd)" ]]
@@ -262,8 +260,8 @@ UNIT_NAME="test-cursor-$RANDOM.service"
 CURSOR_FILE="$(mktemp)"
 # Generate some messages we can match against
 journalctl --cursor-file="$CURSOR_FILE" -n1
-systemd-run --unit="$UNIT_NAME" --wait --service-type=exec bash -ec "sleep 2; set -x; echo hello; echo world; set +x; sleep 2"
-journalctl --sync
+systemd-run --unit="$UNIT_NAME" --wait --service-type=exec -p LogLevelMax=info \
+            bash -ec "set -x; echo hello; echo world; set +x; journalctl --sync"
 # --after-cursor= + --unit=
 # The format of the "Starting ..." message depends on StatusUnitFormat=, so match only the beginning
 # which should be enough in this case