Got the bug again. The log is silent again, after the HTTP timeout messages. sysprof says that all the time is spent in httpGets, but I don't get meaningful stack traces (because Ubuntu builds with -fomit-frame-pointer probably). perf top shows the same.
Attaching with gdb shows me this for the main thread:
#0 __futex_abstimed_wait_common
(cancel=false, private=<optimized out>, abstime=0x0, clockid=0, expected=3, futex_word=0x557767016e6c <lock+12>)
at ./nptl/futex-internal.c:103
#1 __GI___futex_abstimed_wait64
(futex_word=futex_word@entry=0x557767016e6c <lock+12>, expected=expected@entry=3, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:128
#2 0x00007f1235a9566c in __pthread_rwlock_wrlock_full64 (abstime=0x0, clockid=0, rwlock=0x557767016e60 <lock>)
at ./nptl/pthread_rwlock_common.c:730
#3 ___pthread_rwlock_wrlock (rwlock=rwlock@entry=0x557767016e60 <lock>) at ./nptl/pthread_rwlock_wrlock.c:26
#4 0x0000557766ff4a54 in get_local_printers () at daemon/cups-browsed.c:4021
#5 0x0000557766fffab5 in update_local_printers.part.0.lto_priv.0 () at daemon/cups-browsed.c:4383
#6 0x0000557766ff886d in update_local_printers () at daemon/cups-browsed.c:7103
#7 on_printer_deleted
(object=<optimized out>, text=<optimized out>, printer_uri=<optimized out>, printer_state=<optimized out>, printer_state_reasons=<optimized out>, printer_is_accepting_jobs=<optimized out>, user_data=<optimized out>, printer=0x55776866ac00 "HP_Color_LaserJet_MFP_M477fdw_fridge") at daemon/cups-browsed.c:7111
#8 on_printer_deleted
(object=<optimized out>, text=0x5577686e7260 "Printer \"HP_Color_LaserJet_MFP_M477fdw_fridge\" deleted by \"cups-browsed\".", printer_uri=<optimized out>, printer=0x55776866ac00 "HP_Color_LaserJet_MFP_M477fdw_fridge", printer_state=<optimized out>, printer_state_reasons=<optimized out>, printer_is_accepting_jobs=1, user_data=0x0) at daemon/cups-browsed.c:7082
#9 0x00007f1235c158b6 in ffi_call_unix64 () at ../src/x86/unix64.S:104
#10 0x00007f1235c1234d in ffi_call_int
(cif=cif@entry=0x7fffc989bd00, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>, closure=closure@entry=0x0) at ../src/x86/ffi64.c:673
#11 0x00007f1235c14f33 in ffi_call
(cif=cif@entry=0x7fffc989bd00, fn=fn@entry=0x557766ff8750 <on_printer_deleted>, rvalue=rvalue@entry=0x7fffc989bc80, avalue=avalue@entry=0x7fffc989bbe0) at ../src/x86/ffi64.c:710
#12 0x00007f1235f87163 in g_cclosure_marshal_generic
(closure=<optimized out>, return_gvalue=<optimized out>, n_param_values=<optimized out>, param_values=<optimized out>, invocation_hint=<optimized out>, marshal_data=<optimized out>) at ../../../gobject/gclosure.c:1536
#13 0x00007f1235f81010 in g_closure_invoke
(closure=0x5577686e76a0, return_value=0x0, n_param_values=7, param_values=0x55776870a660, invocation_hint=0x7fffc989be80)
at ../../../gobject/gclosure.c:832
#14 0x00007f1235fae3d6 in signal_emit_unlocked_R.isra.0 (node=<optimized out>, detail=0,
detail@entry=3381248240, instance=0x5577686def10, emission_return=emission_return@entry=0x0, instance_and_params=0x55776870a660) at ../../../gobject/gsignal.c:3802
#15 0x00007f1235f9ba5b in g_signal_emitv
(instance_and_params=instance_and_params@entry=0x55776870a660, signal_id=<optimized out>, detail=3381248240,
detail@entry=0, return_value=return_value@entry=0x0) at ../../../gobject/gsignal.c:3274
#16 0x0000557766ffeabc in cups_notifier_proxy_g_signal
(proxy=<optimized out>, sender_name=<optimized out>, signal_name=<optimized out>, parameters=<optimized out>)
at /usr/src/cups-browsed-2.0~rc1-0ubuntu1/cups-notifier.c:2482
#17 0x00007f1235f81010 in g_closure_invoke
(closure=0x5577686d6b50, return_value=0x0, n_param_values=4, param_values=0x7fffc989c180, invocation_hint=0x7fffc989c100)
at ../../../gobject/gclosure.c:832
#18 0x00007f1235fae505 in signal_emit_unlocked_R.isra.0
(node=node@entry=0x5577686d6b80, detail=detail@entry=0, instance=instance@entry=0x5577686def10, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7fffc989c180) at ../../../gobject/gsignal.c:3841
#19 0x00007f1235f9e69a in g_signal_emit_valist
(instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>, var_args=var_args@entry=0x7fffc989c370)
at ../../../gobject/gsignal.c:3555
#20 0x00007f1235f9e923 in g_signal_emit
(instance=instance@entry=0x5577686def10, signal_id=<optimized out>, detail=<optimized out>)
at ../../../gobject/gsignal.c:3612
#21 0x00007f12360e178d in on_signal_received
(connection=<optimized out>, sender_name=0x7f121c009610 ":1.699", object_path=<optimized out>, interface_name=<optimized out>, signal_name=0x7f121c009cc0 "PrinterDeleted", parameters=0x7f121c005030, user_data=0x5577686e77b0)
at ../../../gio/gdbusproxy.c:890
#22 0x00007f12360cd36f in emit_signal_instance_in_idle_cb (data=0x7f121c002220) at ../../../gio/gdbusconnection.c:3800
#23 0x00007f1235e8036f in g_main_dispatch (context=0x5577686aed90) at ../../../glib/gmain.c:3460
#24 g_main_context_dispatch (context=0x5577686aed90) at ../../../glib/gmain.c:4200
#25 0x00007f1235edb178 in g_main_context_iterate.constprop.0
(context=0x5577686aed90, block=<optimized out>, dispatch=1, self=<optimized out>) at ../../../glib/gmain.c:4276
#26 0x00007f1235e7fbdf in g_main_loop_run (loop=0x5577686e3ef0) at ../../../glib/gmain.c:4479
#27 0x0000557766feb3ff in main (argc=<optimized out>, argv=<optimized out>) at daemon/cups-browsed.c:14077
Some background details: both times this happened it happened when I resumed my laptop after coming to work. There's one network printer in the local LAN, and also a Samba server that exports a print queue (for the same printer). I've never touched IPv6 and I doubt it works, outside of whatever local autoconfiguration happens with stock Ubuntu installs.
Got the bug again. The log is silent again, after the HTTP timeout messages. sysprof says that all the time is spent in httpGets, but I don't get meaningful stack traces (because Ubuntu builds with -fomit- frame-pointer probably). perf top shows the same.
Attaching with gdb shows me this for the main thread:
#0 __futex_ abstimed_ wait_common 0x557767016e6c <lock+12>) futex-internal. c:103 futex_abstimed_ wait64 word=futex_ word@entry= 0x557767016e6c <lock+12>, expected= expected@ entry=3, clockid= clockid@ entry=0, abstime= abstime@ entry=0x0, private=<optimized out>) at ./nptl/ futex-internal. c:128 rwlock_ wrlock_ full64 (abstime=0x0, clockid=0, rwlock= 0x557767016e60 <lock>) pthread_ rwlock_ common. c:730 rwlock_ wrlock (rwlock= rwlock@ entry=0x5577670 16e60 <lock>) at ./nptl/ pthread_ rwlock_ wrlock. c:26 cups-browsed. c:4021 local_printers. part.0. lto_priv. 0 () at daemon/ cups-browsed. c:4383 local_printers () at daemon/ cups-browsed. c:7103 <optimized out>, text=<optimized out>, printer_ uri=<optimized out>, printer_ state=< optimized out>, printer_ state_reasons= <optimized out>, printer_ is_accepting_ jobs=<optimized out>, user_data= <optimized out>, printer= 0x55776866ac00 "HP_Color_ LaserJet_ MFP_M477fdw_ fridge" ) at daemon/ cups-browsed. c:7111 <optimized out>, text=0x5577686e7260 "Printer \"HP_Color_ LaserJet_ MFP_M477fdw_ fridge\ " deleted by \"cups-browsed\".", printer_ uri=<optimized out>, printer= 0x55776866ac00 "HP_Color_ LaserJet_ MFP_M477fdw_ fridge" , printer_ state=< optimized out>, printer_ state_reasons= <optimized out>, printer_ is_accepting_ jobs=1, user_data=0x0) at daemon/ cups-browsed. c:7082 x86/unix64. S:104 cif@entry= 0x7fffc989bd00, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>, closure= closure@ entry=0x0) at ../src/ x86/ffi64. c:673 cif@entry= 0x7fffc989bd00, fn=fn@entry= 0x557766ff8750 <on_printer_ deleted> , rvalue= rvalue@ entry=0x7fffc98 9bc80, avalue= avalue@ entry=0x7fffc98 9bbe0) at ../src/ x86/ffi64. c:710 marshal_ generic <optimized out>, return_ gvalue= <optimized out>, n_param_ values= <optimized out>, param_values= <optimized out>, invocation_ hint=<optimized out>, marshal_ data=<optimized out>) at ../../. ./gobject/ gclosure. c:1536 0x5577686e76a0, return_value=0x0, n_param_values=7, param_values= 0x55776870a660, invocation_ hint=0x7fffc989 be80) ./gobject/ gclosure. c:832 emit_unlocked_ R.isra. 0 (node=<optimized out>, detail=0, entry=338124824 0, instance= 0x5577686def10, emission_ return= emission_ return@ entry=0x0, instance_ and_params= 0x55776870a660) at ../../. ./gobject/ gsignal. c:3802 and_params= instance_ and_params@ entry=0x5577687 0a660, signal_ id=<optimized out>, detail=3381248240, value=return_ value@entry= 0x0) at ../../. ./gobject/ gsignal. c:3274 proxy_g_ signal <optimized out>, sender_ name=<optimized out>, signal_ name=<optimized out>, parameters= <optimized out>) cups-browsed- 2.0~rc1- 0ubuntu1/ cups-notifier. c:2482 0x5577686d6b50, return_value=0x0, n_param_values=4, param_values= 0x7fffc989c180, invocation_ hint=0x7fffc989 c100) ./gobject/ gclosure. c:832 emit_unlocked_ R.isra. 0 node@entry= 0x5577686d6b80, detail= detail@ entry=0, instance= instance@ entry=0x5577686 def10, emission_ return= emission_ return@ entry=0x0, instance_ and_params= instance_ and_params@ entry=0x7fffc98 9c180) at ../../. ./gobject/ gsignal. c:3841 emit_valist <optimized out>, signal_ id=<optimized out>, detail=<optimized out>, var_args= var_args@ entry=0x7fffc98 9c370) ./gobject/ gsignal. c:3555 instance@ entry=0x5577686 def10, signal_ id=<optimized out>, detail=<optimized out>) ./gobject/ gsignal. c:3612 =<optimized out>, sender_ name=0x7f121c00 9610 ":1.699", object_ path=<optimized out>, interface_ name=<optimized out>, signal_ name=0x7f121c00 9cc0 "PrinterDeleted", parameters= 0x7f121c005030, user_data= 0x5577686e77b0) ./gio/gdbusprox y.c:890 instance_ in_idle_ cb (data=0x7f121c0 02220) at ../../. ./gio/gdbusconn ection. c:3800 0x5577686aed90) at ../../. ./glib/ gmain.c: 3460 context_ dispatch (context= 0x5577686aed90) at ../../. ./glib/ gmain.c: 4200 context_ iterate. constprop. 0 0x5577686aed90, block=<optimized out>, dispatch=1, self=<optimized out>) at ../../. ./glib/ gmain.c: 4276 e3ef0) at ../../. ./glib/ gmain.c: 4479 cups-browsed. c:14077
(cancel=false, private=<optimized out>, abstime=0x0, clockid=0, expected=3, futex_word=
at ./nptl/
#1 __GI___
(futex_
#2 0x00007f1235a9566c in __pthread_
at ./nptl/
#3 ___pthread_
#4 0x0000557766ff4a54 in get_local_printers () at daemon/
#5 0x0000557766fffab5 in update_
#6 0x0000557766ff886d in update_
#7 on_printer_deleted
(object=
#8 on_printer_deleted
(object=
#9 0x00007f1235c158b6 in ffi_call_unix64 () at ../src/
#10 0x00007f1235c1234d in ffi_call_int
(cif=
#11 0x00007f1235c14f33 in ffi_call
(cif=
#12 0x00007f1235f87163 in g_cclosure_
(closure=
#13 0x00007f1235f81010 in g_closure_invoke
(closure=
at ../../.
#14 0x00007f1235fae3d6 in signal_
detail@
#15 0x00007f1235f9ba5b in g_signal_emitv
(instance_
detail@entry=0, return_
#16 0x0000557766ffeabc in cups_notifier_
(proxy=
at /usr/src/
#17 0x00007f1235f81010 in g_closure_invoke
(closure=
at ../../.
#18 0x00007f1235fae505 in signal_
(node=
#19 0x00007f1235f9e69a in g_signal_
(instance=
at ../../.
#20 0x00007f1235f9e923 in g_signal_emit
(instance=
at ../../.
#21 0x00007f12360e178d in on_signal_received
(connection
at ../../.
#22 0x00007f12360cd36f in emit_signal_
#23 0x00007f1235e8036f in g_main_dispatch (context=
#24 g_main_
#25 0x00007f1235edb178 in g_main_
(context=
#26 0x00007f1235e7fbdf in g_main_loop_run (loop=0x5577686
#27 0x0000557766feb3ff in main (argc=<optimized out>, argv=<optimized out>) at daemon/
Some background details: both times this happened it happened when I resumed my laptop after coming to work. There's one network printer in the local LAN, and also a Samba server that exports a print queue (for the same printer). I've never touched IPv6 and I doubt it works, outside of whatever local autoconfiguration happens with stock Ubuntu installs.