Source: libsoup3
Version: 3.6.5-1
Severity: important
Tags: ftbfs help moreinfo
Control: block 1035983 by -1

In some builds of libsoup3, multithread-test fails with a timeout, for
example:

=================================== 11/100 ===================================
test: multithread-test
start time: 13:41:10
duration: 60.01s
result: killed by signal 15 SIGTERM
command: G_TEST_BUILDDIR=/home/smcv/libsoup3/obj-x86_64-linux-gnu/tests MESON_TEST_ITERATION=11 MALLOC_PERTURB_=108 UBSAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 G_TEST_SRCDIR=/home/smcv/libsoup3/tests MSAN_

OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1:print_stacktrace=1 ASAN_OPTIONS=halt_on_error=1:abort_on_error=1:print_summary=1 LD_LIBRARY_PATH=/home/smcv/libsoup3/obj-x86_64-linux-gnu/tests:/home/smcv/libsoup3/obj-x86_64-linux-gnu/libsoup G_
DEBUG=gc-friendly MALLOC_CHECK_=2 /home/smcv/libsoup3/obj-x86_64-linux-gnu/tests/multithread-test --debug

----------------------------------- stdout -----------------------------------
TAP version 14
# random seed: R02S555f942f5ba3fe3f2b70832b8be7b007
# GLib-GIO-DEBUG: _g_io_module_get_default: Found default implementation gnutls (GTlsBackendGnutls) for ‘gio-tls-backend’
# [3566088.441639] enter apache_init
# Apache command: '/sbin/apache2' '-d' '/home/smcv/libsoup3/obj-x86_64-linux-gnu/tests' '-f' 'httpd.conf' '-c' 'ErrorLog /home/smcv/libsoup3/obj-x86_64-linux-gnu/error.log' '-c' 'PidFile /home/smcv/libsoup3/obj-x86_64-linux-gnu/httpd.pid' '-k' 'start'
# -> success
# [3566088.459659] leave apache_init
1..21
# Start of multithread tests
# GLib-GIO-DEBUG: _g_io_module_get_default: Found default implementation dummy (GDummyProxyResolver) for ‘gio-proxy-resolver’
ok 1 /multithread/no-main-context
# Start of basic tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b6053f80 and GSocketClientAsyncConnectData 0x5603b6053f10
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b5c29360 for GSocketClientAsyncConnectData 0x5603b6053f10
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb078003630 and GSocketClientAsyncConnectData 0x7fb078003460
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb078003570 for GSocketClientAsyncConnectData 0x7fb078003460
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 2 /multithread/basic/async
ok 3 /multithread/basic/sync
# End of basic tests
# Start of basic-ssl tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb074002ee0 and GSocketClientAsyncConnectData 0x7fb07c004400
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb074001960 for GSocketClientAsyncConnectData 0x7fb07c004400
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb068002f10 and GSocketClientAsyncConnectData 0x7fb068005100
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb0680035e0 for GSocketClientAsyncConnectData 0x7fb068005100
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 4 /multithread/basic-ssl/async
ok 5 /multithread/basic-ssl/sync
# End of basic-ssl tests
# Start of basic-proxy tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b605faa0 and GSocketClientAsyncConnectData 0x5603b605f9f0
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b5c29360 for GSocketClientAsyncConnectData 0x5603b605f9f0
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb06801b320 and GSocketClientAsyncConnectData 0x7fb06800bf20
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb06800fac0 for GSocketClientAsyncConnectData 0x7fb06800bf20
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 6 /multithread/basic-proxy/async
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b60529d0 and GSocketClientAsyncConnectData 0x5603b5c23aa0
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b6436ac0 for GSocketClientAsyncConnectData 0x5603b5c23aa0
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 7 /multithread/basic-proxy/sync
# End of basic-proxy tests
# Start of basic-no-main-thread tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb07800acd0 and GSocketClientAsyncConnectData 0x7fb078003350
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb07800a030 for GSocketClientAsyncConnectData 0x7fb078003350
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb06c009310 and GSocketClientAsyncConnectData 0x7fb06c009fe0
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb06c0077b0 for GSocketClientAsyncConnectData 0x7fb06c009fe0
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 8 /multithread/basic-no-main-thread/async
ok 9 /multithread/basic-no-main-thread/sync
# End of basic-no-main-thread tests
# Start of basic-ssl-proxy tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b60511b0 and GSocketClientAsyncConnectData 0x5603b60510c0
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b6046d60 for GSocketClientAsyncConnectData 0x5603b60510c0
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb07800ab50 and GSocketClientAsyncConnectData 0x7fb0780035f0
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb078004720 for GSocketClientAsyncConnectData 0x7fb0780035f0
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 10 /multithread/basic-ssl-proxy/async
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b6435bb0 and GSocketClientAsyncConnectData 0x5603b6053320
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b6051150 for GSocketClientAsyncConnectData 0x5603b6053320
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
ok 11 /multithread/basic-ssl-proxy/sync
# End of basic-ssl-proxy tests
# Start of basic-http2 tests
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x5603b6052830 and GSocketClientAsyncConnectData 0x7fb06c003b80
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x5603b6047900 for GSocketClientAsyncConnectData 0x7fb06c003b80
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful!
# GLib-GIO-DEBUG: g_socket_client_connect_async: starting new g_socket_client_connect_async() with GTask 0x7fb064003850 and GSocketClientAsyncConnectData 0x7fb064003680
# GLib-GIO-DEBUG: GSocketClient: Starting new address enumeration
# GLib-GIO-DEBUG: GSocketClient: Address enumeration succeeded
# GLib-GIO-DEBUG: g_socket_client_enumerator_callback: starting connection attempt 0x7fb064003790 for GSocketClientAsyncConnectData 0x7fb064003680
# GLib-GIO-DEBUG: GSocketClient: Starting TCP connection attempt
# GLib-GIO-DEBUG: GSocketClient: TCP connection successful
# GLib-GIO-DEBUG: GSocketClient: Starting application layer connection
# GLib-GIO-DEBUG: GSocketClient: Connection successful! ==============================================================================

