Mir-kiosk sometimes fails to start on virtual instance

snap
1

We’re building images based on Ubuntu Core 20. Running on Intel NUCs mostly for testing.

I just started some testing in QEMU today, and I found that quite often mir-kiosk fails to start. From the logs, this seems to be the sticking point:

2021-01-12T17:44:16Z mir-kiosk.daemon[1539]: [2021-01-12 17:44:16.701166] <information> gbm-kms: Failed to open DRM device node: Operation not permitted

It does that a few times, and eventually gives up with this error:

2021-01-12T17:38:14Z systemd[1]: snap.mir-kiosk.daemon.service: Start request repeated too quickly.

It’s some kind of timing issue, as when I manually restart the service, it then starts fine.

Couple of questions:

Any idea what is causing this ? Could it be some sort QEMU internal lock that eventually clears ?

Would it be sensible to configure the service so that it pauses for a couple of seconds between restarts, and so it would not get shutdown and eventually it would work without intervention ?

@alan_g I guess this last question is for you :slight_smile:

Cheers, Just

2

The “Failed to open DRM device node” message isn’t inherently a failure, it would be good to see a bit more of the log around that to understand what’s happening.

In principle I’ve no objection to a restart-delay but it would be good to understand the problem it is working around.

I don’t often use QEMU, so exact steps to replicate would be helpful.

3

Thanks @alan_g

I was just playing around with changing various qemu options, like adding -device virtio-vga,virgl=on etc, but nothing I’ve tried as yet make it reliable.

Sometimes it works on boot, sometimes not. So it really does seem to be a timing issue or race condition of some sort.

Here is the last of failure attempts in a series of 5 when it tries:

2021-01-13T09:30:47Z systemd[1]: snap.mir-kiosk.daemon.service: Scheduled restart job, restart counter is at 4.
2021-01-13T09:30:47Z systemd[1]: Stopped Service for snap application mir-kiosk.daemon.
2021-01-13T09:30:47Z systemd[1]: Started Service for snap application mir-kiosk.daemon.
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.890802] <information> mirserver: Starting
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897064] < - debug - > mirserver: Using Linux VT subsystem for session management
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897254] <information> mircommon: Loading modules from: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897355] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-gbm-kms.so.19
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897414] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-wayland.so.19
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897471] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/server-x11.so.19
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.897553] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/input-evdev.so.7
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.899349] <information> gbm-kms: EGL platform does not support EGL_KHR_platform_gbm extension
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.902852] <information> gbm-kms: Failed to open DRM device node: Operation not permitted
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.903015] <information> mirserver: Found graphics driver: mir:gbm-kms (version 2.2.0) Support priority: 0
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.903085] <information> mirserver: Found graphics driver: mir:wayland (version 2.2.0) Support priority: 0
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: [2021-01-13 09:30:47.903150] <information> mirserver: Found graphics driver: mir:x11 (version 2.2.0) Support priority: 0
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: ERROR: /build/mir-K7y0Z4/mir-2.2.0/src/server/graphics/default_configuration.cpp(136): Throw in function mir::DefaultServerConfiguration::the_graphics_platform()::<lambda()>
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: Dynamic exception type: boost::wrapexcept<std::runtime_error>
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: std::exception::what: Exception while creating graphics platform
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: ERROR: /build/mir-K7y0Z4/mir-2.2.0/src/server/graphics/platform_probe.cpp(78): Throw in function std::shared_ptr<mir::SharedLibrary> mir::graphics::module_for_device(const std::vector<std::shared_ptr<mir::SharedLibrary> >&, const mir::options::ProgramOption&, const std::shared_ptr<mir::ConsoleServices>&)
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: Dynamic exception type: boost::wrapexcept<std::runtime_error>
2021-01-13T09:30:47Z mir-kiosk.daemon[1550]: std::exception::what: Failed to find platform for current system
2021-01-13T09:30:47Z systemd[1]: snap.mir-kiosk.daemon.service: Main process exited, code=exited, status=1/FAILURE
2021-01-13T09:30:47Z systemd[1]: snap.mir-kiosk.daemon.service: Failed with result 'exit-code'.
2021-01-13T09:30:48Z systemd[1]: snap.mir-kiosk.daemon.service: Scheduled restart job, restart counter is at 5.
2021-01-13T09:30:48Z systemd[1]: Stopped Service for snap application mir-kiosk.daemon.
2021-01-13T09:30:48Z systemd[1]: snap.mir-kiosk.daemon.service: Start request repeated too quickly.
2021-01-13T09:30:48Z systemd[1]: snap.mir-kiosk.daemon.service: Failed with result 'exit-code'.
2021-01-13T09:30:48Z systemd[1]: Failed to start Service for snap application mir-kiosk.daemon.

