I am running into this issue where the first time I run sudo
the command takes about 30 seconds before it will prompt me for my password. (NOTE: after I have entered my password, all the following sudo
commands run instantly)
I have gotten as far as running the below commands:
# As Root
chmod u+s /usr/bin/strace
# As My User
strace -r -o trace1.log sudo echo hi
Which did show me where the slowdown is happening. The problem is that the log is a little beyond my understanding. Here is what the log says:
0.000039 read(11, "AGREE_UNIX_FD\r\n", 2048) = 15
0.000038 poll([{fd=11, events=POLLOUT}], 1, -1) = 1 ([{fd=11, revents=POLLOUT}])
0.000036 sendto(11, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7
0.000085 poll([{fd=11, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=11, revents=POLLOUT}])
0.000054 sendmsg(11, {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
0.000539 poll([{fd=11, events=POLLIN}], 1, 25000) = 1 ([{fd=11, revents=POLLIN}])
0.000060 recvmsg(11, {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:1.834\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 262
0.000086 recvmsg(11, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
0.000050 eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK) = 12
0.000039 fstat(11, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
0.000032 fcntl(11, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
0.000145 sendmsg(11, {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
0.000245 sendmsg(11, {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
0.000239 sendmsg(11, {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
0.000250 sendmsg(11, {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
0.005535 poll([{fd=11, events=POLLIN}], 1, 25000) = 1 ([{fd=11, revents=POLLIN}])
0.000064 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\3\1\1G\0\0\0\3\0\0\0u\0\0\0\6\1s\0\6\0\0\0:1.834\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 207
0.000099 write(12, "\1\0\0\0\0\0\0\0", 8) = 8
0.000038 recvmsg(11, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
0.000037 poll([{fd=11, events=POLLIN}], 1, 25000) = 1 ([{fd=11, revents=POLLIN}])
24.999999 recvmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\3\1\1c\0\0\0\4\0\0\0m\0\0\0\6\1s\0\6\0\0\0:1.834\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 227
0.000096 write(12, "\1\0\0\0\0\0\0\0", 8) = 8
0.000035 recvmsg(11, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
0.000121 sendmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., 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
0.000081 sendmsg(11, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="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"..., 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
0.000151 close(11) = 0
0.000058 close(12) = 0
0.000045 getuid() = 1001
My Question: What exactly do these logs mean, and how do I fix sudo
taking so long to login?
This is a VM running Fedora 26.
Also, I believe these issues only started occurring after running the following commands as root. So this is more than likely due to do with a permissions issue, but I don't know for sure.
rpm --setperms -a
rpm --setugids -a
Update:
After running journalctl /usr/bin/dbus-daemon
I find a bunch of errors like this:
Oct 13 11:25:32 server.example.com dbus-daemon[718]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service' requested by ':1.848' (uid=0 pid=29713 comm="sudo vim trace.log " label="unconfined_u:unconfined
Oct 13 11:25:57 server.example.com dbus-daemon[718]: [system] Failed to activate service 'net.reactivated.Fprint': timed out (service_start_timeout=25000ms)
Oct 13 11:26:04 server.example.com dbus-daemon[718]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service' requested by ':1.850' (uid=0 pid=29769 comm="sudo vim trace.log " label="unconfined_u:unconfined
Oct 13 11:26:29 server.example.com dbus-daemon[718]: [system] Failed to activate service 'net.reactivated.Fprint': timed out (service_start_timeout=25000ms)
Oct 13 13:44:07 server.example.com dbus-daemon[718]: [system] Activating via systemd: service name='net.reactivated.Fprint' unit='fprintd.service' requested by ':1.908' (uid=0 pid=31397 comm="sudo vim trace.log " label="unconfined_u:unconfined
Oct 13 13:44:32 server.example.com dbus-daemon[718]: [system] Failed to activate service 'net.reactivated.Fprint': timed out (service_start_timeout=25000ms)