Possible race condition in TEST-53-ISSUE-16347

[mrc0mmand]

systemd version the issue has been seen with

latest main

Used distribution

Ubuntu Focal/CentOS Stream 8

Linux kernel version used

No response

CPU architectures issue was seen on

No response

Component

No response

Expected behaviour you didn't see

No response

Unexpected behaviour you saw

I'm not sure if it's a reaction to some recent changes or it has always been there, but in a couple of recent CentOS CI and Ubuntu CI runs I noticed a strange TEST-53-ISSUE-16347 fail:

[   45.497729] testsuite-53.sh[526]: + set -o pipefail
[   45.544567] testsuite-53.sh[526]: + :
[   45.567637] testsuite-53.sh[526]: + systemd-run --unit test-timer-1 --on-calendar '*:0/15:0' true
[  OK  ] Started test-timer-1.timer.
[   48.374532] testsuite-53.sh[534]: Running timer as unit: test-timer-1.timer
[   48.377937] testsuite-53.sh[534]: Will run service as unit: test-timer-1.service
[   48.419366] testsuite-53.sh[526]: + date -s '-3 days'
[   48.934787] testsuite-53.sh[539]: Tue Sep  6 13:44:57 UTC 2022
[   48.942360] testsuite-53.sh[526]: + systemd-run --unit test-timer-2 --on-calendar '*:0/15:0' true
[   50.018413] testsuite-53.sh[540]: Running timer as unit: test-timer-2.timer
[   50.020982] testsuite-53.sh[540]: Will run service as unit: test-timer-2.service
[   50.121015] testsuite-53.sh[543]: ++ systemctl show test-timer-1.timer -p NextElapseUSecRealtime --value
[   50.626071] testsuite-53.sh[526]: + next_elapsed_t1='Tue 2022-09-06 13:45:00 UTC'
[   50.658687] testsuite-53.sh[544]: ++ date -d 'Tue 2022-09-06 13:45:00 UTC' +%s
[   50.711750] testsuite-53.sh[526]: + next_elapsed_t1=1662471900
[   50.742621] testsuite-53.sh[545]: ++ date +%s
[   50.804856] testsuite-53.sh[526]: + now=1662471899
[   50.807462] testsuite-53.sh[526]: + time_delta_t1=1
[   50.830515] testsuite-53.sh[546]: ++ systemctl show test-timer-2.timer -p NextElapseUSecRealtime --value
[   52.125821] testsuite-53.sh[526]: + next_elapsed_t2=
[   52.144978] testsuite-53.sh[549]: ++ date -d '' +%s
[   52.255611] testsuite-53.sh[526]: + next_elapsed_t2=1662422400
[   52.318725] testsuite-53.sh[551]: ++ date +%s
[   52.442738] testsuite-53.sh[526]: + now=1662471901
[   52.444874] testsuite-53.sh[526]: + time_delta_t2=-49501
[   52.448488] testsuite-53.sh[526]: + (( 0 < time_delta_t1 && time_delta_t1 < 1200 ))
[   52.450767] testsuite-53.sh[526]: + (( 0 < time_delta_t2 && time_delta_t2 < 1200 ))
[   52.452585] testsuite-53.sh[526]: + echo 'Timer elapse outside of the expected 20 minute window.'
[   52.456826] testsuite-53.sh[526]: + echo '  next_elapsed_t2=1662422400'
[   52.458998] testsuite-53.sh[526]: + echo '  now=1662471901'
[   52.460800] testsuite-53.sh[526]: + echo '  time_delta_t2=-49501'
[   52.462672] testsuite-53.sh[526]: + echo ''
[   52.464435] testsuite-53.sh[526]: + test '!' -s /failed_t1
[   52.466472] testsuite-53.sh[526]: + test '!' -s /failed_t2

Notice the missing NextElapseUSecRealtime value for test-timer-2.timer:

[   50.830515] testsuite-53.sh[546]: ++ systemctl show test-timer-2.timer -p NextElapseUSecRealtime --value
[   52.125821] testsuite-53.sh[526]: + next_elapsed_t2=

