FS#50871 - [gvfs] `systemctl --user start gvfs-daemon` results in timeout

Attached to Project: Arch Linux
Opened by Simon Kohlmeyer (voyd) - Thursday, 22 September 2016, 14:42 GMT
Last edited by Dave Reisner (falconindy) - Tuesday, 15 November 2016, 15:40 GMT
Task Type Bug Report
Category Packages: Extra
Status Closed
Assigned To Jan de Groot (JGC)
Jan Alexander Steffens (heftig)
Architecture x86_64
Severity Medium
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 2
Private No

Details

I'm using i3 with lightdm. I migrated to lightdm from slim a few days ago, which didn't affect the problem.

== Problem

When I try to start the gvfs-daemon using
systemctl --user start gvfs-daemon
I get the following output

voyd@kanne> systemctl --user start gvfs-daemon ~
Job for gvfs-daemon.service failed because a timeout was exceeded.
See "systemctl status gvfs-daemon.service" and "journalctl -xe" for details.

Here is some more information

voyd@kanne> systemctl --user status gvfs-daemon ~
● gvfs-daemon.service - Virtual filesystem service
Loaded: loaded (/usr/lib/systemd/user/gvfs-daemon.service; static; vendor preset: enabled)
Active: failed (Result: timeout) since Do 2016-09-22 16:10:01 CEST; 4s ago
Process: 8660 ExecStart=/usr/lib/gvfs/gvfsd (code=killed, signal=TERM)
Main PID: 8660 (code=killed, signal=TERM)
CGroup: /user.slice/user-1000.slice/user@1000.service/gvfs-daemon.service

Sep 22 16:08:31 kanne systemd[1072]: Starting Virtual filesystem service...
Sep 22 16:10:01 kanne systemd[1072]: gvfs-daemon.service: Start operation timed out. Terminating.
Sep 22 16:10:01 kanne systemd[1072]: Failed to start Virtual filesystem service.
Sep 22 16:10:01 kanne systemd[1072]: gvfs-daemon.service: Unit entered failed state.
Sep 22 16:10:01 kanne systemd[1072]: gvfs-daemon.service: Failed with result 'timeout'.

It seems that this unix stackexchange question refers to the same problem:
https://unix.stackexchange.com/questions/308036/why-does-gvfs-with-systemd-dbus-timeout

== Impact
gvfsd is automatically started in a variety of situations including opening my pdf read (zathura) as
well as when I open the "Save File" dialog in any application. Everytime this happens, there is
a large delay (logs say 2:30 minutes).

== Theories/Background
My theory is that systemd does not recognize that the gvfs daemon successfully started up.

The service file for gvfs-daemon is /usr/lib/systemd/user/gvfs-daemon.service

[Unit]
Description=Virtual filesystem service

[Service]
ExecStart=/usr/lib/gvfs/gvfsd
Type=dbus
BusName=org.gtk.vfs.Daemon

`Type=dbus` causes systemd to wait until the started application claimed the BusName, in this case
`org.gtk.vfs.Daemon`, on the session bus.

using `dbus-monitor` during `systemctl --user start gvfs-daemon`, I could see the following lines

signal time=1474554284.530889 sender=org.freedesktop.DBus -> destination=:1.2244 serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
string "org.gtk.vfs.Daemon"

I don't know a lot about DBus, but it seems to me that gvfsd did in fact start up correctly.
The whole log (with a few blank lines inserted to distinguish start from timeout) is attached.

I was considering that my session wasn't using the systemd-created session bus, but:

voyd@kanne> ps aux | grep dbus
dbus 682 0.0 0.0 33152 4076 ? Ss 13:42 0:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
voyd 1180 0.0 0.0 32952 3524 ? Ss 13:53 0:01 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation
voyd 26925 0.0 0.0 12288 2524 pts/6 S+ 16:31 0:00 grep dbus

