Gilbert Song created MESOS-9151:
-----------------------------------
Summary: Container stuck at ISOLATING due to FD leaking.
Key: MESOS-9151
URL: https://issues.apache.org/jira/browse/MESOS-9151
Project: Mesos
Issue Type: Bug
Components: containerization
Reporter: Gilbert Song
When containers are launching on a single agent at scale, one container stuck
at ISOLATING could occasionally happen. And this container becomes
un-destroyable due to containerizer destroy always wait for isolate() finish to
continue.
We add more logging to debug this issue:
{noformat}
Aug 10 17:23:28 ip-10-0-1-129.us-west-2.compute.internal mesos-agent[2974]:
I0810 17:23:28.050068 2995 collect.hpp:271] $$$$: AwaitProcess waited invoked
for ProcessBase ID: __await__(26651); futures size: 3; future: Ready; future
index: 2; ready count: 1
Aug 10 17:23:28 ip-10-0-1-129.us-west-2.compute.internal mesos-agent[2974]:
I0810 17:23:28.414436 2998 collect.hpp:271] $$$$: AwaitProcess waited invoked
for ProcessBase ID: __await__(26651); futures size: 3; future: Ready; future
index: 0; ready count: 2
{noformat}
which shows that the await() in CNI::attach() stuck at the second future
(io::read() for stdout).
By looking at the df of this stdout:
{noformat}
Aug 10 17:23:27 ip-10-0-1-129.us-west-2.compute.internal mesos-agent[2974]:
I0810 17:23:27.657501 2995 cni.cpp:1287] !!!!: Start to await for plugin
'/opt/mesosphere/active/mesos/libexec/mesos/mesos-cni-port-mapper' to finish
for container 1c8abf4c-f71a-4704-9a73-1ab0dd709c62 with pid '16644'; stdout fd:
1781; stderr fd: 1800
{noformat}
We found
{noformat}
core@ip-10-0-1-129 ~ $ ps aux | grep mesos-agent
core 1674 0.0 0.0 6704 864 pts/0 S+ 20:00 0:00 grep
--colour=auto mesos-agent
root 2974 16.4 2.5 1211096 414048 ? Ssl 17:02 29:11
/opt/mesosphere/packages/mesos--61265af3be37861f26b657c1f9800293b86a0374/bin/mesos-agent
core@ip-10-0-1-129 ~ $ sudo ls -al /proc/2974/fd/ | grep 1781
l-wx------. 1 root root 64 Aug 10 19:38 1781 ->
/var/lib/mesos/slave/meta/slaves/d3089315-8e34-40b4-b1f7-0ac6a624d7db-S0/frameworks/d3089315-8e34-40b4-b1f7-0ac6a624d7db-0000/executors/test2.d820326d-9cc1-11e8-9809-ee15da5c8980/runs/38e9270d-ebda-4758-ad96-40c5b84bffdc/tasks/test2.d820326d-9cc1-11e8-9809-ee15da5c8980/task.updates
{noformat}
{noformat}
core@ip-10-0-1-129 ~ $ ps aux | grep 27981
core 2201 0.0 0.0 6704 884 pts/0 S+ 20:06 0:00 grep
--colour=auto 27981
root 27981 0.0 0.0 1516 4 ? Ss 17:25 0:00 sleep 10000
core@ip-10-0-1-129 ~ $ cat /proc/s^C
core@ip-10-0-1-129 ~ $ sudo -s
ip-10-0-1-129 core # ls -al /proc/27981/fd | grep 275230
lr-x------. 1 root root 64 Aug 10 20:05 1781 -> pipe:[275230]
l-wx------. 1 root root 64 Aug 10 20:05 1787 -> pipe:[275230]
{noformat}
{noformat}
core@ip-10-0-1-129 ~ $ sudo ls -al /proc/2974/fd/ | grep pipe
lr-x------. 1 root root 64 Aug 10 17:02 11 -> pipe:[49380]
l-wx------. 1 root root 64 Aug 10 17:02 14 -> pipe:[49380]
lr-x------. 1 root root 64 Aug 10 17:02 17 -> pipe:[48909]
lr-x------. 1 root root 64 Aug 10 19:38 1708 -> pipe:[275089]
l-wx------. 1 root root 64 Aug 10 19:38 1755 -> pipe:[275089]
lr-x------. 1 root root 64 Aug 10 19:38 1787 -> pipe:[275230]
l-wx------. 1 root root 64 Aug 10 17:02 19 -> pipe:[48909]
{noformat}
pipe 275230 is held by the agent process and the sleep process at the same time!
The reason why the leak is possible is because we don't use `pipe2` to create a
pipe with `O_CLOEXEC` in subprocess:
https://github.com/apache/mesos/blob/1.5.x/3rdparty/libprocess/src/subprocess_posix.cpp#L61
Although we do set cloexec on those fds later:
https://github.com/apache/mesos/blob/1.5.x/3rdparty/libprocess/src/subprocess.cpp#L366-L373
There is a race where a fork happens after `pipe()` call, but before cloexec is
called later. This is more likely on a busy system (this explains why it's not
hard to repo the issue when launching a lot of containers on a single box).
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
