Closed Saviq closed 11 months ago
@jrmcpeek I've split this issue as it's something different to the OSK not minimizing, as I understand it.
Are you saying that, on boot, your app doesn't always start, but a restart
helps? That sounds like the app not waiting for the Wayland socket to appear. Are you using (a version of) wayland-launch
? That's explicitly there to deal with that problem.
Can you provide logs from the failed run?
Transferred to ubuntu-frame as it doesn't sound OSK specific. (Sounds like #130)
@jrmcpeek I've split this issue as it's something different to the OSK not minimizing, as I understand it.
Note that prior to the comment you copied over, I also included https://github.com/MirServer/ubuntu-frame-osk/issues/58#issuecomment-1726076134:
If I instead use the latest edge version of ubuntu-frame snap :
ubuntu-frame 113-mir2.15.0+dev122 6877 22/edge canonical✓ - ubuntu-frame-osk 44-squeekboard-v1.17.1 316 latest/stable canonical✓ -
The app loads as expected when power cycling.
So at least from the outside, it look(ed)/look(s) like our app worked on the latest 22/edge
prior to the OSK fix, but no longer does.
Of course, it could be unrelated and simply coincidence.
Are you saying that, on boot, your app doesn't always start, but a restart helps?
Correct. Only for 22/stable
and now 22/edge
(after PR merge).
Prior to this, we were using 20/stable
or 20/edge
without any power cycle issue (other than the OSK redraw).
Can you provide logs from the failed run?
From https://github.com/MirServer/ubuntu-frame-osk/issues/58#issuecomment-1726076134:
Checking the logs, I see:
Sep 19 16:34:09 ubuntu systemd[1]: snap.onboard.onboard.service: Scheduled restart job, restart counter is at 5. Sep 19 16:34:09 ubuntu systemd[1]: Stopped Service for snap application onboard.onboard. Sep 19 16:34:09 ubuntu systemd[1]: snap.onboard.onboard.service: Start request repeated too quickly. Sep 19 16:34:09 ubuntu systemd[1]: snap.onboard.onboard.service: Failed with result 'exit-code'. Sep 19 16:34:09 ubuntu systemd[1]: Failed to start Service for snap application onboard.onboard.
If I ssh in and restart the app, it loads, but does log:
Sep 19 16:35:41 ubuntu systemd[1]: Started Service for snap application onboard.onboard. Sep 19 16:35:41 ubuntu onboard[4320]: Settings portal not found: Cannot autolaunch D-Bus without X11 $DISPLAY Sep 19 16:35:41 ubuntu onboard[4320]: gdk_window_get_state: assertion 'GDK_IS_WINDOW (window)' failed
That sounds like the app not waiting for the Wayland socket to appear. Are you using (a version of) wayland-launch? That's explicitly there to deal with that problem.
We had not used this, but I see that the next update of our snap includes both:
onboard:
command-chain: &_cmdchain
- bin/graphics-core22-wrapper
- bin/wayland-launch
So, I will build this and test again 🙂.
I'll report back after testing and see if this is resolved.
Thanks, the lines above this would also be interesting - as that's where the information on why the app was failing should be:
Sep 19 16:34:09 ubuntu systemd[1]: snap.onboard.onboard.service: Scheduled restart job, restart counter is at 5.
@Saviq
I was able to recreate the launch failure, using 22/edge
and the wayland-launch
script 1 time out of 30.
ubuntu-frame 113-mir2.15.0+dev128 6918 22/edge canonical✓ -
ubuntu-frame-osk 44-squeekboard-v1.17.1 316 latest/stable canonical✓ -
This is definitely a much lower frequency of issue, but in our setup, getting to the machine to restart it will be quite inconvenient if the app simply fails to launch.
Here's the log output (as a file, due to its size and line width) from the one failed run across 30 power cycles:
It actually looks like the entire ubuntu-frame
service failed and restarted, but by that point, the onboard
snap had already made its 5 attempts and would no longer restart.
And it's possible the app launch is what killed it?:
Sep 22 16:00:22 ubuntu ubuntu-frame.daemon[1589]: [2023-09-22 16:00:22.561841] <information> frame: New surface for snap="onboard" with title="ONBOARD"
Sep 22 16:00:22 ubuntu ubuntu-frame.daemon[1589]: !!! Fatal signal received. Attempting cleanup, but deadlock may occur
Sep 22 16:00:22 ubuntu wayland-launch[1562]: Failed to start Flutter renderer: No GL implementation is available
Sep 22 16:00:22 ubuntu wayland-launch[1562]: Error 32 (Broken pipe) dispatching to Wayland display.
We are building against Flutter 3.13.4. 3.13.5 only includes iOS and mac fixes that don't apply here.
Here's a successful boot log for comparison:
Yes, something crashed Frame (with a SEGV) at the same time that "onboard" first creates a surface. Will have a closer look on Monday.
(It doesn't look like #130)
@jrmcpeek we're not seeing these failures with other snaps in other environments. Unfortunately, the log you provided above only shows that Frame is segfaulting but doesn't help identify the cause.
Whatever is going on, Frame should not be segfaulting and I'd like to track this down. As I cannot reproduce, I need your help. The following will enable some very verbose logging of the interaction between Frame, the OSK and onboard:
snap set ubuntu-frame config="env-hacks=WAYLAND_DEBUG=server"
I hope that, with this. the logs from a failure will contain the clue I need.
I'll run some more testing against 22/edge
and see if I can reproduce it, now that the frequency is low.
I'll report back with my findings, but it may take a day or two.
@AlanGriffiths - I was able to reproduce it again today after about 20 power cycles.
Using:
ubuntu-frame 113-mir2.15.0+dev133 6944 22/edge canonical✓ -
ubuntu-frame-osk 49-squeekboard-v1.17.1 362 22/stable canonical✓ -
Since the last time, I have upgraded ubuntu-frame-osk
from latest/stable
to 22/stable
, which allowed me to drop both core20
and mesa-core20
. Given reproduction, doesn't seem related, but including the note as an environmental change.
I captured the failure with the verbose logging requested (attached, due to size):
And, for a quick view of the last moment leading up to the failure:
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.039] wl_seat@13.get_pointer(new id wl_pointer@12)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.064] wl_seat@13.get_keyboard(new id wl_keyboard@8)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.477] -> wl_keyboard@8.keymap(1, fd 70, 9465)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.492] -> wl_keyboard@8.repeat_info(25, 600)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.498] wl_seat@13.get_touch(new id wl_touch@18)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.505] wl_registry@2.bind(9, "xdg_wm_base", 1, new id [unknown]@17)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.518] wl_compositor@4.create_surface(new id wl_surface@19)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.529] xdg_wm_base@17.get_xdg_surface(new id xdg_surface@20, wl_surface@19)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.541] xdg_surface@20.get_toplevel(new id xdg_toplevel@21)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.551] -> xdg_toplevel@21.configure(0, 0, array[0])
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.559] -> xdg_surface@20.configure(4)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.563] xdg_toplevel@21.set_parent(nil)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.566] xdg_toplevel@21.set_title("ONBOARD")
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.569] xdg_toplevel@21.set_fullscreen(nil)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [2023-09-26 23:00:04.800385] <information> frame: New surface for snap="onboard" with title="ONBOARD"
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.636] -> xdg_toplevel@21.configure(0, 0, array[0])
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.643] -> xdg_surface@20.configure(5)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: !!! Fatal signal received. Attempting cleanup, but deadlock may occur
Sep 26 23:00:04 ubuntu wayland-launch[1471]: Failed to start Flutter renderer: No GL implementation is available
Sep 26 23:00:04 ubuntu wayland-launch[1471]: Error 32 (Broken pipe) dispatching to Wayland display.
Sep 26 23:00:04 ubuntu systemd[1]: snap.onboard.onboard.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 23:00:04 ubuntu systemd[1]: snap.onboard.onboard.service: Failed with result 'exit-code'.
Sep 26 23:00:04 ubuntu systemd[1]: snap.onboard.onboard.service: Consumed 1.154s CPU time.
For comparison, here's a successful boot with verbose logging running:
OK, so nothing immediately strikes me as weird, but here's the point of divergence:
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [2023-09-26 23:00:04.800385] <information> frame: New surface for snap="onboard" with title="ONBOARD"
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.636] -> xdg_toplevel@21.configure(0, 0, array[0])
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: [ 152222.643] -> xdg_surface@20.configure(5)
Sep 26 23:00:04 ubuntu ubuntu-frame.daemon[1507]: !!! Fatal signal received. Attempting cleanup, but deadlock may occur
Sep 26 23:00:05 ubuntu systemd[1]: snap.ubuntu-frame.daemon.service: Main process exited, code=killed, status=11/SEGV
Sep 27 00:18:01 ubuntu ubuntu-frame.daemon[1481]: [2023-09-27 00:18:01.057213] <information> frame: New surface for snap="onboard" with title="ONBOARD"
Sep 27 00:18:01 ubuntu ubuntu-frame.daemon[1481]: [ 533512.167] -> xdg_toplevel@21.configure(0, 0, array[0])
Sep 27 00:18:01 ubuntu ubuntu-frame.daemon[1481]: [ 533512.175] -> xdg_surface@20.configure(5)
Sep 27 00:18:01 ubuntu ubuntu-frame.daemon[1481]: [ 533522.405] -> xdg_toplevel@21.configure(1920, 1080, array[4])
Sep 27 00:18:01 ubuntu ubuntu-frame.daemon[1481]: [ 533522.422] -> xdg_surface@20.configure(6)
That gives me a specific area to look at: Mir the sizing the "ONBOARD" window. (Curiously enough the same area of code that was not working when the OSK hid - what do they say about bugs coming in bunches?)
I may have a reproducer!
I left this running for an hour:
$ while xvfb-run frame-it qterminal -e ./sleep-exit.sh; do :; done 2>&1 | grep Fatal
!!! Fatal signal received. Attempting cleanup, but deadlock may occur
I just need tweak this to capture the crash and look for more evidence
I have a stack trace I hope represents the same problem (it isn't where I expected to see an issue):
(gdb) bt
#0 __GI___pthread_sigmask (how=how@entry=1, newmask=<optimised out>, newmask@entry=0x7f9e157f7080, oldmask=oldmask@entry=0x0) at ./nptl/pthread_sigmask.c:43
#1 0x00007f9e89e4271d in __GI___sigprocmask (how=how@entry=1, set=set@entry=0x7f9e157f7080, oset=oset@entry=0x0) at ../sysdeps/unix/sysv/linux/sigprocmask.c:25
#2 0x00007f9e89e287a7 in __GI_abort () at ./stdlib/abort.c:64
#3 0x00007f9e8a69f486 in mir::fatal_error_abort(char const*, ...) (reason=0x7f9e89c60137 "Unsupported attempt to continue after a fatal signal: %s") at /home/alan/CLionProjects/mir/src/core/fatal.cpp:40
#4 0x00007f9e89a7f415 in fatal_signal_cleanup(int, siginfo_t*, void*) (sig=6, info=0x7f9e157f7430, ucontext=0x7f9e157f7300) at /home/alan/CLionProjects/mir/src/server/run_mir.cpp:186
#5 0x00007f9e89e42520 in <signal handler called> () at /lib/x86_64-linux-gnu/libc.so.6
#6 __pthread_kill_implementation (no_tid=0, signo=6, threadid=140316942247488) at ./nptl/pthread_kill.c:44
#7 __pthread_kill_internal (signo=6, threadid=140316942247488) at ./nptl/pthread_kill.c:78
#8 __GI___pthread_kill (threadid=140316942247488, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#9 0x00007f9e89e42476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#10 0x00007f9e89e287f3 in __GI_abort () at ./stdlib/abort.c:79
#11 0x00007f9e8a69f486 in mir::fatal_error_abort(char const*, ...) (reason=0x7f9e89c60137 "Unsupported attempt to continue after a fatal signal: %s") at /home/alan/CLionProjects/mir/src/core/fatal.cpp:40
#12 0x00007f9e89a7f415 in fatal_signal_cleanup(int, siginfo_t*, void*) (sig=11, info=0x7f9e157f7e30, ucontext=0x7f9e157f7d00) at /home/alan/CLionProjects/mir/src/server/run_mir.cpp:186
#13 0x00007f9e89e42520 in <signal handler called> () at /lib/x86_64-linux-gnu/libc.so.6
#14 0x00007f9e89ea52a9 in tcache_get (tc_idx=<optimised out>) at ./malloc/malloc.c:3196
#15 __GI___libc_malloc (bytes=208) at ./malloc/malloc.c:3313
#16 0x00007f9e8a68fe8a in () at /lib/x86_64-linux-gnu/libwayland-client.so.0
#17 0x00007f9e8a692fee in wl_proxy_marshal_array_flags () at /lib/x86_64-linux-gnu/libwayland-client.so.0
#18 0x00007f9e8a693c7f in wl_proxy_marshal_flags () at /lib/x86_64-linux-gnu/libwayland-client.so.0
#19 0x000055810aecf7ef in wl_surface_attach(wl_surface*, wl_buffer*, int32_t, int32_t) (wl_surface=0x7f9dec008c20, buffer=0x7f9df80ab500, x=0, y=0) at /usr/include/wayland-client-protocol.h:3739
#20 0x000055810aed1750 in BackgroundClient::Self::draw_screen(egmde::FullscreenClient::SurfaceInfo&, bool) const (this=0x7f9dec004d20, info=..., draws_crash=false)
at /home/alan/CLionProjects/ubuntu-frame/src/background_client.cpp:443
#21 0x000055810aec2634 in egmde::FullscreenClient::draw() (this=0x7f9dec004d20) at /home/alan/CLionProjects/ubuntu-frame/src/egfullscreenclient.cpp:371
#22 0x000055810aec0fa3 in operator()() const (__closure=0x7f9dec0051e0) at /home/alan/CLionProjects/ubuntu-frame/src/egfullscreenclient.cpp:188
#23 0x000055810aec5e7c in std::__invoke_impl<void, egmde::FullscreenClient::FullscreenClient(wl_display*, std::optional<boost::filesystem::path>, uint, miral::MirRunner*, WindowManagerObserver*)::<lambda()>&>(std::__invoke_other, struct {...} &) (__f=...) at /usr/include/c++/11/bits/invoke.h:61
#24 0x000055810aec565c in std::__invoke_r<void, egmde::FullscreenClient::FullscreenClient(wl_display*, std::optional<boost::filesystem::path>, uint, miral::MirRunner*, WindowManagerObserver*)::<lambda()>&>(struct {...} &) (__fn=...) at /usr/include/c++/11/bits/invoke.h:111
#25 0x000055810aec4f32 in std::_Function_handler<void(), egmde::FullscreenClient::FullscreenClient(wl_display*, std::optional<boost::filesystem::path>, uint, miral::MirRunner*, WindowManagerObserver*)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/11/bits/std_function.h:290
#26 0x000055810aebc5ec in std::function<void ()>::operator()() const (this=0x7f9dec0051e0) at /usr/include/c++/11/bits/std_function.h:590
#27 0x000055810aeb8505 in WindowManagerObserver::process_window_opened_callbacks() const (this=0x7ffc91ac6c60) at /home/alan/CLionProjects/ubuntu-frame/src/frame_window_manager.cpp:138
#28 0x000055810aeb9753 in FrameWindowManagerPolicy::advise_new_window(miral::WindowInfo const&) (this=0x55810d5becd0, window_info=...) at /home/alan/CLionProjects/ubuntu-frame/src/frame_window_manager.cpp:379
#29 0x00007f9e8a747ed4 in miral::BasicWindowManager::add_surface(std::shared_ptr<mir::scene::Session> const&, mir::shell::SurfaceSpecification const&, std::function<std::shared_ptr<mir::scene::Surface> (std::shared_ptr<mir::scene::Session> const&, mir::shell::SurfaceSpecification const&)> const&) (this=0x55810ccca810, session=<optimised out>, params=<optimised out>, build=<optimised out>)
at /home/alan/CLionProjects/mir/src/miral/basic_window_manager.cpp:173
#30 0x00007f9e8a749dc0 in virtual thunk to miral::BasicWindowManager::add_surface(std::shared_ptr<mir::scene::Session> const&, mir::shell::SurfaceSpecification const&, std::function<std::shared_ptr<mir::scene::Surface> (std::shared_ptr<mir::scene::Session> const&, mir::shell::SurfaceSpecification const&)> const&) () at /usr/local/lib/libmiral.so.6
#31 0x00007f9e89c05055 in mir::shell::AbstractShell::create_surface(std::shared_ptr<mir::scene::Session> const&, mir::wayland::Weak<mir::frontend::WlSurface> const&, mir::shell::SurfaceSpecification const&, std::shared_ptr<mir::scene::SurfaceObserver> const&, mir::Executor*) (this=0x55810ccea660, session=warning: RTTI symbol not found for class 'std::_Sp_counted_ptr_inplace<mir::scene::ApplicationSession, std::allocator<void>, (__gnu_cxx::_Lock_policy)2>'
warning: RTTI symbol not found for class 'std::_Sp_counted_ptr_inplace<mir::scene::ApplicationSession, std::allocator<void>, (__gnu_cxx::_Lock_policy)2>'
std::shared_ptr<mir::scene::Session> (use count 5, weak count 4) = {...}, wayland_surface=..., spec=..., observer=<error reading variable: Cannot access memory at address 0x7f9df80aaa68>, observer_executor=0x55810de87d70) at /home/alan/CLionProjects/mir/src/server/shell/abstract_shell.cpp:221
#32 0x00007f9e89b7af24 in mir::frontend::WindowWlSurfaceRole::create_scene_surface() (this=this@entry=0x7f9df4017a18) at /home/alan/CLionProjects/mir/src/server/frontend_wayland/window_wl_surface_role.cpp:462
#33 0x00007f9e89b7c1ef in mir::frontend::WindowWlSurfaceRole::commit(mir::frontend::WlSurfaceState const&) (this=0x7f9df4017a18, state=...)
at /home/alan/CLionProjects/mir/src/server/frontend_wayland/window_wl_surface_role.cpp:382
#34 0x00007f9e89b8026b in mir::frontend::WlSurface::commit() (this=0x7f9df8077a10) at /home/alan/CLionProjects/mir/src/server/frontend_wayland/wl_surface.cpp:433
But am at EOD and on leave tomorrow.
#14 0x00007f9e89ea52a9 in tcache_get (tc_idx=<optimised out>) at ./malloc/malloc.c:3196
#15 __GI___libc_malloc (bytes=208) at ./malloc/malloc.c:3313
Oh, no. SIGSEGV in malloc
strongly suggests memory corruption. I wonder if we can get an AddressSanitizer build to do the same thing?
@jrmcpeek there's a fix for the problem I found in --channel 22/edge/pr152
, it would be good to confirm it also fixes things for you.
[update] the fix landed, so it is is now on --edge
(and --beta
, but that won't have the Mir fix for https://github.com/MirServer/ubuntu-frame-osk/issues/58)
[update] the fix landed, so it is is now on
--edge
(and--beta
, but that won't have the Mir fix for MirServer/ubuntu-frame-osk#58)
Actually, that was premature. the 22/edge/pr152
version has been withdrawn, but we're still waiting on an update on edge:
$ snap info ubuntu-frame | grep 22/edge
tracking: 22/edge
22/edge: 113-mir2.15.0+dev135 2023-09-28 (6960) 6MB -
we're still waiting on an update on edge:
It's building right now: https://launchpad.net/~mir-team/+snap/ubuntu-frame-22-edge/+build/2247347
we're still waiting on an update on edge:
It's building right now: https://launchpad.net/~mir-team/+snap/ubuntu-frame-22-edge/+build/2247347
I just kicked off the import from github
I'll run it through a bunch of cycles, see if this fixes it, and get back to you!
@AlanGriffiths -
Using:
ubuntu-frame 116-mir2.15.0+dev135 6989 22/edge canonical✓ -
ubuntu-frame-osk 49-squeekboard-v1.17.1 362 22/stable canonical✓ -
I was no longer able to reproduce this after a few hours of automated, rapid power cycling.
This fix appears to resolve our issue as well.
Using the following:
This is maybe a little bit better, but still the same issue.
It's about a 50% success rate of the app loading and going full screen or attempting to load, failing a bunch, and the init servicing saying "no more".
100% success rate of the app loading as expected if I simply run a
snap restart onboard.onboard
orsystemctl retsart snap.onboard.onboard
after it fails and I ssh into the machine.Originally posted by @jrmcpeek in https://github.com/MirServer/ubuntu-frame-osk/issues/58#issuecomment-1730182354
[edit]
The title may be misleading about the frequency of problems. In https://github.com/MirServer/ubuntu-frame/issues/151#issuecomment-1731894944 it says "one failed run across 30 power cycles"
The log included there shows that Frame segfaults, but doesn't contain anything to help identify why