[SOLVED] Debugging dbus connection errors

girzel · 2021-12-17 18:59:20

Hi all, I first saw this problem in relation to gpg-agent taking 25 seconds to pop up a pinentry prompt, and after much digging on the forums here, the clue seemed to be that 25 seconds is the default timeout for dbus connections.

I use Arch with no window manager [edit: I meant to say desktop environment], but had the Gnome group installed for some dependency or other, I don't even remember. gpg-agent was attempting to connect to the gnome-keyring-daemon via dbus, and that failed connection had to timeout before I was shown the pinentry prompt.

I "solved" the problem by uninstalling the gnome-keyring package, which had the added benefit that Element no longer demands I create a default keyring.

But I'm pretty sure the underlying dbus problem is still there. I use the fcitx5 input method package, and it won't work either, citing a failure to connect over dbus.

I haven't been able to find any obvious error in various places, but I'm going to paste everything I could think of here, and I hope someone will be able to supply some commands I can run to prompt an error directly. I don't know what "home1" is supposed to be.

Thanks in advance...

$ systemctl --user status:

● clem
    State: running
     Jobs: 0 queued
   Failed: 0 units
    Since: Fri 2021-12-17 10:24:35 PST; 28min ago
   CGroup: /user.slice/user-1000.slice/user@1000.service
           ├─app.slice 
           │ ├─mpd.service 
           │ │ └─568 /usr/bin/mpd --no-daemon /home/eric/.mpd/mpd.conf
           │ ├─syncthing.service 
           │ │ ├─570 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
           │ │ └─600 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
           │ ├─pulseaudio.service 
           │ │ ├─569 /usr/bin/pulseaudio
           │ │ └─611 /usr/lib/pulse/gsettings-helper
           │ ├─gpg-agent.service 
           │ │ └─1232 /usr/bin/gpg-agent --supervised
           │ └─dbus.service 
           │   └─605 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation
           └─init.scope 
             ├─560 /usr/lib/systemd/systemd --user
             └─561 (sd-pam)

# journalctl -exb -u dbus

-- Journal begins at Thu 2017-10-05 17:06:26 PDT, ends at Fri 2021-12-17 10:53:17 PST. --
Dec 17 10:24:31 clem systemd[1]: Started D-Bus System Message Bus.
░░ Subject: A start job for unit dbus.service has finished successfully
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░ 
░░ A start job for unit dbus.service has finished successfully.
░░ 
░░ The job identifier is 106.
Dec 17 10:24:33 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.3' (uid=0 pid=442 comm="/bin/login -p --      ")
Dec 17 10:24:33 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:24:35 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.5' (uid=0 pid=560 comm="(systemd) ")
Dec 17 10:24:35 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:24:35 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.7' (uid=1000 pid=569 comm="/usr/bin/pulseaudio ")
Dec 17 10:24:35 clem dbus-daemon[401]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1'
Dec 17 10:24:35 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.8' (uid=0 pid=584 comm="/usr/lib/rtkit-daemon ")
Dec 17 10:24:36 clem dbus-daemon[401]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Dec 17 10:24:36 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.12' (uid=1000 pid=569 comm="/usr/bin/pulseaudio ")
Dec 17 10:24:36 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service not found.
Dec 17 10:30:17 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.52' (uid=0 pid=2209 comm="sudo systemctl status dbus ")
Dec 17 10:30:17 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:34:12 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.55' (uid=0 pid=2345 comm="sudo systemctl status --system ")
Dec 17 10:34:12 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:34:24 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.56' (uid=0 pid=2350 comm="sudo systemctl status --user ")
Dec 17 10:34:24 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:44:45 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.62' (uid=1000 pid=5068 comm="/usr/lib/electron13/electron /usr/lib/element/app.")
Dec 17 10:44:45 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.bluez.service': Unit dbus-org.bluez.service not found.
Dec 17 10:52:34 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.64' (uid=0 pid=5292 comm="sudo journalclt -exb -u dbus ")
Dec 17 10:52:34 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:52:42 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.65' (uid=0 pid=5293 comm="sudo journalctl -exb -u dbus ")
Dec 17 10:52:42 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:53:17 clem dbus-daemon[401]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.66' (uid=0 pid=5300 comm="sudo journalctl -exb -u dbus ")
Dec 17 10:53:17 clem dbus-daemon[401]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.

$ loginctl session-status

