Marathon: Graceful restart of a docker task

[bydga]

Hi,
i'm now trying to implement "graceful" restarts of a Marathon app. Currently the old task just dies (gets from RUNNING into KILLED immediately after the restart is issued). I have a simple nodejs app that listens on marathon-provided port and does nothing but waits on signals to die peacefully. I am unfortuantely not sure if its a problem of Mesos or Marathon or our setup.

The setup is following (im just picking the important parts:

the app is really simple coffescript app:

express = require "express"

console.log new Date(), "start", process.env

process.on "exit", () -> console.log "onExit"

["SIGINT", "SIGTERM"].forEach (sig) ->
    process.on sig, () ->
        console.log new Date(), "got", sig
        setTimeout () ->
            console.log new Date(), "ending on #{sig}"
            process.exit()
        , 10000

app = express()

app.get "/", (req, res, next) ->
    res.send "Hello world"

app.listen process.env.PORT, () ->
    console.log "app listening on #{process.env.PORT}"

mesos-slave (from mesos-slave:5051/state.json)

{
  "containerizers": "docker,mesos",
  "docker": "docker",
  "docker_kill_orphans": "false",
  "docker_remove_delay": "6hrs",
  "docker_socket": "/var/run/docker.sock",
  "docker_stop_timeout": "10secs",
  "executor_registration_timeout": "5mins",
  "executor_shutdown_grace_period": "5secs"
}

marathon app definition (from marathon:8080/apps/example-api)

{
  "app": {
    "id": "/example-api",
    "cmd": null,
    "args": [
      "coffee",
      "index.coffee"
    ],
    "instances": 1,
    "cpus": 0.2,
    "mem": 255,
    "executor": "",
    "uris": [ "file:///etc/docker/docker.tar.gz" ],
    "ports": [ 10002 ],
    "backoffSeconds": 1,
    "backoffFactor": 1.15,
    "maxLaunchDelaySeconds": 30,
    "container": {
      "type": "DOCKER",
      "docker": {
        "image": "private-repo.com/example-api:latest",
        "privileged": false,
        "parameters": [
          { "key": "log-opt", "value": "gelf-address=udp://127.0.0.1:12231" },
          { "key": "log-driver", "value": "gelf" },
          { "key": "log-opt", "value": "env=MESOS_TASK_ID" }
        ],
      }
    },
    "upgradeStrategy": {
      "minimumHealthCapacity": 1,
      "maximumOverCapacity": 1
    }
   }
}

When I issue the restart in Marathon UI, i get startup of a new task and the old one is killed immediately.
stderr and stdout of the killed task is following:

--container="mesos-20151203-095512-437010442-5050-16498-S2.a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a" --docker="docker" --help="false" --initialize_driver_logging="true" --logbufsecs="0" --logging_level="INFO" --mapped_directory="/mnt/mesos/sandbox" --quiet="false" --sandbox_directory="/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a" --stop_timeout="10secs"
--container="mesos-20151203-095512-437010442-5050-16498-S2.a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a" --docker="docker" --help="false" --initialize_driver_logging="true" --logbufsecs="0" --logging_level="INFO" --mapped_directory="/mnt/mesos/sandbox" --quiet="false" --sandbox_directory="/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a" --stop_timeout="10secs"
Registered docker executor on xxx
Starting task example-api.df50df7d-a899-11e5-95df-02423f5b4e48
Tue Dec 22 2015 10:50:54 GMT+0000 (UTC) 'start' { PATH: '/app/.buildpack.bin/v4.2.2/bin:/app/.buildpack.bin/versions/node/v4.2.2/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin',
  PORT_10002: '31870',
  MARATHON_APP_VERSION: '2015-12-22T10:50:53.438Z',
  MARATHON_APP_DOCKER_IMAGE: 'private-repo.ccom/example-api:latest',
  MESOS_TASK_ID: 'example-api.df50df7d-a899-11e5-95df-02423f5b4e48',
  PORT: '31870',
  PORTS: '31870',
  MARATHON_APP_ID: '/example-api',
  PORT0: '31870',
  MESOS_SANDBOX: '/mnt/mesos/sandbox',
  HOME: '/app',
  GIT_HEAD: '17a7cc6d2f116c12633327a335cc5fff04ce2892' }
app listening on 31870
Killing docker task
Shutting down

I1222 10:50:53.572037  4809 fetcher.cpp:414] Fetcher Info: {"cache_directory":"\/tmp\/mesos\/fetch\/slaves\/20151203-095512-437010442-5050-16498-S2","items":[{"action":"BYPASS_CACHE","uri":{"extract":true,"value":"file:\/\/\/etc\/docker\/docker.tar.gz"}}],"sandbox_directory":"\/srv\/mesos\/slaves\/20151203-095512-437010442-5050-16498-S2\/frameworks\/20151202-100301-437010442-5050-31779-0001\/executors\/example-api.df50df7d-a899-11e5-95df-02423f5b4e48\/runs\/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a"}
I1222 10:50:53.574636  4809 fetcher.cpp:369] Fetching URI 'file:///etc/docker/docker.tar.gz'
I1222 10:50:53.574658  4809 fetcher.cpp:243] Fetching directly into the sandbox directory
I1222 10:50:53.574693  4809 fetcher.cpp:180] Fetching URI 'file:///etc/docker/docker.tar.gz'
I1222 10:50:53.574726  4809 fetcher.cpp:160] Copying resource with command:cp '/etc/docker/docker.tar.gz' '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a/docker.tar.gz'
I1222 10:50:53.582002  4809 fetcher.cpp:76] Extracting with command: tar -C '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a' -xf '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a/docker.tar.gz'
I1222 10:50:53.592977  4809 fetcher.cpp:84] Extracted '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a/docker.tar.gz' into '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a'
W1222 10:50:53.593045  4809 fetcher.cpp:265] Copying instead of extracting resource from URI with 'extract' flag, because it does not seem to be an archive: file:///etc/docker/docker.tar.gz
I1222 10:50:53.593071  4809 fetcher.cpp:446] Fetched 'file:///etc/docker/docker.tar.gz' to '/srv/mesos/slaves/20151203-095512-437010442-5050-16498-S2/frameworks/20151202-100301-437010442-5050-31779-0001/executors/example-api.df50df7d-a899-11e5-95df-02423f5b4e48/runs/a817f3cf-04bc-4f7d-951f-6f48a4e0fc2a/docker.tar.gz'
I1222 10:50:53.794795  4819 exec.cpp:133] Version: 0.24.1
I1222 10:50:53.801050  4821 exec.cpp:207] Executor registered on slave 20151203-095512-437010442-5050-16498-S2
Warning: '-c' is deprecated, it will be replaced by '--cpu-shares' soon. See usage.
WARNING: Your kernel does not support swap limit capabilities, memory limited without swap.
W1222 10:50:53.801050  4820 logging.cpp:81] RAW: Received signal SIGTERM from process 22013 of user 0; exiting

