使用 STRACE 對 SUDO 緩慢進行故障排除

我在某些系統上遇到了 sudo 問題。完成一個 sudo 命令甚至登錄系統都需要 15-30 秒。

我跑了一個 strace，可以看到延遲發生在哪裡，但我不確定出了什麼問題。似乎它正在等待對 /dev/log 的寫入請求？但這並沒有告訴我太多資訊，也沒有告訴我為什麼要花這麼長時間。是否有任何 strace 專家可以更好地解釋這一點？

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

您的問題是記錄到 syslog 非常慢。

解釋：

注意 sendto 呼叫和 close 呼叫之間的 13 秒暫停：

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表示程序正在嘗試發送消息。請注意，該消息看起來像一個日誌行 ( May 8 12:08:21 sudo: ma)。它嘗試將其發送到 fd 4。您可以在上面看到 fd 4 指的是 file /dev/log。如果你發出這個命令file /dev/log，它會告訴你這是一個特殊的文件——一個 UNIX 域套接字。如果你再試一下lsof /dev/log，你會看到這個套接字被 rsyslogd 守護程序保持打開狀態。正如您可能猜到的那樣，此套接字用於接受其他程序的日誌消息（它們連接到套接字並發送將被記錄的消息）。所以 sudo 試圖通過 rsyslogd 記錄一條消息，這需要很長時間。

正如您通過查看 /etc/rsyslog.conf 發現的那樣，延遲是因為您已將 rsyslog 配置為登錄到沒有響應的遠端伺服器。使用者@Alex North-Keys 指出有一些選項可以緩解此類問題（在https://wiki.archlinux.org/index.php/Syslog-ng的“故障轉移日誌記錄到遠端主機”下查看）

引用自：https://serverfault.com/questions/506110