1 - eric (1000)
	   Since: Fri 2021-12-17 10:24:35 PST; 29min ago
	  Leader: 442 (login)
	    Seat: seat0; vc1
	     TTY: tty1
	 Service: login; type tty; class user
	   State: active
	    Unit: session-1.scope
		  ├─ 442 "login -- eric" "" "" "" "" "" "" "" ""
		  ├─ 572 -bash
		  ├─ 669 /bin/sh /usr/bin/startx
		  ├─ 687 xinit /home/eric/.xinitrc -- /etc/X11/xinit/xserverrc :0 vt1 -keeptty -auth /tmp/serverauth.RLkunWILMl
		  ├─ 688 /usr/lib/Xorg -nolisten tcp :0 vt1 -keeptty -auth /tmp/serverauth.RLkunWILMl
		  ├─ 698 /usr/bin/i3
		  ├─ 705 i3bar --bar_id=bar-0 --socket=/run/user/1000/i3/ipc-socket.698
		  ├─ 711 i3status
		  ├─ 715 xterm
		  ├─ 717 bash
		  ├─ 720 tmux
		  ├─ 722 tmux
		  ├─ 738 /usr/lib/firefox/firefox
		  ├─ 803 /usr/lib/firefox/firefox -contentproc -parentBuildID 20211206132329 -prefsLen 1 -prefMapSize 264098 -appDir /usr/lib/firefox/browser 738 true socket
		  ├─ 847 /usr/lib/firefox/firefox -contentproc -childID 1 -isForBrowser -prefsLen 127 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─ 892 /usr/lib/firefox/firefox -contentproc -childID 2 -isForBrowser -prefsLen 222 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─ 987 /usr/lib/firefox/firefox -contentproc -childID 4 -isForBrowser -prefsLen 4856 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─1037 /usr/lib/firefox/firefox -contentproc -childID 5 -isForBrowser -prefsLen 5555 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─1249 /usr/lib/firefox/firefox -contentproc -parentBuildID 20211206132329 -prefsLen 6124 -prefMapSize 264098 -appDir /usr/lib/firefox/browser 738 true rdd
		  ├─1395 /usr/lib/firefox/firefox -contentproc -childID 12 -isForBrowser -prefsLen 6247 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─1480 /usr/lib/firefox/firefox -contentproc -childID 14 -isForBrowser -prefsLen 6247 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─1777 /usr/lib/firefox/firefox -contentproc -childID 22 -isForBrowser -prefsLen 6248 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─1860 /usr/lib/firefox/firefox -contentproc -childID 24 -isForBrowser -prefsLen 6248 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─2316 /usr/lib/firefox/firefox -contentproc -childID 33 -isForBrowser -prefsLen 6402 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─2391 /usr/lib/firefox/firefox -contentproc -childID 34 -isForBrowser -prefsLen 6403 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─2443 /usr/lib/firefox/firefox -contentproc -childID 35 -isForBrowser -prefsLen 6713 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─2543 /usr/lib/firefox/firefox -contentproc -childID 37 -isForBrowser -prefsLen 6715 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─5034 /usr/lib/firefox/firefox -contentproc -childID 38 -isForBrowser -prefsLen 6715 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─5068 /usr/lib/electron13/electron /usr/lib/element/app.asar --disable-dev-mode
		  ├─5071 "/usr/lib/electron13/electron --type=zygote --no-zygote-sandbox"
		  ├─5072 "/usr/lib/electron13/electron --type=zygote"
		  ├─5074 "/usr/lib/electron13/electron --type=zygote"
		  ├─5098 "/usr/lib/electron13/electron --type=gpu-process --field-trial-handle=14531210923292568967,8763670325622785906,131072 --enable-features=WebRTCPipeWireCapturer --disable-features=CookiesWithoutSameSiteMustBeSecure,HardwareMediaKeyHandling,MediaSessionService,SameSiteByDefaultCookies,SpareRendererForSitePerProcess --gpu-preferences=UAAAAAAAAAAgAAAQAAAAAAAAAAAAAAAAAABgAAAAAAAwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAgAAAAAAAAACAAAAAAAAAAAAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAACAAAAAAAAAA= --shared-files"
		  ├─5105 "/usr/lib/electron13/electron --type=utility --utility-sub-type=network.mojom.NetworkService --field-trial-handle=14531210923292568967,8763670325622785906,131072 --enable-features=WebRTCPipeWireCapturer --disable-features=CookiesWithoutSameSiteMustBeSecure,HardwareMediaKeyHandling,MediaSessionService,SameSiteByDefaultCookies,SpareRendererForSitePerProcess --lang=en-US --service-sandbox-type=none --standard-schemes=vector --enable-sandbox --secure-schemes=vector --bypasscsp-schemes --cors-schemes --fetch-schemes=vector --service-worker-schemes --streaming-schemes --shared-files=v8_context_snapshot_data:100"
		  ├─5119 "/usr/lib/electron13/electron --type=renderer --field-trial-handle=14531210923292568967,8763670325622785906,131072 --enable-features=WebRTCPipeWireCapturer --disable-features=CookiesWithoutSameSiteMustBeSecure,HardwareMediaKeyHandling,MediaSessionService,SameSiteByDefaultCookies,SpareRendererForSitePerProcess --lang=en-US --standard-schemes=vector --enable-sandbox --secure-schemes=vector --bypasscsp-schemes --cors-schemes --fetch-schemes=vector --service-worker-schemes --streaming-schemes --app-path=/usr/lib/element/app.asar --num-raster-threads=2 --enable-main-frame-before-activation --renderer-client-id=4 --no-v8-untrusted-code-mitigations --shared-files=v8_context_snapshot_data:100"
		  ├─5125 "/usr/lib/electron13/electron --type=broker"
		  ├─5204 /usr/lib/firefox/firefox -contentproc -childID 39 -isForBrowser -prefsLen 6715 -prefMapSize 264098 -jsInitLen 278884 -parentBuildID 20211206132329 -appDir /usr/lib/firefox/browser 738 true tab
		  ├─5232 -bash
		  ├─5244 -bash
		  └─5311 loginctl session-status

