Snapshot hangs on startup
Using snapshot-46.0-1.fc40, I ran flatpak permission-reset org.gnome.Snapshot to reset my camera portal permissions to a clean slate. I noted in the cameras panel in gnome-control-center that Snapshot is no longer listed.
Then I ran Snapshot and it unexpectedly said No Camera Found, a different bug. I also note that somehow Snapshot's camera permission was automatically and permanently denied, since it is once again displayed in the Camera permissions panel, and the permission is off. Those are surely two separate bugs, possibly related, but not this bug.
Subsequent attempts to run Snapshot do not get that far anymore. Instead, Snapshot hangs on startup deep inside GStreamer. Before the hang, I see various errors:
2024-04-09T20:11:05.024346Z ERROR aperture::viewfinder: Could not start camerabin: Element failed to change its state
2024-04-09T20:11:35.339117Z ERROR aperture::viewfinder: Could not start camerabin: Element failed to change its state
2024-04-09T20:11:35.342005Z ERROR aperture::viewfinder: Bus Error from Some("/GstCameraBin:camerabin0/GstWrapperCameraBinSrc:camerasrc/GstAutoVideoSrc:camerasrc-real-src/GstPipeWireSrc:camerasrc-real-src-actual-src-pipewir")
Internal data stream error.
Some("../libs/gst/base/gstbasesrc.c(3132): gst_base_src_loop (): /GstCameraBin:camerabin0/GstWrapperCameraBinSrc:camerasrc/GstAutoVideoSrc:camerasrc-real-src/GstPipeWireSrc:camerasrc-real-src-actual-src-pipewir:\nstreaming stopped, reason not-negotiated (-4)")which looks like #109 or #134 (closed). Then the backtrace looks like this:
#0 0x00007ffff6a16919 in __futex_abstimed_wait_common64 (private=0, futex_word=0x555556dbd488, expected=0, op=393, abstime=0x7fffffff5a60, cancel=true)
at futex-internal.c:57
#1 __futex_abstimed_wait_common
(futex_word=futex_word@entry=0x555556dbd488, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7fffffff5a60, private=private@entry=0, cancel=cancel@entry=true) at futex-internal.c:87
#2 0x00007ffff6a1699f in __GI___futex_abstimed_wait_cancelable64
(futex_word=futex_word@entry=0x555556dbd488, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x7fffffff5a60, private=private@entry=0) at futex-internal.c:139
#3 0x00007ffff6a19652 in __pthread_cond_wait_common (cond=0x555556dbd460, mutex=0x555556dbd488, clockid=0, abstime=0x7fffffff5a60)
at pthread_cond_wait.c:503
#4 ___pthread_cond_timedwait64 (cond=cond@entry=0x555556dbd460, mutex=mutex@entry=0x555556dbd438, abstime=abstime@entry=0x7fffffff5a60)
at pthread_cond_wait.c:643
#5 0x00007fffe409718a in pw_thread_loop_timed_wait_full (loop=0x555556dbd410, abstime=abstime@entry=0x7fffffff5a60) at ../src/pipewire/thread-loop.c:495
#6 0x00007fffe40ede59 in wait_started (this=0x555556dcb380 [GstPipeWireSrc|camerasrc-real-src-actual-src-pipewir]) at ../src/gst/gstpipewiresrc.c:797
#7 gst_pipewire_src_change_state (element=0x555556dcb380 [GstElement|camerasrc-real-src-actual-src-pipewir], transition=<optimized out>)
at ../src/gst/gstpipewiresrc.c:1495
#8 0x00007ffff7d86f96 in gst_element_change_state
(element=element@entry=0x555556dcb380 [GstElement|camerasrc-real-src-actual-src-pipewir], transition=transition@entry=GST_STATE_CHANGE_READY_TO_PAUSED)
at ../gst/gstelement.c:3093
#9 0x00007ffff7d8784b in gst_element_set_state_func (element=0x555556dcb380 [GstElement|camerasrc-real-src-actual-src-pipewir], state=GST_STATE_PAUSED)
at ../gst/gstelement.c:3047
#10 0x00007ffff7d5e699 in gst_bin_element_set_state
(next=<optimized out>, current=<optimized out>, start_time=0 [0:00:00.000000000], base_time=0 [0:00:00.000000000], element=0x555556dcb380 [GstElement|camerasrc-real-src-actual-src-pipewir], bin=<optimized out>) at ../gst/gstbin.c:2582
#11 gst_bin_change_state_func (element=0x555556dc66f0 [GstElement|camerasrc-real-src], transition=GST_STATE_CHANGE_READY_TO_PAUSED) at ../gst/gstbin.c:2931
#12 0x00007fffdf499df0 in gst_auto_detect_change_state (element=0x555556dc66f0 [GstElement|camerasrc-real-src], transition=<optimized out>)
at ../gst/autodetect/gstautodetect.c:427
#13 0x00007ffff7d86f96 in gst_element_change_state
(element=element@entry=0x555556dc66f0 [GstElement|camerasrc-real-src], transition=transition@entry=GST_STATE_CHANGE_READY_TO_PAUSED)
at ../gst/gstelement.c:3093
#14 0x00007ffff7d8784b in gst_element_set_state_func (element=0x555556dc66f0 [GstElement|camerasrc-real-src], state=GST_STATE_PAUSED)
at ../gst/gstelement.c:3047
#15 0x00007ffff7d5e699 in gst_bin_element_set_state
(next=<optimized out>, current=<optimized out>, start_time=0 [0:00:00.000000000], base_time=0 [0:00:00.000000000], element=0x555556dc66f0 [GstElement|camerasrc-real-src], bin=<optimized out>) at ../gst/gstbin.c:2582
#16 gst_bin_change_state_func (element=0x555556d8acb0 [GstElement|camerasrc], transition=GST_STATE_CHANGE_READY_TO_PAUSED) at ../gst/gstbin.c:2931
#17 0x00007fffe5214a3d in gst_wrapper_camera_bin_src_change_state (element=0x555556d8acb0 [GstElement|camerasrc], trans=GST_STATE_CHANGE_READY_TO_PAUSED)
at ../gst/camerabin2/gstwrappercamerabinsrc.c:1062
#18 0x00007ffff7d86f96 in gst_element_change_state
(element=element@entry=0x555556d8acb0 [GstElement|camerasrc], transition=transition@entry=GST_STATE_CHANGE_READY_TO_PAUSED) at ../gst/gstelement.c:3093
#19 0x00007ffff7d8784b in gst_element_set_state_func (element=0x555556d8acb0 [GstElement|camerasrc], state=GST_STATE_PAUSED) at ../gst/gstelement.c:3047
#20 0x00007ffff7d5e699 in gst_bin_element_set_state
(next=<optimized out>, current=<optimized out>, start_time=0 [0:00:00.000000000], base_time=0 [0:00:00.000000000], element=0x555556d8acb0 [GstElement|camerasrc], bin=<optimized out>) at ../gst/gstbin.c:2582
#21 gst_bin_change_state_func (element=0x555555d972c0 [GstElement|camerabin0], transition=GST_STATE_CHANGE_READY_TO_PAUSED) at ../gst/gstbin.c:2931
#22 0x00007ffff7db1e0e in gst_pipeline_change_state (element=0x555555d972c0 [GstElement|camerabin0], transition=GST_STATE_CHANGE_READY_TO_PAUSED)
at ../gst/gstpipeline.c:529
#23 0x00007ffff7d86f96 in gst_element_change_state
(element=element@entry=0x555555d972c0 [GstElement|camerabin0], transition=GST_STATE_CHANGE_READY_TO_PAUSED) at ../gst/gstelement.c:3093
#24 0x00007ffff7d87501 in gst_element_continue_state (element=element@entry=0x555555d972c0 [GstElement|camerabin0], ret=ret@entry=GST_STATE_CHANGE_SUCCESS)
at ../gst/gstelement.c:2801
#25 0x00007ffff7d86fda in gst_element_change_state
(element=element@entry=0x555555d972c0 [GstElement|camerabin0], transition=transition@entry=GST_STATE_CHANGE_NULL_TO_READY) at ../gst/gstelement.c:3132
#26 0x00007ffff7d8784b in gst_element_set_state_func (element=0x555555d972c0 [GstElement|camerabin0], state=GST_STATE_PLAYING) at ../gst/gstelement.c:3047
#27 0x00005555556a3a09 in gstreamer::auto::element::ElementExt::set_state<gstreamer::auto::element::Element>
(state=gstreamer::auto::enums::State::Playing, self=<optimized out>) at vendor/gstreamer/src/auto/element.rs:458
#28 aperture::viewfinder::Viewfinder::start_stream (self=<optimized out>) at aperture/src/viewfinder.rs:613
#32 0x00007ffff7cf1fd3 in <emit signal '???' on instance 0x555555d10dd0 [ApertureViewfinder]>
(instance=instance@entry=0x555555d10dd0, signal_id=<optimized out>, detail=detail@entry=0) at ../gobject/gsignal.c:3583
#29 0x00007ffff7cf1e04 in _g_closure_invoke_va
(closure=0x555555cb2d70, return_value=0x0, instance=0x555555d10dd0, args=0x7fffffff6400, n_params=<optimized out>, param_types=0x0)
at ../gobject/gclosure.c:897
#30 signal_emit_valist_unlocked
(instance=instance@entry=0x555555d10dd0, signal_id=signal_id@entry=88, detail=detail@entry=0, var_args=var_args@entry=0x7fffffff6400)
at ../gobject/gsignal.c:3424
#31 0x00007ffff7cf1f11 in g_signal_emit_valist (instance=0x555555d10dd0, signal_id=88, detail=0, var_args=var_args@entry=0x7fffffff6400)
at ../gobject/gsignal.c:3263
#33 0x00007ffff7258eaf in gtk_widget_realize (widget=0x555555d10dd0 [ApertureViewfinder]) at ../gtk/gtkwidget.c:3446
#34 0x00007ffff7259168 in gtk_widget_map (widget=0x555555d10dd0 [ApertureViewfinder]) at ../gtk/gtkwidget.c:2853
#35 gtk_widget_map (widget=0x555555d10dd0 [ApertureViewfinder]) at ../gtk/gtkwidget.c:2842
--Type <RET> for more, q to quit, c to continue without paging--c
#36 0x00007ffff7260e29 in gtk_widget_real_map (widget=<optimized out>) at ../gtk/gtkwidget.c:7725
#40 0x00007ffff7cf1fd3 in <emit signal '???' on instance ???> (instance=instance@entry=0x555555d96470, signal_id=<optimized out>, detail=detail@entry=0)
at ../gobject/gsignal.c:3583
#37 0x00007ffff7cf1008 in _g_closure_invoke_va (closure=0x555555cb73b0, return_value=Python Exception <class 'gdb.MemoryError'>: Cannot access memory at address 0x7fffffff65b0
#41 0x00007ffff72590f2 in gtk_widget_map (widget=0x555555d96470)
at ../gtk/gtkwidget.c:2855
#42 gtk_widget_map (widget=0x555555d96470) at ../gtk/gtkwidget.c:2842
Python Exception <class 'gdb.MemoryError'>: Cannot access memory at address 0x7fffffff6a68It seems the call to pw_thread_loop_timed_wait_full() has hung. I will attach a backtrace showing all threads, since it looks like a deadlock. Oddly, the futex does not appear to be used on any other thread. The pipewire loop is being used on one other thread, which looks like this:
Thread 42 (Thread 0x7fff8f4006c0 (LWP 214741) "pipewire-main-l"):
#0 0x00007ffff6a9c7a2 in epoll_wait (epfd=39, events=events@entry=0x7fff8f3ff4d0, maxevents=32, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1 0x00007fffe4024416 in impl_pollfd_wait (object=<optimized out>, pfd=<optimized out>, ev=0x7fff8f3ff6a0, n_ev=<optimized out>, timeout=<optimized out>) at ../spa/plugins/support/system.c:137
#2 0x00007fffe40160c1 in loop_iterate (object=0x555556de7ee8, timeout=-1) at ../spa/plugins/support/loop.c:471
#3 0x00007fffe4096827 in do_loop (user_data=0x555556dbac00) at ../src/pipewire/thread-loop.c:295
#4 0x00007ffff6a1a1b7 in start_thread (arg=<optimized out>) at pthread_create.c:447
#5 0x00007ffff6a9c39c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78but that doesn't seem suspicious to me. I don't know why it hangs.
Other relevant software versions:
- gstreamer1-1.22.9-1.fc40
- pipewire-1.0.4-2.fc40
CC @rmader because this looks like a bug in pipewire?