Integration test timeout on aarch64

[ggardet]

Integration test timeout on openSUSE Tumbleweed aarch64.
Error log:

[   26s] + /usr/bin/meson test -C aarch64-suse-linux --num-processes 8 --print-errorlogs
[   26s] ninja: Entering directory `/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux'
[   26s] ninja: no work to do.
[   26s] 1/4 unit-globpath OK              0.04s
[   26s] 2/4 unit-dynports OK              0.26s
[   32s] 3/4 unit-serial   OK              6.01s
[   86s] integration time out (After 60 seconds)
[   86s] 4/4 integration   TIMEOUT        60.12s   killed by signal 15 SIGTERM
[   86s] >>> MSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 PYTHONDONTWRITEBYTECODE=1 MESON_TEST_ITERATION=1 ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 LD_LIBRARY_PATH=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/ UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 /usr/bin/pytest -p no:cacheprovider --ip2unix-path=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/ip2unix --libip2unix-path=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/libip2unix.so --helper-accept-no-peer-addr=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/tests/helpers/helper_accept_no_peer_addr --systemd-support --systemd-sa-path=/usr/bin/systemd-socket-activate
[   86s] ――――――――――――――――――――――――――――――――――――― ✀  ―――――――――――――――――――――――――――――――――――――
[   86s] ============================= test session starts ==============================
[   86s] platform linux -- Python 3.13.2, pytest-8.3.4, pluggy-1.5.0
[   86s] rootdir: /home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/tests
[   86s] collected 105 items
[   86s] 
[   86s] test_abstract_socket.py s                                                [  0%]
[   86s] test_accept_no_peer_addr.py .                                            [  1%]
[   86s] test_addrinfo.py .                                                       [  2%]
[   86s] test_bind_any.py .                                                       [  3%]
[   86s] test_bind_samerule.py .                                                  [  4%]
[   86s] test_blackhole.py .                                                      [  5%]
[   86s] test_closeallfds.py F                                                    [  6%]
[   86s] test_connections.py s......
[   86s] ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
[   86s] 
[   86s] 
[   86s] Summary of Failures:
[   86s] 
[   86s] 4/4 integration   TIMEOUT        60.12s   killed by signal 15 SIGTERM
[   86s] 
[   86s] Ok:                 3   
[   86s] Expected Fail:      0   
[   86s] Fail:               0   
[   86s] Unexpected Pass:    0   
[   86s] Skipped:            0   
[   86s] Timeout:            1   
[   86s] 
[   86s] Full log written to /home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/meson-logs/testlog.txt

[aszlig]

@ggardet: Thanks for the report. Can you please provide an strace -f of the failing test?

[etam]

Here's what I used:

Index: ip2unix-2.2.1/tests/meson.build
===================================================================
--- ip2unix-2.2.1.orig/tests/meson.build
+++ ip2unix-2.2.1/tests/meson.build
@@ -1,9 +1,12 @@
+strace = find_program('strace')
 pytest_canidates = ['pytest-3', 'py.test-3', 'pytest', 'py.test']
 pytest = find_program(pytest_canidates, required: false)
 if pytest.found()
   subdir('helpers')
 
   pytest_args = [
+    '-f',
+    pytest.full_path(),
     '-p', 'no:cacheprovider',
     '--ip2unix-path=@0@'.format(ip2unix.full_path()),
     '--libip2unix-path=@0@'.format(libip2unix.full_path()),
@@ -34,7 +37,10 @@ if pytest.found()
               ' tests for socket activation.')
     endif
   endif
-  test('integration', pytest, args: pytest_args, timeout: timeout,
+
+  pytest_args += ['test_closeallfds.py']
+
+  test('integration', strace, args: pytest_args, timeout: timeout,
        workdir: meson.current_source_dir(),
        depends: [ip2unix, libip2unix, helper_accept_no_peer_addr],
        env: ['PYTHONDONTWRITEBYTECODE=1'])

I picked test_closeallfds.py, because that's the one failing. Although I don't know where the timeout comes from.

and here's what I've got: strace.zip

[ggardet]

@etam the timeout is from test_connections.py.
Tail of strace:

[   86s] integration time out (After 60 seconds)
[   86s] 4/4 integration   TIMEOUT        60.02s   killed by signal 15 SIGTERM
[   86s] >>> MSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 PYTHONDONTWRITEBYTECODE=1 MESON_TEST_ITERATION=1 ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 LD_LIBRARY_PATH=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/ UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 /usr/bin/strace -f /usr/bin/pytest -p no:cacheprovider --ip2unix-path=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/ip2unix --libip2unix-path=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/libip2unix.so --helper-accept-no-peer-addr=/home/abuild/rpmbuild/BUILD/ip2unix-2.2.1-build/ip2unix-2.2.1/aarch64-suse-linux/tests/helpers/helper_accept_no_peer_addr --systemd-support --systemd-sa-path=/usr/bin/systemd-socket-activate test_connections.py
[   86s] ――――――――――――――――――――――――――――――――――――― ✀  ―――――――――――――――――――――――――――――――――――――
[   86s] Listing only the last 100 lines from a long log.
[   86s] [pid 183003] connect(7, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183002] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183003] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137134, tv_nsec=679837201},  <unfinished ...>
[   86s] [pid 183002] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31851) = 63
[   86s] [pid 183002] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183000] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183002] connect(8, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110 <unfinished ...>
[   86s] [pid 183000] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 183002] <... connect resumed>)     = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183000] <... write resumed>)       = 63
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31788) = 63
[   86s] [pid 183002] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137134, tv_nsec=679903334},  <unfinished ...>
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183000] connect(6, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183000] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137134, tv_nsec=679941726},  <unfinished ...>
[   86s] [pid 182998] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 182998] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31725) = 63
[   86s] [pid 182998] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 182998] connect(5, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 182998] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137134, tv_nsec=680254168},  <unfinished ...>
[   86s] [pid 182639] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182639] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 182847] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182847] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 182779] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182779] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 182917] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182917] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 182814] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182814] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 182709] <... ppoll resumed>)       = 0 (Timeout)
[   86s] [pid 182709] ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=0, tv_nsec=500000000}, NULL, 0 <unfinished ...>
[   86s] [pid 183005] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183005] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31662) = 63
[   86s] [pid 183005] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183005] connect(4, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183005] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=178269914},  <unfinished ...>
[   86s] [pid 182997] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 182997] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31599) = 63
[   86s] [pid 182997] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 182997] connect(3, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 182997] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=178613896},  <unfinished ...>
[   86s] [pid 183003] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183003] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31536) = 63
[   86s] [pid 183003] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183003] connect(7, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110 <unfinished ...>
[   86s] [pid 183002] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183003] <... connect resumed>)     = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183002] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 183003] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=179975598},  <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31473) = 63
[   86s] [pid 183002] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183000] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 183002] connect(8, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183000] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 183002] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=180065780},  <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31410) = 63
[   86s] [pid 183000] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 183000] connect(6, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 183000] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=180138895},  <unfinished ...>
[   86s] [pid 182998] <... clock_nanosleep resumed>NULL) = 0
[   86s] [pid 182998] write(2, "Still waiting for connection to "..., 63 <unfinished ...>
[   86s] [pid 182635] <... read resumed>"Still waiting for connection to "..., 31347) = 63
[   86s] [pid 182998] <... write resumed>)       = 63
[   86s] [pid 182635] read(11,  <unfinished ...>
[   86s] [pid 182998] connect(5, {sa_family=AF_UNIX, sun_path="/tmp/tmp9fkjnp59/test.sock"}, 110) = -1 ECONNREFUSED (Connection refused)
[   86s] [pid 182998] clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, {tv_sec=137135, tv_nsec=180393614},  <unfinished ...>
[   86s] [pid 182996] <... futex resumed>)       = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[   86s] /usr/bin/strace: Process 182635 detached
[   86s] /usr/bin/strace: Process 182638 detached
[   86s] /usr/bin/strace: Process 182708 detached
[   86s] /usr/bin/strace: Process 182778 detached
[   86s] /usr/bin/strace: Process 182813 detached
[   86s] /usr/bin/strace: Process 182846 detached
[   86s] /usr/bin/strace: Process 182916 detached
[   86s] /usr/bin/strace: Process 182996 detached
[   86s] /usr/bin/strace: Process 183003 detached
[   86s] /usr/bin/strace: Process 183005 detached
[   86s] /usr/bin/strace: Process 183002 detached
[   86s] /usr/bin/strace: Process 183000 detached
[   86s] /usr/bin/strace: Process 182998 detached
[   86s] /usr/bin/strace: Process 182997 detached
[   86s] /usr/bin/strace: Process 182917 detached
[   86s] /usr/bin/strace: Process 182847 detached
[   86s] /usr/bin/strace: Process 182814 detached
[   86s] /usr/bin/strace: Process 182779 detached
[   86s] /usr/bin/strace: Process 182709 detached
[   86s] /usr/bin/strace: Process 182639 detached
[   86s] ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――