{"action":"created","issue":{"url":"https://api.github.com/repos/docker/docker/issues/24775","repository_url":"https://api.github.com/repos/docker/docker","labels_url":"https://api.github.com/repos/docker/docker/issues/24775/labels{/name}","comments_url":"https://api.github.com/repos/docker/docker/issues/24775/comments","events_url":"https://api.github.com/repos/docker/docker/issues/24775/events","html_url":"https://github.com/docker/docker/issues/24775","id":166201069,"number":24775,"title":"Logs sometimes out of order with awslogs log driver","user":{"login":"joshpurvis","id":685216,"avatar_url":"https://avatars.githubusercontent.com/u/685216?v=3","gravatar_id":"","url":"https://api.github.com/users/joshpurvis","html_url":"https://github.com/joshpurvis","followers_url":"https://api.github.com/users/joshpurvis/followers","following_url":"https://api.github.com/users/joshpurvis/following{/other_user}","gists_url":"https://api.github.com/users/joshpurvis/gists{/gist_id}","starred_url":"https://api.github.com/users/joshpurvis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/joshpurvis/subscriptions","organizations_url":"https://api.github.com/users/joshpurvis/orgs","repos_url":"https://api.github.com/users/joshpurvis/repos","events_url":"https://api.github.com/users/joshpurvis/events{/privacy}","received_events_url":"https://api.github.com/users/joshpurvis/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/docker/docker/labels/area/logging","name":"area/logging","color":"fbca04"},{"url":"https://api.github.com/repos/docker/docker/labels/version/1.12","name":"version/1.12","color":"ededed"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":7,"created_at":"2016-07-18T21:45:30Z","updated_at":"2016-07-20T16:14:59Z","closed_at":null,"body":"**Output of `docker version`:**\r\n\r\n```\r\n$ docker version\r\nClient:\r\n Version:      1.12.0-rc4\r\n API version:  1.24\r\n Go version:   go1.6.2\r\n Git commit:   e4a0dbc\r\n Built:        Wed Jul 13 03:54:54 2016\r\n OS/Arch:      linux/amd64\r\n\r\nServer:\r\n Version:      1.12.0-rc4\r\n API version:  1.24\r\n Go version:   go1.6.2\r\n Git commit:   e4a0dbc\r\n Built:        Wed Jul 13 03:54:54 2016\r\n OS/Arch:      linux/amd64\r\n```\r\n\r\n**Output of `docker info`:**\r\n\r\n```\r\ndocker info\r\nContainers: 4\r\n Running: 0\r\n Paused: 0\r\n Stopped: 4\r\nImages: 151\r\nServer Version: 1.12.0-rc4\r\nStorage Driver: aufs\r\n Root Dir: /var/lib/docker/aufs\r\n Backing Filesystem: extfs\r\n Dirs: 359\r\n Dirperm1 Supported: false\r\nLogging Driver: json-file\r\nCgroup Driver: cgroupfs\r\nPlugins:\r\n Volume: local\r\n Network: overlay null bridge host\r\nSwarm: inactive\r\nRuntimes: runc\r\nDefault Runtime: runc\r\nSecurity Options: apparmor\r\nKernel Version: 3.13.0-48-generic\r\nOperating System: Ubuntu 14.04.2 LTS\r\nOSType: linux\r\nArchitecture: x86_64\r\nCPUs: 8\r\nTotal Memory: 14.69 GiB\r\nName: test-grid-02\r\nID: DKPX:PIXI:AHKL:JYZN:AVER:HDVL:43WL:JJRW:SEJV:ABJP:HCZ4:QIDM\r\nDocker Root Dir: /var/lib/docker\r\nDebug Mode (client): false\r\nDebug Mode (server): false\r\nRegistry: https://index.docker.io/v1/\r\nWARNING: No swap limit support\r\nInsecure Registries:\r\n 127.0.0.0/8\r\n```\r\n\r\n**Additional environment details (AWS, VirtualBox, physical, etc.):**\r\n\r\nAWS\r\n\r\n**Steps to reproduce the issue:**\r\n\r\nI've created a repository to easily reproduce this issue: https://github.com/joshpurvis/docker-awslogs\r\n\r\n```\r\ngit clone https://github.com/joshpurvis/docker-awslogs\r\n```\r\n\r\nSet environment\r\n\r\n```\r\nexport AWS_SECRET_ACCESS_KEY=YOURSECRET\r\nexport AWS_ACCESS_KEY_ID=YOURID\r\nexport AWS_DEFAULT_REGION=us-east-1\r\nexport AWS_LOGS_GROUP=YOURLOGGROUP\r\n```\r\n\r\nBuild test image\r\n```\r\ndocker build -t awslogtest .\r\n```\r\n\r\nRun a loop which logs ~20k times via awslogs driver\r\n```\r\ncid=$(docker run -d --log-driver=awslogs --log-opt awslogs-group=$AWS_LOGS_GROUP awslogtest python /test.py)\r\n```\r\n\r\nRead logs via boto -- logs come back, slightly out of order (same as on aws console)\r\n```\r\ndocker run -it -e AWS_ACCESS_KEY_ID=$AWS_ACCESS_KEY_ID -e AWS_SECRET_ACCESS_KEY=$AWS_SECRET_ACCESS_KEY awslogtest /usr/bin/python /viewer.py --group=$AWS_LOGS_GROUP --stream=$cid\r\n```\r\n\r\n**Describe the results you received:**\r\n\r\n```\r\n# ...\r\n\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19986'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19987'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19988'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19989'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19990'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19991'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19992'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19993'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19994'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19995'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19996'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19997'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19998'}\r\n{u'ingestionTime': 1468876501400, u'timestamp': 1468876501111, u'message': u'INFO:__main__:19507'}\r\n```\r\n\r\n^ The numbers at the far right indicate the actual order in which the logs were sent to STDOUT according to Python. \r\n\r\nNote: this behavior appears in the Cloudwatch log console as well, I just found it easier to demonstrate with boto.\r\n\r\n**Describe the results you expected:**\r\n\r\nLines logged in the order sent to STDOUT\r\n\r\n**Additional information you deem important (e.g. issue happens only occasionally):**\r\n\r\n- I would think the sequence token should prevent this from happening. It seems it's being used in the driver, but the lines are sent in bulk? I'm not too familiar with golang, so I haven't been able to get far reading the code yet\r\n\r\n- I can pretty consistently reproduce it with ~20k lines of logs. It seems on smaller batches, it's more rare that it happens.\r\n\r\n- Also in Docker 1.11 and likely some older versions, the problem appears to happen more often. I believe the related PR #22971 seems to help a bit in 1.12.0-rc4\r\n\r\n\r\n**Edit:**\r\n\r\nAfter reading over the code for the awslog driver and the other logging code, I found this bit:\r\n\r\nhttps://github.com/docker/docker/blob/master/daemon/logger/awslogs/cloudwatchlogs.go#L360\r\n\r\nWhich is sorting the logs by `Message.Timestamp`. I assume this is the issue, given that two lines could have the same `Timestamp`. Is there something else that it can be sorted by to ensure that order is maintained, such as an index?\r\n"},"comment":{"url":"https://api.github.com/repos/docker/docker/issues/comments/233999701","html_url":"https://github.com/docker/docker/issues/24775#issuecomment-233999701","issue_url":"https://api.github.com/repos/docker/docker/issues/24775","id":233999701,"user":{"login":"samuelkarp","id":737750,"avatar_url":"https://avatars.githubusercontent.com/u/737750?v=3","gravatar_id":"","url":"https://api.github.com/users/samuelkarp","html_url":"https://github.com/samuelkarp","followers_url":"https://api.github.com/users/samuelkarp/followers","following_url":"https://api.github.com/users/samuelkarp/following{/other_user}","gists_url":"https://api.github.com/users/samuelkarp/gists{/gist_id}","starred_url":"https://api.github.com/users/samuelkarp/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/samuelkarp/subscriptions","organizations_url":"https://api.github.com/users/samuelkarp/orgs","repos_url":"https://api.github.com/users/samuelkarp/repos","events_url":"https://api.github.com/users/samuelkarp/events{/privacy}","received_events_url":"https://api.github.com/users/samuelkarp/received_events","type":"User","site_admin":false},"created_at":"2016-07-20T16:14:59Z","updated_at":"2016-07-20T16:14:59Z","body":"@joshpurvis Thanks for testing!  Just to rule it out, is there a chance that the clock on your host is jumping around a bit?  If you look at the file that the default `json-file` driver writes (typically located in `/var/lib/docker/containers/${CONTAINER_ID}/${CONTAINER_ID}-json.log`), do you see timestamps that appear to jump at all?"}}
{"actor":{"display_login":"samuelkarp"}}