-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/44657/
-----------------------------------------------------------
(Updated March 23, 2016, 9:45 p.m.)
Review request for mesos, Ben Mahler and Gilbert Song.
Changes
-------
Manually tested the `killTask` path.
Bugs: MESOS-4909
https://issues.apache.org/jira/browse/MESOS-4909
Repository: mesos
Description
-------
The command executor determines how much time it allots the
underlying task to clean up (effectively how long to wait for
the task to comply to SIGTERM before sending SIGKILL) based
on both optional task's `KillPolicy` and optional
`shutdown_grace_period` field in `ExecutorInfo`.
Manual testing was performed to ensure newly introduced protobuf
fields are respected. To do that, "mesos-execute" was modified to
support `KillPolicy` and `CommandInfo.shell=false`. To simulate a
task that does not exit in the allotted period, a tiny app
(https://github.com/rukletsov/unresponsive-process) that ignores
SIGTERM was used.
Diffs
-----
src/launcher/executor.cpp 2df62f09637b55c63ae6fe5d5a70b8debc02fbe2
src/slave/slave.cpp 840534ff0687e82ed063c386e36bbabada230697
Diff: https://reviews.apache.org/r/44657/diff/
Testing (updated)
-------
To test the newly introduced protobuf fields, I've modified "mesos-execute" to
support these fields. I've inserted these lines in `resourceOffers()` method:
```
task.mutable_kill_policy()->mutable_grace_period()->
set_nanoseconds(Seconds(<value>).ns());
```
I've also implemented a "--no-shell" flag to support
setting `CommandInfo.shell` to `false`. An example command used in testing:
```
./src/mesos-execute --master=127.0.0.1:5050 --name=test
--command="/Users/alex/bin/unresponsive_process" --no-shell
```
In order to test the signal escalation path, which is what the command executor
implements currently for kill policy, I've created a tiny application that
ignores SIGTERM (https://github.com/rukletsov/unresponsive-process ).
Test 1.1:
=========
`KillPolicy.grace_period` is **not set**, `shell=false`, framework shutdown.
Framework is asked to shutdown several seconds after the task is started. This
results in agent asking executor to shutdown. From the agent's logs, we see that
the command executor sends a TASK_KILLED update in approx. **3 seconds** (the
default value is **5 seconds**, but we deduct some buffer to make sure the task
can
be reaped and TASK_KILLED is sent) after it has been asked to shut down:
```
I0323 17:24:48.704677 418881536 slave.cpp:2080] Asked to shut down framework
9eb233b5-dfe8-4030-a989-57f31ec0e3aa-0000 by master@127.0.0.1:5050
I0323 17:24:48.704710 418881536 slave.cpp:2105] Shutting down framework
9eb233b5-dfe8-4030-a989-57f31ec0e3aa-0000
I0323 17:24:48.704756 418881536 slave.cpp:4216] Shutting down executor 'test'
of framework 9eb233b5-dfe8-4030-a989-57f31ec0e3aa-0000 at
executor(1)@192.168.178.24:50933
I0323 17:24:51.817987 419418112 slave.cpp:3003] Handling status update
TASK_KILLED (UUID: 9cf799dd-3492-42c2-9b43-fcb7283ebec9) for task test of
framework 9eb233b5-dfe8-4030-a989-57f31ec0e3aa-0000 from
executor(1)@192.168.178.24:50933
```
Excerpt from the executor's log we see, that `CommandExecutor::escalated()` has
been called in 3 seconds:
```
Shutting down
Sending SIGTERM to process tree at pid 23632
9276662428399220356
Sent SIGTERM to the following process trees:
[
--- 23632 /Users/alex/bin/unresponsive_process
]
10137513391590427691
12741826412569908689
Process 23632 did not terminate after 3secs, sending SIGKILL to process tree at
23632
16972857197258033356
Killed the following process trees:
[
--- 23632 /Users/alex/bin/unresponsive_process
]
Command terminated with signal Killed: 9 (pid: 23632)
```
Test 1.2:
=========
`KillPolicy.grace_period` is **not set**, `shell=true`, framework shutdown.
The only difference to test 1.1 is `shell=true`. Similar behavior is observed.
Test 2.1:
=========
`KillPolicy.grace_period` set to **0s**, `shell=false`, framework shutdown.
Similar to test 1.1, but the escalation timeout is set to 0s (no deductions
because the kill policy is set explicitly; the grace period in containerizer
should be adjusted to approx. 2 seconds):
```
I0323 17:38:07.650616 189734912 slave.cpp:2080] Asked to shut down framework
0dbc9e01-89ef-4cff-8c64-cdb3b46e9b2a-0000 by master@127.0.0.1:5050
I0323 17:38:07.650647 189734912 slave.cpp:2105] Shutting down framework
0dbc9e01-89ef-4cff-8c64-cdb3b46e9b2a-0000
I0323 17:38:07.650686 189734912 slave.cpp:4216] Shutting down executor 'test'
of framework 0dbc9e01-89ef-4cff-8c64-cdb3b46e9b2a-0000 at
executor(1)@192.168.178.24:51836
I0323 17:38:07.823477 187052032 slave.cpp:3003] Handling status update
TASK_KILLED (UUID: 56aad190-2ea2-4bb2-8d61-7a49ff42d4ba) for task test of
framework 0dbc9e01-89ef-4cff-8c64-cdb3b46e9b2a-0000 from
executor(1)@192.168.178.24:51836
```
Excerpt from the executor's log we see, that `CommandExecutor::escalated()` has
been called in 0 seconds:
```
Shutting down
Sending SIGTERM to process tree at pid 24075
Sent SIGTERM to the following process trees:
[
10370891801885978953
--- 24075 /Users/alex/bin/unresponsive_process
]
Process 24075 did not terminate after 0ns, sending SIGKILL to process tree at
24075
Killed the following process trees:
[
--- 24075 /Users/alex/bin/unresponsive_process
]
Command terminated with signal Killed: 9 (pid: 24075)
```
Test 2.2:
=========
`KillPolicy.grace_period` set to **0s**, `shell=true`, framework shutdown
The only difference to test 2.1 is `shell=true`. Similar behavior is observed.
Test 3.1:
=========
`KillPolicy.grace_period` set to **11s**, `shell=false`, framework shutdown
Similar to test 1.1, but the escalation timeout is set to 11 seconds
(no deductions because the kill policy is set explicitly):
```
I0323 16:59:19.218186 189407232 slave.cpp:2105] Shutting down framework
8bd2df7e-5659-4887-800e-604db3694e17-0000
I0323 16:59:19.218214 189407232 slave.cpp:4216] Shutting down executor 'test'
of framework 8bd2df7e-5659-4887-800e-604db3694e17-0000 at
executor(1)@192.168.178.24:65526
I0323 16:59:30.353431 190480384 slave.cpp:3003] Handling status update
TASK_KILLED (UUID: e7a5fcfb-33a2-4341-8ca4-d372c754020c) for task test of
framework 8bd2df7e-5659-4887-800e-604db3694e17-0000 from
executor(1)@192.168.178.24:65526
```
Excerpt from the executor's log we see, that `CommandExecutor::escalated()` has
been called in 11 seconds:
```
Shutting down
Sending SIGTERM to process tree at pid 23173
Sent SIGTERM to the following process trees:
5447330384702360843
[
--- 23173 /Users/alex/bin/unresponsive_process
]
9421153335942970033
12365643494559189178
7584901102993551143
12120587866343901205
9383577596543058034
10156641407552912845
12050873774172063028
11004056749756330400
13931472820830639858
16620123046684546445
Process 23173 did not terminate after 11secs, sending SIGKILL to process tree
at 23173
Killed the following process trees:
[
--- 23173 /Users/alex/bin/unresponsive_process
]
Command terminated with signal Killed: 9 (pid: 23173)
```
Test 3.2:
=========
`KillPolicy.grace_period` set to **11s**, `shell=true`, framework shutdown
The only difference to test 3.1 is `shell=true`. Similar behavior is observed.
Test 3.3:
=========
`KillPolicy.grace_period` set to **11s**, `shell=false`, `killTask`
Similar to test 3.1, but instead of framework shutdown, `killTask()` is called.
The difference is the executor's log, which indicates the `killTask` path is
being executed:
```
Received killTask
Shutting down
Sending SIGTERM to process tree at pid 25463
Sent SIGTERM to the following process trees:
[
--- 25463 /Users/alex/bin/unresponsive_process
]
17172602460659762152
4381544758593790168
10370891801885978953
4918013092589539175
9276662428399220356
10137513391590427691
12741826412569908689
16972857197258033356
3581100400388580249
4936931647359169578
14723711275895450681
Process 25463 did not terminate after 11secs, sending SIGKILL to process tree
at 25463
Killed the following process trees:
[
--- 25463 /Users/alex/bin/unresponsive_process
]
Command terminated with signal Killed: 9 (pid: 25463)
Shutting down
```
Thanks,
Alexander Rukletsov
