I ran tcpdump on lo during a failed/hanging wget attempt. This showed the SYN packet coming in, but no SYN|ACK response going out. So the packet is coming in, but nothing appears to be accept()ing it.
I took a look to see what pids are listening on port 5240:
tcp6 0 0 :::5240 :::* LISTEN 1684/python3
tcp6 0 0 :::5240 :::* LISTEN 1694/python3
tcp6 0 0 :::5240 :::* LISTEN 1703/python3
tcp6 51 0 :::5240 :::* LISTEN 1680/python3
I then ran strace on those processes, and ran wget a few times until it hung:
strace of hanging wget (mainly for timestamp):
19:12:28.826032 connect(4, {sa_family=AF_INET6, sin6_port=htons(5240), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28^Cstrace: Process 609353 detached
<detached ...>
When the wget does not hang, we expect to see epoll return an fd followed by an accept(), such as:
[pid 1684] 19:12:30.247918 epoll_wait(5, [{EPOLLIN, {u32=19, u64=140711718551571}}], 10, 499) = 1
[pid 1684] 19:12:30.319911 accept4(19, {sa_family=AF_INET6, sin6_port=htons(55268), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 14
But we do not see that in the above output - each process just seems to be in an epoll_wait() loop, never noticing a new connection. But that's only 3 of the processes. We see nothing from pid 1680. What's it doing?
# strace -p 1680
strace: Process 1680 attached
read(39,
Huh - this process just seems hung in a read() call. And it stays hung here for a very long time (at least an hour), even if I drop the external network interface from the container. Looking at another not-hung MAAS server of the same version, I can see that each of the 4 listening regiond processes are in epoll() loops, so this seems like an important difference. A regiond process has told the kernel it is listening on port 5240, but it isn't actually polling for new connections. So, what it is it trying to read?
# ls -l /proc/1680/fd/39
lrwx------ 1 root root 64 Jan 12 18:20 /proc/1680/fd/39 -> 'socket:[2294475183]'
$ host 91.189.88.136
136.88.189.91.in-addr.arpa domain name pointer images-maas-io.sawo.canonical.com.
Ah.. maas images. So, is it possible that a regiond process remains bound to port 5240 while it goes off to fetch images, and does so w/o a reasonable timeout that causes it to block indefinitely? And is it the case that we therefore only have 3/4 of our regiond workers processing requests, making 1/4 of those requests timeout?
I ran tcpdump on lo during a failed/hanging wget attempt. This showed the SYN packet coming in, but no SYN|ACK response going out. So the packet is coming in, but nothing appears to be accept()ing it.
I took a look to see what pids are listening on port 5240:
tcp6 0 0 :::5240 :::* LISTEN 1684/python3
tcp6 0 0 :::5240 :::* LISTEN 1694/python3
tcp6 0 0 :::5240 :::* LISTEN 1703/python3
tcp6 51 0 :::5240 :::* LISTEN 1680/python3
I then ran strace on those processes, and ran wget a few times until it hung:
strace of hanging wget (mainly for timestamp): AF_INET6, sin6_port= htons(5240) , sin6_flowinfo= htonl(0) , inet_pton(AF_INET6, "::1", &sin6_addr), sin6_scope_id=0}, 28^Cstrace: Process 609353 detached
19:12:28.826032 connect(4, {sa_family=
<detached ...>
strace of the 4 python processes (regiond):
# strace -tt -p 1684 -p 1694 -p 1703 -p1680
[pid 1703] 19:12:28.089944 <... epoll_wait resumed>[], 10, 397) = 0
[pid 1703] 19:12:28.090230 epoll_wait(5, <unfinished ...>
[pid 1694] 19:12:28.178543 <... epoll_wait resumed>[], 9, 206) = 0
[pid 1694] 19:12:28.178798 epoll_wait(5, [], 9, 0) = 0
[pid 1694] 19:12:28.179059 epoll_wait(5, <unfinished ...>
[pid 1703] 19:12:28.190505 <... epoll_wait resumed>[], 10, 100) = 0
[pid 1703] 19:12:28.190798 epoll_wait(5, [], 10, 0) = 0
[pid 1703] 19:12:28.191106 epoll_wait(5, <unfinished ...>
[pid 1684] 19:12:28.247185 <... epoll_wait resumed>[], 10, 300) = 0
[pid 1684] 19:12:28.247463 epoll_wait(5, [], 10, 0) = 0
[pid 1684] 19:12:28.247775 epoll_wait(5, <unfinished ...>
[pid 1694] 19:12:28.677734 <... epoll_wait resumed>[], 9, 498) = 0
[pid 1694] 19:12:28.677978 epoll_wait(5, [], 9, 0) = 0
[pid 1694] 19:12:28.678228 epoll_wait(5, <unfinished ...>
[pid 1703] 19:12:28.690792 <... epoll_wait resumed>[], 10, 499) = 0
[pid 1703] 19:12:28.691054 epoll_wait(5, [], 10, 0) = 0
[pid 1703] 19:12:28.691333 epoll_wait(5, <unfinished ...>
[pid 1684] 19:12:28.747457 <... epoll_wait resumed>[], 10, 499) = 0
[pid 1684] 19:12:28.747698 epoll_wait(5, [], 10, 0) = 0
[pid 1684] 19:12:28.747951 epoll_wait(5, [], 10, 31) = 0
[pid 1684] 19:12:28.779333 epoll_wait(5, <unfinished ...>
[pid 1694] 19:12:28.972708 <... epoll_wait resumed>[], 9, 294) = 0
[pid 1694] 19:12:28.973067 epoll_wait(5, <unfinished ...>
[pid 1703] 19:12:29.090921 <... epoll_wait resumed>[], 10, 399) = 0
When the wget does not hang, we expect to see epoll return an fd followed by an accept(), such as: 1571}}] , 10, 499) = 1 AF_INET6, sin6_port= htons(55268) , sin6_flowinfo= htonl(0) , inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 14
[pid 1684] 19:12:30.247918 epoll_wait(5, [{EPOLLIN, {u32=19, u64=14071171855
[pid 1684] 19:12:30.319911 accept4(19, {sa_family=
But we do not see that in the above output - each process just seems to be in an epoll_wait() loop, never noticing a new connection. But that's only 3 of the processes. We see nothing from pid 1680. What's it doing?
# strace -p 1680
strace: Process 1680 attached
read(39,
Huh - this process just seems hung in a read() call. And it stays hung here for a very long time (at least an hour), even if I drop the external network interface from the container. Looking at another not-hung MAAS server of the same version, I can see that each of the 4 listening regiond processes are in epoll() loops, so this seems like an important difference. A regiond process has told the kernel it is listening on port 5240, but it isn't actually polling for new connections. So, what it is it trying to read?
# ls -l /proc/1680/fd/39 [2294475183] '
lrwx------ 1 root root 64 Jan 12 18:20 /proc/1680/fd/39 -> 'socket:
# lsof -i -a -p 1680 32.21:5240- >10.172. 65.1:41332 (ESTABLISHED) 32.21:5240- >10.172. 69.16:58096 (ESTABLISHED) 32.21:5240- >10.172. 68.66:56308 (ESTABLISHED) 32.21:5240- >10.172. 68.66:47920 (ESTABLISHED) 32.21:5240- >10.172. 68.187: 36276 (CLOSE_WAIT) 32.21:54640- >91.189. 88.136: https (ESTABLISHED) 32.21:5250- >10.229. 32.21:58460 (CLOSE_WAIT)
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python3 1680 root 14u IPv6 1987974159 0t0 TCP 10.229.
python3 1680 root 15u IPv6 1057339385 0t0 TCP *:5250 (LISTEN)
python3 1680 root 23u IPv6 1057352793 0t0 TCP *:5240 (LISTEN)
python3 1680 root 28u IPv6 1082137789 0t0 TCP 10.229.
python3 1680 root 30u IPv6 1652988559 0t0 TCP 10.229.
python3 1680 root 31u IPv6 1466877827 0t0 TCP 10.229.
python3 1680 root 35u IPv6 1937014214 0t0 TCP 10.229.
python3 1680 root 39u IPv4 2294475183 0t0 TCP 10.229.
python3 1680 root 57u IPv6 1699973134 0t0 TCP 10.229.
$ host 91.189.88.136 189.91. in-addr. arpa domain name pointer images- maas-io. sawo.canonical. com.
136.88.
Ah.. maas images. So, is it possible that a regiond process remains bound to port 5240 while it goes off to fetch images, and does so w/o a reasonable timeout that causes it to block indefinitely? And is it the case that we therefore only have 3/4 of our regiond workers processing requests, making 1/4 of those requests timeout?