ip2unix
ip2unix copied to clipboard
nixcloud
Integration test timeout on aarch64
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
@ggardet: Thanks for the report. Can you please provide an strace -f of the failing test?
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
@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] ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
I picked test_closeallfds.py, because that's the one failing. Although I don't know where the timeout comes from.
Thanks for the strace. Here is the bit that most likely caused the timeout:
[ 57s] [pid 1788] write(2, "terminate called after throwing "..., 48) = 48
[ 57s] [pid 1788] write(2, "std::bad_array_new_length", 25) = 25
[ 57s] [pid 1788] write(2, "'\n", 2) = 2
[ 57s] [pid 1788] write(2, " what(): ", 11) = 11
[ 57s] [pid 1788] write(2, "std::bad_array_new_length", 25) = 25
[ 57s] [pid 1788] write(2, "\n", 1) = 1
Does coredumpctl (if you have it enabled) list anything about the above?