If it helps, following the failed start at boot, here is a the log of the successful start after I do a manual mir-kiosk restart:

2021-01-13T09:34:33Z systemd[1]: Started Service for snap application mir-kiosk.daemon.
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.620570] <information> mirserver: Starting
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621228] < - debug - > mirserver: Using Linux VT subsystem for session management
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621375] <information> mircommon: Loading modules from: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621451] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-gbm-kms.so.19
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621505] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-wayland.so.19
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621557] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/server-x11.so.19
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.621613] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/input-evdev.so.7
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.623110] <information> gbm-kms: EGL platform does not support EGL_KHR_platform_gbm extension
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.623336] < - debug - > gbm-kms: MIR_MESA_KMS_DISABLE_MODESET_PROBE is set
2021-01-13T09:34:33Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:33.623401] < -warning- > gbm-kms: Failed to detect whether device /dev/dri/card0 supports KMS, continuing with lower confidence
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.499066] <information> gbm-kms: Detected software renderer: llvmpipe (LLVM 10.0.0, 128 bits)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.499490] <information> mirserver: Found graphics driver: mir:gbm-kms (version 2.2.0) Support priority: 128
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.499574] <information> mirserver: Found graphics driver: mir:wayland (version 2.2.0) Support priority: 0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.499654] <information> mirserver: Found graphics driver: mir:x11 (version 2.2.0) Support priority: 0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.499925] <information> mirserver: Selected driver: mir:gbm-kms (version 2.2.0)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.500512] < - debug - > gbm-kms: MIR_MESA_KMS_DISABLE_MODESET_PROBE is set
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.500581] < -warning- > gbm-kms: Failed to detect whether device /dev/dri/card0 supports KMS, but continuing anyway
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.500718] <information> gbm-kms: Using DRM device /dev/dri/card0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.504158] < -warning- > gbm-kms: Unable to determine the current display mode.
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506223] <information> gbm-kms: DRM device details:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506300] <information> gbm-kms: /dev/dri/card0: using driver virtio_gpu [virtio GPU] (version: 0.1.0 driver date: 0)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506466] <information> gbm-kms: 	Output: Virtual-1 (connected)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506518] <information> gbm-kms: 		Mode: 640×480@59.93
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506566] <information> gbm-kms: 		Mode: 4096×2160@59.99
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506624] <information> gbm-kms: 		Mode: 4096×2160@59.94
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506676] <information> gbm-kms: 		Mode: 2560×1600@59.98
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506740] <information> gbm-kms: 		Mode: 2560×1600@59.97
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506790] <information> gbm-kms: 		Mode: 1920×1440@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506835] <information> gbm-kms: 		Mode: 1856×1392@59.99
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506882] <information> gbm-kms: 		Mode: 1792×1344@59.99
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506926] <information> gbm-kms: 		Mode: 2048×1152@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.506969] <information> gbm-kms: 		Mode: 1920×1200@59.88
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507018] <information> gbm-kms: 		Mode: 1920×1200@59.95
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507066] <information> gbm-kms: 		Mode: 1920×1080@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507113] <information> gbm-kms: 		Mode: 1600×1200@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507159] <information> gbm-kms: 		Mode: 1680×1050@59.95
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507207] <information> gbm-kms: 		Mode: 1680×1050@59.88
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507254] <information> gbm-kms: 		Mode: 1400×1050@59.97
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507298] <information> gbm-kms: 		Mode: 1400×1050@59.94
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507344] <information> gbm-kms: 		Mode: 1600×900@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507397] <information> gbm-kms: 		Mode: 1280×1024@60.01
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507442] <information> gbm-kms: 		Mode: 1440×900@59.88
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507492] <information> gbm-kms: 		Mode: 1440×900@59.90
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507565] <information> gbm-kms: 		Mode: 1280×960@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507619] <information> gbm-kms: 		Mode: 1366×768@59.78
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507667] <information> gbm-kms: 		Mode: 1366×768@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507714] <information> gbm-kms: 		Mode: 1360×768@60.01
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507764] <information> gbm-kms: 		Mode: 1280×800@59.81
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507812] <information> gbm-kms: 		Mode: 1280×800@59.90
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507859] <information> gbm-kms: 		Mode: 1280×768@59.87
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507910] <information> gbm-kms: 		Mode: 1280×768@59.99
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.507958] <information> gbm-kms: 		Mode: 1280×720@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508005] <information> gbm-kms: 		Mode: 1024×768@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508052] <information> gbm-kms: 		Mode: 800×600@60.31
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508101] <information> gbm-kms: 		Mode: 800×600@56.25
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508149] <information> gbm-kms: 		Mode: 848×480@60.00
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508200] <information> gbm-kms: 		Mode: 640×480@59.94
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508254] < - debug - > miral: Display config using layout: 'default'
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.508363] <information> miral: Display config:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: 8>< ---------------------------------------------------
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: layouts:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: # keys here are layout labels (used for atomically switching between them)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: # when enabling displays, surfaces should be matched in reverse recency order
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:   default:                         # the default layout
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:     cards:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:     # a list of cards (currently matched by card-id)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:     - card-id: 0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:       Virtual-1:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # This output supports the following modes: 640x480@59.9, 4096x2160@60.0,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 4096x2160@59.9, 2560x1600@60.0, 2560x1600@60.0, 1920x1440@60.0, 1856x1392@60.0,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 1792x1344@60.0, 2048x1152@60.0, 1920x1200@59.9, 1920x1200@60.0, 1920x1080@60.0,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 1600x1200@60.0, 1680x1050@60.0, 1680x1050@59.9, 1400x1050@60.0, 1400x1050@59.9,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 1600x900@60.0, 1280x1024@60.0, 1440x900@59.9, 1440x900@59.9, 1280x960@60.0,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 1366x768@59.8, 1366x768@60.0, 1360x768@60.0, 1280x800@59.8, 1280x800@59.9,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 1280x768@59.9, 1280x768@60.0, 1280x720@60.0, 1024x768@60.0, 800x600@60.3,
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # 800x600@56.2, 848x480@60.0, 640x480@59.9
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         #
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # Uncomment the following to enforce the selected configuration.
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # Or amend as desired.
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         #
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # state: enabled	# {enabled, disabled}, defaults to enabled
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # mode: 640x480@59.9	# Defaults to preferred mode
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # position: [0, 0]	# Defaults to [0, 0]
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # orientation: normal	# {normal, left, right, inverted}, defaults to normal
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # scale: 1
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]:         # group: 0	# Outputs with the same non-zero value are treated as a single display
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: 8>< ---------------------------------------------------
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.509862] < -warning- > gbm-kms: drmModeCrtcSetGamma failed: Function not implemented
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.554561] <information> gbm-kms: Detected single-GPU DisplayBuffer. Rendering will be sent directly to output
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.568976] <information> mirserver: Cursor disabled
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.571481] < -warning- > gbm-kms-buffer-allocator: Failed to bind EGL Display to Wayland display, falling back to software buffers: /build/mir-K7y0Z4/mir-2.2.0/src/platform/graphics/egl_extensions.cpp(92): Throw in function mir::graphics::EGLExtensions::WaylandExtensions::WaylandExtensions(EGLDisplay)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: Dynamic exception type: boost::wrapexcept<std::runtime_error>
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: std::exception::what: EGL display doesn't support EGL_WL_bind_wayland_display
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.571739] <information> gbm-kms-buffer-allocator: No EGL_EXT_image_dma_buf_import_modifiers support, disabling linux-dmabuf import
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.572018] <information> mircommon: Loading modules from: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.572351] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-gbm-kms.so.19
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.572423] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/graphics-wayland.so.19
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.572485] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/server-x11.so.19
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.572541] <information> mircommon: Loading module: /snap/mir-kiosk/5487/usr/lib/x86_64-linux-gnu/mir/server-platform/input-evdev.so.7
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.575001] <information> mirserver: Selected input driver: mir:evdev-input (version: 2.2.0)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.575132] <information> mirserver: Mir version 2.2.0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.586774] <information> GLRenderer: EGL vendor: Mesa Project
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.586898] <information> GLRenderer: EGL version: 1.4
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.586955] <information> GLRenderer: EGL client APIs: OpenGL OpenGL_ES
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.587005] <information> GLRenderer: EGL extensions: EGL_ANDROID_blob_cache EGL_EXT_buffer_age EGL_EXT_image_dma_buf_import EGL_KHR_cl_event2 EGL_KHR_config_attribs EGL_KHR_create_context EGL_KHR_create_context_no_error EGL_KHR_fence_sync EGL_KHR_get_all_proc_addresses EGL_KHR_gl_colorspace EGL_KHR_gl_renderbuffer_image EGL_KHR_gl_texture_2D_image EGL_KHR_gl_texture_3D_image EGL_KHR_gl_texture_cubemap_image EGL_KHR_image EGL_KHR_image_base EGL_KHR_image_pixmap EGL_KHR_no_config_context EGL_KHR_reusable_sync EGL_KHR_surfaceless_context EGL_EXT_pixel_format_float EGL_KHR_wait_sync EGL_MESA_configless_context EGL_MESA_image_dma_buf_export EGL_MESA_query_driver
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.587897] <information> GLRenderer: GL vendor: VMware, Inc.
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.587975] <information> GLRenderer: GL renderer: llvmpipe (LLVM 10.0.0, 128 bits)
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.590461] <information> GLRenderer: GL version: OpenGL ES 3.1 Mesa 20.0.8
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.590530] <information> GLRenderer: GLSL version: OpenGL ES GLSL ES 3.10
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.590641] <information> GLRenderer: GL extensions: GL_EXT_blend_minmax GL_EXT_multi_draw_arrays GL_EXT_texture_compression_s3tc GL_EXT_texture_compression_dxt1 GL_EXT_texture_compression_rgtc GL_EXT_texture_format_BGRA8888 GL_OES_compressed_ETC1_RGB8_texture GL_OES_depth24 GL_OES_element_index_uint GL_OES_fbo_render_mipmap GL_OES_mapbuffer GL_OES_rgb8_rgba8 GL_OES_standard_derivatives GL_OES_stencil8 GL_OES_texture_3D GL_OES_texture_float GL_OES_texture_float_linear GL_OES_texture_half_float GL_OES_texture_half_float_linear GL_OES_texture_npot GL_OES_vertex_half_float GL_EXT_texture_sRGB_decode GL_OES_EGL_image GL_OES_depth_texture GL_OES_packed_depth_stencil GL_EXT_texture_type_2_10_10_10_REV GL_NV_conditional_render GL_OES_get_program_binary GL_APPLE_texture_max_level GL_EXT_discard_framebuffer GL_EXT_read_format_bgra GL_EXT_frag_depth GL_NV_fbo_color_attachments GL_OES_EGL_image_external GL_OES_EGL_sync GL_OES_vertex_array_object GL_ANGLE_texture_compression_dxt3 GL_ANGLE_texture_compression_dxt5 GL_EXT_occlusion_query_boolean GL_EXT_texture_rg GL_EXT_unpack_subimage GL_NV_draw_buffers GL_NV_read_buffer GL_NV_read_depth GL_NV_read_depth_stencil GL_NV_read_stencil GL_EXT_draw_buffers GL_EXT_map_buffer_range GL_KHR_debug GL_KHR_texture_compression_astc_ldr GL_OES_depth_texture_cube_map GL_OES_required_internalformat GL_OES_surfaceless_context GL_EXT_color_buffer_float GL_EXT_sRGB_write_control GL_EXT_separate_shader_objects GL_EXT_shader_implicit_conversions GL_EXT_shader_integer_mix GL_EXT_base_instance GL_EXT_compressed_ETC1_RGB8_sub_texture GL_EXT_copy_image GL_EXT_draw_buffers_indexed GL_EXT_draw_elements_base_vertex GL_EXT_polygon_offset_clamp GL_EXT_render_snorm GL_EXT_shader_io_blocks GL_EXT_texture_border_clamp GL_EXT_texture_buffer GL_EXT_texture_norm16 GL_EXT_texture_view GL_KHR_context_flush_control GL_NV_image_formats GL_OES_copy_image GL_OES_draw_buffers_indexed GL_OES_draw_elements_base_vertex GL_OES_shader_io_blocks GL_OES_texture_border_clamp GL_OES_texture_buffer GL_OES_texture_stencil8 GL_OES_texture_storage_multisample_2d_array GL_OES_texture_view GL_EXT_blend_func_extended GL_EXT_buffer_storage GL_EXT_float_blend GL_KHR_no_error GL_KHR_texture_compression_astc_sliced_3d GL_OES_EGL_image_external_essl3 GL_OES_shader_image_atomic GL_EXT_clip_cull_distance GL_EXT_disjoint_timer_query GL_EXT_texture_compression_s3tc_srgb GL_MESA_shader_integer_functions GL_EXT_clip_control GL_EXT_texture_compression_bptc GL_KHR_parallel_shader_compile GL_EXT_EGL_image_storage GL_EXT_texture_sRGB_R8 GL_MESA_framebuffer_flip_y GL_EXT_depth_clamp GL_EXT_texture_query_lod
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.590741] <information> GLRenderer: GL max texture size = 8192
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.590796] <information> GLRenderer: GL framebuffer bits: RGBA=8880, depth=0, stencil=0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594413] <information> mirserver: Initial display configuration:
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594515] <information> mirserver: * Output 1: Virtual connected, used
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594567] <information> mirserver: . |_ Physical size 0.0" 0x0mm
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594616] <information> mirserver: . |_ Power is on
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594668] <information> mirserver: . |_ Current mode 640x480 59.93Hz
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594731] <information> mirserver: . |_ Preferred mode 640x480 59.93Hz
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594808] <information> mirserver: . |_ Orientation normal
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594865] <information> mirserver: . |_ Logical size 640x480
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594917] <information> mirserver: . |_ Logical position +0+0
2021-01-13T09:34:34Z mir-kiosk.daemon[4044]: [2021-01-13 09:34:34.594960] <information> mirserver: . |_ Scaling factor: 1.00