This is **not** the same as the failure mode that has been the most common
in the past, where tests that use Apache fail with "Address already in
use: AH00072: make_sock: could not bind to address 127.0.0.1:xxx".

The failure mode that I have reported as a separate bug, where
multithread-test fails quickly with evidence of memory corruption, is
also out-of-scope for this particular bug report - although it might
turn out that their root cause ends up being the same.

To get an idea of how frequent this is, I tried these steps on the amd64 porterbox, barriere:

1. build libsoup3 (from unstable):

schroot -c $chroot -r -- \
env DEB_BUILD_PROFILES=noudeb \
debuild -e CCACHE_DIR=$HOME/.ccache -e PATH=/usr/lib/ccache:$PATH -us -uc -B

2. run multithread-test repeatedly:

schroot -c $chroot -r -- \
env -C obj-x86_64-linux-gnu \
DEB_BUILD_PROFILES=noudeb CCACHE_DIR=$HOME/.ccache PATH=/usr/lib/ccache:$PATH \
DEB_PYTHON_INSTALL_LAYOUT=deb LC_ALL=C.UTF-8 \
meson test --repeat 100 -j1 multithread-test

(I tried this 3 times; optionally add --timeout-multiplier=6 to the
`meson test` command-line to emulate the original package build more
accurately)

3. read obj-x86_64-linux-gnu/meson-logs/testlog.txt for details of the
failures, if any

and my results were as follows:

- 7 successes, 1 timeout, 1 failure with memory corruption
- 19 successes, 1 timeout, 6 more successes, 1 more timeout, I cancelled
the run at this point
- 10 successes, 1 timeout, 15 more successes, 1 failure with
memory corruption

Anyone who wants libsoup3 tests to pass more often is invited to help to
debug and fix this. I cannot provide specific instructions for how to go
about this.

Annoyingly, it is not possible to run two or more copies of this test in parallel, so that cannot be used to get to a failure sooner (this is
because each run of this test uses the same fixed filenames and port
numbers).

I am a member of the GNOME team, but not an Uploader of this particular package. I am aware that some project members believe that, because I
have solved test issues it in the past, I should be held personally
responsible for every test failure that occurs in GNOME. As per the
Debian Social Contract §2.1.1, I decline that responsibility: I am not
able to fix everything all of the time, and I'm sorry if the project
considers my contributions to be inadequate.

smcv

--- SoupGate-Win32 v1.05
* Origin: fsxNet Usenet Gateway (21:1/5)