0

I'm having trouble with sudo on some systems. It is taking anywhere from 15-30 seconds to complete a sudo command or to even login to the system.

I ran an strace and can see where the delay is happening, but I'm not sure what's wrong. It seems it's waiting on a write request to /dev/log maybe? But that doesn't tell me much info, nor does it tell me why it's taking so long. Are there any strace experts out there that can explain this better?

12:08:21 munmap(0x7f5ccef9d000, 4096)   = 0
12:08:21 socket(PF_NETLINK, SOCK_RAW, 9) = 4
12:08:21 fcntl(4, F_SETFD, FD_CLOEXEC)  = 0
12:08:21 readlink("/proc/self/exe", "/usr/bin/sudo", 4096) = 13
12:08:21 sendto(4, "t\0\0\0M\4\5\0\2\0\0\0\0\0\0\0op=PAM:accountin"..., 116, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 116
12:08:21 poll([{fd=4, events=POLLIN}], 1, 500) = 1 ([{fd=4, revents=POLLIN}])
12:08:21 recvfrom(4, "$\0\0\0\2\0\0\0\2\0\0\0b3\0\0\0\0\0\0t\0\0\0M\4\5\0\2\0\0\0"..., 8988, MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
12:08:21 recvfrom(4, "$\0\0\0\2\0\0\0\2\0\0\0b3\0\0\0\0\0\0t\0\0\0M\4\5\0\2\0\0\0"..., 8988, MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
12:08:21 close(4)                       = 0
12:08:21 rt_sigaction(SIGTSTP, {SIG_IGN, [], SA_RESTORER|SA_RESTART, 0x7f5cce1de920}, NULL, 8) = 0
12:08:21 open("/var/db/sudo/matt/0", O_WRONLY|O_CREAT, 0600) = 4
12:08:21 fcntl(4, F_SETLKW, {type=F_WRLCK, whence=SEEK_CUR, start=0, len=0}) = 0
12:08:21 write(4, "\v\0\0\0\0\0\0\0\0\210\0\0\0\0\0\0\3\0\0\0\0\0\0\0`\206\212Q\0\0\0\0"..., 40) = 40
12:08:21 close(4)                       = 0
12:08:21 socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 4
12:08:21 connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
12:08:21 sendto(4, "<85>May  8 12:08:21 sudo:     ma"..., 95, MSG_NOSIGNAL, NULL, 0) = 95
12:08:34 close(4)                       = 0
12:08:34 close(3)                       = 0
12:08:34 munmap(0x7f5ccef9e000, 4096)   = 0
12:08:34 umask(022)                     = 02
12:08:34 umask(02)                      = 022
12:08:34 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f5cce1de920}, NULL, 8) = 0
12:08:34 rt_sigaction(SIGQUIT, {SIG_DFL, [], SA_RESTORER, 0x7f5cce1de920}, NULL, 8) = 0
12:08:34 rt_sigaction(SIGTSTP, {SIG_DFL, [], SA_RESTORER, 0x7f5cce1de920}, NULL, 8) = 0
12:08:34 socket(PF_NETLINK, SOCK_RAW, 9) = 3
12:08:34 fcntl(3, F_SETFD, FD_CLOEXEC)  = 0
12:08:34 fcntl(3, F_SETFD, FD_CLOEXEC)  = 0
12:08:34 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
12:08:34 readlink("/proc/self/fd/0", "/dev/pts/0"..., 31) = 10
12:08:34 lstat("/dev/pts/0", {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0
12:08:34 getcwd("/home/matt", 4096)     = 11
Improve this question
3
  • Well the big delay seems to be related to the sendto() which Google explains is a function for writing to a socket. The socket appears to be /dev/log which is normally syslog. Your syslog seems to be slow for some reason. Are you using a network-based syslog?
    – Zoredache
    May 8, 2013 at 17:36
  • Yep...tracked it down to rsyslog. I'm logging to a remote server and that remote server had gone offline causing rsyslog to delay everything. I thought rsyslog would handle that better. It's supposed to queue log messages to /var/spool/rsyslog I think and then send them when it sees the remote come back online. I'll have to do some more research on that.
    – Matt Mencel
    May 8, 2013 at 17:56
  • 1
    When diagnosing slowness with strace, the -T and -tt options are indispensible. Microsecond timestamp at the start of every line and deltas at the end of each line.
    – Ladadadada
    May 8, 2013 at 19:09

3 Answers 3

Reset to default
1

Your problem is that logging to syslog is extremely slow.

Explanation:

Note the 13 sec pause between the sendto call and the close call:

12:08:21 connect(4, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
12:08:21 sendto(4, "<85>May  8 12:08:21 sudo:     ma"..., 95, MSG_NOSIGNAL, NULL, 0) = 95
12:08:34 close(4)

sendto means that the program is trying to send a message. Notice that the message looks like a log line (May 8 12:08:21 sudo: ma). It tries to send it to fd 4. You can see above that fd 4 refers to file /dev/log. If you issue the command file /dev/log it will show you that this is a special file -- a UNIX domain socket. If you then try lsof /dev/log you'll see that this socket is held open by the rsyslogd daemon. As you can probably guess this socket is used to accept log messages by other programs (they connect to the socket and send messages which will be logged). So sudo is trying to log a message via rsyslogd and this takes a very long time.

As you found out by viewing /etc/rsyslog.conf the delay was caused because you had configured rsyslog to log to a remote server that was not responding. User @Alex North-Keys points out that there are options to mitigate this kind of problem (look under "Failover Logging to Remote Host" at https://wiki.archlinux.org/index.php/Syslog-ng)

Improve this answer
0

syslog-ng has a lot of useful options for mitigating problems with dead remote logging servers. Have a look under "Failover Logging to Remote Host" at https://wiki.archlinux.org/index.php/Syslog-ng

Improve this answer
1
  • Good suggestion but it should be a comment not an answer
    – ndemou
    Aug 28, 2017 at 11:02
-1

Rsyslog remote was down. See my comment above.

Improve this answer
1
  • Leaving aside that you should know when your syslog server went down, most syslogd implementations provide a means for buffering messages.
    – symcbean
    Aug 28, 2017 at 12:08

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .