Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TEST-09-REBOOT is flaky in Github Actions #32890

Closed
DaanDeMeyer opened this issue May 17, 2024 · 1 comment · Fixed by #32911 or #32964
Closed

TEST-09-REBOOT is flaky in Github Actions #32890

DaanDeMeyer opened this issue May 17, 2024 · 1 comment · Fixed by #32911 or #32964
Labels
bug 🐛 Programming errors, that need preferential fixing tests

Comments

@DaanDeMeyer
Copy link
Contributor

systemd version the issue has been seen with

main

Used distribution

No response

Linux kernel version used

No response

CPU architectures issue was seen on

None

Component

No response

Expected behaviour you didn't see

No response

Unexpected behaviour you saw

https://github.com/systemd/systemd/actions/runs/9123190929/job/25085230521?pr=32884

gh run download 9123190929 --name ci-mkosi-9123190929-1-debian-testing-failed-test-journals -D ci/ci-mkosi-9123190929-1-debian-testing-failed-test-journals && journalctl --file ci/ci-mkosi-9123190929-1-debian-testing-failed-test-journals/test/journal/TEST-09-REBOOT.journal --no-hostname -o short-monotonic -u TEST-09-REBOOT.service -p info

Steps to reproduce the problem

No response

Additional program output to the terminal or log subsystem illustrating the issue

