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
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
|
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
Tuesday, 15 November 2016, 15:40 GMT
Reason for closing: Not a bug
Additional comments about closing: user error
What were you expecting to find out from this output?
=====================
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.
Are you setting DBUS_SESSION_BUS_ADDRESS anywhere in your dotfiles or /etc/environment or /etc/profile or /etc/profile.d?
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`.