{"action":"closed","issue":{"url":"https://api.github.com/repos/deis/deis/issues/5077","repository_url":"https://api.github.com/repos/deis/deis","labels_url":"https://api.github.com/repos/deis/deis/issues/5077/labels{/name}","comments_url":"https://api.github.com/repos/deis/deis/issues/5077/comments","events_url":"https://api.github.com/repos/deis/deis/issues/5077/events","html_url":"https://github.com/deis/deis/issues/5077","id":169739520,"number":5077,"title":"logspout does not recover on container restart (V1)","user":{"login":"nathansamson","id":93735,"avatar_url":"https://avatars.githubusercontent.com/u/93735?v=3","gravatar_id":"","url":"https://api.github.com/users/nathansamson","html_url":"https://github.com/nathansamson","followers_url":"https://api.github.com/users/nathansamson/followers","following_url":"https://api.github.com/users/nathansamson/following{/other_user}","gists_url":"https://api.github.com/users/nathansamson/gists{/gist_id}","starred_url":"https://api.github.com/users/nathansamson/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nathansamson/subscriptions","organizations_url":"https://api.github.com/users/nathansamson/orgs","repos_url":"https://api.github.com/users/nathansamson/repos","events_url":"https://api.github.com/users/nathansamson/events{/privacy}","received_events_url":"https://api.github.com/users/nathansamson/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/deis/deis/labels/bug","name":"bug","color":"e11d21"},{"url":"https://api.github.com/repos/deis/deis/labels/logspout","name":"logspout","color":"f7c6c7"}],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2016-08-06T09:56:02Z","updated_at":"2016-08-15T22:56:42Z","closed_at":"2016-08-15T22:56:42Z","body":"I have noticed this behaviour for quite some while now but never bothered to try to debug it.\r\n\r\nI noticed that logspout basically stops logging after service restarts (eg deploys or any other reason why new containers are booted)\r\n\r\nNote I am on a stateless V1.13.2 cluster with CoreOS 1068.8.0 and applied fix #5074 (although I do not think that matters)\r\nI believe I had similar issues in V1.12 (stateful cluster) but I blamed that on \"deis-logspout now continuously re-discovers the logger’s connection information, should it be re-scheduled onto another host\" which got released in V1.13 so I had hoped my problems would go away with V1.13.\r\n\r\nAt this point I can not tell if this is actually a new issue in V1.13; if it is related to staless vs statefull (I don't think it is by looking at the backtraces), or if it is related to newer CoreOS version, or if the problem exists for a long time already\r\n\r\n\r\nSo here is the complete scenario (complete logs: http://pastebin.com/6a6ksEE6 but I recommend you read the scenario first)\r\n\r\n* restart logspout so it is in a working state (eg it logs attaching to nodeABC on startup for all containers)\r\n* Restart a container (eg `deis ps:restart`)\r\n* At the moment the old container is destroyed this gets detected; but logspout crashes\r\n~~~\r\nAug 06 09:32:51 eu1-cloud-worker-01 sh[5391]: 2016/08/06 09:32:51 event: 417ba0517a81 kill\r\nAug 06 09:32:51 eu1-cloud-worker-01 sh[5391]: 2016/08/06 09:32:51 event: 417ba0517a81 die\r\nAug 06 09:32:51 eu1-cloud-worker-01 sh[5391]: 2016/08/06 09:32:51 attach: 417ba0517a81 finished\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]: panic: runtime error: slice bounds out of range\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]: goroutine 84 [running]:\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]: main.NewAttachManager.func1(0xc82009a180, 0xc820011160)\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]:         /home/jenkins/workspace/test-acceptance/src/github.com/deis/deis/logspout/attacher.go:35 +0x3f0\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]: created by main.NewAttachManager\r\nAug 06 09:32:52 eu1-cloud-worker-01 sh[5391]:         /home/jenkins/workspace/test-acceptance/src/github.com/deis/deis/logspout/attacher.go:41 +0x313\r\n~~~\r\n* Logspout crashing is \"okay\"; it gets restarted automatically and can even attach to containers\r\n~~~\r\nAug 06 09:32:52 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Unit entered failed state.\r\nAug 06 09:32:52 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Failed with result 'exit-code'.\r\nAug 06 09:32:57 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Service hold-off time over, scheduling restart.\r\nAug 06 09:32:57 eu1-cloud-worker-01 systemd[1]: Stopped deis-logspout.\r\nAug 06 09:32:57 eu1-cloud-worker-01 systemd[1]: Starting deis-logspout...\r\nAug 06 09:32:58 eu1-cloud-worker-01 systemd[1]: Started deis-logspout.\r\nAug 06 09:32:58 eu1-cloud-worker-01 sh[7052]: 2016/08/06 09:32:58 attach: 1d6a60f94ff0 deis-logspout success\r\nAug 06 09:32:58 eu1-cloud-worker-01 sh[7052]: 2016/08/06 09:32:58 attach: 4c745b55f30a bplpp-staging_v109.web.1 success\r\n....\r\n~~~\r\n* Then the new container is started again gets detected by logspout but crashes again in similar way\r\n~~~\r\nAug 06 09:33:06 eu1-cloud-worker-01 sh[7052]: 2016/08/06 09:33:06 event: 10.133.20.19 pull\r\nAug 06 09:33:06 eu1-cloud-worker-01 sh[7052]: 2016/08/06 09:33:06 event: 5913ff325cb6 create\r\nAug 06 09:33:06 eu1-cloud-worker-01 sh[7052]: 2016/08/06 09:33:06 event: 5913ff325cb6 attach\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]: panic: runtime error: slice bounds out of range\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]: goroutine 79 [running]:\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]: main.NewAttachManager.func1(0xc820086180, 0xc820010e80)\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]:         /home/jenkins/workspace/test-acceptance/src/github.com/deis/deis/logspout/attacher.go:35 +0x3f0\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]: created by main.NewAttachManager\r\nAug 06 09:33:07 eu1-cloud-worker-01 sh[7052]:         /home/jenkins/workspace/test-acceptance/src/github.com/deis/deis/logspout/attacher.go:41 +0x313\r\n~~~\r\n* Ok so logspout crashes; fleet and/or systemd will handle this for us right?\r\n~~~\r\nAug 06 09:33:07 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Main process exited, code=exited, status=2/INVALIDARGUMENT\r\nAug 06 09:33:07 eu1-cloud-worker-01 docker[7394]: Failed to stop container (deis-logspout): Error response from daemon: No such container: deis-logspout\r\nAug 06 09:33:07 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Unit entered failed state.\r\nAug 06 09:33:07 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Failed with result 'exit-code'.\r\nAug 06 09:33:12 eu1-cloud-worker-01 systemd[1]: deis-logspout.service: Service hold-off time over, scheduling restart.\r\nAug 06 09:33:12 eu1-cloud-worker-01 systemd[1]: Stopped deis-logspout.\r\nAug 06 09:33:12 eu1-cloud-worker-01 systemd[1]: Starting deis-logspout...\r\nAug 06 09:33:13 eu1-cloud-worker-01 systemd[1]: Started deis-logspout.\r\nAug 06 09:33:33 eu1-cloud-worker-01 sh[7579]: 2016/08/06 09:33:33 routing all to udp://10.133.20.195:514\r\nAug 06 09:33:43 eu1-cloud-worker-01 sh[7579]: 2016/08/06 09:33:43 routing all to udp://10.133.20.195:514\r\nAug 06 09:33:53 eu1-cloud-worker-01 sh[7579]: 2016/08/06 09:33:53 routing all to udp://10.133.20.195:514\r\n~~~\r\n\r\nSo it did restart the service, but for some reason it did not attach to ANY containers but silently does nothing.\r\n\r\nNote that it still listens for events and the same cycle can be repeated again. It is undeterministic if at the end it will actually have attached to containers or not\r\n\r\n\r\nSo I see 2 probably distinct bugs\r\n\r\nA) It crashes on a container restart (this seems to be consistent and we get a stacktrace so probably quite easy to debug and solve). At minimum this will give us some missing logs during container restarts (probably the boot logs of a container which is very frustrating if that container is crashing on boot and there is no easy way to see the logs)\r\n\r\nB) It does not seem to attach to containers on startup (this is without logs and does not happen every time, I suspect some sort of race condition in the boot sequence)\r\n\r\nIf there is anything I can do to help debug this issue (eg try out a custom logspout image) I am obviously willing to do so\r\n\r\n"}}
{"actor":{"display_login":"mboersma"}}