{"action":"created","issue":{"url":"https://api.github.com/repos/flynn/flynn/issues/3601","repository_url":"https://api.github.com/repos/flynn/flynn","labels_url":"https://api.github.com/repos/flynn/flynn/issues/3601/labels{/name}","comments_url":"https://api.github.com/repos/flynn/flynn/issues/3601/comments","events_url":"https://api.github.com/repos/flynn/flynn/issues/3601/events","html_url":"https://github.com/flynn/flynn/issues/3601","id":186402475,"number":3601,"title":"Shutdown behavior doesn't actually send SIGTERM","user":{"login":"evantahler","id":303226,"avatar_url":"https://avatars.githubusercontent.com/u/303226?v=3","gravatar_id":"","url":"https://api.github.com/users/evantahler","html_url":"https://github.com/evantahler","followers_url":"https://api.github.com/users/evantahler/followers","following_url":"https://api.github.com/users/evantahler/following{/other_user}","gists_url":"https://api.github.com/users/evantahler/gists{/gist_id}","starred_url":"https://api.github.com/users/evantahler/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/evantahler/subscriptions","organizations_url":"https://api.github.com/users/evantahler/orgs","repos_url":"https://api.github.com/users/evantahler/repos","events_url":"https://api.github.com/users/evantahler/events{/privacy}","received_events_url":"https://api.github.com/users/evantahler/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2016-10-31T21:29:02Z","updated_at":"2016-11-01T01:19:47Z","closed_at":null,"body":"I've made a very simple example app to test this: https://github.com/messagebot/tick-tester\r\n\r\nWhen stopping a process (either via `flynn ps` or deployment), the logs *never* reflect that the signal was received by the application. \r\n\r\n```\r\n> flynn log -f\r\n2016-10-31T21:18:23.592568Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]:\r\n2016-10-31T21:18:23.592631Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: > tick-tester@1.0.0 start /app\r\n2016-10-31T21:18:23.592755Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: > node tick.js\r\n2016-10-31T21:18:23.592800Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]:\r\n2016-10-31T21:18:23.660455Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: *** STARTING ***\r\n2016-10-31T21:18:24.651912Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:24.651Z | mode: normal\r\n2016-10-31T21:18:25.653779Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:25.653Z | mode: normal\r\n2016-10-31T21:18:26.655230Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:26.655Z | mode: normal\r\n2016-10-31T21:18:27.655754Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:27.655Z | mode: normal\r\n2016-10-31T21:18:28.656256Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:28.656Z | mode: normal\r\n2016-10-31T21:18:29.656771Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:29.656Z | mode: normal\r\n2016-10-31T21:18:30.657275Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:30.657Z | mode: normal\r\n2016-10-31T21:18:31.657781Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:31.657Z | mode: normal\r\n2016-10-31T21:18:32.658256Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:32.658Z | mode: normal\r\n2016-10-31T21:18:33.658741Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:33.658Z | mode: normal\r\n2016-10-31T21:18:34.659219Z app[web.ip172311424-df5a048b-1c66-4010-becd-f48659248940]: 2016-10-31T21:18:34.659Z | mode: normal\r\n<< application shutdown >>\r\n```\r\n\r\nIn comparison, deploying the same application on Heroku:\r\n\r\n```\r\n2016-10-31T21:25:57.051479+00:00 app[web.1]: > tick-tester@1.0.0 start /app\r\n2016-10-31T21:25:57.051480+00:00 app[web.1]: > node tick.js\r\n2016-10-31T21:25:57.051480+00:00 app[web.1]:\r\n2016-10-31T21:25:57.165181+00:00 app[web.1]: *** STARTING ***\r\n2016-10-31T21:25:58.147713+00:00 app[web.1]: 2016-10-31T21:25:58.146Z | mode: normal\r\n2016-10-31T21:25:59.150068+00:00 app[web.1]: 2016-10-31T21:25:59.149Z | mode: normal\r\n2016-10-31T21:26:00.155511+00:00 app[web.1]: 2016-10-31T21:26:00.155Z | mode: normal\r\n2016-10-31T21:26:01.159179+00:00 app[web.1]: 2016-10-31T21:26:01.159Z | mode: normal\r\n2016-10-31T21:26:02.160509+00:00 app[web.1]: 2016-10-31T21:26:02.160Z | mode: normal\r\n2016-10-31T21:26:03.161853+00:00 app[web.1]: 2016-10-31T21:26:03.161Z | mode: normal\r\n2016-10-31T21:26:04.163076+00:00 app[web.1]: 2016-10-31T21:26:04.162Z | mode: normal\r\n2016-10-31T21:26:05.170457+00:00 app[web.1]: 2016-10-31T21:26:05.170Z | mode: normal\r\n2016-10-31T21:26:06.171778+00:00 app[web.1]: 2016-10-31T21:26:06.171Z | mode: normal\r\n2016-10-31T21:26:07.172976+00:00 app[web.1]: 2016-10-31T21:26:07.172Z | mode: normal\r\n2016-10-31T21:26:08.173363+00:00 app[web.1]: 2016-10-31T21:26:08.173Z | mode: normal\r\n2016-10-31T21:26:09.173929+00:00 app[web.1]: 2016-10-31T21:26:09.173Z | mode: normal\r\n2016-10-31T21:26:10.174942+00:00 app[web.1]: 2016-10-31T21:26:10.174Z | mode: normal\r\n2016-10-31T21:26:11.167049+00:00 heroku[web.1]: State changed from starting to down\r\n2016-10-31T21:26:11.176302+00:00 app[web.1]: 2016-10-31T21:26:11.176Z | mode: normal\r\n2016-10-31T21:26:12.177247+00:00 app[web.1]: 2016-10-31T21:26:12.177Z | mode: normal\r\n2016-10-31T21:26:13.180995+00:00 app[web.1]: 2016-10-31T21:26:13.180Z | mode: normal\r\n2016-10-31T21:26:14.181402+00:00 app[web.1]: 2016-10-31T21:26:14.181Z | mode: normal\r\n2016-10-31T21:26:15.182448+00:00 app[web.1]: 2016-10-31T21:26:15.182Z | mode: normal\r\n2016-10-31T21:26:15.563859+00:00 heroku[web.1]: Stopping all processes with SIGTERM\r\n2016-10-31T21:26:16.184353+00:00 app[web.1]: 2016-10-31T21:26:16.184Z | mode: normal\r\n2016-10-31T21:26:16.523929+00:00 app[web.1]: 2016-10-31T21:26:16.523Z | stopping...\r\n2016-10-31T21:26:16.721960+00:00 heroku[web.1]: Process exited with status 143\r\n```"},"comment":{"url":"https://api.github.com/repos/flynn/flynn/issues/comments/257467231","html_url":"https://github.com/flynn/flynn/issues/3601#issuecomment-257467231","issue_url":"https://api.github.com/repos/flynn/flynn/issues/3601","id":257467231,"user":{"login":"lmars","id":488515,"avatar_url":"https://avatars.githubusercontent.com/u/488515?v=3","gravatar_id":"","url":"https://api.github.com/users/lmars","html_url":"https://github.com/lmars","followers_url":"https://api.github.com/users/lmars/followers","following_url":"https://api.github.com/users/lmars/following{/other_user}","gists_url":"https://api.github.com/users/lmars/gists{/gist_id}","starred_url":"https://api.github.com/users/lmars/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lmars/subscriptions","organizations_url":"https://api.github.com/users/lmars/orgs","repos_url":"https://api.github.com/users/lmars/repos","events_url":"https://api.github.com/users/lmars/events{/privacy}","received_events_url":"https://api.github.com/users/lmars/received_events","type":"User","site_admin":false},"created_at":"2016-11-01T01:19:47Z","updated_at":"2016-11-01T01:19:47Z","body":"@evantahler ok I looked a bit closer at your app and realised you are using `npm start`, which ends up running `node tick.js` in a child shell.\r\n\r\nThe process tree looks like this:\r\n\r\n```\r\nroot      97723  1.3  0.0  10864  5448 ?        Ssl  01:00   0:00  \\_ /.containerinit host0-b017e2d0-2c26-47a8-9f8d-44b1d36689cd\r\nnobody    97763 26.0  0.0 1065084 53068 ?       Ssl  01:00   0:00      \\_ npm                                 \r\nnobody    97792  0.0  0.0   4448   688 ?        S    01:00   0:00          \\_ sh -c node tick.js\r\nnobody    97793  5.0  0.0 614576 25164 ?        Sl   01:00   0:00              \\_ node tick.js\r\n```\r\n\r\nWhen Flynn sends the `SIGTERM`, it is being sent to the `npm` process which is exiting straight away, and so the job finishes because `containerinit` only monitors its direct child process.\r\n\r\nChanging the `Procfile` entry to `worker: node tick.js` leads to the desired behaviour:\r\n\r\n```\r\n$ flynn scale worker=0\r\nscaling worker: 1=>0\r\n\r\n01:09:41.500 ==> worker host0-35fa8bc2-cd95-46df-af9c-6f7adc86f9d0 stopping\r\n01:09:46.510 ==> worker host0-35fa8bc2-cd95-46df-af9c-6f7adc86f9d0 down\r\n\r\nscale completed in 5.020485955s\r\n\r\n$ flynn log --raw-output\r\n*** STARTING ***\r\n2016-11-01T01:09:38.821Z | mode: normal\r\n2016-11-01T01:09:39.823Z | mode: normal\r\n2016-11-01T01:09:40.824Z | mode: normal\r\n2016-11-01T01:09:41.492Z | stopping...\r\n2016-11-01T01:09:46.498Z | all done!\r\n```\r\n\r\nPersonally I feel like this is a bug in `npm`, if it is acting as the \"process monitor\" (i.e. forwarding signals), it should probably wait for it's child to die, otherwise it should just `exec node tick.js`.\r\n\r\nFunnily enough, I found people complaining about this in https://github.com/npm/npm/issues/4603 which was opened by you :smile:."}}
{"actor":{"display_login":"lmars"}}