voyd@kanne> systemctl --user status dbus ~
● dbus.service - D-Bus User Message Bus
Loaded: loaded (/usr/lib/systemd/user/dbus.service; static; vendor preset: enabled)
Active: active (running) since Do 2016-09-22 13:53:28 CEST; 2h 46min ago
Docs: man:dbus-daemon(1)
Main PID: 1180 (dbus-daemon)
CGroup: /user.slice/user-1000.slice/user@1000.service/dbus.service
├─1180 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation
├─3336 /usr/lib/GConf/gconfd-2
└─3438 /usr/lib/dconf/dconf-service

<full log is below>

voyd@kanne> journalctl --user-unit=dbus.service -b
-- Logs begin at So 2015-05-17 18:14:45 CEST, end at Do 2016-09-22 16:39:19 CEST. --
Sep 22 13:53:28 kanne systemd[1072]: Started D-Bus User Message Bus.
Sep 22 13:53:37 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.freedesktop.Notifications' unit='xfce4-notifyd.service'
Sep 22 13:54:00 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Sep 22 13:55:28 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 13:55:37 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.Notifications': timed out
Sep 22 13:56:00 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.Daemon': timed out
Sep 22 13:56:22 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Sep 22 13:58:22 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.Daemon': timed out
Sep 22 13:58:22 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 13:59:43 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service'
Sep 22 13:59:43 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Sep 22 14:00:22 kanne dbus-daemon[1180]: Activating service name='org.gnome.GConf'
Sep 22 14:00:22 kanne dbus-daemon[1180]: Successfully activated service 'org.gnome.GConf'
Sep 22 14:00:32 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.freedesktop.Notifications' unit='xfce4-notifyd.service'
Sep 22 14:00:57 kanne dbus-daemon[1180]: Activating service name='ca.desrt.dconf'
Sep 22 14:00:57 kanne dbus-daemon[1180]: Successfully activated service 'ca.desrt.dconf'
Sep 22 14:01:41 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 14:01:43 kanne dbus-daemon[1180]: Failed to activate service 'org.a11y.Bus': timed out
Sep 22 14:01:43 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.Daemon': timed out
Sep 22 14:02:32 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.Notifications': timed out
Sep 22 14:55:38 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Sep 22 14:56:03 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.UDisks2VolumeMonitor' unit='gvfs-udisks2-volume-monitor.service'
Sep 22 14:56:28 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Sep 22 14:56:53 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Sep 22 14:57:38 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.Daemon': timed out
Sep 22 14:57:38 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 14:58:03 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.UDisks2VolumeMonitor': timed out
Sep 22 14:58:28 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.MTPVolumeMonitor': timed out
Sep 22 14:58:53 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.GPhoto2VolumeMonitor': timed out
Sep 22 15:00:31 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Sep 22 15:00:56 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Sep 22 15:02:31 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.MTPVolumeMonitor': timed out
Sep 22 15:02:31 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 15:02:56 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.GPhoto2VolumeMonitor': timed out
Sep 22 15:15:47 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Sep 22 15:16:12 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Sep 22 15:17:47 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.MTPVolumeMonitor': timed out
Sep 22 15:17:47 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 15:18:12 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.GPhoto2VolumeMonitor': timed out
Sep 22 15:18:16 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Sep 22 15:18:41 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Sep 22 15:20:16 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.MTPVolumeMonitor': timed out
Sep 22 15:20:16 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 15:20:41 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.GPhoto2VolumeMonitor': timed out
Sep 22 16:01:20 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service'
Sep 22 16:01:45 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.UDisks2VolumeMonitor' unit='gvfs-udisks2-volume-monitor.service'
Sep 22 16:02:10 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service'
Sep 22 16:02:35 kanne dbus-daemon[1180]: Activating systemd to hand-off: service name='org.gtk.vfs.GPhoto2VolumeMonitor' unit='gvfs-gphoto2-volume-monitor.service'
Sep 22 16:03:20 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.Daemon': timed out
Sep 22 16:03:20 kanne dbus-daemon[1180]: Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 22 16:03:45 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.UDisks2VolumeMonitor': timed out
Sep 22 16:04:10 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.MTPVolumeMonitor': timed out
Sep 22 16:04:35 kanne dbus-daemon[1180]: Failed to activate service 'org.gtk.vfs.GPhoto2VolumeMonitor': timed out
Sep 22 16:22:36 kanne dbus-daemon[1180]: Connection :1.2210 (uid=1000 pid=7019 comm="dbus-monitor ") became a monitor.
Sep 22 16:31:13 kanne dbus-daemon[1180]: Monitoring connection :1.2210 closed.

