Bug 1271394 - All logins, like ssh, sudo, su take many seconds
Summary: All logins, like ssh, sudo, su take many seconds
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 25
Hardware: x86_64
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1384300
TreeView+ depends on / blocked
 
Reported: 2015-10-13 20:22 UTC by Richard W.M. Jones
Modified: 2020-08-22 08:00 UTC (History)
38 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1384300 (view as bug list)
Environment:
Last Closed: 2017-12-12 11:11:45 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
log3.txt (894.78 KB, text/plain)
2015-10-13 21:19 UTC, Richard W.M. Jones
no flags Details
strace -s 2048 -tt -f -o /tmp/log4 sudo bash (2.07 MB, text/plain)
2015-10-14 08:58 UTC, Richard W.M. Jones
no flags Details
journalctl -u systemd-logind -l -b 0 (13.59 KB, text/plain)
2015-10-14 09:02 UTC, Richard W.M. Jones
no flags Details

Description Richard W.M. Jones 2015-10-13 20:22:30 UTC
Description of problem:

On Rawhide, x86-64, any program that involves a new session, like
ssh into the machine, sudo, su, take many seconds to run:

$ time sudo bash -c exit

real	0m24.797s
user	0m0.010s
sys	0m0.007s

Version-Release number of selected component (if applicable):

systemd-227-1.fc24.x86_64

How reproducible:

100%

Steps to Reproduce:
1. Update to Rawhide.
2. Run 'sudo bash', ssh into box, etc.

Comment 1 Florian Weimer 2015-10-13 20:27:20 UTC
Does “hostname -f” block as well?  What's the contents of /etc/hosts, /etc/resolv.conf, and /etc/nsswitch.conf?

