docker
Error grabbing logs: invalid character '\x00' looking for beginning of value
- [x] This is a bug report
- [ ] This is a feature request
- [x] I searched existing issues before opening this one
Expected behavior
reading logs from docker containers
Actual behavior
Can't read logs using:
docker-compose logs -f myservice
nor with:
docker logs -f 6f454c73ff9c
I am getting this error:
error from daemon in stream: Error grabbing logs: invalid character '\x00' looking for beginning of value
Steps to reproduce the behavior
After some hours I can't read logs from my containers
Output of docker version:
Client:
Version: 17.09.0-ce
API version: 1.32
Go version: go1.8.3
Git commit: afdb6d4
Built: Tue Sep 26 22:42:18 2017
OS/Arch: linux/amd64
Server:
Version: 17.09.0-ce
API version: 1.32 (minimum version 1.12)
Go version: go1.8.3
Git commit: afdb6d4
Built: Tue Sep 26 22:40:56 2017
OS/Arch: linux/amd64
Experimental: false
Output of docker info:
Containers: 11
Running: 11
Paused: 0
Stopped: 0
Images: 8
Server Version: 17.09.0-ce
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 76
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host macvlan null overlay
Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 06b9cb35161009dcb7123345749fef02f7cea8e0
runc version: 3f2f8b84a77f73d38244dd690525642a72156c64
init version: 949e6fa
Security Options:
apparmor
seccomp
Profile: default
Kernel Version: 4.4.0-97-generic
Operating System: Ubuntu 16.04.3 LTS
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 7.695GiB
Name: egmintel-desktop
ID: VB22:IXWI:GY6D:QPM4:SPHX:HYUP:OQN7:ZM55:LLKE:P3UU:XK7F:26TH
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
WARNING: No swap limit support
My docker-compose version:
docker-compose version 1.16.1, build 6d1ac21
Are you getting the same error for any container, or just a specific one? What's running in the container, and how is it started (what options are set for the container?)
Also receiving this issue from time to time on OSX. Can only fix by rebuilding.
I'd just like to let you know that this does seem to be a real issue and It has affected us as well, we solved it by manually removing the null "\x00" characters from the offending logs found with the grep below.
grep -P '\x00' /var/lib/docker/containers/**/*json.log
I'll link the two issues that we were having before we found that real cause is this. gliderlabs/logspout#246 moby/moby#29511
@thaJeztah I can confirm @WBad suggested fix does get my logs back after manually plucking out the corrupted line in the log file.
I'm running the following docker version:
Client:
Version: 17.05.0-ce
API version: 1.29
Go version: go1.7.5
Git commit: 89658be
Built: Thu May 4 22:10:54 2017
OS/Arch: linux/amd64
Server:
Version: 17.05.0-ce
API version: 1.29 (minimum version 1.12)
Go version: go1.7.5
Git commit: 89658be
Built: Thu May 4 22:10:54 2017
OS/Arch: linux/amd64
Experimental: false
Glad i found this one. I have got the same problem on Docker for Windows with Hyper-V. Looks like docker is kind of dying after this issue in my case, because i am unable to access my containerized web applications after hitting it.
Facing the same issue on Ubuntu after hard reboot of the server.
lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 14.04.5 LTS
Release: 14.04
Codename: trusty
uname -r
4.4.0-109-generic
docker version
Client:
Version: 17.05.0-ce
API version: 1.29
Go version: go1.7.5
Git commit: 89658be
Built: Thu May 4 22:06:06 2017
OS/Arch: linux/amd64
Server:
Version: 17.05.0-ce
API version: 1.29 (minimum version 1.12)
Go version: go1.7.5
Git commit: 89658be
Built: Thu May 4 22:06:06 2017
OS/Arch: linux/amd64
Experimental: false
After hard reboot having the same issue with 17.09 but this time getting:
Jan 25 22:27:58 dockerd[1218]: time="2018-01-25T22:27:58.979480120Z" level=error msg="Error streaming logs: invalid character 'l' after object key:value pair" container=3b65284c435e method="(*Daemon).ContainerLogs" module=daemon Jan 25 22:27:59 dockerd[1218]: time="2018-01-25T22:27:59.712920995Z" level=error msg="Error streaming logs: invalid character 'l' after object key:value pair" container=3b65284c435e method="(*Daemon).ContainerLogs" module=daemon Jan 25 22:28:00 dockerd[1218]: time="2018-01-25T22:28:00.439213542Z" level=error msg="Error streaming logs: invalid character 'l' after object key:value pair" container=3b65284c435e method="(*Daemon).ContainerLogs" module=daemon
If someone is able to share a sample log-file with the \x00 (of course, "sanitised" if it contains sensible information); that could be useful to reproduce and fix the issue.
While having the same issue. I use a workaround with--tail=10 flag (or whatever number you like) to only get the lines after the "invalid" character.
@thaJeztah I debugged this issue in a different project. For me, the cause was an initialized buffer having a starting size. When you Write() to the buffer, it appends everything to the \x00 characters at the beginning -- not what I expected. Lots of things don't like \x00, like encoding/json.Unmarshal() which gives: error invalid character '\x00' looking for beginning of value.
Change the 50 to 0 and the problem goes away.
output := bytes.NewBuffer(make([]byte, 50, 1024))
output.Write([]byte("{ \"Number\": 1 }"))
resp := &jFormat{}
err := json.Unmarshal(output.Bytes(), resp)
Docker version 18.09.2, build 6247962 CentOS 7.6.1810
This is happening in my environment as well. I only found it because my Logstash instances are throwing tons of errors when trying to json parse these logs.
I can easily tell this is happening by looking at the log file encoding. Problematic logs are showing up as having a binary encoding:
$ file -i *.log*
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.1: text/plain; charset=utf-8
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.2: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.3: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.4: text/plain; charset=utf-8
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.5: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.6: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.7: application/octet-stream; charset=binary
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.8: text/plain; charset=utf-8
9ea960b82438faac9e0339425a37a5655735465cac5a00e7de074d6ce6f275f7-json.log.9: application/octet-stream; charset=binary
journalctl also shows a bunch of errors while viewing logs through the "docker logs" command:
Mar 13 14:36:03 myhostname.domain dockerd[4191]: time="2019-03-13T14:36:02.841619856-07:00" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=2497
Mar 13 14:36:03 myhostname.domain dockerd[4191]: time="2019-03-13T14:36:02.841631120-07:00" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=2498
Mar 13 14:36:03 myhostname.domain dockerd[4191]: time="2019-03-13T14:36:02.841642228-07:00" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=2499
Mar 13 14:36:03 myhostname.domain dockerd[4191]: time="2019-03-13T14:36:02.841653011-07:00" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=2500
To follow up on my previous comment. I did some testing, and this only happens when I have docker perform it's own log rotation. If I add the following flags to my docker daemon this issue happens fairly consistently on newly created logs after rotation:
--log-opt max-size=10m --log-opt max-file=10
When I remove those flags and use logrotate.d for log rotation I no longer have this issue. So I'm convinced this has something to do with docker rotating it's own logs.
Tried reproducing with Docker version 18.09.2, build 6247962 on CentOS 7.6.1810 with:
d run --log-opt max-size=1m --log-opt max-file=100 ubuntu bash -c 'cat /dev/urandom'- the same, with docker compose
- a container running a small C program outputting null bytes and UTF8 strings randomly
Wasn't able to get a repro.
@jbehrends : would you be able to share the compose file with which you obtained this? Thanks!
I'm not using compose, these are settings I'm using globally for the docker daemon's config located in "/etc/sysconfig/docker" on all of my systems that run docker. So any container that gets launched will get these logging options. I've had this happen on Kubernetes hosts, and on hosts where I'm manually running containers via "docker run ...."
I don't know if it's the same issue, but the invalid character '\x00' looking for beginning of value. part is similar.
When I run
docker run -it --isolation=process mcr.microsoft.com/windows/nanoserver:1809 cmd
on an unpatched windows 10 1809, I get a bluescreen TERMINAL SERVER DRIVER MADE INCORRECT MEMORY REFERENCE. (This seems to be a known, already patched issue: https://techcommunity.microsoft.com/t5/Windows-Server-Insiders/Problem-running-microsoft-nanoserver-insider-10-0-17074-1000/td-p/146104)
Afterwards, docker is kaputt:
docker run -it --isolation=process mcr.microsoft.com/windows/nanoserver:1809 cmd
docker: Error response from daemon: Failed to unmarshall layerchain json - invalid character '\x00' looking for beginning of value.
See 'docker run --help'.
I only got it back working by completely uninstalling and reinstalling it.
We are hitting this too, on pretty much ALL our hosts in a Kubernetes environment, but also on hosts not running Kubernetes.
- Docker version 18.09.6 (client) 18.09.2 (engine) on Ubuntu 16.04.6 LTS kernel 4.15.0-1041-azure
- Same config on all hosts /etc/docker/daemon.json:
{
"live-restore": true,
"log-driver": "json-file",
"log-opts": {
"max-size": "50m",
"max-file": "5"
}
}
Here's where the \x00 bits are, always at the beginning of the file:
cat /var/lib/docker/containers/4f2ec4b99328f8da0f153760886f3e88696f529984f2e89ed1ad296c55cce752/4f2ec4b99328f8da0f153760886f3e88696f529984f2e89ed1ad296c55cce752-json.log |\
hexdump -C |\
grep "00 00" -B3 -A5
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
017be550 00 00 00 00 00 00 00 00 00 00 00 00 7b 22 6c 6f |............{"lo|
017be560 67 22 3a 22 49 30 37 32 32 20 30 36 3a 32 35 3a |g":"I0722 06:25:|
017be570 30 39 2e 35 39 34 39 31 39 20 20 20 20 20 20 20 |09.594919 |
017be580 31 20 74 72 61 63 65 2e 67 6f 3a 37 36 5d 20 54 |1 trace.go:76] T|
017be590 72 61 63 65 5b 31 34 35 33 37 36 31 38 36 32 5d |race[1453761862]|
017be5a0 3a 20 5c 22 47 75 61 72 61 6e 74 65 65 64 55 70 |: \"GuaranteedUp|
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
0153ae10 00 7b 22 6c 6f 67 22 3a 22 32 30 31 39 2d 30 37 |.{"log":"2019-07|
0153ae20 2d 31 39 20 30 36 3a 32 35 3a 30 35 2e 34 30 32 |-19 06:25:05.402|
0153ae30 20 5b 49 4e 46 4f 5d 5b 32 30 30 37 33 5d 20 69 | [INFO][20073] i|
0153ae40 6e 74 5f 64 61 74 61 70 6c 61 6e 65 2e 67 6f 20 |nt_dataplane.go |
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
01197b90 00 00 00 00 7b 22 6c 6f 67 22 3a 22 32 30 31 39 |....{"log":"2019|
01197ba0 2d 30 37 2d 31 37 20 30 36 3a 32 35 3a 30 37 2e |-07-17 06:25:07.|
01197bb0 36 37 35 20 5b 49 4e 46 4f 5d 5b 32 30 30 37 33 |675 [INFO][20073|
01197bc0 5d 20 68 65 61 6c 74 68 2e 67 6f 20 31 35 30 3a |] health.go 150:|
01197bd0 20 4f 76 65 72 61 6c 6c 20 68 65 61 6c 74 68 20 | Overall health |
The fact that we are seeing this only at the beginning of a json log file makes me suspect @jbehrends 's guess about docker log rotation is the root cause.
Related to that we are having issues shipping the docker logs through Elasticsearch, but those problems may not be 100% correlated, since I have found hosts /with/ the docker log \x00 issue which /don't/ show our most common the ELK filebeat issue:
write error: data size (79748532 bytes) is greater than the max file size (10485760 bytes)
(although filebeat would obviously also be trying to ship the \x00-affected files, and presumably fail to parse the json also).
Error grabbing logs, my personal FIX
- docker-compose ps
- docker inspect CONTAINER_NAME | grep log
- cd LOG_FOLDER
- file -i .log
The files type: "application/octet-stream; charset=binary" have errors, can be RENAMED/REMOVED/UPDATED for fix.
This issue happened to me too, what's the fix ( without losing logs )
| 0 1 2 3 4 5 6 7 8 9 a b c d e f 10 11 12 13 14 15 16 17 |
0bbe3258 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3270 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3288 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe32a0 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe32b8 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe32d0 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe32e8 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3300 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3318 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3330 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3348 | 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ........................ |
0bbe3360 | 00 00 00 00 00 00 00 00 00 00 00 00 00 7b 22 6c 6f 67 22 3a 22 32 30 32 | .............{"log":"202 |
0bbe3378 | 30 2d 30 35 2d 30 34 20 31 39 3a 35 36 3a 30 35 2e 39 33 32 20 32 34 32 | 0-05-04 19:56:05.932 242 |
0bbe3390 | 34 20 44 45 42 55 47 20 6f 73 6c 6f 5f 73 65 72 76 69 63 65 2e 70 65 72 | 4 DEBUG oslo_service.per |
0bbe33a8 | 69 6f 64 69 63 5f 74 61 73 6b 20 5b 72 65 71 2d 62 36 62 66 38 33 37 33 | iodic_task [req-b6bf8373 |
0bbe33c0 | 2d 31 61 33 30 2d 34 39 37 63 2d 62 32 37 61 2d 35 30 31 62 37 30 66 39 | -1a30-497c-b27a-501b70f9 |
0bbe33d8 | 32 61 34 66 20 2d 20 2d 20 2d 20 2d 20 2d 5d 20 52 75 6e 6e 69 6e 67 20 | 2a4f - - - - -] Running |
0bbe33f0 | 70 65 72 69 6f 64 69 63 20 74 61 73 6b 20 43 6f 6d 70 75 74 65 4d 61 6e | periodic task ComputeMan |
0bbe3408 | 61 67 65 72 2e 5f 69 6e 73 74 61 6e 63 65 5f 75 73 61 67 65 5f 61 75 64 | ager._instance_usage_aud |
0bbe3420 | 69 74 20 72 75 6e 5f 70 65 72 69 6f 64 69 63 5f 74 61 73 6b 73 20 2f 75 | it run_periodic_tasks /u |
0bbe3438 | 73 72 2f 6c 69 62 2f 70 79 74 68 6f 6e 32 2e 37 2f 73 69 74 65 2d 70 61 | sr/lib/python2.7/site-pa |
0bbe3450 | 63 6b 61 67 65 73 2f 6f 73 6c 6f 5f 73 65 72 76 69 63 65 2f 70 65 72 69 | ckages/oslo_service/peri |
0bbe3468 | 6f 64 69 63 5f 74 61 73 6b 2e 70 79 3a 32 31 37 5c 75 30 30 31 62 5b 30 | odic_task.py:217\u001b[0 #
k8s version: 1.17.2
docker version
Server: Docker Engine - Community
Engine:
Version: 19.03.5
API version: 1.40 (minimum version 1.12)
Go version: go1.12.12
Git commit: 633a0ea
Built: Wed Nov 13 07:24:18 2019
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.2.10
GitCommit: b34a5c8af56e510852c35414db4c1f4fa6172339
runc:
Version: 1.0.0-rc8+dev
GitCommit: 3e425f80a8c931f88e6d94a8c831b9d5aa481657
docker-init:
Version: 0.18.0
GitCommit: fec3683
According to this line: https://sourcegraph.com/github.com/docker/docker-ce@05bbb382e1bf56c66a0711b8d14f8360e3e39acb/-/blob/components/engine/daemon/logger/jsonfilelog/jsonfilelog.go#L103:2
the buffer is empty initialized, no default \x00 prefix I think. @YakDriver
buf := bytes.NewBuffer(nil)
Relate code here, https://sourcegraph.com/github.com/docker/docker-ce@05bbb382e1bf56c66a0711b8d14f8360e3e39acb/-/blob/components/engine/daemon/logger/jsonfilelog/jsonlog/jsonlogbytes.go#L85
does any one know, the real cause, maybe some bug there?
func ffjsonWriteJSONBytesAsString(buf *bytes.Buffer, s []byte) {
const hex = "0123456789abcdef"
buf.WriteByte('"')
start := 0
for i := 0; i < len(s); {
if b := s[i]; b < utf8.RuneSelf {
if 0x20 <= b && b != '\\' && b != '"' && b != '<' && b != '>' && b != '&' {
i++
continue
}
if start < i {
buf.Write(s[start:i])
}
switch b {
case '\\', '"':
buf.WriteByte('\\')
buf.WriteByte(b)
case '\n':
buf.WriteByte('\\')
buf.WriteByte('n')
case '\r':
buf.WriteByte('\\')
buf.WriteByte('r')
default:
buf.WriteString(`\u00`)
buf.WriteByte(hex[b>>4])
buf.WriteByte(hex[b&0xF])
}
i++
start = i
continue
}
c, size := utf8.DecodeRune(s[i:])
if c == utf8.RuneError && size == 1 {
if start < i {
buf.Write(s[start:i])
}
buf.WriteString(`\ufffd`)
i += size
start = i
continue
}
if c == '\u2028' || c == '\u2029' {
if start < i {
buf.Write(s[start:i])
}
buf.WriteString(`\u202`)
buf.WriteByte(hex[c&0xF])
i += size
start = i
continue
}
i += size
}
if start < len(s) {
buf.Write(s[start:])
}
buf.WriteByte('"')
}
To fix the corrupt logs (adapt to your docker data-root)
grep -P '\x00' /da1/docker/containers/**/*.log* | awk '{ print $3 }'
grep -P '\x00' /da1/docker/containers/**/*.log* | awk '{ print $3 }' | xargs sed -i 's/\x0//g'
edited: the above fix if the log file does not have number suffix, it may cause docker logs to stop receive new logs
At first I think, it may relate to that I changed docker data-root ( without move docker directory to new path, date: 2020-5-4 )
But recent logs (it's the in use logs, not rotated log) show, it still happens at about 2020-5-8, both of corrupt log at 14:09, though don't know why.
[root@nt9 ~]# grep -P '\x00' /da1/docker/containers/**/*.log* | awk '{ print $3 }'
/da1/docker/containers/8b988e1d18e571ff6eb376930ad86ff466769149d4afbd9d690d6515297b1817/8b988e1d18e571ff6eb376930ad86ff466769149d4afbd9d690d6515297b1817-json.log
/da1/docker/containers/9df878d3e54f23432fd51c4e34ad6c0bd7b36dc0ee3a38a4f4a79af667254097/9df878d3e54f23432fd51c4e34ad6c0bd7b36dc0ee3a38a4f4a79af667254097-json.log
[root@nt9 ~]# cat /da1/docker/containers/8b988e1d18e571ff6eb376930ad86ff466769149d4afbd9d690d6515297b1817/8b988e1d18e571ff6eb376930ad86ff466769149d4afbd9d690d6515297b1817-json.log |\
> hexdump -C |\
> grep "00 00" -B3 -A5
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
020ab240 00 00 00 00 00 00 00 00 00 00 7b 22 6c 6f 67 22 |..........{"log"|
020ab250 3a 22 32 30 32 30 2d 30 35 2d 30 38 20 31 34 3a |:"2020-05-08 14:|
020ab260 30 39 3a 31 37 2e 34 37 31 20 34 33 31 30 38 20 |09:17.471 43108 |
020ab270 44 45 42 55 47 20 6f 73 6c 6f 5f 73 65 72 76 69 |DEBUG oslo_servi|
020ab280 63 65 2e 70 65 72 69 6f 64 69 63 5f 74 61 73 6b |ce.periodic_task|
020ab290 20 5b 72 65 71 2d 36 38 61 61 35 39 39 61 2d 62 | [req-68aa599a-b|
[root@nt9 ~]# uptime
14:18:23 up 13 days, 20:10, 8 users, load average: 2.44, 1.96, 1.87
[root@nt9 ~]# cat /da1/docker/containers/9df878d3e54f23432fd51c4e34ad6c0bd7b36dc0ee3a38a4f4a79af667254097/9df878d3e54f23432fd51c4e34ad6c0bd7b36dc0ee3a38a4f4a79af667254097-json.log | hexdump -C | grep "00 00" -B3 -A5
00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
031d4aa0 00 00 00 00 00 00 00 00 7b 22 6c 6f 67 22 3a 22 |........{"log":"|
031d4ab0 32 30 32 30 2d 30 35 2d 30 38 20 30 36 3a 30 39 |2020-05-08 06:09|
031d4ac0 3a 31 33 2e 37 36 38 2b 30 30 30 30 3a 20 33 35 |:13.768+0000: 35|
031d4ad0 34 3a 20 69 6e 66 6f 20 3a 20 76 69 72 45 76 65 |4: info : virEve|
031d4ae0 6e 74 50 6f 6c 6c 44 69 73 70 61 74 63 68 54 69 |ntPollDispatchTi|
031d4af0 6d 65 6f 75 74 73 3a 34 35 35 20 3a 20 45 56 45 |meouts:455 : EVE|
[root@nt9 ~]#
this issue is a big problem for us even at now time, for docker 19.03.5.
imagine, if you can't enable docker container logs(rotate, setting log-opts) , how to deal with the log growing issue?
We had the same issue and I added the following layer in the base image we are using:
ENV LANG C.UTF-8
And since then we do not see the invalid charts: 'X00'
After a closer look it seems like a race condition - it will only happens when the container is very chatty ( ~ under 100ms between logs) and some external process (like log rotate) truncate the log file. Steps to reproduce the behavior with k8s and docker run the following pod
apiVersion: v1
kind: Pod
metadata:
name: counter
spec:
containers:
- name: count
image: busybox
args: [/bin/sh, -c,
'i=0; while true; do echo "$(date) INFO $i: Testing logging problems!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!"; i=$((i+1)); sleep 0.01; done']
Use docker inspect to find the log file and run the truncate command:
cp e504410aaf83394f3359d7ebec2461ff1674e0296bf4087685f64ab6abfa9750-json.log 1.log && truncate -s0 e504410aaf83394f3359d7ebec2461ff1674e0296bf4087685f64ab6abfa9750-json.log
Can also watch the offset with lsof:
$lsof +d /var/lib/docker/containers/e504410aaf83394f3359d7ebec2461ff1674e0296bf4087685f64ab6abfa9750
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
dockerd 4137 root 127w REG 253,1 2473782 142528918 /var/lib/docker/containers/e504410aaf83394f3359d7ebec2461ff1674e0296bf4087685f64ab6abfa9750/e504410aaf83394f3359d7ebec2461ff1674e0296bf4087685f64ab6abfa9750-json.log
Workaround
Find and disable all process that truncate the log file (usually logrotate) / use only docker builtin logrotate
More info
https://superuser.com/questions/881777/what-happens-when-i-truncate-a-file-that-is-in-use
https://stackoverflow.com/questions/43345474/behavior-when-opening-file-in-truncate-mode
I faced a similar issue when starting of docker daemon on win10 and I fixed it with: https://success.docker.com/article/warning-error-loading-configjson
I solved this by deleting the scheduler-state.json file. It lived on a Ceph cluster that my docker registry suddenly lost access to and must have corrupted the file.
We are also seeing this issue when logs rotate and container is very busy logging. Anyone looking at how to fix this?
Currently getting some weird system freezes on Ubuntu Server 20.04.3 LTS and came across this in the logs. Any ideas?
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.891908772Z" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=0
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.891988392Z" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=1
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892019270Z" level=warning msg="got error while decoding json" error="invalid character '\\x00' looking for beginning of value" retries=2
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892042974Z" level=warning msg="got error while decoding json" error="invalid character ':' looking for beginning of value" retries=3
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892069093Z" level=warning msg="got error while decoding json" error="invalid character '.' looking for beginning of value" retries=4
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892091585Z" level=warning msg="got error while decoding json" error="invalid character 'v' looking for beginning of value" retries=5
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892111573Z" level=warning msg="got error while decoding json" error="invalid character 'p' looking for beginning of value" retries=6
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892132782Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=7
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892155275Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=8
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892175583Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=9
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892193897Z" level=warning msg="got error while decoding json" error="invalid character '}' looking for beginning of value" retries=10
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892213444Z" level=warning msg="got error while decoding json" error="invalid character 'e' looking for beginning of value" retries=11
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892232149Z" level=warning msg="got error while decoding json" error="invalid character 's' looking for beginning of value" retries=12
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892250754Z" level=warning msg="got error while decoding json" error="invalid character 'c' looking for beginning of value" retries=13
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892270340Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=14
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892289807Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=15
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892307810Z" level=warning msg="got error while decoding json" error="invalid character 'o' looking for beginning of value" retries=16
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892326475Z" level=warning msg="got error while decoding json" error="invalid character 'g' looking for beginning of value" retries=17
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892349148Z" level=warning msg="got error while decoding json" error="invalid character ':' looking for beginning of value" retries=18
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892367753Z" level=warning msg="got error while decoding json" error="invalid character 'i' looking for beginning of value" retries=19
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892388993Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=20
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892407327Z" level=warning msg="got error while decoding json" error="invalid character ':' looking for beginning of value" retries=21
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892429939Z" level=warning msg="got error while decoding json" error="invalid character '\\\\' looking for beginning of value" retries=22
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892457411Z" level=warning msg="got error while decoding json" error="invalid character 'e' looking for beginning of value" retries=23
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892485243Z" level=warning msg="got error while decoding json" error="invalid character 'e' looking for beginning of value" retries=24
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892516832Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=25
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892544675Z" level=warning msg="got error while decoding json" error="invalid character 'Z' looking for beginning of value" retries=26
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892578558Z" level=warning msg="got error while decoding json" error="invalid character 'e' looking for beginning of value" retries=27
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892609927Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=28
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892639623Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=29
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892657987Z" level=warning msg="got error while decoding json" error="invalid character 'T' looking for beginning of value" retries=30
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892678555Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=31
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892698453Z" level=warning msg="got error while decoding json" error="invalid character 'Z' looking for beginning of value" retries=32
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892718180Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=33
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892737346Z" level=warning msg="got error while decoding json" error="invalid character '\\\\' looking for beginning of value" retries=34
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892756582Z" level=warning msg="got error while decoding json" error="invalid character 'a' looking for beginning of value" retries=35
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892776459Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=36
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892796146Z" level=warning msg="got error while decoding json" error="invalid character 'c' looking for beginning of value" retries=37
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892815652Z" level=warning msg="got error while decoding json" error="json: cannot unmarshal number into Go value of type jsonlog.JSONLog" retries=38
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892834167Z" level=warning msg="got error while decoding json" error="invalid character ':' looking for beginning of value" retries=39
Dec 12 14:11:26 ubuntu dockerd[1178]: time="2021-12-12T14:11:26.892853944Z" level=warning msg="got error while decoding json" error="invalid character ' ' in literal null (expecting 'u')" retries=40