My theory at this point is that systemd doesn't properly monitor the session bus it has created.

Any ideas how I can pinpoint this further or suggestions what I could try would be appreciated.
The delay everywhere is really annoying.

Best wishes,
voyd
This task depends upon

Closed by  Dave Reisner (falconindy)
Tuesday, 15 November 2016, 15:40 GMT
Reason for closing:  Not a bug
Additional comments about closing:  user error
Comment by Simon Kohlmeyer (voyd) - Thursday, 22 September 2016, 14:44 GMT
Forgot attachment.
Comment by Jan Alexander Steffens (heftig) - Thursday, 29 September 2016, 14:53 GMT
Output of busctl --user?
Comment by Simon Kohlmeyer (voyd) - Thursday, 29 September 2016, 15:32 GMT
Attached. I did not know of busctl until now.

What were you expecting to find out from this output?
Comment by Jan Alexander Steffens (heftig) - Thursday, 29 September 2016, 15:55 GMT
org.freedesktop.systemd1 isn't connected to the bus, so this is indeed the issue.
Comment by Simon Kohlmeyer (voyd) - Thursday, 03 November 2016, 12:02 GMT
EDIT: busctl shows the system bus, so the rest of this comment doesn't make sense. Systemd still isn't connected to the session bus.

=====================
I still see this problem, but `busctl` contains the following line now:

org.freedesktop.systemd1 1 systemd root :1.0 init.scope - -

So I assume that systemd is connected to the user bus.
While running `systemctl --user start gvfs-daemon`, `dbus-monitor` shows the following entry:

signal time=1478172931.456523 sender=org.freedesktop.DBus -> destination=:1.322 serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
string "org.gtk.vfs.Daemon"

:1.322 is the gvfs-daemon itself.

Running the same thing on a machine with similar configuration but without this issue prints

method call time=1478174361.631801 sender=:1.0 -> destination=org.freedesktop.DBus serial=13 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
string "type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0='org.gtk.vfs.Daemon'"

As the first entry in dbus-monitor when running `systemctl --user start gvfs-daemon`. So I assume that systemd forgets to watch for the signal.
Comment by Jan Alexander Steffens (heftig) - Thursday, 03 November 2016, 12:55 GMT
You ran `busctl` instead of `busctl --user`.

Are you setting DBUS_SESSION_BUS_ADDRESS anywhere in your dotfiles or /etc/environment or /etc/profile or /etc/profile.d?
Comment by Simon Kohlmeyer (voyd) - Thursday, 03 November 2016, 13:11 GMT
I'm sorry, you're right. `busctl --user` still shows systemd1 as activatable.

I am pretty sure that I am not setting DBUS_SESSION_BUS_ADDRESS anywhere.
`sudo grep -r DBUS_SESSION_BUS_ADDRESS /etc` only yields

/etc/systemd/system/user@.service.d/dbus.conf:Environment=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/%I/dbus/user_bus_socket

Which is where it should be set as far as I know. `echo $DBUS_SESION_BUS_ADDRESS` prints `unix:path=/run/user/1000/bus`.
Comment by Simon Kohlmeyer (voyd) - Thursday, 03 November 2016, 13:13 GMT Comment by Dave Reisner (falconindy) - Tuesday, 15 November 2016, 15:40 GMT
As discussed on IRC, this is a user configuration problem -- /etc/systemd/system/user@.service.d/dbus.conf mangles the address that the systemd user session connects to.

Loading...