{"action":"created","issue":{"url":"https://api.github.com/repos/mesosphere/marathon/issues/2876","labels_url":"https://api.github.com/repos/mesosphere/marathon/issues/2876/labels{/name}","comments_url":"https://api.github.com/repos/mesosphere/marathon/issues/2876/comments","events_url":"https://api.github.com/repos/mesosphere/marathon/issues/2876/events","html_url":"https://github.com/mesosphere/marathon/issues/2876","id":123683665,"number":2876,"title":"Graceful restart of a docker task","user":{"login":"bydga","id":2520017,"avatar_url":"https://avatars.githubusercontent.com/u/2520017?v=3","gravatar_id":"","url":"https://api.github.com/users/bydga","html_url":"https://github.com/bydga","followers_url":"https://api.github.com/users/bydga/followers","following_url":"https://api.github.com/users/bydga/following{/other_user}","gists_url":"https://api.github.com/users/bydga/gists{/gist_id}","starred_url":"https://api.github.com/users/bydga/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bydga/subscriptions","organizations_url":"https://api.github.com/users/bydga/orgs","repos_url":"https://api.github.com/users/bydga/repos","events_url":"https://api.github.com/users/bydga/events{/privacy}","received_events_url":"https://api.github.com/users/bydga/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":5,"created_at":"2015-12-23T16:06:28Z","updated_at":"2016-01-04T15:23:25Z","closed_at":"2016-01-04T15:23:25Z","body":"Hi,\r\ni'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.\r\n\r\nThe setup is following (im just picking the important parts:\r\n\r\nthe app is really simple coffescript app:\r\n```coffee\r\nexpress = require \"express\"\r\n\r\nconsole.log new Date(), \"start\", process.env\r\n\r\nprocess.on \"exit\", () -> console.log \"onExit\"\r\n\r\n[\"SIGINT\", \"SIGTERM\"].forEach (sig) ->\r\n\tprocess.on sig, () ->\r\n\t\tconsole.log new Date(), \"got\", sig\r\n\t\tsetTimeout () ->\r\n\t\t\tconsole.log new Date(), \"ending on #{sig}\"\r\n\t\t\tprocess.exit()\r\n\t\t, 10000\r\n\r\napp = express()\r\n\r\napp.get \"/\", (req, res, next) ->\r\n\tres.send \"Hello world\"\r\n\r\napp.listen process.env.PORT, () ->\r\n\tconsole.log \"app listening on #{process.env.PORT}\"\r\n```\r\n\r\nmesos-slave (from mesos-slave:5051/state.json)\r\n```json\r\n{\r\n  \"containerizers\": \"docker,mesos\",\r\n  \"docker\": \"docker\",\r\n  \"docker_kill_orphans\": \"false\",\r\n  \"docker_remove_delay\": \"6hrs\",\r\n  \"docker_socket\": \"/var/run/docker.sock\",\r\n  \"docker_stop_timeout\": \"10secs\",\r\n  \"executor_registration_timeout\": \"5mins\",\r\n  \"executor_shutdown_grace_period\": \"5secs\"\r\n}\r\n```\r\n\r\nmarathon app definition (from marathon:8080/apps/example-api)\r\n```json\r\n{\r\n  \"app\": {\r\n    \"id\": \"/example-api\",\r\n    \"cmd\": null,\r\n    \"args\": [\r\n      \"coffee\",\r\n      \"index.coffee\"\r\n    ],\r\n    \"instances\": 1,\r\n    \"cpus\": 0.2,\r\n    \"mem\": 255,\r\n    \"executor\": \"\",\r\n    \"uris\": [ \"file:///etc/docker/docker.tar.gz\" ],\r\n    \"ports\": [ 10002 ],\r\n    \"backoffSeconds\": 1,\r\n    \"backoffFactor\": 1.15,\r\n    \"maxLaunchDelaySeconds\": 30,\r\n    \"container\": {\r\n      \"type\": \"DOCKER\",\r\n      \"docker\": {\r\n        \"image\": \"private-repo.com/example-api:latest\",\r\n        \"privileged\": false,\r\n        \"parameters\": [\r\n          { \"key\": \"log-opt\", \"value\": \"gelf-address=udp://127.0.0.1:12231\" },\r\n          { \"key\": \"log-driver\", \"value\": \"gelf\" },\r\n          { \"key\": \"log-opt\", \"value\": \"env=MESOS_TASK_ID\" }\r\n        ],\r\n      }\r\n    },\r\n    \"upgradeStrategy\": {\r\n      \"minimumHealthCapacity\": 1,\r\n      \"maximumOverCapacity\": 1\r\n    }\r\n   }\r\n}\r\n```\r\n\r\n\r\nWhen I issue the restart in Marathon UI, i get startup of a new task and the old one is killed immediately.\r\nstderr and stdout of the killed task is following:\r\n\r\n```\r\n--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\"\r\n--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\"\r\nRegistered docker executor on xxx\r\nStarting task example-api.df50df7d-a899-11e5-95df-02423f5b4e48\r\nTue 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',\r\n  PORT_10002: '31870',\r\n  MARATHON_APP_VERSION: '2015-12-22T10:50:53.438Z',\r\n  MARATHON_APP_DOCKER_IMAGE: 'private-repo.ccom/example-api:latest',\r\n  MESOS_TASK_ID: 'example-api.df50df7d-a899-11e5-95df-02423f5b4e48',\r\n  PORT: '31870',\r\n  PORTS: '31870',\r\n  MARATHON_APP_ID: '/example-api',\r\n  PORT0: '31870',\r\n  MESOS_SANDBOX: '/mnt/mesos/sandbox',\r\n  HOME: '/app',\r\n  GIT_HEAD: '17a7cc6d2f116c12633327a335cc5fff04ce2892' }\r\napp listening on 31870\r\nKilling docker task\r\nShutting down\r\n```\r\n\r\n```\r\nI1222 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\"}\r\nI1222 10:50:53.574636  4809 fetcher.cpp:369] Fetching URI 'file:///etc/docker/docker.tar.gz'\r\nI1222 10:50:53.574658  4809 fetcher.cpp:243] Fetching directly into the sandbox directory\r\nI1222 10:50:53.574693  4809 fetcher.cpp:180] Fetching URI 'file:///etc/docker/docker.tar.gz'\r\nI1222 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'\r\nI1222 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'\r\nI1222 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'\r\nW1222 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\r\nI1222 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'\r\nI1222 10:50:53.794795  4819 exec.cpp:133] Version: 0.24.1\r\nI1222 10:50:53.801050  4821 exec.cpp:207] Executor registered on slave 20151203-095512-437010442-5050-16498-S2\r\nWarning: '-c' is deprecated, it will be replaced by '--cpu-shares' soon. See usage.\r\nWARNING: Your kernel does not support swap limit capabilities, memory limited without swap.\r\nW1222 10:50:53.801050  4820 logging.cpp:81] RAW: Received signal SIGTERM from process 22013 of user 0; exiting\r\n```\r\n\r\nThe 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\"`\r\n\r\nHowever, 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):\r\n\r\n```\r\nRegistered docker executor on xxx\r\nStarting task example-api.26d5e82e-a987-11e5-95df-02423f5b4e48\r\nWed 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',\r\n  PORT_10002: '31172',\r\n  MARATHON_APP_VERSION: '2015-12-23T15:09:24.078Z',\r\n  MARATHON_APP_DOCKER_IMAGE: 'private-repo.com/example-api:latest',\r\n  MESOS_TASK_ID: 'example-api.26d5e82e-a987-11e5-95df-02423f5b4e48',\r\n  PORT: '31172',\r\n  PORTS: '31172',\r\n  MARATHON_APP_ID: '/example-api',\r\n  PORT0: '31172',\r\n  MESOS_SANDBOX: '/mnt/mesos/sandbox',\r\n  HOME: '/app',\r\n  GIT_HEAD: '17a7cc6d2f116c12633327a335cc5fff04ce2892' }\r\napp listening on 31172\r\nWed Dec 23 2015 15:53:45 GMT+0000 (UTC) 'got' 'SIGTERM'\r\nWed Dec 23 2015 15:53:55 GMT+0000 (UTC) 'ending on SIGTERM'\r\nonExit\r\n```\r\n\r\nAnd now my questions are:\r\nIs the Marathon sending \"wrong\" kill command and can i reconfigure it or is it a bug?\r\nIs the Mesos misconfigured so he doesn't issue the kill command properly and I should get in touch with the Mesos guys?\r\n\r\nSorry 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.. :)\r\n"},"comment":{"url":"https://api.github.com/repos/mesosphere/marathon/issues/comments/168704869","html_url":"https://github.com/mesosphere/marathon/issues/2876#issuecomment-168704869","issue_url":"https://api.github.com/repos/mesosphere/marathon/issues/2876","id":168704869,"user":{"login":"gkleiman","id":146374,"avatar_url":"https://avatars.githubusercontent.com/u/146374?v=3","gravatar_id":"","url":"https://api.github.com/users/gkleiman","html_url":"https://github.com/gkleiman","followers_url":"https://api.github.com/users/gkleiman/followers","following_url":"https://api.github.com/users/gkleiman/following{/other_user}","gists_url":"https://api.github.com/users/gkleiman/gists{/gist_id}","starred_url":"https://api.github.com/users/gkleiman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gkleiman/subscriptions","organizations_url":"https://api.github.com/users/gkleiman/orgs","repos_url":"https://api.github.com/users/gkleiman/repos","events_url":"https://api.github.com/users/gkleiman/events{/privacy}","received_events_url":"https://api.github.com/users/gkleiman/received_events","type":"User","site_admin":false},"created_at":"2016-01-04T15:23:25Z","updated_at":"2016-01-04T15:23:25Z","body":"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](https://issues.apache.org/jira/secure/) with your findings?\r\n\r\nI 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`."}}