/connection/client-auth-pkcs11 times out on ubuntu/s390x
I've uploaded 2.68.1 to Ubuntu now, and it fails on s390x with a timeout in the tests. This is with Glib 2.68.3.
Running interactively with G_MESSAGES_DEBUG=all
shows:
MockPKCS11-INFO: 11:30:23.523: Ignoring search template for 258
MockPKCS11-INFO: 11:30:23.523: Ignoring search template for 128
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.523: CLIENT[0x2aa37a6e1d0]: starting to read data from TLS connection
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.523: CLIENT[0x2aa37a6e1d0]: claiming operation OP_READ
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.523: CLIENT[0x2aa37a6e1d0]: Implcit TLS handshaking starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.523: CLIENT[0x2aa37a6e1d0]: claim_op failed: implicit handshake required
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.533: CLIENT[0x2aa37a6e1d0]: Asynchronous TLS handshake thread starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.533: CLIENT[0x2aa37a6e1d0]: TLS handshake thread starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.533: CLIENT[0x2aa37a6e1d0]: claiming operation OP_HANDSHAKE
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.533: CLIENT[0x2aa37a6e1d0]: claiming operation OP_HANDSHAKE succeeded
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: starting to write 24 bytes to TLS connection
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: claiming operation OP_WRITE
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: Implcit TLS handshaking starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: claim_op failed: implicit handshake required
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: Asynchronous TLS handshake thread starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: TLS handshake thread starts
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: claiming operation OP_HANDSHAKE
(/home/ubuntu/glib-networking/build/tls/tests/connection-gnutls:18263): GLib-Net-DEBUG: 11:30:23.536: SERVER[0x2aa37e5e230]: claiming operation OP_HANDSHAKE succeeded
connection-gnutls time out (After 30 seconds)
1/1 connection-gnutls TIMEOUT 30.01s
Here's a backtrace while the hang is happening:
(gdb) t a a bt
Thread 5 (Thread 0x3fffaffc870 (LWP 9627) "pool-/home/ubun"):
#0 0x000003fffd7156a2 in __GI___poll (fds=fds@entry=0x3fffaffa4f0, nfds=1, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x000003fffdafbb06 in poll (__timeout=<optimized out>, __timeout@entry=-1, __nfds=<optimized out>, __fds=__fds@entry=0x3fffaffa4f0) at /usr/include/s390x-linux-gnu/bits/poll2.h:47
#2 0x000003fffdd3378a in g_socket_condition_timed_wait (error=<optimized out>, cancellable=<optimized out>, timeout_us=-1, condition=<optimized out>, socket=0x3fffaffa4f0) at ../../../gio/gsocket.c:4459
#3 g_socket_condition_timed_wait (socket=0x3fffaffa4f0, socket@entry=0x2aa00065130, condition=condition@entry=G_IO_IN, timeout_us=timeout_us@entry=-1, cancellable=<optimized out>, cancellable@entry=0x0, error=<optimized out>, error@entry=0x2aa0007f558) at ../../../gio/gsocket.c:4320
#4 0x000003fffdd33e50 in block_on_timeout (error=0x2aa0007f558, cancellable=0x0, start_time=<optimized out>, timeout_us=-1, condition=G_IO_IN, socket=0x2aa00065130) at ../../../gio/gsocket.c:3197
#5 g_socket_receive_with_timeout (error=0x2aa0007f558, cancellable=0x0, timeout_us=<optimized out>, size=5, buffer=0x3ffe40188e3 '1' <repeats 200 times>..., socket=0x2aa00065130) at ../../../gio/gsocket.c:3245
#6 g_socket_receive_with_blocking (socket=0x2aa00065130, buffer=0x3ffe40188e3 '1' <repeats 200 times>..., size=5, blocking=<optimized out>, cancellable=0x0, error=0x2aa0007f558) at ../../../gio/gsocket.c:3344
#7 0x000003fffdd40524 in g_socket_input_stream_read (stream=0x2aa003f2ed0, buffer=0x3ffe40188e3, count=5, cancellable=0x0, error=0x2aa0007f558) at ../../../gio/gsocketinputstream.c:126
#8 0x000003fffdcfc0f4 in g_input_stream_read (stream=0x2aa003f2ed0, buffer=0x3ffe40188e3, count=5, cancellable=0x0, error=0x2aa0007f558) at ../../../gio/ginputstream.c:198
#9 0x000003fffdd20986 in g_pollable_stream_read (stream=<optimized out>, buffer=<optimized out>, count=<optimized out>, blocking=<optimized out>, cancellable=0x0, error=0x2aa0007f558) at ../../../gio/gpollableutils.c:204
#10 0x000003fffc89067c in g_tls_connection_gnutls_pull_func (transport_data=0x2aa0007f5e0, buf=0x3ffe40188e3, buflen=5) at ../tls/gnutls/gtlsconnection-gnutls.c:555
#11 0x000003fffd978de6 in _gnutls_stream_read (ms=0x3fffaffac0c, pull_func=<optimized out>, size=5, bufel=<synthetic pointer>, session=0x2aa0040cd50) at ../../lib/buffers.c:346
#12 _gnutls_read (ms=0x3fffaffac0c, pull_func=<optimized out>, size=5, bufel=<synthetic pointer>, session=0x2aa0040cd50) at ../../lib/buffers.c:426
#13 _gnutls_io_read_buffered.constprop.0 (session=session@entry=0x2aa0040cd50, total=5, ms=ms@entry=0x3fffaffac0c, recv_type=<optimized out>) at ../../lib/buffers.c:582
#14 0x000003fffd833338 in recv_headers (session=session@entry=0x2aa0040cd50, record_params=record_params@entry=0x3ffe400b5f0, type=type@entry=GNUTLS_HANDSHAKE, htype=<error reading variable: value has been optimized out>, record=record@entry=0x3fffaffac20, ms=0x3fffaffac0c) at ../../lib/record.c:1174
#15 0x000003fffd83736c in _gnutls_recv_in_buffers (session=0x2aa0040cd50, type=<optimized out>, htype=<optimized out>, ms=<optimized out>) at ../../lib/record.c:1308
#16 0x000003fffd84742c in _gnutls_handshake_io_recv_int (optional=0, hsk=0x3fffaffae30, htype=GNUTLS_HANDSHAKE_CERTIFICATE_PKT, session=0x2aa0040cd50) at ../../lib/buffers.c:1463
#17 _gnutls_handshake_io_recv_int (optional=0, hsk=0x3fffaffae30, htype=GNUTLS_HANDSHAKE_CERTIFICATE_PKT, session=0x2aa0040cd50) at ../../lib/buffers.c:1415
#18 _gnutls_recv_handshake (session=0x2aa0040cd50, type=<optimized out>, optional=<optimized out>, buf=0x3fffaffb090) at ../../lib/handshake.c:1577
#19 0x000003fffd89ac68 in _gnutls13_recv_certificate (session=0x2aa0040cd50) at ../../lib/tls13/certificate.c:54
#20 0x000003fffd83e8d0 in _gnutls13_handshake_server (session=0x2aa0040cd50) at ../../lib/handshake-tls13.c:513
#21 0x000003fffd84ecea in gnutls_handshake (session=0x2aa0040cd50) at ../../lib/handshake.c:2858
#22 0x000003fffc89150a in g_tls_connection_gnutls_handshake_thread_handshake (tls=0x2aa0007f5e0, timeout=-1, cancellable=0x0, error=0x3fffaffb958) at ../tls/gnutls/gtlsconnection-gnutls.c:885
#23 0x000003fffc89b0e4 in handshake_thread (task=0x2aa000660e0, object=0x2aa0007f5e0, task_data=0x2aa00415950, cancellable=0x0) at ../tls/base/gtlsconnection-base.c:1521
#24 0x000003fffc89bfb2 in async_handshake_thread (task=0x2aa000660e0, object=0x2aa0007f5e0, task_data=0x2aa00415950, cancellable=0x0) at ../tls/base/gtlsconnection-base.c:1793
#25 0x000003fffdd488fc in g_task_thread_pool_thread (thread_data=0x2aa000660e0, pool_data=<optimized out>) at ../../../gio/gtask.c:1430
#26 0x000003fffdb2bdcc in g_thread_pool_thread_proxy (data=<optimized out>) at ../../../glib/gthreadpool.c:354
#27 0x000003fffdb273e0 in g_thread_proxy (data=0x2aa0001e2a0) at ../../../glib/gthread.c:826
#28 0x000003fffd0892f6 in start_thread (arg=0x3fffaffc870) at pthread_create.c:481
#29 0x000003fffd721bc6 in thread_start () at ../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 4 (Thread 0x3fffb7fd870 (LWP 9626) "pool-/home/ubun"):
#0 syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1 0x000003fffdb585b8 in g_cond_wait_until (end_time=<optimized out>, mutex=0x2aa0005f900, cond=0x2aa0005f908) at ../../../glib/gthread-posix.c:1622
#2 g_cond_wait_until (cond=0x2aa0005f908, mutex=0x2aa0005f900, end_time=<optimized out>) at ../../../glib/gthread-posix.c:1595
#3 0x000003fffdaa5e3e in g_async_queue_pop_intern_unlocked (end_time=<optimized out>, wait=1, queue=0x2aa0005f900) at ../../../glib/gasyncqueue.c:422
#4 g_async_queue_timeout_pop (queue=0x2aa0005f900, timeout=<optimized out>) at ../../../glib/gasyncqueue.c:545
#5 0x000003fffdb2be8a in g_thread_pool_wait_for_new_pool () at ../../../glib/gthreadpool.c:183
#6 g_thread_pool_thread_proxy (data=<optimized out>) at ../../../glib/gthreadpool.c:411
#7 0x000003fffdb273e0 in g_thread_proxy (data=0x2aa00073520) at ../../../glib/gthread.c:826
#8 0x000003fffd0892f6 in start_thread (arg=0x3fffb7fd870) at pthread_create.c:481
#9 0x000003fffd721bc6 in thread_start () at ../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 3 (Thread 0x3fffbffe870 (LWP 9625) "pool-/home/ubun"):
#0 syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1 0x000003fffdb57212 in g_mutex_unlock_slowpath (mutex=<optimized out>, prev=<optimized out>) at ../../../glib/gthread-posix.c:1508
#2 0x000003fffdae7cd4 in g_source_attach (source=source@entry=0x3ffec00bfa0, context=context@entry=0x2aa00057b20) at ../../../glib/gmain.c:1296
#3 0x000003fffdae94e4 in g_main_context_invoke_full (context=0x2aa00057b20, priority=<optimized out>, function=0x3fffdd50710 <on_invoke_ask_password_sync>, data=0x3ffec001470, notify=0x0) at ../../../glib/gmain.c:6078
#4 0x000003fffdae9582 in g_main_context_invoke (context=<optimized out>, function=function@entry=0x3fffdd50710 <on_invoke_ask_password_sync>, data=data@entry=0x3ffec001470) at ../../../glib/gmain.c:6009
#5 0x000003fffdd55b48 in g_tls_interaction_invoke_ask_password (interaction=0x2aa00067810, password=<optimized out>, cancellable=<optimized out>, error=0x3fffbffbe60) at ../../../gio/gtlsinteraction.c:389
#6 0x000003fffc88f800 in on_pin_request (userdata=0x2aa00074440, attempt=1326734, token_url=0x3ffec002f70 "pkcs11:model=mock;manufacturer=GLib-Networking;serial=1;token=Mock%20Certificate", token_label=0x3ffec007670 "Mock Certificate", callback_flags=41, pin=0x3fffbffbf70 "ABC123\206", <incomplete sequence \320>, pin_max=256) at ../tls/gnutls/gtlsconnection-gnutls.c:262
#7 0x000003fffd8a4352 in retrieve_pin_from_callback (pin_info=pin_info@entry=0x3ffec003e18, token_info=token_info@entry=0x3fffbffc218, attempts=attempts@entry=1326734, user_type=user_type@entry=1, pin=<optimized out>, pin@entry=0x3fffbffc1f0) at ../../lib/pkcs11.c:2813
#8 0x000003fffd8a463a in pkcs11_retrieve_pin (pin_info=pin_info@entry=0x3ffec003e18, info=<error reading variable: value has been optimized out>, token_info=token_info@entry=0x3fffbffc218, attempts=attempts@entry=1326734, user_type=user_type@entry=1, pin=0x3fffbffc1f0) at ../../lib/pkcs11.c:2873
#9 0x000003fffd8a5764 in pkcs11_login (sinfo=0x3ffec003ca0, pin_info=0x3ffec003e18, info=<optimized out>, flags=<optimized out>) at ../../lib/pkcs11.c:2982
#10 0x000003fffd8a5e52 in pkcs11_login (flags=0, info=0x3ffec003a20, pin_info=0x3ffec003e18, sinfo=0x3ffec003ca0) at ../../lib/pkcs11.c:2900
#11 pkcs11_open_session (sinfo=0x3ffec003ca0, pin_info=0x3ffec003e18, info=0x3ffec003a20, flags=<optimized out>) at ../../lib/pkcs11.c:1537
#12 0x000003fffd8b1868 in find_object (flags=2, info=0x3ffec003a20, _ctx=0x3ffec003e00, pin_info=0x3ffec003e18, sinfo=0x3ffec003ca0) at ../../lib/pkcs11_privkey.c:186
#13 gnutls_pkcs11_privkey_import_url (pkey=0x3ffec003c80, url=0x2aa003d4200 "pkcs11:model=mock;manufacturer=GLib-Networking;serial=1;token=Mock%20Certificate;id=%4D%6F%63%6B%20%50%72%69%76%61%74%65%20%4B%65%79;object=Mock%20Private%20Key;type=private", flags=<optimized out>) at ../../lib/pkcs11_privkey.c:561
#14 0x000003fffd88296e in _gnutls_privkey_import_pkcs11_url (flags=0, url=0x2aa003d4200 "pkcs11:model=mock;manufacturer=GLib-Networking;serial=1;token=Mock%20Certificate;id=%4D%6F%63%6B%20%50%72%69%76%61%74%65%20%4B%65%79;object=Mock%20Private%20Key;type=private", key=0x3ffec00b4f0) at ../../lib/privkey.c:559
#15 gnutls_privkey_import_url (key=0x3ffec00b4f0, url=0x2aa003d4200 "pkcs11:model=mock;manufacturer=GLib-Networking;serial=1;token=Mock%20Certificate;id=%4D%6F%63%6B%20%50%72%69%76%61%74%65%20%4B%65%79;object=Mock%20Private%20Key;type=private", flags=<optimized out>) at ../../lib/privkey.c:1735
#16 0x000003fffc88bc9a in g_tls_certificate_gnutls_copy (gnutls=0x2aa000761e0, interaction_id=0x2aa003805b0 "gtls:36", pcert=0x3fffbffce68, pcert_length=0x3fffbffce58, pkey=0x3fffbffcb80) at ../tls/gnutls/gtlscertificate-gnutls.c:528
#17 0x000003fffc88fab6 in g_tls_connection_gnutls_handshake_thread_get_certificate (gnutls=0x2aa00074440, pcert=0x3fffbffce68, pcert_length=0x3fffbffce58, pkey=0x3fffbffce60) at ../tls/gnutls/gtlsconnection-gnutls.c:314
#18 0x000003fffc88e1a0 in g_tls_client_connection_gnutls_handshake_thread_retrieve_function (session=0x2aa003bf240, req_ca_rdn=0x0, nreqs=0, pk_algos=0x3fffbffd014, pk_algos_length=5, pcert=0x3fffbffce68, pcert_length=0x3fffbffce58, pkey=0x3fffbffce60) at ../tls/gnutls/gtlsclientconnection-gnutls.c:419
#19 0x000003fffd866dba in call_legacy_cert_cb2 (session=<optimized out>, info=<optimized out>, certs=<optimized out>, pcert_length=<optimized out>, ocsp=<optimized out>, ocsp_length=0x3fffbffce54, privkey=0x3fffbffce60, flags=0x3fffbffce5c) at ../../lib/cert-cred.c:738
#20 0x000003fffd94a310 in call_get_cert_callback (pk_algos_length=5, pk_algos=<optimized out>, issuers_dn_length=<optimized out>, issuers_dn=<optimized out>, session=0x2aa003bf240) at auth/../../../lib/auth/cert.c:446
#21 _gnutls_select_client_cert (session=0x2aa003bf240, _data=<optimized out>, _data_size=<optimized out>, pk_algos=<optimized out>, pk_algos_length=<optimized out>) at auth/../../../lib/auth/cert.c:538
#22 0x000003fffd89a72c in _gnutls13_recv_certificate_request_int (session=0x2aa003bf240, buf=<optimized out>) at ../../lib/tls13/certificate_request.c:186
#23 0x000003fffd83db78 in _gnutls13_recv_certificate_request (session=0x2aa003bf240) at ../../lib/tls13/certificate_request.c:234
#24 _gnutls13_handshake_client (session=0x2aa003bf240) at ../../lib/handshake-tls13.c:117
#25 0x000003fffd84ed98 in handshake_client (session=0x2aa003bf240) at ../../lib/handshake.c:3012
#26 gnutls_handshake (session=0x2aa003bf240) at ../../lib/handshake.c:2855
#27 0x000003fffc89150a in g_tls_connection_gnutls_handshake_thread_handshake (tls=0x2aa00074440, timeout=-1, cancellable=0x0, error=0x3fffbffd958) at ../tls/gnutls/gtlsconnection-gnutls.c:885
#28 0x000003fffc89b0e4 in handshake_thread (task=0x2aa0008ea50, object=0x2aa00074440, task_data=0x2aa00375fe0, cancellable=0x0) at ../tls/base/gtlsconnection-base.c:1521
#29 0x000003fffc89bfb2 in async_handshake_thread (task=0x2aa0008ea50, object=0x2aa00074440, task_data=0x2aa00375fe0, cancellable=0x0) at ../tls/base/gtlsconnection-base.c:1793
#30 0x000003fffdd488fc in g_task_thread_pool_thread (thread_data=0x2aa0008ea50, pool_data=<optimized out>) at ../../../gio/gtask.c:1430
#31 0x000003fffdb2bdcc in g_thread_pool_thread_proxy (data=<optimized out>) at ../../../glib/gthreadpool.c:354
#32 0x000003fffdb273e0 in g_thread_proxy (data=0x2aa0001e300) at ../../../glib/gthread.c:826
#33 0x000003fffd0892f6 in start_thread (arg=0x3fffbffe870) at pthread_create.c:481
#34 0x000003fffd721bc6 in thread_start () at ../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 2 (Thread 0x3fffc7ff870 (LWP 9624) "gmain"):
#0 0x000003fffd7156a2 in __GI___poll (fds=0x2aa00037740, nfds=1, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x000003fffdaea2f0 in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x2aa00037740, timeout=<optimized out>, context=0x2aa00064c70) at ../../../glib/gmain.c:4434
#2 g_main_context_iterate (self=<optimized out>, dispatch=1, block=1, context=0x2aa00064c70) at ../../../glib/gmain.c:4126
#3 g_main_context_iteration (context=0x2aa00064c70, may_block=may_block@entry=1) at ../../../glib/gmain.c:4196
#4 0x000003fffdaea41c in glib_worker_main (data=<optimized out>) at ../../../glib/gmain.c:6089
#5 0x000003fffdb273e0 in g_thread_proxy (data=0x2aa0001e120) at ../../../glib/gthread.c:826
#6 0x000003fffd0892f6 in start_thread (arg=0x3fffc7ff870) at pthread_create.c:481
#7 0x000003fffd721bc6 in thread_start () at ../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
Thread 1 (Thread 0x3fffdff0f00 (LWP 9621) "connection-gnut"):
#0 syscall () at ../sysdeps/unix/sysv/linux/s390/s390-64/syscall.S:37
#1 0x000003fffdb57c62 in g_cond_signal (cond=cond@entry=0x3ffec0014b8) at ../../../glib/gthread-posix.c:1583
#2 0x000003fffdd5077a in on_invoke_ask_password_sync (user_data=0x3ffec001470) at ../../../gio/gtlsinteraction.c:285
#3 0x000003fffdae9b16 in g_main_dispatch (context=0x2aa00057b20) at ../../../glib/gmain.c:3337
#4 g_main_context_dispatch (context=0x2aa00057b20) at ../../../glib/gmain.c:4055
#5 0x000003fffdaeaaa0 in g_main_context_iterate (self=<optimized out>, dispatch=1, block=1, context=0x2aa00057b20) at ../../../glib/gmain.c:4131
#6 g_main_loop_run (loop=<optimized out>) at ../../../glib/gmain.c:4329
#7 0x000002aa00009d90 in test_client_auth_pkcs11_connection (test=0x2aa00395a00, data=0x0) at ../tls/tests/connection.c:1134
#8 0x000003fffdb262b6 in test_case_run (tc=0x2aa00051610) at ../../../glib/gtestutils.c:2777
#9 g_test_run_suite_internal (suite=suite@entry=0x2aa00046120, path=path@entry=0x0) at ../../../glib/gtestutils.c:2865
#10 0x000003fffdb25f9a in g_test_run_suite_internal (suite=suite@entry=0x2aa00045420, path=path@entry=0x0) at ../../../glib/gtestutils.c:2882
#11 0x000003fffdb25f9a in g_test_run_suite_internal (suite=suite@entry=0x2aa00045400, path=path@entry=0x0) at ../../../glib/gtestutils.c:2882
#12 0x000003fffdb25f9a in g_test_run_suite_internal (suite=suite@entry=0x2aa00045440, path=path@entry=0x0) at ../../../glib/gtestutils.c:2882
#13 0x000003fffdb26890 in g_test_run_suite (suite=0x2aa00045440) at ../../../glib/gtestutils.c:2959
#14 0x000003fffdb268e8 in g_test_run () at ../../../glib/gtestutils.c:2170
#15 0x000002aa000141bc in main (argc=1, argv=0x3fffffff298) at ../tls/tests/connection.c:3047
Any ideas?