BUG REPORT: docker logs follow gets stuck when the json-file log driver rotates files #23913
Description
Output of docker version:
Docker version 1.11.2, build b9f10c9
Output of docker info:
Containers: 5
Running: 4
Paused: 0
Stopped: 1
Images: 8
Server Version: 1.11.2
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 63
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge null host
Kernel Version: 4.4.0-24-generic
Operating System: Ubuntu 16.04 LTS
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 7.795 GiB
Name: ip-10-47-10-249
ID: VVQ3:QEHD:WM5H:SY6Q:Y43P:MFQ6:BZ5Z:GO2M:YZ5Y:VQ5P:FSXW:JFDE
Docker Root Dir: /var/lib/docker
Debug mode (client): false
Debug mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Additional environment details (AWS, VirtualBox, physical, etc.):
Reproduced on Ubuntu 15.10, 16.04 EC2 instances. Reproduced on Ubuntu 14.04 docker-machine VM on my laptop. All tests were performed at a terminal in an SSH session connecting to a local docker daemon.
Steps to reproduce the issue:
- To demonstrate the issue, Configure the Docker daemon to use the
json-filelog driver with a max-size of 10mb.
Mine looks like:
$ cat /etc/systemd/system/docker.service.d/docker-opts.conf
[Service]
ExecStart=
ExecStart=/usr/bin/docker daemon -H fd:// -s aufs --bip=192.168.255.1/24 --log-driver="json-file" --log-opt max-size=10m --log-opt max-file=5- Attempt to print the numbers 1 to 200000 to the stdout of a container and use
docker logsto follow the output by running the following command:
$ docker run -d --name loggen ubuntu:16.04 /bin/bash -c 'for ((i=1; i<=200000; ++i)); do echo $i; done' && docker logs --timestamps --follow loggen > boom.txt
71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256aDescribe the results you received:
I would expect to see the numbers 1 to 200000 along with the time each number was output by the loggen container in boom.txt
What I actually see:
$ tail boom.txt
2016-06-17T06:39:55.123832147Z 131491
2016-06-17T06:39:55.123837123Z 131492
2016-06-17T06:39:55.123842067Z 131493
2016-06-17T06:39:55.123846929Z 131494
2016-06-17T06:39:55.123851785Z 131495
2016-06-17T06:39:55.123856759Z 131496
2016-06-17T06:39:55.123861681Z 131497
2016-06-17T06:39:55.123866606Z 131498
2016-06-17T06:39:55.123871552Z 131499
2016-06-17T06:39:55.123876490Z 131500Looking at the files generated by the json-file log driver for this container shows that things have gone wrong when the docker log driver rotates the json files.
$ sudo -s
$ ls /var/lib/docker/containers/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a/*.log*
/var/lib/docker/containers/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a-json.log
/var/lib/docker/containers/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a-json.log.1
$ tail /var/lib/docker/containers/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a-json.log.1
{"log":"131491\n","stream":"stdout","time":"2016-06-17T06:39:55.123832147Z"}
{"log":"131492\n","stream":"stdout","time":"2016-06-17T06:39:55.123837123Z"}
{"log":"131493\n","stream":"stdout","time":"2016-06-17T06:39:55.123842067Z"}
{"log":"131494\n","stream":"stdout","time":"2016-06-17T06:39:55.123846929Z"}
{"log":"131495\n","stream":"stdout","time":"2016-06-17T06:39:55.123851785Z"}
{"log":"131496\n","stream":"stdout","time":"2016-06-17T06:39:55.123856759Z"}
{"log":"131497\n","stream":"stdout","time":"2016-06-17T06:39:55.123861681Z"}
{"log":"131498\n","stream":"stdout","time":"2016-06-17T06:39:55.123866606Z"}
{"log":"131499\n","stream":"stdout","time":"2016-06-17T06:39:55.123871552Z"}
{"log":"131500\n","stream":"stdout","time":"2016-06-17T06:39:55.12387649Z"}
$ head -n 10 /var/lib/docker/containers/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a/71943ba916fb365fb3178ab9dabd37158d690b49aeaa595420fde4f92b62256a-json.log
{"log":"131501\n","stream":"stdout","time":"2016-06-17T06:39:55.123881404Z"}
{"log":"131502\n","stream":"stdout","time":"2016-06-17T06:39:55.123994259Z"}
{"log":"131503\n","stream":"stdout","time":"2016-06-17T06:39:55.124001593Z"}
{"log":"131504\n","stream":"stdout","time":"2016-06-17T06:39:55.124006555Z"}
{"log":"131505\n","stream":"stdout","time":"2016-06-17T06:39:55.124011382Z"}
{"log":"131506\n","stream":"stdout","time":"2016-06-17T06:39:55.124016163Z"}
{"log":"131507\n","stream":"stdout","time":"2016-06-17T06:39:55.124020854Z"}
{"log":"131508\n","stream":"stdout","time":"2016-06-17T06:39:55.12402562Z"}
{"log":"131509\n","stream":"stdout","time":"2016-06-17T06:39:55.124030396Z"}
{"log":"131510\n","stream":"stdout","time":"2016-06-17T06:39:55.12403511Z"}
Describe the results you expected:
I would expect to see the numbers 1 to 200000 along with the time each number was output by the loggen container in boom.txt
Additional information you deem important (e.g. issue happens only occasionally):
I did a little more digging and found an upper bound on the --log-opt max-size where the docker logs --follow was not broken by rotating the json log files.
When max-size is <= 215k, docker logs --follow behaves as expected.
When max-size is >= 216k, docker logs --follow gets stuck.