Cheers,
Just

4

@jocado it would help to examine dmesg to identify the specific device that fails to open and the reason. (E.g. is it udev or AppArmor that denies.)

5

@alan_g

This seems to be it, it’s the only thing that us denied by the mir-kiosk snap:

[    7.889866] audit: type=1400 audit(1610534057.908:64): apparmor="DENIED" operation="open" profile="snap.mir-kiosk.daemon" name="/run/user/0/" pid=784 comm="mkdir" requested_mask="r" denied_mask="r" fsuid=0 ouid=0

Cheers,
Just

6

No, that’s not it. Drm devices are under /dev.

7

Ahh, sorry I missed the fact you were looking for a device, not just an apparmor deny.

That is the only apparmor entry for mir-kiosk in dmesg.

Cheers,
Just

8

@alan_g

I wonder if it’s related to this. It’s anecdotal so far, but I noticed that on successful attempts these messages are slightly earlier:

[    9.177183] Console: switching to colour dummy device 80x25
[    9.198664] Console: switching to colour frame buffer device 80x30
[    9.211594] virtio_gpu virtio2: fb0: virtio_gpudrmfb frame buffer device

Cheers,
Just

9

Actually, that could be a red herring.

@alan_g if you don’t object, I can share the full dmesg with you privately for working and not working system boots.

