Slow authentication on Fedora VM due to /var/run/dbus/system_bus_socket connect timeout

Question

I have this Fedora VM that for some reason after a while always starts having very slow "sudo" authentication (or an authentication in general, like GUI apps asking for credentials). It's will work normally until at some moment (*) it starts waiting 20 seconds are more before showing the password prompt.

(*) That moment might after I have suspended and restarted the VM, but I haven't been able to reproduce this reliably.

I think I tracked it down to something to do with DBus because doing an "strace" of sudo gives me this:

 0.000040 connect(8, {sa_family=AF_LOCAL, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
 0.000095 fcntl(8, F_GETFL)         = 0x2 (flags O_RDWR)
 0.000035 fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0
 0.000039 geteuid()                 = 0
 0.000038 getsockname(8, {sa_family=AF_LOCAL, NULL}, [2]) = 0
 0.000060 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}])
 0.000041 sendto(8, "\0", 1, MSG_NOSIGNAL, NULL, 0) = 1
 0.000090 sendto(8, "AUTH EXTERNAL 30\r\n", 18, MSG_NOSIGNAL, NULL, 0) = 18
 0.000135 poll([{fd=8, events=POLLIN}], 1, 4294967295) = 1 ([{fd=8, revents=POLLIN}])
 0.000053 read(8, "OK 646ed40b36ee6ecf4fee737c54368"..., 2048) = 37
 0.000047 poll([{fd=8, events=POLLOUT}], 1, 4294967295) = 1 ([{fd=8, revents=POLLOUT}])
 0.000039 sendto(8, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL, NULL, 0) = 19
 0.000369 poll([{fd=8, events=POLLIN}], 1, 4294967295) = 1 ([{fd=8, revents=POLLIN}])
 0.000047 read(8, "AGREE_UNIX_FD\r\n", 2048) = 15
 0.000043 poll([{fd=8, events=POLLOUT}], 1, 4294967295) = 1 ([{fd=8, revents=POLLOUT}])
 0.000039 sendto(8, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7
 0.000088 poll([{fd=8, events=POLLIN|POLLOUT}], 1, 4294967295) = 1 ([{fd=8, revents=POLLOUT}])
 0.000041 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 128
 0.000108 clock_gettime(CLOCK_MONOTONIC, {115342, 676969855}) = 0
 0.000042 poll([{fd=8, events=POLLIN}], 1, 25000) = 1 ([{fd=8, revents=POLLIN}])
 0.000818 recvmsg(8, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0:1.196\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 262
 0.000062 recvmsg(8, 0x7fff421ab1a0, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
 0.000312 eventfd2(0, O_NONBLOCK|O_CLOEXEC) = 9
 0.000046 write(9, "\1\0\0\0\0\0\0\0", 8) = 8
 0.000042 fstat(8, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
 0.000039 fcntl(8, F_GETFL)         = 0x802 (flags O_RDWR|O_NONBLOCK)
 0.000038 write(9, "\1\0\0\0\0\0\0\0", 8) = 8
 0.000133 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\204\0\0\0\2\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\177\0\0\0type='signal',sender='net.re"..., 132}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 276
 0.000130 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\246\0\0\0\3\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\241\0\0\0type='signal',sender='org.fr"..., 166}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 310
 0.000126 clock_gettime(CLOCK_MONOTONIC, {115342, 678759459}) = 0
 0.000048 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\33\0\0\0\4\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\26\0\0\0net.reactivated.Fprint\0", 27}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 171
 0.000119 clock_gettime(CLOCK_MONOTONIC, {115342, 678926239}) = 0
 0.000048 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\5\0\0\0\203\0\0\0\1\1o\0\37\0\0\0/net/rea"..., 152}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 152
 0.000267 clock_gettime(CLOCK_MONOTONIC, {115342, 679268460}) = 0
 0.000123 poll([{fd=8, events=POLLIN}], 1, 25000) = 1 ([{fd=8, revents=POLLIN}])
 0.000060 recvmsg(8, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\3\0\0\0=\0\0\0\6\1s\0\6\0\0\0:1.196\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 91
 0.000065 write(9, "\1\0\0\0\0\0\0\0", 8) = 8
 0.000040 recvmsg(8, 0x7fff421ab010, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
 0.000053 clock_gettime(CLOCK_MONOTONIC, {115342, 679581347}) = 0
 vvvvvvvv
 0.000042 poll([{fd=8, events=POLLIN}], 1, 25000) = 0 (Timeout)  <<<****** HERE
 ^^^^^^^^
25.025437 clock_gettime(CLOCK_MONOTONIC, {115367, 705179464}) = 0
 0.000562 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\204\0\0\0\6\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\177\0\0\0type='signal',sender='net.re"..., 132}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 276
 0.000835 sendmsg(8, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\1\1\246\0\0\0\7\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 144}, {"\241\0\0\0type='signal',sender='org.fr"..., 166}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 310
 0.000704 write(9, "\1\0\0\0\0\0\0\0", 8) = 8
 0.000503 close(8)                  = 0

The execution halts for about 20 seconds in the marked line with the Timeout.

Anyone have any ideas? (And no, it does not have to do with my host file)

I've had similar problems when the dbus socket file is SELinux-labeled incorrectly. — dannysauer, Nov 14 '17 at 21:15

score 2 · Answer 1 · answered Jun 20 '20 at 13:26

I had the similar problem: sudo, su, and login all hang for about 20 seconds waiting on dbus system socket.

Sometimes such problem is caused by missing local hostname in /etc/hosts. (e.g. if hostname command prints foo you can add 127.0.0.1 foo to /etc/hosts).

However, in my case, the problem was caused by not running systemd-logind or its replacement elogind (which is used on Gentoo). Usually it's started automatically when libelogind is used, but on my system it was disabled and recently things stopped working after system update.

Starting elogind fixed the issue for me.

score 0 · Answer 2 · answered Mar 21 '21 at 07:04

I had a similar problem where su or even similar command like id root hang on polling /run/dbus/system_bus_socket:

connect(3, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 30) = 0 <0.000031>
...
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000011>
clock_gettime(CLOCK_MONOTONIC, {tv_sec=35439646, tv_nsec=638969580}) = 0 <0.000015>
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999824000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=0, tv_nsec=0}) <25.018954>

This was on long unmaintained pre-systemd VM. I end up shutting down dbus just to be able to login.

Slow authentication on Fedora VM due to /var/run/dbus/system_bus_socket connect timeout

2 Answers2