Kdenlive cannot render any projects (stuck in "waiting...")

Running the latest kdenlive 21.08 snap on kubuntu 21.04 with nvidia GPU, I cannot render any projects, as the dialog sits at a waiting state forever.

image

* CREATED JOB WITH ARGS:  ("/snap/kdenlive/39/usr/bin/melt-7", "/tmp/kdenlive-eYAlDK.mlt", "/home/sbutcher/Videos/Kdenlive/pytorch2.wav", "-pid:161521", "-out", "11649")
starting kdenlive_render process using:  "/snap/kdenlive/39/usr/bin/kdenlive_render"
Qt: Session management error: Could not open network socket
dbus[161834]: arguments to dbus_message_new_method_call() were incorrect, assertion "_dbus_check_is_valid_path (path)" failed in file ../../../dbus/dbus-message.c line 1366.
This is normally a bug in some application using the D-Bus library.

  D-Bus not built with -rdynamic so unable to print a backtrace

I also see the following in /var/log/syslog

Sep 21 12:14:19 yoda kernel: [118451.632793] audit: type=1400 audit(1632222859.725:603524): apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libudev.so.1.6.17" pid=161834 comm="kdenlive_render" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0

i have tried uninstalling and reinstalling the snap to no avail.

1 Like

I see the same same problem, also on kubuntu 21.04 with nvidia drivers. I confess I’ve seen it before but haven’t done anything about it.

So I installed this snap since I was asked to take a look at it, and I can reproduce not being able to render anything and I see a bunch of system journal denials, it appears that a whole bunch of paths for some reason are being resolved as /snap/core20/current/lib/foo/… instead of just being accessed directly as /lib/foo/… so someone should look into why this snap seems to be trying to defeat the mount namespace and reach into the core20 snap directly. If I were to guess, I would guess that this snap used to be classic and has code that is doing it this way because that’s the thing to do for classic snaps (or it is incorrectly borrowing code from another classic snap that does it correctly this way).

Also I see some denials that would be resolved by adding hardware-observe plug to the snap, which makes sense to me since it’s a rendering snap that probably needs to know about the hardware it is running on.

There are also denials for /etc/xdg/menus and /etc/xdg/menus/applications-merged, but I think maybe this is just indicative of not having the right set of snap specific XDG env variables defined?

There are also some paths we don’t seem to have support for anywhere that we might need to add in snapd mainly:

  • /proc/sys/kernel/core_pattern <- this probably could be added to the default template I think, it makes sense for snaps to be able to read their own core dumps since core dumps get put in the snaps current working directory, but this denial is probably harmless for now, just less debugging is possible
  • /var/lib/snapd/hostfs/usr/lib/x86_64-linux-gnu/libOpenGL.so.0.0.0 <- this one needs to be added to the opengl interface, seems we added it to snap-confine mounts, but not to the corresponding snapd opengl interface

Finally there are a number of D-Bus denials for the following things:

  • path="/org/freedesktop/UPower" interface="org.freedesktop.DBus.Introspectable" member="Introspect" mask="send" name="org.freedesktop.UPower"
  • path="/org/freedesktop/UDisks2/block_devices" interface="org.freedesktop.DBus.Introspectable" member="Introspect" mask="send" name="org.freedesktop.UDisks2"
  • path="/org/freedesktop/UDisks2/drives" interface="org.freedesktop.DBus.Introspectable" member="Introspect" mask="send" name="org.freedesktop.UDisks2"

which I’m not sure if this snap really needs to be able to talk to UDisks2 or not, but if it really does it can do so with the udisks2 plug.

Hope this helps in debugging other problems with the snap.

1 Like

Oh also there are two seccomp denials for sched_setattr and setpriority, neither of which are likely to be granted to this snap since they are considered somewhat privileged and we currently lack the ability to do fine grained pid filtering for syscalls in seccomp to limit the pids that a snap can use syscalls with to only their own snap cgroup.

Thanks for having a look. I agree, the kdenlive_render supporting binary seems to be crashing when it tries to load /snap/core20/usr/lib/libacl.0 instead of /usr/lib/libacl.0 (I’m paraphrasing). I don’t know why it would do that. I’ll keep playing around to see if anything helps.

I’ve removed kdenlive from stable for now until we work this out

