1

I have a VM running Debian 9 (Stretch).

I can log in to my own user account fine.

However, every time I try to switch users using sudo su, after entering my password (instantaneously), it takes several minutes before succeeding. It does not matter if the other user is root, or some other user account.

Other commands using sudo, such as sudo echo, work just fine (I have tried steps to debug slow sudo commands in general, including issues relating to resolving the hostname, and everything should be okay.)

I have checked for other processes involving sudo and found nothing.

I have tried running sudo strace sudo su, and have gotten the following output (just showing the last few lines; again this process took several minutes before succeeding):

fcntl(8, F_SETLKW, {l_type=F_RDLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
read(8, "\2\0\0\0\0\0\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
read(8, "\6\0\0\0\213\2\0\0ttyS0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
read(8, "\6\0\0\0\214\2\0\0tty1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
read(8, "\1\0\0\0005\0\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
read(8, "\7\0\0\0e\32\0\0pts/0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
read(8, "\7\0\0\0TL\0\0pts/1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384
fcntl(8, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
alarm(0)                                = 10
rt_sigaction(SIGALRM, {sa_handler=0x55dacfaa8200, sa_mask=~[KILL STOP RTMIN RT_1], sa_flags=SA_RESTORER|SA_INTERRUPT|SA_SIGINFO, sa_restorer=0x7f8ab6d33060}, NULL, 8) = 0
close(8)                                = 0
getuid()                                = 0
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
connect(8, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0
sendto(8, "<86>Mar  4 00:20:35 sudo: pam_un"..., 95, MSG_NOSIGNAL, NULL, 0) = 95
socket(AF_NETLINK, SOCK_RAW, NETLINK_AUDIT) = 9
fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
sendto(9, {{len=120, type=0x451 /* NLMSG_??? */, flags=NLM_F_REQUEST|NLM_F_ACK, seq=3, pid=0}, "op=PAM:session_open acct=\"root\" "...}, 120, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 120
poll([{fd=9, events=POLLIN}], 1, 500)   = 1 ([{fd=9, revents=POLLIN}])
recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=0, seq=3, pid=2859367897}, "\0\0\0\0x\0\0\0Q\4\5\0\3\0\0\0\0\0\0\0"}, 8988, MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36
recvfrom(9, {{len=36, type=NLMSG_ERROR, flags=0, seq=3, pid=2859367897}, "\0\0\0\0x\0\0\0Q\4\5\0\3\0\0\0\0\0\0\0"}, 8988, MSG_DONTWAIT, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, [12]) = 36
close(9)                                = 0
getpgrp()                               = 23062
rt_sigaction(SIGCHLD, {sa_handler=0x55dacfaa8200, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_INTERRUPT|SA_SIGINFO, sa_restorer=0x7f8ab6d33060}, NULL, 8) = 0
rt_sigaction(SIGCONT, {sa_handler=0x55dacfaa8200, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_INTERRUPT|SA_SIGINFO, sa_restorer=0x7f8ab6d33060}, NULL, 8) = 0
rt_sigaction(SIGTSTP, {sa_handler=0x55dacfaa8140, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER|SA_INTERRUPT|SA_SIGINFO, sa_restorer=0x7f8ab6d33060}, NULL, 8) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f8ab7d1ff50) = 23072
close(7)                                = 0
poll([{fd=3, events=POLLIN}, {fd=6, events=POLLIN}], 2, -1) = 1 ([{fd=6, revents=POLLIN|POLLHUP}])
recvfrom(6, "", 8, MSG_WAITALL, NULL, NULL) = 0
poll([{fd=3, events=POLLIN}], 1, -1)    = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} ---
restart_syscall(<... resuming interrupted poll ...>) = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} ---
restart_syscall(<... resuming interrupted restart_syscall ...>

It is hard to say precisely on which line the process stalls as it seems to not flush the buffer (it will pause on an incomplete line), but the lines towards the end of the log starting with poll and restart_syscall seem to be the lines on which the process is delayed.

I am not sure how to interpret this strace output, so any pointers or hints are appreciated.

My question: Based on this strace output, why does switching users using sudo take so long?


Edit: Thanks to the tip by @Ferenc Wágner in the comments, I added -f to strace and found that the sudo su was forking lots of processes that seemed to be cycling over and over. I am still not sure what precisely is the issue. (I've anonymised the domain name in the following log. I think the IP addresses are standard Google Cloud IPs.)

The following is a sample of the output from sudo strace -f -t sudo su. The output is very large and fast but seems to repeat the same processes over and over in different forks.

pid 17113] 17:29:51 poll(NULL, 0, 4strace: Process 20730 attached
 <unfinished ...>
[pid 20730] 17:29:51 set_robust_list(0x7fa609e0a9e0, 24) = 0
[pid 20730] 17:29:51 getpid()           = 17113
[pid 20730] 17:29:51 open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
[pid 20730] 17:29:51 fstat(3, {st_mode=S_IFREG|0644, st_size=154, ...}) = 0
[pid 20730] 17:29:51 read(3, "domain us-central1-a.c.my-domai"..., 4096) = 154
[pid 20730] 17:29:51 read(3, "", 4096)  = 0
[pid 20730] 17:29:51 close(3)           = 0
[pid 20730] 17:29:51 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 3
[pid 20730] 17:29:51 fstat(3, {st_mode=S_IFREG|0644, st_size=453, ...}) = 0
[pid 20730] 17:29:51 read(3, "127.0.0.1\tlocalhost my-domain i"..., 4096) = 453
[pid 20730] 17:29:51 read(3, "", 4096)  = 0
[pid 20730] 17:29:51 close(3)           = 0
[pid 20730] 17:29:51 madvise(0x7fa60960a000, 8368128, MADV_DONTNEED) = 0
[pid 20730] 17:29:51 exit(0)            = ?
[pid 20730] 17:29:51 +++ exited with 0 +++
[pid 17113] 17:29:51 <... poll resumed> ) = 0 (Timeout)
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
[pid 17113] 17:29:51 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
[pid 17113] 17:29:51 fcntl(3, F_GETFL)  = 0x2 (flags O_RDWR)
[pid 17113] 17:29:51 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 17113] 17:29:51 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("169.254.169.254")}, 16) = -1 EINPROGRESS (Operation now in progress)
[pid 17113] 17:29:51 poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 0 (Timeout)
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 poll([{fd=3, events=POLLOUT}], 1, 199) = 1 ([{fd=3, revents=POLLOUT}])
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 poll([{fd=3, events=POLLOUT|POLLWRNORM}], 1, 0) = 1 ([{fd=3, revents=POLLOUT|POLLWRNORM}])
[pid 17113] 17:29:51 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
[pid 17113] 17:29:51 getpeername(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("169.254.169.254")}, [128->16]) = 0
[pid 17113] 17:29:51 getsockname(3, {sa_family=AF_INET, sin_port=htons(37960), sin_addr=inet_addr("10.128.0.2")}, [128->16]) = 0
[pid 17113] 17:29:51 sendto(3, "GET /computeMetadata/v1/oslogin/"..., 134, MSG_NOSIGNAL, NULL, 0) = 134
[pid 17113] 17:29:51 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 poll([{fd=3, events=POLLIN}], 1, 198) = 1 ([{fd=3, revents=POLLIN}])
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=3, revents=POLLIN|POLLRDNORM}])
[pid 17113] 17:29:51 recvfrom(3, "HTTP/1.1 404 Not Found\r\nMetadata"..., 16384, 0, NULL, NULL) = 496
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 close(3)           = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 stat("/var/google-users.d/root", 0x7fff47fdaf50) = -1 ENOENT (No such file or directory)
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 clone(child_stack=0x7fa609e09fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fa609e0a9d0, tls=0x7fa609e0a700, child_tidptr=0x7fa609e0a9d0) = 20732
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fa611ec0060}, NULL, 8) = 0
[pid 17113] 17:29:51 poll(NULL, 0, 4strace: Process 20732 attached
 <unfinished ...>

So it is undoubtedly a network issue, but not sure I understand where the issue is.

The /etc/hosts file looks like:

127.0.0.1       localhost my-domain my-domain.site.com
127.0.1.1       localhost my-domain my-domain.site.com # trying to resolve this issue, probably not needed
::1             localhost ip6-localhost ip6-loopback my-domain my-domain.site.com
ff02::1         ip6-allnodes
ff02::2         ip6-allrouters

10.128.0.2 my-domain.us-central1-a.c.my-domain.internal my-domain  # Added by Google
169.254.169.254 metadata.google.internal  # Added by Google

The /etc/resolv.conf file reads:

domain us-central1-a.c.my-domain.internal
search us-central1-a.c.my-domain.internal. c.my-domain.internal. google.internal.
nameserver 169.254.169.254

The command hostname gives:

my-domain

I have read that sudo somehow depends on hostname, but I am not sure what sudo su is trying to look up here that (e.g.) sudo echo is not interested in.

8
  • 1
    Why do you think you need to use sudo su? What problem do you think you are solving? Commented Mar 4, 2021 at 2:30
  • I could survive without it, but I need to coordinate data between my user and two other users preconfigured on the VM for an application and a database that are not in the same group. Probably I could resolve this issue another way, but I'd like to solve this issue first as switching users is inherently useful (not necessarily requiring switching to root).
    – badroit
    Commented Mar 4, 2021 at 3:15
  • 2
    Use the -t option of strace to add timestamps to the output. Maybe -f as well to trace into forks if needed. Then edit the "slow part" of the output into your question. Commented Mar 4, 2021 at 12:20
  • 1
    sudo su can be simplified as sudo -s (and if you want to change to a different user, do that directly, for example sudo -s -u otheruser). Does that sidestep the issue? Commented Mar 4, 2021 at 17:58
  • 1
    The strace output shows a Google Cloud Compute Engine OS Login query returning "404 Not Found". Maybe cloud.google.com/compute/docs/oslogin/troubleshoot-os-login can help you some more, maybe the actual problem is somewhere else entirely. Commented Mar 5, 2021 at 7:31

1 Answer 1

2

Although not answering your question directly, this sidesteps the delay

sudo su can be simplified as sudo -s. If you want to change to a different user, you can do that directly, for example sudo -s -u otheruser

You must log in to answer this question.

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