{"action":"created","issue":{"url":"https://api.github.com/repos/docker/docker/issues/29511","repository_url":"https://api.github.com/repos/docker/docker","labels_url":"https://api.github.com/repos/docker/docker/issues/29511/labels{/name}","comments_url":"https://api.github.com/repos/docker/docker/issues/29511/comments","events_url":"https://api.github.com/repos/docker/docker/issues/29511/events","html_url":"https://github.com/docker/docker/issues/29511","id":196280130,"number":29511,"title":"docker logs with the json-file driver can attempt to parse half-written events","user":{"login":"imriz","id":5706843,"avatar_url":"https://avatars.githubusercontent.com/u/5706843?v=3","gravatar_id":"","url":"https://api.github.com/users/imriz","html_url":"https://github.com/imriz","followers_url":"https://api.github.com/users/imriz/followers","following_url":"https://api.github.com/users/imriz/following{/other_user}","gists_url":"https://api.github.com/users/imriz/gists{/gist_id}","starred_url":"https://api.github.com/users/imriz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/imriz/subscriptions","organizations_url":"https://api.github.com/users/imriz/orgs","repos_url":"https://api.github.com/users/imriz/repos","events_url":"https://api.github.com/users/imriz/events{/privacy}","received_events_url":"https://api.github.com/users/imriz/received_events","type":"User","site_admin":false},"labels":[{"id":70404987,"url":"https://api.github.com/repos/docker/docker/labels/area/logging","name":"area/logging","color":"fbca04","default":false},{"id":190258329,"url":"https://api.github.com/repos/docker/docker/labels/kind/bug","name":"kind/bug","color":"FF8C94","default":false},{"id":182417459,"url":"https://api.github.com/repos/docker/docker/labels/status/more-info-needed","name":"status/more-info-needed","color":"C6A49A","default":false},{"id":375241603,"url":"https://api.github.com/repos/docker/docker/labels/version/1.8","name":"version/1.8","color":"ededed","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-12-18T15:02:03Z","updated_at":"2016-12-18T16:47:19Z","closed_at":null,"body":"Running:\r\n\r\n`docker logs -f --since=1382068460 --tail=6000 f941a30cde1a`\r\n\r\ncan sometimes fail like this:\r\n\r\n```\r\nDec 18 08:54:26 mesos-slave002 docker: time=\"2016-12-18T08:54:26.635980272-06:00\" level=info msg=\"GET /v1.20/containers/f941a30cde1a/json\"\r\nDec 18 08:54:26 mesos-slave002 docker: time=\"2016-12-18T08:54:26.638140054-06:00\" level=info msg=\"GET /v1.20/containers/f941a30cde1a/logs?follow=1&since=1382068460&stderr=1&stdout=1&tail=6000\"\r\nDec 18 08:54:33 mesos-slave002 docker: time=\"2016-12-18T08:54:33.487239994-06:00\" level=error msg=\"Error streaming logs: invalid character ',' after object key\"\r\n```\r\n\r\n\r\nMore examples of such failures:\r\n```\r\nDec 18 08:16:02 mesos-slave002 docker: time=\"2016-12-18T08:16:02.553020309-06:00\" level=error msg=\"Error streaming logs: invalid character ':' after object key:value pair\"\r\nDec 18 08:16:13 mesos-slave002 docker: time=\"2016-12-18T08:16:13.492777824-06:00\" level=error msg=\"Error streaming logs: invalid character ',' after object key\"\r\nDec 18 08:16:15 mesos-slave002 docker: time=\"2016-12-18T08:16:15.494205383-06:00\" level=error msg=\"Error streaming logs: invalid character 'e' in string escape code\"\r\nDec 18 08:16:26 mesos-slave002 docker: time=\"2016-12-18T08:16:26.996115676-06:00\" level=error msg=\"Error streaming logs: parsing time \\\"\\\"2016-12-18T13:58\\\\\\\"endOfBatch\\\\\\\":false,\\\\\\\"loggerFqcn\\\\\\\":\\\\\\\"org.apache.logging.slf4j.Log4jLogger\\\\\\\"}\\\\r\\\\n\\\"\\\" as \\\"\\\"2006-01-02T15:04:05Z07:00\\\"\\\": cannot parse \\\"\\\\\\\"endOfBatch\\\\\\\":false,\\\\\\\"loggerFqcn\\\\\\\":\\\\\\\"org.apache.logging.slf4j.Log4jLogger\\\\\\\"}\\\\r\\\\n\\\"\\\" as \\\":\\\"\"\r\nDec 18 08:16:29 mesos-slave002 docker: time=\"2016-12-18T08:16:29.411139650-06:00\" level=error msg=\"Error streaming logs: invalid character 'n' after object key:value pair\"\r\nDec 18 08:50:54 mesos-slave002 docker: time=\"2016-12-18T08:50:54.839945157-06:00\" level=error msg=\"Error streaming logs: parsing time \\\"\\\"2016-12-188T14:36:15.81034299Z\\\"\\\" as \\\"\\\"2006-01-02T15:04:05Z07:00\\\"\\\": cannot parse \\\"8T14:36:15.81034299Z\\\"\\\" as \\\"T\\\"\"\r\nDec 18 08:52:52 mesos-slave002 docker: time=\"2016-12-18T08:52:52.252974471-06:00\" level=error msg=\"Error streaming logs: parsing time \\\"\\\"2016-12-18Togger\\\\\\\"}\\\\r\\\\n\\\"\\\" as \\\"\\\"2006-01-02T15:04:05Z07:00\\\"\\\": cannot parse \\\"ogger\\\\\\\"}\\\\r\\\\n\\\"\\\" as \\\"15\\\"\"\r\nDec 18 08:54:03 mesos-slave002 docker: time=\"2016-12-18T08:54:03.600889447-06:00\" level=error msg=\"Error streaming logs: parsing time \\\"\\\"2016-12-18T14:38:13.41779331ZZ\\\"\\\" as \\\"\\\"2006-01-02T15:04:05Z07:00\\\"\\\": cannot parse \\\"Z\\\"\\\" as \\\"\\\"\\\"\"\r\nDec 18 08:54:33 mesos-slave002 docker: time=\"2016-12-18T08:54:33.487239994-06:00\" level=error msg=\"Error streaming logs: invalid character ',' after object key\"\r\nDec 18 08:56:27 mesos-slave002 docker: time=\"2016-12-18T08:56:27.689649493-06:00\" level=error msg=\"Error streaming logs: invalid character 'l' after object key:value pair\"\r\nDec 18 08:56:36 mesos-slave002 docker: time=\"2016-12-18T08:56:36.369600346-06:00\" level=error msg=\"Error streaming logs: invalid character '2' in string escape code\"\r\nDec 18 08:56:57 mesos-slave002 docker: time=\"2016-12-18T08:56:57.007100933-06:00\" level=error msg=\"Error streaming logs: invalid character '2' in string escape code\"\r\nDec 18 08:57:10 mesos-slave002 docker: time=\"2016-12-18T08:57:10.835772958-06:00\" level=error msg=\"Error streaming logs: invalid character 'l' looking for beginning of value\"\r\nDec 18 08:57:47 mesos-slave002 docker: time=\"2016-12-18T08:57:47.885845478-06:00\" level=error msg=\"Error streaming logs: invalid character 'e' in string escape code\"\r\n```\r\n\r\nReducing the tail number reduces the chance of hitting this.\r\n\r\nEnvironment:\r\n```\r\n[root@mesos-slave002 ~]# docker version\r\nClient:\r\n Version:      1.8.3\r\n API version:  1.20\r\n Go version:   go1.4.2\r\n Git commit:   f4bf5c7\r\n Built:        Mon Oct 12 06:06:01 UTC 2015\r\n OS/Arch:      linux/amd64\r\n\r\nServer:\r\n Version:      1.8.3\r\n API version:  1.20\r\n Go version:   go1.4.2\r\n Git commit:   f4bf5c7\r\n Built:        Mon Oct 12 06:06:01 UTC 2015\r\n OS/Arch:      linux/amd64\r\n[root@mesos-slave002 ~]# docker info\r\nContainers: 14\r\nImages: 881\r\nStorage Driver: devicemapper\r\n Pool Name: docker-253:1-395176-pool\r\n Pool Blocksize: 65.54 kB\r\n Backing Filesystem: extfs\r\n Data file: /dev/mapper/data-docker_data\r\n Metadata file: /dev/mapper/data-docker_metadata\r\n Data Space Used: 41.26 GB\r\n Data Space Total: 868 GB\r\n Data Space Available: 826.8 GB\r\n Metadata Space Used: 65.61 MB\r\n Metadata Space Total: 9.664 GB\r\n Metadata Space Available: 9.598 GB\r\n Udev Sync Supported: true\r\n Deferred Removal Enabled: false\r\n Library Version: 1.02.107-RHEL7 (2015-12-01)\r\nExecution Driver: native-0.2\r\nLogging Driver: json-file\r\nKernel Version: 3.10.0-327.10.1.el7.x86_64\r\nOperating System: CentOS Linux 7 (Core)\r\nCPUs: 24\r\nTotal Memory: 125.7 GiB\r\nName: mesos-slave002\r\nID: HB6Z:I5QD:NGED:DD7Z:DAHJ:KKYH:GGKP:VSPG:NBR3:WM6P:HD7T:SBNY\r\nWARNING: bridge-nf-call-iptables is disabled\r\nWARNING: bridge-nf-call-ip6tables is disabled\r\n[root@mesos-slave002 ~]# uname -a\r\nLinux mesos-slave002 3.10.0-327.10.1.el7.x86_64 #1 SMP Tue Feb 16 17:03:50 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux\r\n[root@mesos-slave002 ~]# \r\n```\r\n\r\nAt first, I thought this might be related to the events themselves being JSON, but this happens even with plain lines.\r\nGiven logs like this:\r\n`upstream_connect_time=0.000 upstream_response_time=0.024 upstream_status=200 request_time=0.024 status=200`\r\n\r\nI see the following:\r\n```\r\nDec 18 09:22:23 mesos-slave002 docker: time=\"2016-12-18T09:22:23.508786745-06:00\" level=info msg=\"GET /v1.20/containers/a9bb15414744/json\"\r\nDec 18 09:22:23 mesos-slave002 docker: time=\"2016-12-18T09:22:23.510472525-06:00\" level=info msg=\"GET /v1.20/containers/a9bb15414744/logs?follow=1&since=1382068460&stderr=1&stdout=1&tail=6000\"\r\nDec 18 09:22:24 mesos-slave002 docker: time=\"2016-12-18T09:22:24.977953415-06:00\" level=error msg=\"Error streaming logs: parsing time \\\"\\\"2016-12-18T:20:34.244241065Z\\\"\\\" as \\\"\\\"2006-01-02T15:04:05Z07:00\\\"\\\": cannot parse \\\":20:34.244241065Z\\\"\\\" as \\\"15\\\"\"\r\n```"},"comment":{"url":"https://api.github.com/repos/docker/docker/issues/comments/267831806","html_url":"https://github.com/docker/docker/issues/29511#issuecomment-267831806","issue_url":"https://api.github.com/repos/docker/docker/issues/29511","id":267831806,"user":{"login":"thaJeztah","id":1804568,"avatar_url":"https://avatars.githubusercontent.com/u/1804568?v=3","gravatar_id":"","url":"https://api.github.com/users/thaJeztah","html_url":"https://github.com/thaJeztah","followers_url":"https://api.github.com/users/thaJeztah/followers","following_url":"https://api.github.com/users/thaJeztah/following{/other_user}","gists_url":"https://api.github.com/users/thaJeztah/gists{/gist_id}","starred_url":"https://api.github.com/users/thaJeztah/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/thaJeztah/subscriptions","organizations_url":"https://api.github.com/users/thaJeztah/orgs","repos_url":"https://api.github.com/users/thaJeztah/repos","events_url":"https://api.github.com/users/thaJeztah/events{/privacy}","received_events_url":"https://api.github.com/users/thaJeztah/received_events","type":"User","site_admin":false},"created_at":"2016-12-18T16:47:18Z","updated_at":"2016-12-18T16:47:18Z","body":"docker 1.8.3 is [over a year old](https://github.com/docker/docker/releases/tag/v1.8.3) and no longer maintained; a lot of changes have gone into the JSON-file logging driver since. Are you still able to reproduce this issue on the current (1.12.5) release?"}}
{"actor":{"display_login":"thaJeztah"}}