Those core20 denials seem to be caused by the rpath of libpulsecommon-13.99.so, don’t they?

$ patchelf --print-rpath /snap/kde-frameworks-5-qt-5-15-3-core20/current/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-13.99.so
$ORIGIN/..:/snap/core20/current/lib/x86_64-linux-gnu

e.g.

249875:	find library=liblzma.so.5 [0]; searching
    249875:	 search path=/snap/kdenlive/39/kf5/usr/lib/x86_64-linux-gnu/pulseaudio/..:/snap/core20/current/lib/x86_64-linux-gnu		(RPATH from file /snap/kdenlive/39/kf5/usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-13.99.so)
    249875:	  trying file=/snap/kdenlive/39/kf5/usr/lib/x86_64-linux-gnu/pulseaudio/../liblzma.so.5
    249875:	  trying file=/snap/core20/current/lib/x86_64-linux-gnu/liblzma.so.5
[...]

Is this any different from any other library in there?
e.g.

>patchelf --print-rpath /snap/kde-frameworks-5-qt-5-15-3-core20/current/usr/lib/x86_64-linux-gnu/libcanberra-0.30/libcanberra-alsa.so
$ORIGIN/..:/snap/core20/current/lib/x86_64-linux-gnu

Probably not. I’m just pointing out the reason for those denials. The loader tries the rpath first, and thus we get a denial.

The render queue problem seems related to this:

starting kdenlive_render process using:  "/snap/kdenlive/39/usr/bin/kdenlive_render"
Qt: Session management error: Could not open network socket
No org.kde.JobViewServer registered, trying to start kuiserver
Failed to start kuiserver

Ah very insightful, this seems to imply that the kde-frameworks-5-qt-5-15-3-core20 snap is built incorrectly, I’m not sure why it was built such that the dynamic libraries there have rpath setup to look in /snap/core20/current/… unless that content snap was built to be consumed by classic snaps somehow?

Do you see any journal denials on your system when this happens? I don’t see this message on the terminal when I tried testing kdenlive last week by just doing snap run kdenlive

