Skip to content

Integration test timeout on aarch64 #37

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
Open
ggardet opened this issue Mar 18, 2025 · 3 comments
Open

Integration test timeout on aarch64 #37

ggardet opened this issue Mar 18, 2025 · 3 comments

Comments

@ggardet
Copy link

ggardet commented Mar 18, 2025

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
Copy link
Contributor

aszlig commented Apr 15, 2025

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

@etam
Copy link
Contributor

etam commented Apr 15, 2025

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
Copy link
Author

ggardet commented Apr 16, 2025

@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] ――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@aszlig @etam @ggardet