Full journal: system.journal.tar.gz

The same thing, but from Ubuntu CI:

[   49.325835] testsuite-53.sh[298]: + set -o pipefail
[   49.363770] testsuite-53.sh[298]: + :
[   49.407415] testsuite-53.sh[298]: + systemd-run --unit test-timer-1 --on-calendar '*:0/15:0' true
[   51.134998] testsuite-53.sh[299]: Running timer as unit: test-timer-1.timer
[   51.230432] testsuite-53.sh[299]: Will run service as unit: test-timer-1.service
[   51.325999] testsuite-53.sh[298]: + date -s '-3 days'
[   53.870394] testsuite-53.sh[300]: Tue Sep  6 00:29:57 UTC 2022
[   53.980440] testsuite-53.sh[298]: + systemd-run --unit test-timer-2 --on-calendar '*:0/15:0' true
[   54.089164] testsuite-53.sh[301]: Running timer as unit: test-timer-2.timer
[   54.134518] testsuite-53.sh[301]: Will run service as unit: test-timer-2.service
[   54.235366] testsuite-53.sh[303]: ++ systemctl show test-timer-1.timer -p NextElapseUSecRealtime --value
[   54.738377] testsuite-53.sh[298]: + next_elapsed_t1='Tue 2022-09-06 00:30:00 UTC'
[   54.851704] testsuite-53.sh[304]: ++ date -d 'Tue 2022-09-06 00:30:00 UTC' +%s
[   55.331204] testsuite-53.sh[298]: + next_elapsed_t1=1662424200
[   55.448913] testsuite-53.sh[305]: ++ date +%s
[   55.714485] testsuite-53.sh[298]: + now=1662424201
[   55.798475] testsuite-53.sh[298]: + time_delta_t1=-1
[   55.876748] testsuite-53.sh[306]: ++ systemctl show test-timer-2.timer -p NextElapseUSecRealtime --value
[   58.201552] testsuite-53.sh[298]: + next_elapsed_t2=
[   58.286082] testsuite-53.sh[309]: ++ date -d '' +%s
[   58.623132] testsuite-53.sh[298]: + next_elapsed_t2=1662422400
[   58.746694] testsuite-53.sh[310]: ++ date +%s
[   59.215409] testsuite-53.sh[298]: + now=1662424204
[   59.297944] testsuite-53.sh[298]: + time_delta_t2=-1804
[   59.382275] testsuite-53.sh[298]: + (( 0 < time_delta_t1 && time_delta_t1 < 1200 ))
[   59.450166] testsuite-53.sh[298]: + echo 'Timer elapse outside of the expected 20 minute window.'
[   59.530057] testsuite-53.sh[298]: + echo '  next_elapsed_t1=1662424200'
[   59.581855] testsuite-53.sh[298]: + echo '  now=1662424204'
[   59.637856] testsuite-53.sh[298]: + echo '  time_delta_t1=-1'
[   59.683069] testsuite-53.sh[298]: + echo ''
[   59.713659] testsuite-53.sh[298]: + (( 0 < time_delta_t2 && time_delta_t2 < 1200 ))
[   59.758867] testsuite-53.sh[298]: + echo 'Timer elapse outside of the expected 20 minute window.'
[   59.807046] testsuite-53.sh[298]: + echo '  next_elapsed_t2=1662422400'
[   59.849727] testsuite-53.sh[298]: + echo '  now=1662424204'
[   59.889795] testsuite-53.sh[298]: + echo '  time_delta_t2=-1804'
[   59.926814] testsuite-53.sh[298]: + echo ''
[   59.958978] testsuite-53.sh[298]: + test '!' -s /failed_t1

Full journal: TEST-53-ISSUE-16347.journal.tar.gz

It seems to happen when the test runs just around the time when the 15 min timer elapses (13:44:57 in the first case, 00:29:57 in the second one).

Steps to reproduce the problem

No response

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

No response

[mrc0mmand]

Ah, #24131 might be related.

[yuwata]

#24131 was reverted. Closing.