Home / server / Questions / 506110
Accepted
Matt Mencel
Asked: 2013-05-09 09:13:54 +0800 CST

Troubleshooting SUDO Slowness with STRACE

  • 772

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
centos6

3 Answers

  1. Best Answer

    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)

    • 1

  2. 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

    • 0

  3. Rsyslog remote was down. See my comment above.

    • -1