[   27.430621] reboot: Restarting system
3h3hBdsDxe: loading Boot0001 "UEFI QEMU QEMU HARDDISK " from PciRoot(0x0)/Pci(0x4,0x0)/Scsi(0x0,0x0)
BdsDxe: starting Boot0001 "UEFI QEMU QEMU HARDDISK " from PciRoot(0x0)/Pci(0x4,0x0)/Scsi(0x0,0x0)
EFI stub: Loaded initrd from LINUX_EFI_INITRD_MEDIA_GUID device path
EFI stub: Measured initrd data into PCR 9
SELinux:  Could not open policy file <= /etc/selinux/targeted/policy/policy.33:  No such file or directory
[   16.578064] platform regulatory.0: firmware: failed to load regulatory.db (-2)
[   16.579962] firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware
[   16.582395] platform regulatory.0: firmware: failed to load regulatory.db (-2)
[   24.727675] TEST-09-REBOOT.sh[493]: + set -o pipefail
[   24.729815] TEST-09-REBOOT.sh[493]: + export NUM_REBOOT=4
[   24.732344] TEST-09-REBOOT.sh[493]: + NUM_REBOOT=4
[   24.736534] TEST-09-REBOOT.sh[495]: ++ dirname /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.sh
[   24.748525] TEST-09-REBOOT.sh[493]: + . /usr/lib/systemd/tests/testdata/units/test-control.sh
[   24.755804] TEST-09-REBOOT.sh[493]: ++ [[ /usr/lib/systemd/tests/testdata/units/test-control.sh -ef /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.sh ]]
[   24.768740] TEST-09-REBOOT.sh[493]: ++ declare -i _CHILD_PID=0
[   24.770681] TEST-09-REBOOT.sh[493]: ++ _PASSED_TESTS=()
[   24.779452] TEST-09-REBOOT.sh[496]: ++ dirname /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.sh
[   24.785923] TEST-09-REBOOT.sh[493]: + . /usr/lib/systemd/tests/testdata/units/util.sh
[   24.788293] TEST-09-REBOOT.sh[493]: ++ [[ -e /var/tmp/.systemd_reboot_count ]]
[   24.790685] TEST-09-REBOOT.sh[493]: ++ REBOOT_COUNT=1
[   24.792837] TEST-09-REBOOT.sh[493]: + systemd-cat echo 'Reboot count: 1'
[   24.824129] TEST-09-REBOOT.sh[493]: + systemd-cat journalctl --list-boots
[   24.840235] TEST-09-REBOOT.sh[493]: + run_subtests
[   24.845039] TEST-09-REBOOT.sh[493]: + subtests=('/usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh')
[   24.864189] TEST-09-REBOOT.sh[493]: + local subtests
[   24.865978] TEST-09-REBOOT.sh[493]: + local subtest
[   24.867717] TEST-09-REBOOT.sh[493]: + [[ 1 -eq 0 ]]
[   24.893995] TEST-09-REBOOT.sh[493]: + for subtest in "${subtests[@]}"
[   24.896107] TEST-09-REBOOT.sh[493]: + [[ -n '' ]]
[   24.903458] TEST-09-REBOOT.sh[493]: + : '--- /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh BEGIN ---'
[   24.907848] TEST-09-REBOOT.sh[493]: + SECONDS=0
[   24.911262] TEST-09-REBOOT.sh[493]: + .//usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh
[   24.914940] TEST-09-REBOOT.sh[501]: + set -o pipefail
[   24.919713] TEST-09-REBOOT.sh[502]: ++ dirname .//usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh
[   24.923115] TEST-09-REBOOT.sh[501]: + . .//usr/lib/systemd/tests/testdata/units/util.sh
[   24.925488] TEST-09-REBOOT.sh[501]: ++ [[ -e /var/tmp/.systemd_reboot_count ]]
[   24.927852] TEST-09-REBOOT.sh[501]: ++ REBOOT_COUNT=1
[   24.929432] TEST-09-REBOOT.sh[501]: + index=0
[   24.931453] TEST-09-REBOOT.sh[501]: + SYSTEMD_LOG_LEVEL=debug
[   24.933253] TEST-09-REBOOT.sh[501]: + journalctl --list-boots
[   24.935089] TEST-09-REBOOT.sh[503]: IDX BOOT ID                          FIRST ENTRY                 LAST ENTRY
[   24.937597] TEST-09-REBOOT.sh[503]:  -1 59f9d8e7c909406d8c2846e08b3bb944 Fri 2024-05-17 05:50:09 UTC Fri 2024-05-17 05:50:34 UTC
[   24.943673] TEST-09-REBOOT.sh[503]:   0 49033669cb924f7f831d4d4f1f098728 Fri 2024-05-17 05:50:57 UTC Fri 2024-05-17 05:51:20 UTC
[   24.947793] TEST-09-REBOOT.sh[504]: + journalctl --list-boots -o json
[   24.951455] TEST-09-REBOOT.sh[506]: + read -r offset boot_id first_ts last_ts
[   24.962964] TEST-09-REBOOT.sh[505]: + jq -r '.[] | [.index, .boot_id, .first_entry, .last_entry] | @tsv'
[   24.974663] TEST-09-REBOOT.sh[506]: + : 'Boot #1 (-1) with ID 59f9d8e7c909406d8c2846e08b3bb944'
[   24.978309] TEST-09-REBOOT.sh[506]: + SYSTEMD_LOG_LEVEL=debug
[   24.986143] TEST-09-REBOOT.sh[506]: + journalctl -q -n 0 -b 1
[   24.990908] TEST-09-REBOOT.sh[506]: + SYSTEMD_LOG_LEVEL=debug
[   24.998015] TEST-09-REBOOT.sh[506]: + journalctl -q -n 0 -b -1
[   25.000152] TEST-09-REBOOT.sh[506]: + SYSTEMD_LOG_LEVEL=debug
[   25.002216] TEST-09-REBOOT.sh[506]: + journalctl -q -n 0 -b 59f9d8e7c909406d8c2846e08b3bb944
[   25.004112] TEST-09-REBOOT.sh[510]: ++ get_first_boot_id 1
[   25.005755] TEST-09-REBOOT.sh[511]: ++ journalctl -b 1 -o json -n +1
[   25.066109] TEST-09-REBOOT.sh[512]: ++ jq -r ._BOOT_ID
[   25.073888] TEST-09-REBOOT.sh[506]: + entry_boot_id=59f9d8e7c909406d8c2846e08b3bb944
[   25.099227] TEST-09-REBOOT.sh[506]: + assert_eq 59f9d8e7c909406d8c2846e08b3bb944 59f9d8e7c909406d8c2846e08b3bb944
[   25.102509] TEST-09-REBOOT.sh[513]: + set +ex
[   25.104768] TEST-09-REBOOT.sh[514]: ++ get_first_boot_id -1
[   25.106836] TEST-09-REBOOT.sh[515]: ++ journalctl -b -1 -o json -n +1
[   25.117625] TEST-09-REBOOT.sh[516]: ++ jq -r ._BOOT_ID
[   25.124992] TEST-09-REBOOT.sh[506]: + entry_boot_id=59f9d8e7c909406d8c2846e08b3bb944
[   25.140258] TEST-09-REBOOT.sh[506]: + assert_eq 59f9d8e7c909406d8c2846e08b3bb944 59f9d8e7c909406d8c2846e08b3bb944
[   25.146890] TEST-09-REBOOT.sh[517]: + set +ex
[   25.149172] TEST-09-REBOOT.sh[518]: ++ get_first_boot_id 59f9d8e7c909406d8c2846e08b3bb944
[   25.152334] TEST-09-REBOOT.sh[519]: ++ journalctl -b 59f9d8e7c909406d8c2846e08b3bb944 -o json -n +1
[   25.157504] TEST-09-REBOOT.sh[520]: ++ jq -r ._BOOT_ID
[   25.161006] TEST-09-REBOOT.sh[506]: + entry_boot_id=59f9d8e7c909406d8c2846e08b3bb944
[   25.164971] TEST-09-REBOOT.sh[506]: + assert_eq 59f9d8e7c909406d8c2846e08b3bb944 59f9d8e7c909406d8c2846e08b3bb944
[   25.169181] TEST-09-REBOOT.sh[521]: + set +ex
[   25.170769] TEST-09-REBOOT.sh[522]: ++ get_first_timestamp 1
[   25.172406] TEST-09-REBOOT.sh[523]: ++ journalctl -b 1 -o json -n +1
[   25.175409] TEST-09-REBOOT.sh[524]: ++ jq -r .__REALTIME_TIMESTAMP
[   25.177131] TEST-09-REBOOT.sh[506]: + entry_ts=1715925009491532
[   25.178672] TEST-09-REBOOT.sh[506]: + assert_eq 1715925009491532 1715925009491532
[   25.180873] TEST-09-REBOOT.sh[525]: + set +ex
[   25.184494] TEST-09-REBOOT.sh[526]: ++ get_first_timestamp -1
[   25.189185] TEST-09-REBOOT.sh[527]: ++ journalctl -b -1 -o json -n +1
[   25.193200] TEST-09-REBOOT.sh[528]: ++ jq -r .__REALTIME_TIMESTAMP
[   25.195125] TEST-09-REBOOT.sh[506]: + entry_ts=1715925009491532
[   25.196961] TEST-09-REBOOT.sh[506]: + assert_eq 1715925009491532 1715925009491532
[   25.205130] TEST-09-REBOOT.sh[529]: + set +ex
[   25.207232] TEST-09-REBOOT.sh[530]: ++ get_first_timestamp 59f9d8e7c909406d8c2846e08b3bb944
[   25.210393] TEST-09-REBOOT.sh[531]: ++ journalctl -b 59f9d8e7c909406d8c2846e08b3bb944 -o json -n +1
[   25.213766] TEST-09-REBOOT.sh[532]: ++ jq -r .__REALTIME_TIMESTAMP
[   25.216156] TEST-09-REBOOT.sh[506]: + entry_ts=1715925031046917
[   25.218310] TEST-09-REBOOT.sh[506]: + assert_eq 1715925031046917 1715925009491532
[   25.221124] TEST-09-REBOOT.sh[533]: + set +ex
[   25.222683] TEST-09-REBOOT.sh[533]: FAIL: expected: '1715925009491532' actual: '1715925031046917'
[   25.225856] TEST-09-REBOOT.sh[493]: + echo 'Subtest /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh failed'
[   25.229409] TEST-09-REBOOT.sh[493]: Subtest /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh failed
[   25.232855] TEST-09-REBOOT.sh[493]: + return 1
[   27.103719] reboot: Power down
@DaanDeMeyer DaanDeMeyer added bug 🐛 Programming errors, that need preferential fixing tests labels May 17, 2024
yuwata added a commit to yuwata/systemd that referenced this issue May 18, 2024
@yuwata
test: sync journal before read
51db703 
Workaround for systemd#32834 and systemd#32890.
@yuwata yuwata mentioned this issue May 19, 2024
Merged
@yuwata yuwata linked a pull request May 19, 2024 that will close this issue
test: sync journals before reading them #32911
Merged
bluca pushed a commit that referenced this issue May 19, 2024
@yuwata @bluca
test: sync journal before read
a610ba0 
Workaround for #32834 and #32890.
@yuwata
Copy link
Member

yuwata commented May 20, 2024

Huh, still fails:
https://github.com/systemd/systemd/actions/runs/9161999562/job/25188054988?pr=32939

[   31.269650] TEST-09-REBOOT.sh[428]: + SYSTEMD_LOG_LEVEL=debug
[   31.276397] TEST-09-REBOOT.sh[428]: + journalctl --list-boots
[   31.291824] TEST-09-REBOOT.sh[432]: IDX BOOT ID                          FIRST ENTRY                 LAST ENTRY
[   31.308365] TEST-09-REBOOT.sh[432]:  -1 1ab0c4691c0b43358111e872556332f1 Mon 2024-05-20 17:24:19 UTC Mon 2024-05-20 17:24:44 UTC
[   31.330237] TEST-09-REBOOT.sh[432]:   0 811d1ede046449dd99d426fb12cc323e Mon 2024-05-20 17:25:27 UTC Mon 2024-05-20 17:25:55 UTC
[   31.344387] TEST-09-REBOOT.sh[433]: + journalctl --list-boots -o json
[   31.352448] TEST-09-REBOOT.sh[434]: + jq -r '.[] | [.index, .boot_id, .first_entry, .last_entry] | @tsv'
[   31.359301] TEST-09-REBOOT.sh[435]: + read -r offset boot_id first_ts last_ts
[   31.394162] TEST-09-REBOOT.sh[435]: + : 'Boot #1 (-1) with ID 1ab0c4691c0b43358111e872556332f1'
[   31.398224] TEST-09-REBOOT.sh[435]: + SYSTEMD_LOG_LEVEL=debug
[   31.401920] TEST-09-REBOOT.sh[435]: + journalctl -q -n 0 -b 1
[   31.405598] TEST-09-REBOOT.sh[435]: + SYSTEMD_LOG_LEVEL=debug
[   31.411397] TEST-09-REBOOT.sh[435]: + journalctl -q -n 0 -b -1
[   31.418335] TEST-09-REBOOT.sh[435]: + SYSTEMD_LOG_LEVEL=debug
[   31.420666] TEST-09-REBOOT.sh[435]: + journalctl -q -n 0 -b 1ab0c4691c0b43358111e872556332f1
[   31.431276] TEST-09-REBOOT.sh[439]: ++ get_first_boot_id 1
[   31.442246] TEST-09-REBOOT.sh[440]: ++ journalctl -b 1 -o json -n +1
[   31.453130] TEST-09-REBOOT.sh[441]: ++ jq -r ._BOOT_ID
[   31.473327] TEST-09-REBOOT.sh[435]: + entry_boot_id=1ab0c4691c0b43358111e872556332f1
[   31.499384] TEST-09-REBOOT.sh[435]: + assert_eq 1ab0c4691c0b43358111e872556332f1 1ab0c4691c0b43358111e872556332f1
[   31.503045] TEST-09-REBOOT.sh[442]: + set +ex
[   31.504990] TEST-09-REBOOT.sh[443]: ++ get_first_boot_id -1
[   31.507793] TEST-09-REBOOT.sh[444]: ++ journalctl -b -1 -o json -n +1
[   31.511378] TEST-09-REBOOT.sh[445]: ++ jq -r ._BOOT_ID
[   31.522845] TEST-09-REBOOT.sh[435]: + entry_boot_id=1ab0c4691c0b43358111e872556332f1
[   31.525956] TEST-09-REBOOT.sh[435]: + assert_eq 1ab0c4691c0b43358111e872556332f1 1ab0c4691c0b43358111e872556332f1
[   31.535435] TEST-09-REBOOT.sh[446]: + set +ex
[   31.553449] TEST-09-REBOOT.sh[447]: ++ get_first_boot_id 1ab0c4691c0b43358111e872556332f1
[   31.556665] TEST-09-REBOOT.sh[449]: ++ jq -r ._BOOT_ID
[   31.561623] TEST-09-REBOOT.sh[448]: ++ journalctl -b 1ab0c4691c0b43358111e872556332f1 -o json -n +1
[   31.568947] TEST-09-REBOOT.sh[435]: + entry_boot_id=1ab0c4691c0b43358111e872556332f1
[   31.571992] TEST-09-REBOOT.sh[435]: + assert_eq 1ab0c4691c0b43358111e872556332f1 1ab0c4691c0b43358111e872556332f1
[   31.576423] TEST-09-REBOOT.sh[450]: + set +ex
[   31.581834] TEST-09-REBOOT.sh[451]: ++ get_first_timestamp 1
[   31.588431] TEST-09-REBOOT.sh[452]: ++ journalctl -b 1 -o json -n +1
[   31.594184] TEST-09-REBOOT.sh[453]: ++ jq -r .__REALTIME_TIMESTAMP
[   31.604546] TEST-09-REBOOT.sh[435]: + entry_ts=1716225859103721
[   31.607160] TEST-09-REBOOT.sh[435]: + assert_eq 1716225859103721 1716225881363502
[   31.610846] TEST-09-REBOOT.sh[454]: + set +ex
[   31.612758] TEST-09-REBOOT.sh[454]: FAIL: expected: '1716225881363502' actual: '1716225859103721'
[   31.616829] TEST-09-REBOOT.sh[422]: + echo 'Subtest /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh failed'
[   31.620767] TEST-09-REBOOT.sh[422]: Subtest /usr/lib/systemd/tests/testdata/units/TEST-09-REBOOT.journal.sh failed
[   31.624463] TEST-09-REBOOT.sh[422]: + return 1
[   34.083458] reboot: Power down
Finishing after writing 79996 entries
Test failed, relevant logs can be viewed with: 