Cheers,
Just

10

Ok

(more characters for posting rules)

11

Sadly, while I can see some timing differences in the logs there’s nothing to indicate why Mir is failing to open a DRM node. (Nor which node it is.)

12

@alan_g Thanks for taking the time to look.

I have created a PR in mir-kiosk , please take a look: https://github.com/MirServer/mir-kiosk/pull/53

I think it’s a useful addition anyhow. We are doing that in a few services already that we just want to keep trying to start indefinitely.

Cheers,
Just

13

That PR has been merged and is available on the edge and candidate channels.

We’ve also reviewed Mir’s logging of this failure mode and made improvements to provide more information (such as identifying the node that fails to open). These changes are only on the edge channel.

1 Like
14

Awesome - thanks @alan_g

Cheers,
Just

15

@alan_g So, after check the logging change, I installed the edge version, and I guess this is the information you’re looking for ? :slight_smile:

2021-01-14T12:18:14Z mir-kiosk.daemon[585]: [2021-01-14 12:18:14.965961] <information> gbm-kms: Failed to probe DRM device: /build/mir-i7On7Y/mir-2.2.0+dev200-g0b06c83602/src/server/console/linux_virtual_terminal.cpp(157): T
hrow in function {anonymous}::DRMDevice::DRMDevice(mir::VTFileOperations&, const char*, std::unique_ptr<mir::Device::Observer>, const std::shared_ptr<mir::LinuxVirtualTerminal::DeviceList>&)
2021-01-14T12:18:14Z mir-kiosk.daemon[585]: Dynamic exception type: boost::wrapexcept<std::system_error>
2021-01-14T12:18:14Z mir-kiosk.daemon[585]: std::exception::what: Failed to open DRM device node: Operation not permitted
2021-01-14T12:18:14Z mir-kiosk.daemon[585]: [boost::errinfo_file_name_*] = /dev/dri/card0
16

Yes. That confirms what is happening. Doesn’t explain why (yet), but hopefully the restart-delay will work around that for you.

17

Yes, that’s starting reliably now, which is great :+1:

Cheers, Just