{"action":"created","issue":{"url":"https://api.github.com/repos/docker/docker/issues/16463","labels_url":"https://api.github.com/repos/docker/docker/issues/16463/labels{/name}","comments_url":"https://api.github.com/repos/docker/docker/issues/16463/comments","events_url":"https://api.github.com/repos/docker/docker/issues/16463/events","html_url":"https://github.com/docker/docker/pull/16463","id":107570807,"number":16463,"title":"docker/logs: Fix race in --follow option","user":{"login":"michael-holzheu","id":13906644,"avatar_url":"https://avatars.githubusercontent.com/u/13906644?v=3","gravatar_id":"","url":"https://api.github.com/users/michael-holzheu","html_url":"https://github.com/michael-holzheu","followers_url":"https://api.github.com/users/michael-holzheu/followers","following_url":"https://api.github.com/users/michael-holzheu/following{/other_user}","gists_url":"https://api.github.com/users/michael-holzheu/gists{/gist_id}","starred_url":"https://api.github.com/users/michael-holzheu/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/michael-holzheu/subscriptions","organizations_url":"https://api.github.com/users/michael-holzheu/orgs","repos_url":"https://api.github.com/users/michael-holzheu/repos","events_url":"https://api.github.com/users/michael-holzheu/events{/privacy}","received_events_url":"https://api.github.com/users/michael-holzheu/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/docker/docker/labels/status/1-design-review","name":"status/1-design-review","color":"fef2c0"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":5,"created_at":"2015-09-21T18:28:40Z","updated_at":"2015-09-21T19:30:30Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/docker/docker/pulls/16463","html_url":"https://github.com/docker/docker/pull/16463","diff_url":"https://github.com/docker/docker/pull/16463.diff","patch_url":"https://github.com/docker/docker/pull/16463.patch"},"body":"The \"TestLogsFollowSlowStdoutConsumer\" test sometimes hangs on s390x.\r\nAlso on x86 systems we could reproduce the hang by changing the test\r\nvariables as follows:\r\n\r\n```\r\n- out, _ := dockerCmd(c, \"run\",...`usleep 200000;yes X | head -c 200000`)\r\n+ out, _ := dockerCmd(c, \"run\",...`usleep 10000;yes X | head -c 10000`)\r\n```\r\n\r\nWe analyzed the problem and found a race in \"docker logs -f\".\r\nThe following sequence leads to the hang situation:\r\n\r\n```\r\n[1] Container is started: <container ID> =\r\n    docker run -d busybox /bin/sh -c \"usleep 200000;yes X | head -c 200000\"\r\n\r\n[2] Docker logs -f is started: docker logs -f <container ID>\r\n\r\n    daemon/logs.go:\r\n\r\n    ContainerLogs()\r\n     follow := config.Follow && container.IsRunning()\r\n     readConfig.Follow = follow  [3] follow is true\r\n\r\n     [4] Container exits here -> no more inode actity on json log file\r\n\r\n     logReader.ReadLogs(readConfig)\r\n\r\n    daemon/logger/jsonfilelog/jsonfilelog.go:\r\n\r\n    ReadLogs(config)\r\n     go readLogs(config)\r\n\r\n      tailFile() -> read current log\r\n        if (!config.Follow) <--- follow is true\r\n          return\r\n        else\r\n          followLogs()\r\n            fileWatcher.Add(f.Name()) [5] fsnotify watcher for json file\r\n            for {\r\n               msg, err := decodeLogLine(dec, l)\r\n                 -> msg = nil, err = EOF\r\n\r\n               if err != nil {\r\n                 select {\r\n\r\n                 [6] We block here because fsnotify will not report\r\n                     any events\r\n\r\n                 }\r\n```\r\nTo fix the problem add a new channel \"containerStopped\" to \"ReadConfig\"\r\nand start a go routine that informs the follow logs code via the channel\r\nwhen the container is stopped. In \"followLogs()\" add the new channel to\r\nthe select statement where the hang situation occurs. Now the select\r\nstatement is unblocked via the \"containerStopped\" channel if the container\r\nis stopped.\r\n\r\nCloses #16462\r\nSigned-off-by: Michael Holzheu <holzheu@linux.vnet.ibm.com>"},"comment":{"url":"https://api.github.com/repos/docker/docker/issues/comments/142085780","html_url":"https://github.com/docker/docker/pull/16463#issuecomment-142085780","issue_url":"https://api.github.com/repos/docker/docker/issues/16463","id":142085780,"user":{"login":"cpuguy83","id":799078,"avatar_url":"https://avatars.githubusercontent.com/u/799078?v=3","gravatar_id":"","url":"https://api.github.com/users/cpuguy83","html_url":"https://github.com/cpuguy83","followers_url":"https://api.github.com/users/cpuguy83/followers","following_url":"https://api.github.com/users/cpuguy83/following{/other_user}","gists_url":"https://api.github.com/users/cpuguy83/gists{/gist_id}","starred_url":"https://api.github.com/users/cpuguy83/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cpuguy83/subscriptions","organizations_url":"https://api.github.com/users/cpuguy83/orgs","repos_url":"https://api.github.com/users/cpuguy83/repos","events_url":"https://api.github.com/users/cpuguy83/events{/privacy}","received_events_url":"https://api.github.com/users/cpuguy83/received_events","type":"User","site_admin":false},"created_at":"2015-09-21T19:30:30Z","updated_at":"2015-09-21T19:30:30Z","body":"Actually, it looks like we are already stopping the log reader when the container stops. This is probably due to the log copier timing out before finishing writing all logs."}}