Dec 17 10:34:24 clem sudo[2350]: pam_unix(sudo:session): session closed for user root
Dec 17 10:52:34 clem sudo[5292]: pam_systemd_home(sudo:auth): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:52:42 clem sudo[5293]: pam_systemd_home(sudo:account): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:52:42 clem sudo[5293]:     eric : TTY=pts/2 ; PWD=/home/eric ; USER=root ; COMMAND=/usr/bin/journalctl -exb -u dbus
Dec 17 10:52:42 clem sudo[5293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 17 10:53:05 clem sudo[5293]: pam_unix(sudo:session): session closed for user root
Dec 17 10:53:17 clem sudo[5300]: pam_systemd_home(sudo:account): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
Dec 17 10:53:17 clem sudo[5300]:     eric : TTY=pts/2 ; PWD=/home/eric ; USER=root ; COMMAND=/usr/bin/journalctl -exb -u dbus
Dec 17 10:53:17 clem sudo[5300]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 17 10:53:17 clem sudo[5300]: pam_unix(sudo:session): session closed for user root

ps -df | grep dbus

dbus         401       1  0 10:24 ?        00:00:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation --syslog-only
eric         605     560  0 10:24 ?        00:00:00 /usr/bin/dbus-daemon --session --address=systemd: --nofork --nopidfile --systemd-activation
eric        5505    5232  0 10:57 pts/2    00:00:00 grep dbus

Last edited by girzel (2021-12-18 23:59:56)

seth · 2021-12-17 21:32:56

Please post your xinitrc and see the last link below.

---

I use Arch with no window manager

/usr/bin/i3

?

girzel · 2021-12-17 22:55:29

Desktop environment! I meant to say no desktop environment!

I didn't post my ~/.xinitrc because the same thing happens at the console, before "startx". It uses the curses pinentry instead of qt, of course, but the 25 second delay is still there. But, for completeness:

export GTK_IM_MODULE=fcitx
export QT_IM_MODULE=fcitx
export XMODIFIERS=@im=fcitx

#echo "UPDATESTARTUPTTY" | gpg-connect-agent > /dev/null 2&>1

#numlockx &

exec /usr/bin/i3

I commented out those lines above earlier today, thinking they might be interfering, but it made no difference.

Thanks.

seth · 2021-12-18 08:00:01

You're not importing the session variables - again: last link below (2nd blue note)
About the pinentry in particular and in case it remains a problem even w/ properly imported dbus session: what's your local configuration (preexec)

girzel · 2021-12-18 23:32:33

Okay, that was enough to get me searching in the right direction, and it turns out that at some point in the past I added systemctl dbus.service/socket files to /etc/systemd/user. I'm sure I thought I had a good reason for doing that, but at some point recently that started breaking user-level apps' connection to dbus altogether. Simply removing those service files was enough to do the trick: now DBUS_SESSION_BUS_ADDRESS is set correctly from the moment of login.

Thanks for the pointers, and I'll mark this as solved.

Arch Linux

#1 2021-12-17 18:59:20

[SOLVED] Debugging dbus connection errors

#2 2021-12-17 21:32:56

Re: [SOLVED] Debugging dbus connection errors

#3 2021-12-17 22:55:29

Re: [SOLVED] Debugging dbus connection errors

#4 2021-12-18 08:00:01

Re: [SOLVED] Debugging dbus connection errors

#5 2021-12-18 23:32:33

Re: [SOLVED] Debugging dbus connection errors

Board footer