gh run download 9161999562 --name ci-mkosi-9161999562-1-ubuntu-noble-failed-test-journals -D ci/ci-mkosi-9161999562-1-ubuntu-noble-failed-test-journals && journalctl --file ci/ci-mkosi-9161999562-1-ubuntu-noble-failed-test-journals/test/journal/TEST-09-REBOOT.journal --no-hostname -o short-monotonic -u TEST-09-REBOOT.service -p info

@yuwata yuwata reopened this May 20, 2024
yuwata added a commit to yuwata/systemd that referenced this issue May 22, 2024
@yuwata
test: also flush and rotate journal before read
9802f3f 
Follow-up for a610ba0.

Fixes systemd#32890.
@yuwata yuwata mentioned this issue May 22, 2024
Merged
bluca pushed a commit that referenced this issue May 22, 2024
@yuwata @bluca
test: also flush and rotate journal before read
87ed87e 
Follow-up for a610ba0.

Fixes #32890.
mwilck pushed a commit to mwilck/systemd that referenced this issue May 28, 2024
@yuwata @keszybz
test: sync journal before read
77c5b47 
Workaround for systemd#32834 and systemd#32890.

(cherry picked from commit a610ba0)
mwilck pushed a commit to mwilck/systemd that referenced this issue May 28, 2024
@yuwata @keszybz
test: also flush and rotate journal before read
5b7b056 
Follow-up for a610ba0.

Fixes systemd#32890.

(cherry picked from commit 87ed87e)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug 🐛 Programming errors, that need preferential fixing tests
Milestone
No milestone
2 participants
@DaanDeMeyer @yuwata