Bug#994865: Delayed start due to Pipewire not running

[Vincent Bernat]

Package: xdg-desktop-portal
Version: 1.10.1-1
Severity: normal

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Hey!

Since upgrading to 1.10.1-1, xdg-desktop-portal service takes a lot of
time to start on a desktop not using Pipewire.

09:52 ❱ journalctl -b0 --user-unit=xdg-desktop-portal
- -- Journal begins at Sat 2021-07-31 17:43:34 CEST, ends at Wed 2021-09-22 09:50:26 CEST. --
Sep 22 09:39:02 neo systemd[1655]: Starting Portal service...
Sep 22 09:39:27 neo xdg-desktop-portal[2274]: context 0x56081dd4ed40: can't load config client.conf: No such file or directory
Sep 22 09:39:27 neo xdg-desktop-portal[2274]: context 0x56081dd4ed40: can't load config client.conf: No such file or directory
Sep 22 09:39:27 neo xdg-desktop-por[2274]: Failed connect to PipeWire: Couldn't create PipeWire context
Sep 22 09:39:27 neo systemd[1655]: Started Portal service.

In turn, this seems to delay many other things that rely on this
service. For example, VTE terminals are delayed.

- -- System Information:
Debian Release: bookworm/sid
APT prefers unstable-debug
APT policy: (500, 'unstable-debug'), (500, 'unstable'), (500, 'testing'), (101, 'experimental-debug'), (101, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 5.14.0-1-amd64 (SMP w/12 CPU threads)
Locale: LANG=C.UTF-8, LC_CTYPE=C.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages xdg-desktop-portal depends on:
ii bubblewrap 0.5.0-1
ii dbus-user-session [default-dbus-session-bus] 1.12.20-2
ii dbus-x11 [dbus-session-bus] 1.12.20-2
ii fuse3 [fuse] 3.10.5-1
ii libc6 2.32-4
ii libfuse2 2.9.9-5
ii libgdk-pixbuf-2.0-0 2.42.6+dfsg-2
ii libglib2.0-0 2.70.0-1
ii libjson-glib-1.0-0 1.6.6-1
ii libpipewire-0.3-0 0.3.36-1

xdg-desktop-portal recommends no packages.

xdg-desktop-portal suggests no packages.

- -- no debconf information

-----BEGIN PGP SIGNATURE-----

iQJGBAEBCAAwFiEErvI0h2bzccaJpzYAlaQv6DU1JfkFAmFK4UMSHGJlcm5hdEBk
ZWJpYW4ub3JnAAoJEJWkL+g1NSX5PdQP/2ucWQj0hy8lUcziq0ipJAXrA4gAgw/4
0ItN/TXnFvjFEphm8GNf+phCX1GMMpZ8hDsd0GSrh075heabLeslT5SgTTzf66Hj
uTXCrtGyCWRfy4Gejs24FqfUbRthWJKUfLfhoWzwdmltxrVCupaMUVnUmGHVnc/+
bb17WtIGBRgXuVn7i3o9HbmyeN/g52j9hwq8r01gdpr20jtlSgntj8JrHVZa0FIy
d9Le4GCDEtJixvoS3Rd34anLOvUituma9ykrGYR+H3HGSKCTZYBMGlG5USUMxvyz
p+GaBP+/RRUyW4ylCtack9VdJxlMFqbM5qJX/KZOTQGOEp82NqCHirUtoVvHV1NO
H7q9KZ6a5zZQ7ow+orfZ68pHnlZW0is1JLr2ZQM5S/lONsUFlmXlfnTvk/WzjtRf
wO7WE85eg1tHtgpgxzytZTl/9LAV7yeY0UL6hA6iNRwGjAm8nD6BwvUaBcOelhMU
zR+8pzDoFPRmfVxHQeJEfOTWI7q6RMdXOonUF3t+v1h0MqRN+MWkdjqcBIdPDN6g
mWwaOr4gr7Y+c5pBrvO0DzoegpiHEkC8LDF1cVSeXTJDbOoSGdR3fPCvdZEoPBTD
/BTOZ2foZgZfHiziGoACis/C9iPB7vWRaKmtumzi2UZvqQ6R1IffbZca2Ljgnd7

[Simon McVittie]

Control: tags -1 + moreinfo

Post by Vincent Bernat
Since upgrading to 1.10.1-1, xdg-desktop-portal service takes a lot of
time to start on a desktop not using Pipewire.

Looking at the diff, I don't understand why this particular upgrade
would trigger this: the only Pipewire-related change was to add a 10
second timeout on some operations, instead of waiting indefinitely.

Are you sure this is triggered by upgrading xdg-desktop-portal, and not
by upgrading some related package - perhaps x-d-p-gtk or pipewire?

The 25 second delay you reported is the default timeout for D-Bus method
calls, so I suspect what you are seeing here is a D-Bus method call that
never gets a reply and times out.

I'm less confident than you are that the missing Pipewire service is the
root cause here. I think the log you reported is equally consistent with
some unrelated D-Bus method call starting, timing out 25 seconds later,
and then x-d-p proceeding through its remaining startup tasks, one of
which is to try to talk to Pipewire to decide whether it can provide
video-related portals (screen-sharing and remote-desktop).

It might be helpful to run

/usr/libexec/xdg-desktop-portal --verbose --replace

or even

G_MESSAGES_DEBUG=all /usr/libexec/xdg-desktop-portal --verbose --replace

and report what the output is, and where in the output the 25 second delay
happened.

Doing the same for xdg-desktop-portal-gtk (or whatever other backend you
are using, if not -gtk) could also provide useful information; or watching
the output of `dbus-monitor --session` might also be helpful, although
there will be a lot of noise from unrelated D-Bus operations in that.

After running one of these services with --replace, you can terminate it
with Ctrl+C and a replacement will be started in the background by D-Bus
activation the next time it is needed.

Post by Vincent Bernat
In turn, this seems to delay many other things that rely on this
service. For example, VTE terminals are delayed.

I would have expected xdg-desktop-portal to start up at most once per
GUI login session, so I would have expected you to only see a delay once.

If you're seeing a delay in opening VTE terminals, one possible reason
is that when /etc/profile.d/flatpak.sh runs
`GIO_USE_VFS=local flatpak --installations`, it might be doing IPC to some
service that takes a long time.

If you run

G_MESSAGES_DEBUG=all flatpak --installations -vv

is that also delayed, and are there any clues in its output?

smcv

[Vincent Bernat]

Post by Simon McVittie

Post by Vincent Bernat
Since upgrading to 1.10.1-1, xdg-desktop-portal service takes a lot of
time to start on a desktop not using Pipewire.

Looking at the diff, I don't understand why this particular upgrade
would trigger this: the only Pipewire-related change was to add a 10
second timeout on some operations, instead of waiting indefinitely.
Are you sure this is triggered by upgrading xdg-desktop-portal, and not
by upgrading some related package - perhaps x-d-p-gtk or pipewire?

I don't have Pipewire installed (but it was installed at some point). I
see that on a previous boot, the same error was here but did not
introduce a delay.

Post by Simon McVittie
The 25 second delay you reported is the default timeout for D-Bus method
calls, so I suspect what you are seeing here is a D-Bus method call that
never gets a reply and times out.
I'm less confident than you are that the missing Pipewire service is the
root cause here. I think the log you reported is equally consistent with
some unrelated D-Bus method call starting, timing out 25 seconds later,
and then x-d-p proceeding through its remaining startup tasks, one of
which is to try to talk to Pipewire to decide whether it can provide
video-related portals (screen-sharing and remote-desktop).
It might be helpful to run
/usr/libexec/xdg-desktop-portal --verbose --replace
or even
G_MESSAGES_DEBUG=all /usr/libexec/xdg-desktop-portal --verbose --replace
and report what the output is, and where in the output the 25 second delay
happened.

Unfortunately, it seems the problem only happens on boot. I have added
--verbose for the next boot and I'll keep you posted.

Post by Simon McVittie
Doing the same for xdg-desktop-portal-gtk (or whatever other backend you
are using, if not -gtk) could also provide useful information; or watching
the output of `dbus-monitor --session` might also be helpful, although
there will be a lot of noise from unrelated D-Bus operations in that.

xdg-desktop-portal-gtk started without delay and its log does not have
any error.

Post by Simon McVittie

Post by Vincent Bernat
In turn, this seems to delay many other things that rely on this
service. For example, VTE terminals are delayed.

I would have expected xdg-desktop-portal to start up at most once per
GUI login session, so I would have expected you to only see a delay once.

Yes, the delay happens only once.

Post by Simon McVittie
If you're seeing a delay in opening VTE terminals, one possible reason
is that when /etc/profile.d/flatpak.sh runs
`GIO_USE_VFS=local flatpak --installations`, it might be doing IPC to some
service that takes a long time.
If you run
G_MESSAGES_DEBUG=all flatpak --installations -vv
is that also delayed, and are there any clues in its output?

The terminal window does is not displayed. The delay is related to the
fact that VTE terminals (like Gnome Terminal) are "GTK apps" and they
synchronize with DBus to find an existing instance if any. For some
reason, this requires a desktop portal.

So, I'll reboot before the end of the week and I'll tell you what's in
the logs.

[Simon McVittie]

Post by Vincent Bernat

Post by Simon McVittie
Are you sure this is triggered by upgrading xdg-desktop-portal, and not
by upgrading some related package - perhaps x-d-p-gtk or pipewire?

I don't have Pipewire installed (but it was installed at some point).

You do have the client library libpipewire-0.3-0, though, because
xdg-desktop-portal Depends on it - so an upgrade to that package might
have been what triggered this.

(Or, what you're seeing might be completely unrelated to Pipewire.)

Post by Vincent Bernat
Unfortunately, it seems the problem only happens on boot.

Logout/login might be sufficient to reproduce this with less loss
of state.

What else is going on in the Journal at the time that the delay happens?
It would be ideal if you could do something like:

- log in
- wait a few seconds for everything to settle, to reduce irrelevant logging
- use xterm or some other unaffected mechanism to run
`logger -t timestamp "before delayed start"`
- start an affected GTK app

I see from your initial bug report that you are using systemd as pid 1,
systemd --user, and dbus-user-session (i.e. dbus-daemon --session is
running as a systemd --user unit). Is that correct?

What desktop environment are you using? Or if you have made your own
desktop environment from individual components, what are the major
components like window manager and session manager (if any)?

It might be helpful to run the affected GTK app with G_MESSAGES_DEBUG=all
in the environment. This doesn't work for gnome-terminal because
gnome-terminal is weird, but gnome-terminal -vv is close enough.

Post by Vincent Bernat
the delay happens only once.

This probably indicates that it's to do with some other component that
xdg-desktop-portal talks to, which doesn't start up properly or doesn't
reply to a method call the first time. On the second and subsequent
attempts, if the other component is already running, then x-d-p is more
likely to be able to communicate with it immediately, hence no delay.

Post by Vincent Bernat
The delay is related to the
fact that VTE terminals (like Gnome Terminal) are "GTK apps" and they
synchronize with DBus to find an existing instance if any.

Most components that talk to xdg-desktop-portal only do so when they find
that they're running as a Flatpak app, or maybe some other sandboxed app
framework like Snap. Just to rule some things out: are you launching
Flatpak and/or Snap apps? Or if not, do you have environment variable
GTK_USE_PORTAL set?

One thing for which the GTK 3 implementation of GtkApplication *does*
use xdg-desktop-portal, even when not in a container, is: if it was
unable to communicate with gnome-session or XFCE's equivalent, it will
try to use xdg-desktop-portal's Inhibit proxy, to attach to an appropriate
desktop-specific mechanism for monitoring desktop session state if one is
available. It's possible that it's doing this more often than it really
needs to, or more synchronously than it really needs to.

smcv

[Vincent Bernat]

Let me reboot at the end of the day with just xdg-desktop-portal in
verbose mode, it may be enough to find the cause. If not, I will apply
your other tricks.

OK, a bit late, but on verbose, I get:

Sep 30 07:57:56 chocobo xdg-desktop-portal[1730]: XDP: providing portal org.freedesktop.portal.FileChooser
Sep 30 07:57:56 chocobo xdg-desktop-portal[1730]: XDP: Falling back to gtk.portal for org.freedesktop.impl.portal.AppChooser
Sep 30 07:58:21 chocobo xdg-desktop-portal[1730]: XDP: Failed to create FileManager proxy: Error calling StartServiceByName for org.freedesktop.FileManager1: Timeout was reached
Sep 30 07:58:21 chocobo xdg-desktop-portal[1730]: XDP: providing portal org.freedesktop.portal.OpenURI
Sep 30 07:58:21 chocobo xdg-desktop-portal[1730]: XDP: Falling back to gtk.portal for org.freedesktop.impl.portal.Print

I have Thunar installed and I think there may be just a dependency loop:

Sep 30 07:58:21 chocobo dbus-daemon[1433]: [session uid=1000 pid=1433] Successfully activated service 'org.freedesktop.portal.Desktop'
Sep 30 07:58:22 chocobo dbus-daemon[1433]: [session uid=1000 pid=1433] Successfully activated service 'org.freedesktop.FileManager1'

08:07 ❱ journalctl -b0 --user-unit=thunar.service
-- Journal begins at Sun 2021-08-01 16:26:21 CEST, ends at Thu 2021-09-30 08:05:07 CEST. --
Sep 30 07:57:56 chocobo systemd[1402]: Starting Thunar file manager...
Sep 30 07:58:22 chocobo systemd[1402]: Started Thunar file manager.

So, the bug may be more in Thunar. This looks like:

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=929490
https://www.reddit.com/r/swaywm/comments/ptwd6p/thunar_and_xdgdesktopportal_block_each_other/

Personally, I don't care much about org.freedesktop.FileManager1 and I
would prefer this dbus service to not be provided at all. I'll try to
mask thunar.service to avoid this.

[Simon McVittie]

Control: retitle -1 xdg-desktop-portal: Delayed start due to deadlock with Thunar

Post by Vincent Bernat
Sep 30 07:58:21 chocobo xdg-desktop-portal[1730]: XDP: Failed to create FileManager proxy: Error calling StartServiceByName for org.freedesktop.FileManager1: Timeout was reached

Ugh, the FileManager interface strikes again...

I think file managers being service-activatable for the FileManager
interface is a bad design, to be honest. This means that if you have more
than one file manager installed (for example Thunar + Nautilus, if you
are an XFCE user who shares a machine with a GNOME user), D-Bus activation
for that interface name will give you a randomly chosen file manager, which
I suspect is not what anyone wants.

However, the interface name exists, each desktop's file manager seems to
be service-activatable for that name, and removing that would be a feature
regression; so we're stuck with it.

Post by Vincent Bernat
I have Thunar installed and I think there may be just a dependency loop

Yes, I think that's it. GTK 3 (specifically GtkApplication) sets up
communication with the Inhibit portal, which it uses as a desktop-neutral
way to watch screensaver status and implement gtk_application_inhibit().
Meanwhile, xdg-desktop-portal sets up communication with the implementation
of FileManager (whatever that might be), to use it to open directories if
requested.

This would be fine, except both of them do this with blocking D-Bus calls,
which makes them deadlock: each is waiting for a reply from the other.

Luckily, this doesn't seem to be critical functionality for
xdg-desktop-portal, so I think we can turn at least the x-d-p side into
an async D-Bus call.

On the GTK side, this is an accident waiting to happen, so ideally GTK
would use async calls for all this too. However, the API of GtkApplication
isn't really set up for that.

smcv