The weird line is the Killing docker task - printed on the app's stdout by mesos - I would expect to get the line from my signal handler - something like " 2015-12-23 10:00:00 ending on SIGTERM"

However, if I ssh on the mesos-slave and issue docker stop containerId of the desired task i get proper behavior (ofc marathon immediately notices the app is underscaled and creates a new task instead):

Registered docker executor on xxx
Starting task example-api.26d5e82e-a987-11e5-95df-02423f5b4e48
Wed Dec 23 2015 15:09:25 GMT+0000 (UTC) 'start' { PATH: '/app/.buildpack.bin/v4.2.2/bin:/app/.buildpack.bin/versions/node/v4.2.2/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin',
  PORT_10002: '31172',
  MARATHON_APP_VERSION: '2015-12-23T15:09:24.078Z',
  MARATHON_APP_DOCKER_IMAGE: 'private-repo.com/example-api:latest',
  MESOS_TASK_ID: 'example-api.26d5e82e-a987-11e5-95df-02423f5b4e48',
  PORT: '31172',
  PORTS: '31172',
  MARATHON_APP_ID: '/example-api',
  PORT0: '31172',
  MESOS_SANDBOX: '/mnt/mesos/sandbox',
  HOME: '/app',
  GIT_HEAD: '17a7cc6d2f116c12633327a335cc5fff04ce2892' }
app listening on 31172
Wed Dec 23 2015 15:53:45 GMT+0000 (UTC) 'got' 'SIGTERM'
Wed Dec 23 2015 15:53:55 GMT+0000 (UTC) 'ending on SIGTERM'
onExit

And now my questions are:
Is the Marathon sending "wrong" kill command and can i reconfigure it or is it a bug?
Is the Mesos misconfigured so he doesn't issue the kill command properly and I should get in touch with the Mesos guys?

Sorry for so long and exhausting report, but thats all i was able to dig about it. Btw, I also have the mesos and marathon logs from server, if it would be helpful.. :)

[scalp42]

