timer_test unit test intermittently fails in CI
timer_test fails on assert_true(diff == timer_expect) in timer_test.c:420 in job#3614206.
Currently, the failure seems to only affect v9.19. I haven't managed to reproduce it locally.
I examined the nightly pipelines since 2023-06-01 and the first appearance of this failure was on 2023-07-22.
- 2023-07-22
unit:gcc:tarballhttps://gitlab.isc.org/isc-projects/bind9/-/jobs/3538559 - 2023-08-02
unit:clang:asanhttps://gitlab.isc.org/isc-projects/bind9/-/jobs/3556852 - 2023-08-06
unit:gcc:asanhttps://gitlab.isc.org/isc-projects/bind9/-/jobs/3567115 - 2023-08-15
unit:gcc:out-of-treehttps://gitlab.isc.org/isc-projects/bind9/-/jobs/3584050 - 2023-08-27
unit:gcc:tarballhttps://gitlab.isc.org/isc-projects/bind9/-/jobs/3613353
timer_test.log
[==========] Running 9 test(s).
[ RUN ] ticker
[ OK ] ticker
[ RUN ] once_idle
[ OK ] once_idle
[ RUN ] reset
[ OK ] reset
[ RUN ] purge
[ OK ] purge
[ RUN ] reschedule_up
diff == timer_expect
[ LINE ] --- timer_test.c:420: error: Failure!I:timer_test:Core dump found: ./core.17684
D:timer_test:backtrace from ./core.17684 start
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
warning: Can't open file anon_inode:[io_uring] which was expanded to anon_inode:[io_uring] during file-backed mapping note processing
[New LWP 17684]
[New LWP 19267]
[New LWP 19268]
[New LWP 19269]
[New LWP 19270]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/builds/isc-projects/bind9/tests/isc/.libs/timer_test'.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
44 ./nptl/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f2bd94b2b00 (LWP 17684))]
Thread 5 (LWP 19270):
#0 0x0000000000000000 in ?? ()
No symbol table info available.
Backtrace stopped: Cannot access memory at address 0x0
Thread 4 (LWP 19269):
#0 0x0000000000000000 in ?? ()
No symbol table info available.
Backtrace stopped: Cannot access memory at address 0x0
Thread 3 (LWP 19268):
#0 0x0000000000000000 in ?? ()
No symbol table info available.
Backtrace stopped: Cannot access memory at address 0x0
Thread 2 (LWP 19267):
#0 0x0000000000000000 in ?? ()
No symbol table info available.
Backtrace stopped: Cannot access memory at address 0x0
Thread 1 (Thread 0x7f2bd94b2b00 (LWP 17684)):
#0 __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
tid = <optimized out>
ret = 0
pd = <optimized out>
old_mask = {__val = {0}}
ret = <optimized out>
#1 0x00007f2bdbeb5d9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
No locals.
#2 0x00007f2bdbe66f32 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
ret = <optimized out>
#3 0x00007f2bdbe51472 in __GI_abort () at ./stdlib/abort.c:79
save_stage = 1
act = {__sigaction_handler = {sa_handler = 0x20, sa_sigaction = 0x20}, sa_mask = {__val = {94122061756704, 139826305905888, 4294934528, 139826351299680, 117, 139826351299680, 115, 0, 0, 0, 0, 0, 139826349646050, 0, 139826349646050, 0}}, sa_flags = 2137661845, sa_restorer = 0x1a4}
#4 0x00007f2bdc10cf45 in ?? () from /lib/x86_64-linux-gnu/libcmocka.so.0
No symbol table info available.
#5 0x00007f2bdc10cfda in _fail () from /lib/x86_64-linux-gnu/libcmocka.so.0
No symbol table info available.
#6 0x0000559a7f6a0b3a in teardown_loop_timer_expect (arg=0x559a800da670) at timer_test.c:420
diff = <optimized out>
#7 run_test_reschedule_up (state=0x559a800da670) at timer_test.c:441
setup_loop = <optimized out>
teardown_loop = <optimized out>
#8 0x00007f2bdc10f8f8 in ?? () from /lib/x86_64-linux-gnu/libcmocka.so.0
No symbol table info available.
#9 0x00007f2bdc10ffdb in _cmocka_run_group_tests () from /lib/x86_64-linux-gnu/libcmocka.so.0
No symbol table info available.
#10 0x0000559a7f6a11d0 in main () at timer_test.c:538
r = <optimized out>
D:timer_test:backtrace from ./core.17684 end
FAIL timer_test (exit status: 134)