Nothing interesting:

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="dbus_method_call"  bus="session" path="/org/freedesktop/DBus" interface="org.freedesktop.DBus" member="ListNames" mask="send" name="org.freedesktop.DBus" pid=21594 label="snap.kdenlive.kdenlive" peer_label="unconfined"
DBus access

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="dbus_method_call"  bus="session" path="/org/a11y/bus" interface="org.freedesktop.DBus.Properties" member="Get" mask="send" name="org.a11y.Bus" pid=21594 label="snap.kdenlive.kdenlive" peer_pid=7265 peer_label="unconfined"
DBus access

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libsystemd.so.0.28.0" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libsystemd.so.0.28.0 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libwrap.so.0.7.6" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libwrap.so.0.7.6 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libapparmor.so.1.6.1" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libapparmor.so.1.6.1 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/librt-2.31.so" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/librt-2.31.so (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/liblzma.so.5.2.4" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/liblzma.so.5.2.4 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/liblz4.so.1.9.2" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/liblz4.so.1.9.2 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libgcrypt.so.20.2.5" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libgcrypt.so.20.2.5 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libnsl-2.31.so" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libnsl-2.31.so (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libresolv-2.31.so" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libresolv-2.31.so (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/snap/core20/1081/usr/lib/x86_64-linux-gnu/libgpg-error.so.0.28.0" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /snap/core20/1081/usr/lib/x86_64-linux-gnu/libgpg-error.so.0.28.0 (read)
Suggestion:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="open" profile="snap.kdenlive.kdenlive" name="/var/lib/snapd/hostfs/usr/lib/x86_64-linux-gnu/libOpenGL.so.0.0.0" pid=21600 comm="melt-7" requested_mask="r" denied_mask="r" fsuid=1001 ouid=0
File: /var/lib/snapd/hostfs/usr/lib/x86_64-linux-gnu/libOpenGL.so.0.0.0 (read)
Suggestions:
* adjust program to read necessary files from $SNAP, $SNAP_DATA, $SNAP_COMMON, $SNAP_USER_DATA or $SNAP_USER_COMMON
* adjust snap to use snap layouts (https://forum.snapcraft.io/t/snap-layouts/7207)

= AppArmor =
Time: Sep 29 09:55:54
Log: apparmor="DENIED" operation="dbus_method_call"  bus="session" path="/org/a11y/bus" interface="org.freedesktop.DBus.Properties" member="Get" mask="send" name="org.a11y.Bus" pid=21594 label="snap.kdenlive.kdenlive" peer_pid=7265 peer_label="unconfined"
DBus access

An interesting observation: For me, the videos get rendered just fine. It’s just that kdenlive does not get feedback from its renderer process. So that’s where we need to investigate. So probably dbus related: https://github.com/KDE/kdenlive/blob/a24b8fe294905cd2f6f562555ca5271d5bb936e8/renderer/renderjob.cpp#L273

I think it’s a dbus permission problem. If you install with devmode and set QDBUS_DEBUG=1, you can see the working communication between kdenlive_render and kdenlive.

I think it fails here:

QDBusConnectionPrivate(0x7f52e0003c00) sending message: QDBusMessage(type=MethodCall, service="org.freedesktop.DBus", path="/org/freedesktop/DBus", interface="org.freedesktop.DBus", member="ListNames", signature="", contents=() )

QDBusConnectionPrivate(0x7f52e0003c00) got message reply: QDBusMessage(type=Error, service="org.freedesktop.DBus", error name="org.freedesktop.DBus.Error.AccessDenied", error message="An AppArmor policy prevents this sender from sending this message to this recipient; type=\"method_call\", sender=\":1.286\" (uid=1001 pid=68175 comm=\"/snap/kdenlive/x4/usr/bin/kdenlive_render /snap/kd\" label=\"snap.kdenlive.kdenlive (enforce)\") interface=\"org.freedesktop.DBus\" member=\"ListNames\" error name=\"(unset)\" requested_reply=\"0\" destination=\"org.freedesktop.DBus\" (bus)", signature="s", contents=("An AppArmor policy prevents this sender from sending this message to this recipient; type="method_call", sender=":1.286" (uid=1001 pid=68175 comm="/snap/kdenlive/x4/usr/bin/kdenlive_render /snap/kd" label="snap.kdenlive.kdenlive (enforce)") interface="org.freedesktop.DBus" member="ListNames" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (bus)") )

which means it probably needs the system-observe interface. I tried and this seems to solve the problem. Is that an interface that makes sense for a video editor, and would autoconnect be granted?

1 Like

Yes I think system-observe is reasonable to be granted auto-connection for a video editor, if one of the snap collaborators can add system-observe to the snap and then start a forum topic in #store-requests for auto-connection we can get that moving.

I’m still very confused why the qt content snap has these rpaths set like that, it probably needs to be looked at more

1 Like

@jriddell https://invent.kde.org/packaging/snapcraft-kde-applications/-/merge_requests/2

building https://build.neon.kde.org/view/Snaps/job/focal_release_forks_kdenlive_snap_amd64/

Oh no. I proposed the change for the wrong snap :man_facepalming: (ark instead of kdenlive). Sorry. See https://invent.kde.org/packaging/snapcraft-kde-applications/-/merge_requests/3 for the real fix.

mm, indeed. Building again https://build.neon.kde.org/view/Snaps/job/focal_release_forks_kdenlive_snap_amd64/

Revision 44 solves the problem for me with system-observe connected. You should request an auto-connection and then publish it to stable.

Consider https://build.neon.kde.org/view/Snaps/job/kde-frameworks-5-qt-5-15-3-core20-release_amd64.snap/lastSuccessfulBuild/artifact/build.snapcraft.yaml

specifically

kf5:
        after: []
        plugin: nil
        build-attributes:
        - enable-patchelf

I reckon this is the culprit for those strange rpaths. This stems from https://invent.kde.org/packaging/snap-kf5/-/blob/core20/atomize-debs.rb#L205, I think.
But that seems to be an intentional addition:
https://invent.kde.org/packaging/snap-kf5/-/commit/507bb1027b2a077247dee95502ffc55abd8e3f7c

From: Jonathan Riddell jr@jriddell.org
Date: Tue, 9 Feb 2021 10:52:34 +0000
Subject: [PATCH] enable patchelf as we can not do the hack of patchelf
manually as we did in core18 (see Rakefile) cos now snapcraft is installed as
a readonly snap

Probably something for @sergiusens to comment on when he is back