Bug#909416: gnome-keyring: sometimes FTBFS, mostly with single CPU: test-gkd-ssh-agent-service /ssh-agent/service/startup_shutdown hangs

[Simon McVittie]

Control: retitle -1 gnome-keyring: sometimes FTBFS, mostly with single CPU: test-gkd-ssh-agent-service /ssh-agent/service/startup_shutdown hangs
Control: tags -1 + confirmed

On Sun, 23 Sep 2018 at 10:35:50 +0000, Santiago Vila wrote:
> E: Build killed with signal TERM after 60 minutes of inactivity
...
> on a single-CPU machine using sbuild (as I do),
> where this failure seems to be particularly easy to trigger

I can reproduce this on a qemu VM with -smp 1, either in sbuild or
directly. With the tests hacked to kill themselves with SIGALRM after
5 minutes, the only failure was:

# ./build/tap-driver --test-name test-gkd-ssh-agent-service --log-file test-gkd-ssh-agent-service.log --trs-file test-gkd-ssh-agent-service.trs --color-tests no --enable-hard-errors yes --expect-failure no --format=tap -- ./build/tap-gtester ./test-gkd-ssh-agent-service
1..15
# random seed: R02S1be577b30b81118adec00b4fc3e13815
# Bail out! Test timed out (SIGALRM received)
not ok 1 /ssh-agent/service/startup_shutdown

Test-cases 2 to 15 out of 15 all succeed (I'm not sure how they managed
to do this after the first test-case called abort() but whatever).

This seems to be daemon/ssh-agent/test-gkd-ssh-agent-service.c, which
can be run in a built tree as:

    ./test-gtk-ssh-agent-service --tap

It passes when run under gdb, but blocks when run without gdb. (Race
condition?)

Tracebacks from a code dump (killing the test with SIGABRT) below.

Regards,
    smcv
    at the Cambridge BSP

Thread 3 (Thread 0x7feea17c2700 (LWP 21413)):
#0  0x00007feea27bdb69 in __GI___poll (fds=0x7fee9c008c20, nfds=1, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007feea2901136 in g_main_context_poll
    (priority=<optimized out>, n_fds=1, fds=0x7fee9c008c20, timeout=<optimized out>, context=0x7fee9c007da0)
    at ../../../glib/gmain.c:4221
#2  0x00007feea2901136 in g_main_context_iterate
    (context=context at entry=0x7fee9c007da0, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>)
    at ../../../glib/gmain.c:3915
#3  0x00007feea290125c in g_main_context_iteration (context=0x7fee9c007da0, may_block=may_block at entry=1)
    at ../../../glib/gmain.c:3981
#4  0x00007feea29012a1 in glib_worker_main (data=<optimized out>) at ../../../glib/gmain.c:5861
#5  0x00007feea2929425 in g_thread_proxy (data=0x559a58881a80) at ../../../glib/gthread.c:784
#6  0x00007feea2897fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007feea27c882f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 2 (Thread 0x7feea1fc3700 (LWP 21412)):
#0  0x00007feea27bdb69 in __GI___poll (fds=0x7fee9c005a70, nfds=2, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007feea2901136 in g_main_context_poll
    (priority=<optimized out>, n_fds=2, fds=0x7fee9c005a70, timeout=<optimized out>, context=0x7fee9c000b40)
    at ../../../glib/gmain.c:4221
#2  0x00007feea2901136 in g_main_context_iterate
    (context=0x7fee9c000b40, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>)
    at ../../../glib/gmain.c:3915
#3  0x00007feea29014c2 in g_main_loop_run (loop=0x7fee9c003600) at ../../../glib/gmain.c:4116
#4  0x0000559a57b2a9cc in server_thread (data=0x559a58877a00) at daemon/ssh-agent/test-gkd-ssh-agent-service.c:67
#5  0x00007feea2929425 in g_thread_proxy (data=0x559a58881000) at ../../../glib/gthread.c:784
#6  0x00007feea2897fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007feea27c882f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 1 (Thread 0x7feea1fc4a80 (LWP 21411)):
#0  0x00007feea2899495 in __GI___pthread_timedjoin_ex
    (threadid=140662896604928, thread_return=thread_return at entry=0x0, abstime=abstime at entry=0x0, block=block at entry=true) at pthread_join_common.c:89
#1  0x00007feea289926c in __pthread_join (threadid=<optimized out>, thread_return=thread_return at entry=0x0)
    at pthread_join.c:24
#2  0x00007feea294aec7 in g_system_thread_wait (thread=0x559a58881000) at ../../../glib/gthread-posix.c:1219
#3  0x00007feea292986a in g_thread_join (thread=0x559a58881000) at ../../../glib/gthread.c:952
#4  0x0000559a57b2a766 in teardown (test=0x559a58877a00, unused=<optimized out>)
    at daemon/ssh-agent/test-gkd-ssh-agent-service.c:155
#5  0x00007feea29281cb in test_case_run (tc=0x559a58876800) at ../../../glib/gtestutils.c:2328
#6  0x00007feea29281cb in g_test_run_suite_internal (suite=suite at entry=0x559a58875660, path=path at entry=0x0)
    at ../../../glib/gtestutils.c:2403
#7  0x00007feea2928024 in g_test_run_suite_internal (suite=suite at entry=0x559a58875640, path=path at entry=0x0)
    at ../../../glib/gtestutils.c:2415
#8  0x00007feea2928024 in g_test_run_suite_internal (suite=suite at entry=0x559a58875620, path=path at entry=0x0)
    at ../../../glib/gtestutils.c:2415
#9  0x00007feea2928422 in g_test_run_suite (suite=0x559a58875620) at ../../../glib/gtestutils.c:2490
#10 0x00007feea2928441 in g_test_run () at ../../../glib/gtestutils.c:1755
#11 0x0000559a57b2a48a in main (argc=<optimized out>, argv=<optimized out>)
    at daemon/ssh-agent/test-gkd-ssh-agent-service.c:616