Comment 2 Richard W.M. Jones 2015-10-13 20:44:16 UTC
(In reply to Florian Weimer from comment #1)
> Does “hostname -f” block as well?

No.

> What's the contents of /etc/hosts,

$ cat /etc/hosts
127.0.0.1		localhost.localdomain localhost
::1		localhost6.localdomain6 localhost6

> /etc/resolv.conf,

It has details of my internal network, but there is nothing
unusual in this file, and the nameserver is working.

> and /etc/nsswitch.conf?

$ cat /etc/nsswitch.conf
#
# /etc/nsswitch.conf
#
# An example Name Service Switch config file. This file should be
# sorted with the most-used services at the beginning.
#
# The entry '[NOTFOUND=return]' means that the search for an
# entry should stop if the search in the previous entry turned
# up nothing. Note that if the search failed due to some other reason
# (like no NIS server responding) then the search continues with the
# next entry.
#
# Valid entries include:
#
#	nisplus			Use NIS+ (NIS version 3)
#	nis			Use NIS (NIS version 2), also called YP
#	dns			Use DNS (Domain Name Service)
#	files			Use the local files
#	db			Use the local database (.db) files
#	compat			Use NIS on compat mode
#	hesiod			Use Hesiod for user lookups
#	[NOTFOUND=return]	Stop searching if not found so far
#

# To use db, put the "db" in front of "files" for entries you want to be
# looked up first in the databases
#
# Example:
#passwd:    db files nisplus nis
#shadow:    db files nisplus nis
#group:     db files nisplus nis

passwd:     files mymachines
shadow:     files
group:      files mymachines
initgroups: files

#hosts:     db files nisplus nis dns
hosts:      files mdns4_minimal [NOTFOUND=return] dns myhostname mymachines

# Example - obey only what nisplus tells us...
#services:   nisplus [NOTFOUND=return] files
#networks:   nisplus [NOTFOUND=return] files
#protocols:  nisplus [NOTFOUND=return] files
#rpc:        nisplus [NOTFOUND=return] files
#ethers:     nisplus [NOTFOUND=return] files
#netmasks:   nisplus [NOTFOUND=return] files     

bootparams: nisplus [NOTFOUND=return] files

ethers:     files
netmasks:   files
networks:   files
protocols:  files
rpc:        files
services:   files

netgroup:   nisplus

publickey:  nisplus

automount:  files nisplus
aliases:    files nisplus

Comment 3 Richard W.M. Jones 2015-10-13 21:19:09 UTC
Created attachment 1082623 [details]
log3.txt

Attached output of:

# strace -tt -f -o /tmp/log3 sudo bash

which seems to indicate it has something to do with dbus?

Comment 4 Florian Weimer 2015-10-14 05:55:18 UTC
(In reply to Richard W.M. Jones from comment #3)
> Created attachment 1082623 [details]
> log3.txt
> 
> Attached output of:
> 
> # strace -tt -f -o /tmp/log3 sudo bash
> 
> which seems to indicate it has something to do with dbus?

19844 22:16:41.867657 sendto(9, "<83>Oct 13 22:16:41 sudo: pam_sy"..., 99, MSG_NOSIGNAL, NULL, 0) = 99

It would be nice to have full log message (and the complete sendmsg data, too).

Comment 5 Lukáš Nykrýn 2015-10-14 08:14:04 UTC
Is systemd-logind running? Can you try to use debug-sheĺl[1] and restart logind before login?

[1]  https://wiki.freedesktop.org/www/Software/systemd/Debugging/

Comment 6 Richard W.M. Jones 2015-10-14 08:58:20 UTC
Created attachment 1082751 [details]
strace -s 2048 -tt -f -o /tmp/log4 sudo bash

In reply to comment 4, the output of:

strace -s 2048 -tt -f -o /tmp/log4 sudo bash

so fewer strings should be truncated.

That also reveals the error message:

Oct 14 09:56:53 sudo: pam_systemd(sudo:session): Failed to create session: Connection timed out

Comment 7 Richard W.M. Jones 2015-10-14 09:02:31 UTC
Created attachment 1082752 [details]
journalctl -u systemd-logind -l -b 0

(In reply to Lukáš Nykrýn from comment #5)
> Is systemd-logind running?

Yes.  Shortly after boot:

 1918 ?        Ss     0:00 /usr/lib/systemd/systemd-logind

> Can you try to use debug-sheĺl[1] and restart
> logind before login?
> 
> [1]  https://wiki.freedesktop.org/www/Software/systemd/Debugging/

Tricky - this server is remote and has no serial console (unfortunately -
something to be sorted out one day).

The journal has some messages relating to systemd-logind which I've
attached.

Comment 8 Richard W.M. Jones 2015-10-14 09:06:14 UTC
Also:

# systemctl restart systemd-logind
Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.PolicyKit1': timed out (g-dbus-error-quark, 20)
Job for systemd-logind.service failed because a timeout was exceeded. See "systemctl status systemd-logind.service" and "journalctl -xe" for details.

While it was timing out, the process tree looked like this:

 1598 pts/0    S      0:00  |               \_ bash
 2067 pts/0    S+     0:00  |                   \_ systemctl restart systemd-log
 2068 pts/0    S+     0:00  |                       \_ /usr/bin/systemd-tty-ask-
 2069 pts/0    Z+     0:00  |                       \_ [pkttyagent] <defunct>

Comment 9 Jóhann B. Guðmundsson 2015-10-14 11:16:52 UTC
Rich is this systemd in aarch64? 

could you attach the output from "journalctl -b _SYSTEMD_UNIT=polkit.service" and or try running polkid manually (  /usr/lib/polkit-1/polkitd ) 

Also see upstream bug [1] which might be related to this.

https://github.com/systemd/systemd/issues/1505

Comment 10 Richard W.M. Jones 2015-10-14 12:05:32 UTC
Well, here's a strange thing.  The bug is now non-reproducible
after a reboot (earlier reboots did *not* fix the problem).

No package has been installed or removed, and no configuration
changes made.

Comment 11 Petr Pisar 2015-10-14 13:01:26 UTC
I recall similar symptoms after restarting systemd-logind.service (and reexecing systemd?). After reboot it worked again. I guess some parts of systemd cannot be restarted otherwise they loose some authenticated file descriptor.

Comment 12 Petr Pisar 2015-10-14 13:09:42 UTC
Now I could reproduce it on Fedora 22:

I upgraded some packages (linux-firmware, nss, nss-sysinit, nss-tools, pcre, perl-generators, python-fedora) and because some mapped shared libraries changed, I reexecuted systemd, then restarted systemd-logind.service. So far SSH login was immediate.

Then I restarted dbus.service. It resulted into:

# systemctl restart dbus.service
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.

And since then any SSH login halts for 25 seconds exactly.

Comment 13 Petr Pisar 2015-10-14 13:14:20 UTC
And after starting polkit.service manually and the restarting systemd-logind.service the SSH login is immediate again.

Comment 14 Jóhann B. Guðmundsson 2015-10-14 16:08:42 UTC
Sounds like a misconfiguration polkit type service unit and or it's dbus implementation.

Comment 15 Richard W.M. Jones 2015-10-25 16:22:58 UTC
This has started to happen again.  I didn't change/upgrade anything.

However I'm now going to try updating the system to current
Rawhide to see if it improves things.

Comment 16 Jan Kurik 2016-02-24 13:50:22 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 24 development cycle.
Changing version to '24'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora24#Rawhide_Rebase

Comment 17 Stan Hu 2016-08-05 15:24:25 UTC
We experienced this problem on GitLab.com, and we had a customer report this issue on RHEL7.

There are bugs in systemd and dbus causing these delays. This issue has been fixed in systemd: https://github.com/systemd/systemd/issues/1961

It was merged in https://github.com/systemd/systemd/commit/5ab42bc85a11a5250dcdf8e86291d3da90aa84bd and released in systemd v230 and v231.

Right now RHEL7 appears to be on v219.

There is also a patch in dbus to make this problem go away: https://bugs.freedesktop.org/show_bug.cgi?id=95263

Comment 18 Alastair Scobie 2016-08-19 10:56:27 UTC
Still seems to be a problem in RHEL 7.2 (as of 2016/08/19).

Comment 19 BCrook 2016-09-30 17:53:51 UTC
This bug is still present in RHEL 7.2 as of 2016-09-30.  We require the upstream fix backported into RHEL7.  When can we expect this to be completed?  (ETA Date)

Comment 20 Richard W.M. Jones 2016-09-30 18:01:28 UTC
Please contact Red Hat support:
http://redhat.com/support

Comment 21 Arjen Heidinga 2016-10-28 13:31:40 UTC
Still seems to be a problem in RHEL 7.2 (as of 2016/10/28).

Comment 22 David Hill 2017-01-12 04:30:31 UTC
We're hitting something similar and I have the feeling selinux is the culprit here ...  It seems like crontab/zabbix or something else is preventing a session from totally being established because selinux is denying the system call but systemd doesn't cope properly with this situation.

Comment 23 Raman Gupta 2017-04-28 17:24:58 UTC
I've had this issue randomly after updates. Typically journalctl -n 100 will show something like:

 pam_systemd(crond:session): Failed to create session: Activation of org.freedesktop.login1 timed out 

I've found this procedure to solve it consistently:

systemctl daemon-reload
systemctl restart dbus
systemctl restart systemd-logind

If restart of systemd-logind fails, try the following and then restart it again:

Delete session files

 find /run/systemd/system -name "session-*.scope" -delete 

Delete session directories

 rm -rf /run/systemd/system/session*scope* 

Remove the abandoned sessions

 systemctl | grep "abandoned" | grep -e "-[[:digit:]]" | sed "s/\.scope.*/.scope/" | xargs systemctl stop 

References: 
https://github.com/systemd/systemd/issues/1961
https://bugs.freedesktop.org/show_bug.cgi?id=95263

Comment 24 Linux_freak 2017-05-24 18:16:09 UTC
Hi everyone!,
this problem turns into headache,
since this pam module is optional (pam_systemd.so) we will proceed to comment it out from system-auth-ac file in /etc/pam.d/.
After this, all logins (ssh, su) connect immediately.

Comment 25 Ben Greear 2017-07-18 21:34:31 UTC
Looks like we just hit this problem on an up-to-date Fedora-24 system.

Here is a 'strace -t sudo su -' call.  I hit enter a few times where it was
hung until ppol timed out.

I tried the suggestions above, but daemon-reload fails as well:

[root@lf0350-895c ~]# systemctl daemon-reload
Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.freedesktop.PolicyKit1': timed out (service_start_timeout=25000ms) (g-dbus-error-quark, 20)

Reboots have so far not helped.


14:23:44 lseek(4, 0, SEEK_CUR)          = 1225
14:23:44 lseek(4, 0, SEEK_CUR)          = 1225
14:23:44 read(4, "", 4096)              = 0
14:23:44 close(4)                       = 0
14:23:44 open("/var/lib/sss/mc/initgroups", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
14:23:44 open("/var/lib/sss/mc/initgroups", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
14:23:44 socket(AF_UNIX, SOCK_STREAM, 0) = 4
14:23:44 fcntl(4, F_GETFL)              = 0x2 (flags O_RDWR)
14:23:44 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
14:23:44 fcntl(4, F_GETFD)              = 0
14:23:44 fcntl(4, F_SETFD, FD_CLOEXEC)  = 0
14:23:44 connect(4, {sa_family=AF_UNIX, sun_path="/var/lib/sss/pipes/nss"}, 110) = -1 ENOENT (No such file or directory)
14:23:44 close(4)                       = 0
14:23:44 read(3, "", 4096)              = 0
14:23:44 close(3)                       = 0
14:23:44 setpriority(PRIO_PROCESS, 0, 0) = 0
14:23:44 access("/run/systemd/seats/", F_OK) = 0
14:23:44 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3
14:23:44 fstat(3, {st_mode=S_IFREG|0644, st_size=3024, ...}) = 0
14:23:44 read(3, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 3024
14:23:44 close(3)                       = 0
14:23:44 open("/sys/fs/kdbus/0-system/bus", O_RDWR|O_NOCTTY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
14:23:44 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
14:23:44 getsockopt(3, SOL_SOCKET, SO_RCVBUF, [212992], [4]) = 0
14:23:44 setsockopt(3, SOL_SOCKET, SO_RCVBUFFORCE, [8388608], 4) = 0
14:23:44 getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
14:23:44 setsockopt(3, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
14:23:44 connect(3, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
14:23:44 getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
14:23:44 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
14:23:44 getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
14:23:44 getsockname(3, {sa_family=AF_UNIX}, [128->2]) = 0
14:23:44 geteuid()                      = 0
14:23:44 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL ", iov_len=15}, {iov_base="30", iov_len=2}, {iov_base="\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", iov_len=28}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 45
14:23:44 gettid()                       = 4523
14:23:44 getrandom("\x22\x7a\x70\x48\x2c\xa7\x3f\x8b\xa0\x17\xa9\x3a\xed\x22\x12\x06", 16, GRND_NONBLOCK) = 16
14:23:44 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="OK d78c51a291a8d82989867b6b596e7"..., iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
14:23:44 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., iov_len=128}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
14:23:44 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
14:23:44 ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999141000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=24, tv_nsec=998374400})
14:23:44 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
14:23:44 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=":1.181\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0"..., iov_len=67}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 67
14:23:44 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1p\0\0\0\2\0\0\0\230\0\0\0\1\1o\0\27\0\0\0/org/fre"..., iov_len=168}, {iov_base="\0\0\0\0\253\21\0\0\4\0\0\0su-l\0\0\0\0\3\0\0\0tty\0\4\0\0\0"..., iov_len=112}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 280
14:23:44 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\v\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
14:23:44 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0"..., iov_len=147}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 147
14:23:44 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
14:23:44 ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=998917000}, NULL, 8





) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=0, tv_nsec=0})
14:24:09 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\3\1\1c\0\0\0\3\0\0\0m\0\0\0\6\1s\0\6\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
14:24:09 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=":1.181\0\0\4\1s\0#\0\0\0org.freedesktop."..., iov_len=203}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 203
14:24:09 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
14:24:09 connect(4, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0
14:24:09 sendto(4, "<83>Jul 18 14:24:09 su: pam_syst"..., 171, MSG_NOSIGNAL, NULL, 0) = 171

Comment 26 Richard W.M. Jones 2017-07-19 11:47:55 UTC
(In reply to Ben Greear from comment #25)
> Looks like we just hit this problem on an up-to-date Fedora-24 system.
> 
> Here is a 'strace -t sudo su -' call.  I hit enter a few times where it was
> hung until ppol timed out.
> 
> I tried the suggestions above, but daemon-reload fails as well:
> 
> [root@lf0350-895c ~]# systemctl daemon-reload
> Error getting authority: Error initializing authority: Error calling
> StartServiceByName for org.freedesktop.PolicyKit1:
> GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service
> 'org.freedesktop.PolicyKit1': timed out (service_start_timeout=25000ms)
> (g-dbus-error-quark, 20)
> 
> Reboots have so far not helped.

The root cause again will be that dbus is broken.  What's interesting is that
reboots don't help, so not only is dbus broken, it's somehow permanently
broken so maybe there's some configuration problem.

In any case Fedora 24 is about to go out of support, so unless this is
reproducible on Fedora 26 there's not much anyone is going to do.

Comment 27 Fedora End Of Life 2017-07-25 19:22:13 UTC
This message is a reminder that Fedora 24 is nearing its end of life.
Approximately 2 (two) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 24. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '24'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 24 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 28 Petr Pisar 2017-07-26 11:59:36 UTC
This bug exhibits on Fedora 25.

Comment 29 Ben Greear 2017-07-26 14:40:06 UTC
We noticed that this problem went away when we moved from a 4.7.10+ to a 4.9.29+ kernel.
Both kernels are compiled by us and contain lots of local patches, but still, seems 4.9 might have fixed something that triggers this...or makes it harder to reproduce at least.

Comment 30 Ravindra Patil 2017-09-29 16:46:20 UTC
This bug is with RHEL7.4 as well. I was able to reproduce it on RHEL7.4 with latest systemd and dbus packages. 

dbus-1.6.12-17.el7.x86_64
systemd-219-42.el7.x86_64

Any possible ETA for the release of the fix ?

Comment 31 Michal Sekletar 2017-10-02 07:35:44 UTC
(In reply to Ravindra Patil from comment #30)
> This bug is with RHEL7.4 as well. I was able to reproduce it on RHEL7.4 with
> latest systemd and dbus packages. 

Then please open a new bug report against Red Hat Enterprise Linux 7 and don't abuse bug report against Fedora for RHEL business.

Comment 32 Fedora End Of Life 2017-12-12 11:11:45 UTC
Fedora 25 changed to end-of-life (EOL) status on 2017-12-12. Fedora 25 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 33 Arnaud Lacombe 2019-10-23 17:44:05 UTC
This bugs exhibits on Fedora 30

socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 5
connect(5, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 29) = 0
fcntl(5, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
geteuid()                               = 1000
getsockname(5, {sa_family=AF_UNIX}, [128->2]) = 0
poll([{fd=5, events=POLLOUT}], 1, 0)    = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "\0", 1, MSG_NOSIGNAL, NULL, 0) = 1
sendto(5, "AUTH EXTERNAL 31303030\r\n", 24, MSG_NOSIGNAL, NULL, 0) = 24
poll([{fd=5, events=POLLIN}], 1, -1)    = 1 ([{fd=5, revents=POLLIN}])
read(5, "OK 3c0872baea5baeb12ae3b444aab2a"..., 2048) = 37
poll([{fd=5, events=POLLOUT}], 1, -1)   = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL, NULL, 0) = 19
poll([{fd=5, events=POLLIN}], 1, -1)    = 1 ([{fd=5, revents=POLLIN}])
read(5, "AGREE_UNIX_FD\r\n", 2048)      = 15
poll([{fd=5, events=POLLOUT}], 1, -1)   = 1 ([{fd=5, revents=POLLOUT}])
sendto(5, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7
poll([{fd=5, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=5, revents=POLLOUT}])
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., iov_len=128}, {iov_base="", iov_len=0}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 128
poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])
recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\r\0\0\0\377\377\377\377G\0\0\0\5\1u\0\1\0\0\0\7\1s\0\24\0\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 282
recvmsg(5, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK)   = 6
write(6, "\1\0\0\0\0\0\0\0", 8)         = 8
fstat(5, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fcntl(5, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)
write(6, "\1\0\0\0\0\0\0\0", 8)         = 8
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., iov_len=144}, {iov_base="\177\0\0\0type='signal',sender='net.re"..., iov_len=132}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 276
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., iov_len=144}, {iov_base="\241\0\0\0type='signal',sender='org.fr"..., iov_len=166}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 310
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., iov_len=144}, {iov_base="\26\0\0\0net.reactivated.Fprint\0", iov_len=27}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 171
sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., iov_len=152}, {iov_base="", iov_len=0}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 152
poll([{fd=5, events=POLLIN}], 1, 25000) = 1 ([{fd=5, revents=POLLIN}])
recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\3\1\1$\0\0\0\377\377\377\377y\0\0\0\5\1u\0\4\0\0\0\7\1s\0\24\0\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 180
write(6, "\1\0\0\0\0\0\0\0", 8)         = 8
recvmsg(5, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=5, events=POLLIN}], 1, 25000^C) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)

Comment 34 Arnaud Lacombe 2019-10-23 18:08:45 UTC
nevermind, removing fingerprint auth packages fixed the delay.

Comment 35 Mike 2019-11-07 08:32:40 UTC
(In reply to Arnaud Lacombe from comment #34)
> nevermind, removing fingerprint auth packages fixed the delay.

Thanks, I was just getting crazy about this one (FC30).

Btw my laptop doesn't have a fingerprint reader.

Comment 36 luther138 2019-11-11 17:56:38 UTC
sudo dnf remove fprintd-pam

Worked for:
5.2.14-200.fc30.x86_64

sudo is snappy again.

Comment 37 Didier 2020-08-22 08:00:48 UTC
Related to bz#1534873 ?


Note You need to log in before you can comment on or make changes to this bug.