@bydga have a look at docker_stop_timeout on the mesos slave:

{
  'executor_registration_timeout' => '5mins',
  'containerizers' => 'docker,mesos',
  'ip' => node['ipaddress'],
  'docker_stop_timeout' => '30secs',
  'executor_shutdown_grace_period' => '90secs',
  'isolation' => 'cgroups/cpu,cgroups/mem',
  'recover' => 'reconnect', # Need to use "cleanup" when doing an incompatible slave or executor upgrade!
  'logbufsecs' => 1,
  'strict' => false,
}

Hopefully it helps, if not disregard then.

[bydga]

Well i can try increasing the values you are mentioning, but as I've shown above - we have them set up like

{  "docker_stop_timeout": "10secs",
  "executor_shutdown_grace_period": "5secs"
}

And the problem is, that the signal doensn't get propagated into my application and the app dies immediately. If I do docker stop directly on the slave it works like expected. So the question is - is there a problem with mesos containerizer not issuing "proper" docker stop or is marathon somehow able to control this shutdown process?

[bydga]

Nope, I'm still not able to achieve a graceful restart like I would expect when issuing docker stop --time=10 (SIGTERM followed by SIGKILL in 10s). I modified the timeouts to reflect your advice, but the tasks still die immediately with the message:

Killing docker task
Shutting down

on stdout. tracing this message, i got into https://github.com/apache/mesos/blob/d01585f1b312ffbe3c17f69d4c37d8e2375f9409/src/docker/executor.cpp#L195. I'm still convinced, that "someone" is orchestrating wrong command to stop the docker container - any ideas how can i trace it?

[bydga]

So now i've deployed a simpel python script on all mesos-slaves:

#!/usr/bin/python

from time import sleep
import signal
import sys
import datetime


def sigterm_handler(_signo, _stack_frame):
    print "got %i" % _signo
    print datetime.datetime.now().time()
    sys.stdout.flush()
    sleep(2)
    print datetime.datetime.now().time()
    print "ending"
    sys.stdout.flush()
    sys.exit(0)

signal.signal(signal.SIGTERM, sigterm_handler)
signal.signal(signal.SIGINT, sigterm_handler)

try:
    print "Hello"
    i = 0
    while True:
        i += 1
        print datetime.datetime.now().time()
        print "Iteration #%i" % i
        sys.stdout.flush()
        sleep(1)
finally:
    print "Goodbye"

and ran that script WITHOUT DOCKER like:

data =
    args: ["/tmp/script/script.py"]
    cpus: 0.1
    mem: 256
    ports: [0]
    backoffSeconds: 1
    backoffFactor: 1.15
    maxLaunchDelaySeconds: 30
    instances: 1
    id: "marathon-test-api"

request
    method: "post"
    url: "http://mesos-master:8080/v2/apps"
    json: data
, (e, r, b) ->
    console.log "err", e if e
    console.log r.statusCode
    console.log b

and I achieved the grafeful restart.

Then i easily wrapped this (same) script in docker

FROM node:4.2

RUN mkdir /app
ADD . /app
WORKDIR /app
ENTRYPOINT []

and ran it like

data =
    args: ["./script.py"]
    container:
        type: "DOCKER"
        docker:
            image: "bydga/marathon-test-api"
        forcePullImage: yes
    cpus: 0.1
    mem: 256
    ports: [0]
    backoffSeconds: 1
    backoffFactor: 1.15
    maxLaunchDelaySeconds: 30
    instances: 1
    id: "marathon-test-api"

request
    method: "post"
    url: "http://mesos-master:8080/v2/apps"
    json: data
, (e, r, b) ->
    console.log "err", e if e
    console.log r.statusCode
    console.log b

and BOOM - no graceful shutdown.

[gkleiman]

bydga, thanks for the detailed issue. It looks like this might actually be a Mesos Agent bug, could you please create an issue in Mesos' JIRA with your findings?

I guess that the Docker containerizer is either calling docker kill instead of docker stop or just killing the executor process, which might indirectly lead to a docker kill.

[gkleiman]

@bydga I checked with a Mesos developer and this he mentioned that more recent versios of Mesos include some Docker related fixes.

Could you please repeat the test with the latest Mesos (v0.26.0)?

Thanks again!

[bydga]

Hi, I'm now chatting with mesos folks. https://issues.apache.org/jira/browse/MESOS-4279. I really dont know whats wrong and why our setup is still not working. If you got any idea WHAT could be causing this, I would love to hear that..

[xiaods]

+1 on MESOS-4279