Repository: moby/moby (language: go)

Issue:
OOM when following "local" logs of high-log-output container
**Description**

When logging to the `local` driver, Docker will quickly run out of memory when following the logs of a container with a lot of log output.

This also occurs when following local logs while using a driver such as `syslog` that supports dual logging.

This issue appears to be similar or identical to #39963.

**Steps to reproduce the issue:**
1. Run a container that logs heavily to the `local` driver:

    ```
    ID=$(docker run --rm -d --log-driver local alpine cat /dev/urandom)
    ```
2. Follow the container's logs:

    ```
    docker logs -f $ID > /dev/null
    ```

Alternatively:

1. Run a container that logs heavily to a driver that supports dual logging:

    ```
    ID=$(docker run --rm -d --log-driver syslog --log-opt syslog-address=udp://127.0.0.1:0 alpine cat /dev/urandom)
    ```
2. Follow the container's logs:

    ```
    docker logs -f $ID > /dev/null
    ```

**Describe the results you received:**
`dockerd` exits with `fatal error: runtime: out of memory`.

Stack trace: https://gist.github.com/2f674f1ff24c679ba4778f458facb7b2

**Describe the results you expected:**
Docker remains stable and keeps a reasonable memory footprint.

**Additional information you deem important (e.g. issue happens only occasionally):**
I have been unable to reproduce the issue when logging to the `json-file` driver.

**Output of `docker version`:**

```
Client: Docker Engine - Community
 Version:           20.10.5
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        55c4c88
 Built:             Tue Mar  2 20:18:20 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.5
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       363e9a8
  Built:            Tue Mar  2 20:16:15 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.3
  GitCommit:        269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc:
  Version:          1.0.0-rc92
  GitCommit:        ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
```

**Output of `docker info`:**

```
Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)

Server:
 Containers: 1
  Running: 1
  Paused: 0
  Stopped: 0
 Images: 1
 Server Version: 20.10.5
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: local
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-54-generic
 Operating System: Ubuntu 20.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 981.1MiB
 Name: ubuntu-focal
 ID: 5X6F:5OLY:MQHX:I5T3:AVJQ:AMIX:5OBO:XI4L:CI62:LRA7:INKW:26IT
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 30
  Goroutines: 40
  System Time: 2021-03-08T20:11:15.100104538Z
  EventsListeners: 0
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No swap limit support
```

**Additional environment details (AWS, VirtualBox, physical, etc.):**

This was initially observed in a [Nomad](https://www.nomadproject.io/) environment. Nomad follows logs by default for Docker tasks. The host was a lightly loaded AWS `m5.xlarge` instance.

I have reproduced it on Ubuntu 16.04 and 20.04 using Virtualbox VMs, and on Docker for Mac 3.1.0 (20.10.2).
OOM when following "local" logs of high-log-output container
**Description**

When logging to the `local` driver, Docker will quickly run out of memory when following the logs of a container with a lot of log output.

This also occurs when following local logs while using a driver such as `syslog` that supports dual logging.

This issue appears to be similar or identical to #39963.

**Steps to reproduce the issue:**
1. Run a container that logs heavily to the `local` driver:

    ```
    ID=$(docker run --rm -d --log-driver local alpine cat /dev/urandom)
    ```
2. Follow the container's logs:

    ```
    docker logs -f $ID > /dev/null
    ```

Alternatively:

1. Run a container that logs heavily to a driver that supports dual logging:

    ```
    ID=$(docker run --rm -d --log-driver syslog --log-opt syslog-address=udp://127.0.0.1:0 alpine cat /dev/urandom)
    ```
2. Follow the container's logs:

    ```
    docker logs -f $ID > /dev/null
    ```

**Describe the results you received:**
`dockerd` exits with `fatal error: runtime: out of memory`.

Stack trace: https://gist.github.com/2f674f1ff24c679ba4778f458facb7b2

**Describe the results you expected:**
Docker remains stable and keeps a reasonable memory footprint.

**Additional information you deem important (e.g. issue happens only occasionally):**
I have been unable to reproduce the issue when logging to the `json-file` driver.

**Output of `docker version`:**

```
Client: Docker Engine - Community
 Version:           20.10.5
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        55c4c88
 Built:             Tue Mar  2 20:18:20 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.5
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       363e9a8
  Built:            Tue Mar  2 20:16:15 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.3
  GitCommit:        269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc:
  Version:          1.0.0-rc92
  GitCommit:        ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
```

**Output of `docker info`:**

```
Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)

Server:
 Containers: 1
  Running: 1
  Paused: 0
  Stopped: 0
 Images: 1
 Server Version: 20.10.5
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: local
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-54-generic
 Operating System: Ubuntu 20.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 981.1MiB
 Name: ubuntu-focal
 ID: 5X6F:5OLY:MQHX:I5T3:AVJQ:AMIX:5OBO:XI4L:CI62:LRA7:INKW:26IT
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 30
  Goroutines: 40
  System Time: 2021-03-08T20:11:15.100104538Z
  EventsListeners: 0
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No swap limit support
```

**Additional environment details (AWS, VirtualBox, physical, etc.):**

This was initially observed in a [Nomad](https://www.nomadproject.io/) environment. Nomad follows logs by default for Docker tasks. The host was a lightly loaded AWS `m5.xlarge` instance.

I have reproduced it on Ubuntu 16.04 and 20.04 using Virtualbox VMs, and on Docker for Mac 3.1.0 (20.10.2).


Discussion / hints:
@cpuguy83 PTAL
I have a feeling this is happening here: https://github.com/moby/moby/blob/master/daemon/logger/local/read.go#L199

I do see you have a reader attached in your stack trace.
It will help if you can provide a heap dump.

You should be able to get it if you hit the docker API at `/debug/pprof/heap`.
Heap dump: [heap1615862444.out.gz](https://github.com/moby/moby/files/6145718/heap1615862444.out.gz)

Hopefully this is helpful. It's a bit hard to time but I tried to get it shortly before a crash.

Thanks for taking a look!
Thanks for grabbing that.

This doesn't look complete. Maybe you can get the svg version?
The `pprof` (https://github.com/google/pprof) command (or if you have `go` on the machine already `go tool pprof`) can generate svg (depends on graphviz).
Also just to note, it'd probably be fine to grab it regardless of if it was just before it crashes, just so long as its had some time to exercise the logger.
Seeing the same error here. Is there any updates on this issue? 
I have this in my backlog for the next week or so to grab additional `pprof` output (but don't let me stop you from doing so! :wink:).
@cpuguy83 here's what I managed to come up with on another couple attempts:

1. [heap](https://github.com/moby/moby/files/6368379/heap1.gz), alloc_space:
![alloc_space1](https://user-images.githubusercontent.com/1084619/115936194-a19b6c80-a462-11eb-934b-f43c26e6913c.png)
2. [heap](https://github.com/moby/moby/files/6368394/heap2.gz), alloc_space:
![alloc_space2](https://user-images.githubusercontent.com/1084619/115936302-dc9da000-a462-11eb-9d6a-66fe22fe6eb2.png)

I'm still not sure I'm capturing it right so if this still doesn't get you what you need I can try further. This is reproducible with this [`Vagrantfile`](https://github.com/moby/moby/files/6368400/Vagrantfile.txt).






Hey, experiencing the same issue here, looking for a fix because we need logs from these critical containers stored locally and shipped.
I am seeing the same stack trace with the splunk logging driver. I think that all (?) loggers nowadays support dual logging since it was backported to the CE edition.
FWIW I do not think "high" log output is neccessary. I managed to trigger this in a nomad setup where nomad (I think) runs log on every container and the amount of logs for a day are few MB (in this testcase).
@cpuguy83 This is what I was able to gather:

alloc space:
![alloc_space](https://user-images.githubusercontent.com/81547/120757155-73ed1d00-c510-11eb-93e8-acb2b32aeb8c.png)
alloc objects:
![alloc_objects](https://user-images.githubusercontent.com/81547/120757145-72bbf000-c510-11eb-9949-cde5198e5592.png)
in use:
![in_use](https://user-images.githubusercontent.com/81547/120757158-751e4a00-c510-11eb-8475-c42e8166adfe.png)
inuse objects:
![inuse_objects](https://user-images.githubusercontent.com/81547/120757159-75b6e080-c510-11eb-9fee-8d7fe4588df0.png)

funnily enough the memory usage "jumped" at one point rather quickly without any log messages in the journal or anything interesting happening:
![graph](https://user-images.githubusercontent.com/81547/120757289-a72fac00-c510-11eb-9df2-33aac6e73729.png)

I just noted that the rendered PNGs are not really readable, I have uploaded the SVGs to https://apolloner.eu/~apollo13/moby/
I wonder if `d.buf` in my case is set to a few gb at some point and never resized down (capacity wise) -- would this be possible? That said I do not see why or how I could have such long log messages?
After another jump in memory I stopped all containers (and log tailers). Memory usage did not decrease, restarting docker did ;)
At work we're running docker containers managed by Hashicorp Nomad, and use the `fluentd` log-driver in our docker daemon config. We've had the same issue with dockerd's memory usage ballooning over time, but we found we could prevent this using the following daemon.json setting:

```
  "log-opts": {
    "cache-disabled": "true",
```

[This disables Docker's "dual-logging" feature](https://docs.docker.com/config/containers/logging/dual-logging/#disable-the-dual-logging-cache), which creates a local log cache for log drivers that don't support local reads. Although this fixes the memory usage issue, it breaks the `docker logs` and `nomad alloc logs` commands. We decided we were fine with this compromise, because we already backup logs to a local file using fluentbit.

Before we made this change, over the course of a few hours dockerd would climb to 3 GB memory usage. After making the change it uses a steady ~240 MB. Hope others find this useful.
@thaJeztah Is there anything the community can provide to move this along and maybe get a patch?
We recently deployed a container that logs a lot more than previously and have been battling unexplained out of memory-issues for dockerd.
We're using the syslog-driver, and "docker logs" isn't critical, but it's definitely nice to have, instead of grep'ing through the syslog for the right time and container
What is your Go version on `docker version`?

From Go 1.12 to Go 1.15, Go was using MADV_FREE to ask OS to reclaim memory. However it was not updating many userland-surfacing statistics (including RSS) and causing a lot of confusion. So in Go 1.16, the behavior has changed again to use MADV_DONTNEED instead.

https://github.com/golang/go/commit/05e6d28849293266028c0bc9e9b0f8d0da38a2e2

Note that moby/moby's Dockerfile is using Go 1.13.15 in 20.10.7.
Interesting, what affect would this have? Wrong pprofs and we'd need to regenerate them using a newer go version?

On Thu, Nov 18, 2021, at 19:54, Kazuyoshi Kato wrote:
> What is your Go version on `docker version`? From Go 1.12 to Go 1.15, 
> Go was using MADV_FREE to ask OS to reclaim memory. However it was not 
> updating many userland-surfacing statistics (including RSS) and causing 
> a lot of confusion. So in Go 1.16, the behavior has changed again to 
> use MADV_DONTNEED instead.
>
> Note that moby/moby's Dockerfile is using Go 1.13.15 in 20.10.7.
>
> —
> You are receiving this because you commented.
> Reply to this email directly, view it on GitHub 
> <https://github.com/moby/moby/issues/42125#issuecomment-973161788>, or 
> unsubscribe 
> <https://github.com/notifications/unsubscribe-auth/AAAT5C6NRYFAGIN4VS7HHODUMVDWRANCNFSM4Y2DSGKQ>.
> Triage notifications on the go with GitHub Mobile for iOS 
> <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> 
> or Android 
> <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

No. I think tools that are aware about Go runtime (such as pprof) is fine. However top and other general-purpose Linux commands may not report RSS and other stats correctly if your Go version is old.
Apparently msgLen below is sometimes getting pretty big, such as 71343681. Interestingly the byte sequence (4409e41) is actually appeared in the log file (in my case, /var/lib/docker/containers/09d9263ca4946e5543b0a0c979dd74c94dfc4cfc819204517eb310718d287b2c/local-logs/container.log).

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/local/read.go#L136-L146

It is happening after calling Reset() due to below.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/loggerutils/logfile.go#L666-L670

I think, Decode() is assuming that the current position of the file is the beginning of a record. But fileWatcher wouldn't guarantee such a thing.
> I think, Decode() is assuming that the current position of the file is the beginning of a record. But fileWatcher wouldn't guarantee such a thing.

Sorry. No. Decode is not assuming that the current position of the file is the beginning of a record. EOF errors from Decode is ignored like below.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/loggerutils/logfile.go#L706-L735

However allocating a buffer based on `binary.BigEndian.Uint32(d.buf[:read])` is still problematic and potentially kills dockerd due to `fatal error: runtime: out of memory`.
The value we are reading in this section you mentioned is literally the size of the record.

The biggest each log entry can be is 1MB.
Add the protobuf encoding and whatever metadata (timestamp, explicitly specified container labels).
These are not unbounded.
We could look at chunking the records somehow so they do not exceed some pre-determined buffer size.

I am surprised that you would see a buffer of 71MB and would be curious what the data in that file looks like.
I was doing `docker run --rm -d --log-driver local alpine cat /dev/urandom` as @dnrce suggested. So this would be too harsh and less realistic.

That being said, IIUC `d.buf[:read]` in Decode() could point literally anywhere in a protobuf-encoded log stream file. Since protobuf embeds UTF-8 strings as is, if a log message contains `abcd` (in UTF-8, `0x61 0x62 0x63 0x64`), is there a possibility of allocating 0x61626364 bytes -> 1633837924 bytes -> 1.6GB?
@kzys No we write the log stream as `<record len><record><record len>`, which makes it easy to read both backwards and forwards.
So what's happening there when we set the buffer like above is we are reading `<record len>`.
Those lengths have a fixed size.
I added Docker Engine a few extra logging and a panic condition like https://github.com/kzys/docker/commit/d4e2856281b8be448a19256f0d8912794ba36532.

By running `docker logs -f $(docker run --rm -d --log-driver local alpine cat /dev/urandom) > /dev/null`, it eventually hits `panic: too large 95e09737`. The byte sequence is appeared in the saved protobuf log file like below (highlighted by `{...}`).

```
0000cfa0  1d*00 00 01 65 0a 06 73  74 64 6f 75 74 10 eb ac  |....e..stdout...|
0000cfb0  f2 e4 e0 a5 c5 dc 16 1a  d0 02 63 ad 35 de 40 05  |..........c.5.@.|
0000cfc0  27 88 0e 13 c5 ce be a3  6e 6e d1 6b 44 76 cf a5  |'.......nn.kDv..|
0000cfd0  b5 76 b0 98 8f 2a 68 30  5f 2f 82 74 53 9e 41 90  |.v...*h0_/.tS.A.|
0000cfe0  c0 84 3c 12 9c c2 79 de  48 17 3e 4b 9d c9 a2 7b  |..<...y.H.>K...{|
0000cff0  7d 53 6b 5f 7f 4f 3a c0  f1 03 14 6a ca 0e 61 3b  |}Sk_.O:....j..a;|
0000d000 {95 e0 97 37}37 62 c3 94  c6 8c f4 05 db ac 89 6d  |...77b.........m|
0000d010  fb a9 23 de 7a a7 32 4e  ed 68 eb 56 86 27 9e 86  |..#.z.2N.h.V.'..|
0000d020  d8 1d 65 f2 c4 b1 35 88  a5 e5 34 bd 4a 51 2e 15  |..e...5...4.JQ..|
0000d030  74 cf 0f 16 f1 1c 68 59  2c 9c 2b 14 cd f6 35 26  |t.....hY,.+...5&|
0000d040  c4 85 6c 9e 9b 29 6f 08  c5 69 da 54 b4 86 46 0f  |..l..)o..i.T..F.|
0000d050  11 7e f3 67 0e 31 b6 c0  8a 1f 09 6f 18 9b b5 ac  |.~.g.1.....o....|
0000d060  56 72 f5 53 90 69 ca 2a  e7 f3 34 01 37 c1 9f b5  |Vr.S.i.*..4.7...|
0000d070  88 42 7d 97 9a e7 a3 13  56 93 65 c8 77 2c 95 a3  |.B}.....V.e.w,..|
0000d080  b8 da b2 03 0f 17 1f c7  0b 4f 19 f0 27 f1 98 51  |.........O..'..Q|
0000d090  84 7b 75 3d 04 ae d9 dd  f3 bc 14 e9 1e 0c 28 b5  |.{u=..........(.|
0000d0a0  72 63 32 f2 55 01 32 c5  1d 90 ec ca f0 0c 4f 70  |rc2.U.2.......Op|
0000d0b0  b8 e4 85 c1 f5 32 50 6d  65 3b 20 f0 50 39 88 75  |.....2Pme; .P9.u|
0000d0c0  c8 e5 2f 09 7a 8a 8b e2  15 6b 45 25 d8 7a 54 d3  |../.z....kE%.zT.|
0000d0d0  54 06 bc a8 48 bd 1b da  5c d1 50 08 f6 78 3f b9  |T...H...\.P..x?.|
0000d0e0  df 17 8c 89 69 1a a7 fe  f9 f6 09 29 a5 b7 63 40  |....i......)..c@|
0000d0f0  98 e4 d3 6f 25 25 97 00  cb c3 ad 31 f6 e5 ed a1  |...o%%.....1....|
0000d100  cc 48 4e bc 75 d4 ed 48  87 ec 00 00 01 65*00 00  |.HN.u..H.....e..|
0000d110  00 39 0a 06 73 74 64 6f  75 74 10 96 a9 f3 e4 e0  |.9..stdout......|

```

`00 00 01 65` and `00 00 00 39` (highlighted by `*`) are the record length headers. So seems Decode() is reading the middle of the record somehow.

[bad-7088503659120093909.log](https://github.com/moby/moby/files/7573350/bad-7088503659120093909.log)

Here is the logs around the panic.

```
Nov 19 23:07:05 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:05.375494976Z" level=info msg="handleRotate /var/lib/docker/containers/ef1973d73da5280e8f583e8b2208635f999be88d7d74
Nov 19 23:07:05 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:05.386052980Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536371120Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536415602Z" level=info msg=waitRead
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536432394Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536441379Z" level=info msg=waitRead
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.551459454Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.552278411Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.047956265Z" level=info msg="handleRotate /var/lib/docker/containers/ef1973d73da5280e8f583e8b2208635f999be88d7d74
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048228185Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048443941Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048463066Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.050187068Z" level=info msg="handleDecodeErr could not decode log entry: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.050216651Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: 0xc0009e63c0 make 2514523959+4=2514523963
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: panic: too large 95e09737
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: goroutine 235 [running]:
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/local.(*decoder).Decode(0xc0009e63c0, 0xc000b5f9e0, 0x0, 0x0)
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:149 +0x8f9
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/loggerutils.followLogs(0xc000010038, 0xc0000a53c0, 0xc000b5e180, 0xc000b5f9e0, 0x29a0370, 0xc0009e6
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/loggerutils/logfile.go:754 +0x502
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/loggerutils.(*LogFile).ReadLogs(0xc000fd3a40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffffffffffff, 0x1
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/loggerutils/logfile.go:439 +0x4e8
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/local.(*driver).readLogs(0xc0007ffbc0, 0xc0000a53c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffffffffff
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:35 +0xfa
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: created by github.com/docker/docker/daemon/logger/local.(*driver).ReadLogs
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:24 +0x16f
```

When io.ReadFull() below doesn't read the bytes fully (returning ErrUnexpectedEOF), the next invocation of Decode() must not decode the record header.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/local/read.go#L179-L190
@kzys
> When io.ReadFull() below doesn't read the bytes fully (returning ErrUnexpectedEOF), the next invocation of Decode() must not decode the record header.

But when `ErrUnexpectedEOF` is returned from `readFull`, the `maxDecodeRetry` loop continues to read the bytes from the reader till the length is read fully, no?
The only thing I can imagine is that `readFull` returns `EOF` as shown in your log and now you have read half a msg length from the buffer? and now the next `Decode()` would be in the middle somewhere

EDIT:// EOF Should only be returned when no bytes are read at all, so this should not happen either.
Oh that could be it: What happens in `decodeLogEntry` might be the following. Assume there is a message length of 100.

 * The first `readFull` reads 50 bytes because there are only 50 bytes available and set `ErrUnexpectedEOF`
 * The second `readFull` reads 0 bytes and sets `EOF` because we are still at the end of the filestream.
 
Now we return with the error `EOF` and the next decode is in the middle of the stream and tries to read the message length again. Does that make any sense @kzys & @cpuguy83?
Working on the branch @kzys started I can get a stable behavior with the following diff:
```diff
diff --git a/daemon/logger/local/read.go b/daemon/logger/local/read.go
index 81c35902b9..1cbbaf4dc8 100644
--- a/daemon/logger/local/read.go
+++ b/daemon/logger/local/read.go
@@ -5,11 +5,11 @@ import (
        "encoding/binary"
        "io"
 
-       "fmt"
        "bytes"
+       "fmt"
+       "math/rand"
        "os"
        "os/exec"
-       "math/rand"
 
        "github.com/docker/docker/api/types/plugins/logdriver"
        "github.com/docker/docker/daemon/logger"
@@ -124,7 +124,7 @@ func (d *decoder) Decode() (*logger.Message, error) {
                var n int
                n, err = io.ReadFull(d.rdr, d.buf[read:encodeBinaryLen])
                if err != nil {
-                       if err != io.ErrUnexpectedEOF {
+                       if err != io.ErrUnexpectedEOF && err != io.EOF {
                                return nil, errors.Wrap(err, "error reading log message length")
                        }
                        read += n
@@ -189,13 +189,13 @@ func decodeLogEntry(rdr io.Reader, proto *logdriver.LogEntry, buf []byte, msgLen
        var (
                read int
                err  error
-               i int
+               i    int
        )
        for i = 0; i < maxDecodeRetry; i++ {
                var n int
                n, err = io.ReadFull(rdr, buf[read:msgLen+encodeBinaryLen])
                if err != nil {
-                       if err != io.ErrUnexpectedEOF {
+                       if err != io.ErrUnexpectedEOF && err != io.EOF {
                                return nil, errors.Wrap(err, "could not decode log entry")
                        }
                        read += n
```

This seems to suggest that much hunch was correct. I can still imagine edge cases with this patch, but I am running the provided example for minutes without a crash now.
Found an even better panic condition than the one @kzys added:
```diff
diff --git a/daemon/logger/local/read.go b/daemon/logger/local/read.go
index b28aa90651..ab9d21c3c3 100644
--- a/daemon/logger/local/read.go
+++ b/daemon/logger/local/read.go
@@ -3,6 +3,7 @@ package local
 import (
        "context"
        "encoding/binary"
+       "fmt"
        "io"
 
        "bytes"
@@ -121,6 +122,9 @@ func (d *decoder) Decode() (*logger.Message, error) {
                n, err = io.ReadFull(d.rdr, d.buf[read:encodeBinaryLen])
                if err != nil {
                        if err != io.ErrUnexpectedEOF {
+                               if err == io.EOF && read > 0 {
+                                       panic(fmt.Sprintf("(readMsgLen) Failing with EOF, read %d of %d", read, encodeBinaryLen))
+                               }
                                return nil, errors.Wrap(err, "error reading log message length")
                        }
                        read += n
@@ -181,6 +185,9 @@ func decodeLogEntry(rdr io.Reader, proto *logdriver.LogEntry, buf []byte, msgLen
                n, err = io.ReadFull(rdr, buf[read:msgLen+encodeBinaryLen])
                if err != nil {
                        if err != io.ErrUnexpectedEOF {
+                               if err == io.EOF {
+                                       panic(fmt.Sprintf("(decodeLogEntry) Failing with EOF, read %d of %d", read, msgLen+encodeBinaryLen))
+                               }
                                return nil, errors.Wrap(err, "could not decode log entry")
                        }
                        read += n
```

It exactly illustrates the problem, when reading the msgLen:
 * `EOF` when reading the length of the message is fatal when we already read more than one byte from the stream. The reason is that this would advance the stream and the next call to `Decode()` would read a new length from a starting position incremented by one
and when reading the message itself:
 * `EOF` here is not valid even if read=0 because the length has already been read so if we exit here the next `Decode` will try to start reading a new msg length from somewhere inside the message. 
This is kind of a strange condition.

> If an EOF happens after reading some but not all the bytes, ReadFull returns ErrUnexpectedEOF

But we write the whole record in one shot.
So maybe the cursor is getting off somewhere else, or perhaps some weird fs behavior.

I think we should likely use ReadAt, track the cursor ourselves, and only advance after the cursor after a successful proto unmarshal.
> I think we should likely use ReadAt, track the cursor ourselves, and only advance after the cursor after a successful proto unmarshal.

Yes, something like this is certainly the safest approach. Returning from `Decode` before the whole message is read just cries for issue (at least as soon as the reader state/seek position is advanced)
@cpuguy83 PTAL
I have a feeling this is happening here: https://github.com/moby/moby/blob/master/daemon/logger/local/read.go#L199

I do see you have a reader attached in your stack trace.
It will help if you can provide a heap dump.

You should be able to get it if you hit the docker API at `/debug/pprof/heap`.
Heap dump: [heap1615862444.out.gz](https://github.com/moby/moby/files/6145718/heap1615862444.out.gz)

Hopefully this is helpful. It's a bit hard to time but I tried to get it shortly before a crash.

Thanks for taking a look!
Thanks for grabbing that.

This doesn't look complete. Maybe you can get the svg version?
The `pprof` (https://github.com/google/pprof) command (or if you have `go` on the machine already `go tool pprof`) can generate svg (depends on graphviz).
Also just to note, it'd probably be fine to grab it regardless of if it was just before it crashes, just so long as its had some time to exercise the logger.
Seeing the same error here. Is there any updates on this issue? 
I have this in my backlog for the next week or so to grab additional `pprof` output (but don't let me stop you from doing so! :wink:).
@cpuguy83 here's what I managed to come up with on another couple attempts:

1. [heap](https://github.com/moby/moby/files/6368379/heap1.gz), alloc_space:
![alloc_space1](https://user-images.githubusercontent.com/1084619/115936194-a19b6c80-a462-11eb-934b-f43c26e6913c.png)
2. [heap](https://github.com/moby/moby/files/6368394/heap2.gz), alloc_space:
![alloc_space2](https://user-images.githubusercontent.com/1084619/115936302-dc9da000-a462-11eb-9d6a-66fe22fe6eb2.png)

I'm still not sure I'm capturing it right so if this still doesn't get you what you need I can try further. This is reproducible with this [`Vagrantfile`](https://github.com/moby/moby/files/6368400/Vagrantfile.txt).






Hey, experiencing the same issue here, looking for a fix because we need logs from these critical containers stored locally and shipped.
I am seeing the same stack trace with the splunk logging driver. I think that all (?) loggers nowadays support dual logging since it was backported to the CE edition.
FWIW I do not think "high" log output is neccessary. I managed to trigger this in a nomad setup where nomad (I think) runs log on every container and the amount of logs for a day are few MB (in this testcase).
@cpuguy83 This is what I was able to gather:

alloc space:
![alloc_space](https://user-images.githubusercontent.com/81547/120757155-73ed1d00-c510-11eb-93e8-acb2b32aeb8c.png)
alloc objects:
![alloc_objects](https://user-images.githubusercontent.com/81547/120757145-72bbf000-c510-11eb-9949-cde5198e5592.png)
in use:
![in_use](https://user-images.githubusercontent.com/81547/120757158-751e4a00-c510-11eb-8475-c42e8166adfe.png)
inuse objects:
![inuse_objects](https://user-images.githubusercontent.com/81547/120757159-75b6e080-c510-11eb-9fee-8d7fe4588df0.png)

funnily enough the memory usage "jumped" at one point rather quickly without any log messages in the journal or anything interesting happening:
![graph](https://user-images.githubusercontent.com/81547/120757289-a72fac00-c510-11eb-9df2-33aac6e73729.png)

I just noted that the rendered PNGs are not really readable, I have uploaded the SVGs to https://apolloner.eu/~apollo13/moby/
I wonder if `d.buf` in my case is set to a few gb at some point and never resized down (capacity wise) -- would this be possible? That said I do not see why or how I could have such long log messages?
After another jump in memory I stopped all containers (and log tailers). Memory usage did not decrease, restarting docker did ;)
At work we're running docker containers managed by Hashicorp Nomad, and use the `fluentd` log-driver in our docker daemon config. We've had the same issue with dockerd's memory usage ballooning over time, but we found we could prevent this using the following daemon.json setting:

```
  "log-opts": {
    "cache-disabled": "true",
```

[This disables Docker's "dual-logging" feature](https://docs.docker.com/config/containers/logging/dual-logging/#disable-the-dual-logging-cache), which creates a local log cache for log drivers that don't support local reads. Although this fixes the memory usage issue, it breaks the `docker logs` and `nomad alloc logs` commands. We decided we were fine with this compromise, because we already backup logs to a local file using fluentbit.

Before we made this change, over the course of a few hours dockerd would climb to 3 GB memory usage. After making the change it uses a steady ~240 MB. Hope others find this useful.
@thaJeztah Is there anything the community can provide to move this along and maybe get a patch?
We recently deployed a container that logs a lot more than previously and have been battling unexplained out of memory-issues for dockerd.
We're using the syslog-driver, and "docker logs" isn't critical, but it's definitely nice to have, instead of grep'ing through the syslog for the right time and container
What is your Go version on `docker version`?

From Go 1.12 to Go 1.15, Go was using MADV_FREE to ask OS to reclaim memory. However it was not updating many userland-surfacing statistics (including RSS) and causing a lot of confusion. So in Go 1.16, the behavior has changed again to use MADV_DONTNEED instead.

https://github.com/golang/go/commit/05e6d28849293266028c0bc9e9b0f8d0da38a2e2

Note that moby/moby's Dockerfile is using Go 1.13.15 in 20.10.7.
Interesting, what affect would this have? Wrong pprofs and we'd need to regenerate them using a newer go version?

On Thu, Nov 18, 2021, at 19:54, Kazuyoshi Kato wrote:
> What is your Go version on `docker version`? From Go 1.12 to Go 1.15, 
> Go was using MADV_FREE to ask OS to reclaim memory. However it was not 
> updating many userland-surfacing statistics (including RSS) and causing 
> a lot of confusion. So in Go 1.16, the behavior has changed again to 
> use MADV_DONTNEED instead.
>
> Note that moby/moby's Dockerfile is using Go 1.13.15 in 20.10.7.
>
> —
> You are receiving this because you commented.
> Reply to this email directly, view it on GitHub 
> <https://github.com/moby/moby/issues/42125#issuecomment-973161788>, or 
> unsubscribe 
> <https://github.com/notifications/unsubscribe-auth/AAAT5C6NRYFAGIN4VS7HHODUMVDWRANCNFSM4Y2DSGKQ>.
> Triage notifications on the go with GitHub Mobile for iOS 
> <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> 
> or Android 
> <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

No. I think tools that are aware about Go runtime (such as pprof) is fine. However top and other general-purpose Linux commands may not report RSS and other stats correctly if your Go version is old.
Apparently msgLen below is sometimes getting pretty big, such as 71343681. Interestingly the byte sequence (4409e41) is actually appeared in the log file (in my case, /var/lib/docker/containers/09d9263ca4946e5543b0a0c979dd74c94dfc4cfc819204517eb310718d287b2c/local-logs/container.log).

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/local/read.go#L136-L146

It is happening after calling Reset() due to below.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/loggerutils/logfile.go#L666-L670

I think, Decode() is assuming that the current position of the file is the beginning of a record. But fileWatcher wouldn't guarantee such a thing.
> I think, Decode() is assuming that the current position of the file is the beginning of a record. But fileWatcher wouldn't guarantee such a thing.

Sorry. No. Decode is not assuming that the current position of the file is the beginning of a record. EOF errors from Decode is ignored like below.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/loggerutils/logfile.go#L706-L735

However allocating a buffer based on `binary.BigEndian.Uint32(d.buf[:read])` is still problematic and potentially kills dockerd due to `fatal error: runtime: out of memory`.
The value we are reading in this section you mentioned is literally the size of the record.

The biggest each log entry can be is 1MB.
Add the protobuf encoding and whatever metadata (timestamp, explicitly specified container labels).
These are not unbounded.
We could look at chunking the records somehow so they do not exceed some pre-determined buffer size.

I am surprised that you would see a buffer of 71MB and would be curious what the data in that file looks like.
I was doing `docker run --rm -d --log-driver local alpine cat /dev/urandom` as @dnrce suggested. So this would be too harsh and less realistic.

That being said, IIUC `d.buf[:read]` in Decode() could point literally anywhere in a protobuf-encoded log stream file. Since protobuf embeds UTF-8 strings as is, if a log message contains `abcd` (in UTF-8, `0x61 0x62 0x63 0x64`), is there a possibility of allocating 0x61626364 bytes -> 1633837924 bytes -> 1.6GB?
@kzys No we write the log stream as `<record len><record><record len>`, which makes it easy to read both backwards and forwards.
So what's happening there when we set the buffer like above is we are reading `<record len>`.
Those lengths have a fixed size.
I added Docker Engine a few extra logging and a panic condition like https://github.com/kzys/docker/commit/d4e2856281b8be448a19256f0d8912794ba36532.

By running `docker logs -f $(docker run --rm -d --log-driver local alpine cat /dev/urandom) > /dev/null`, it eventually hits `panic: too large 95e09737`. The byte sequence is appeared in the saved protobuf log file like below (highlighted by `{...}`).

```
0000cfa0  1d*00 00 01 65 0a 06 73  74 64 6f 75 74 10 eb ac  |....e..stdout...|
0000cfb0  f2 e4 e0 a5 c5 dc 16 1a  d0 02 63 ad 35 de 40 05  |..........c.5.@.|
0000cfc0  27 88 0e 13 c5 ce be a3  6e 6e d1 6b 44 76 cf a5  |'.......nn.kDv..|
0000cfd0  b5 76 b0 98 8f 2a 68 30  5f 2f 82 74 53 9e 41 90  |.v...*h0_/.tS.A.|
0000cfe0  c0 84 3c 12 9c c2 79 de  48 17 3e 4b 9d c9 a2 7b  |..<...y.H.>K...{|
0000cff0  7d 53 6b 5f 7f 4f 3a c0  f1 03 14 6a ca 0e 61 3b  |}Sk_.O:....j..a;|
0000d000 {95 e0 97 37}37 62 c3 94  c6 8c f4 05 db ac 89 6d  |...77b.........m|
0000d010  fb a9 23 de 7a a7 32 4e  ed 68 eb 56 86 27 9e 86  |..#.z.2N.h.V.'..|
0000d020  d8 1d 65 f2 c4 b1 35 88  a5 e5 34 bd 4a 51 2e 15  |..e...5...4.JQ..|
0000d030  74 cf 0f 16 f1 1c 68 59  2c 9c 2b 14 cd f6 35 26  |t.....hY,.+...5&|
0000d040  c4 85 6c 9e 9b 29 6f 08  c5 69 da 54 b4 86 46 0f  |..l..)o..i.T..F.|
0000d050  11 7e f3 67 0e 31 b6 c0  8a 1f 09 6f 18 9b b5 ac  |.~.g.1.....o....|
0000d060  56 72 f5 53 90 69 ca 2a  e7 f3 34 01 37 c1 9f b5  |Vr.S.i.*..4.7...|
0000d070  88 42 7d 97 9a e7 a3 13  56 93 65 c8 77 2c 95 a3  |.B}.....V.e.w,..|
0000d080  b8 da b2 03 0f 17 1f c7  0b 4f 19 f0 27 f1 98 51  |.........O..'..Q|
0000d090  84 7b 75 3d 04 ae d9 dd  f3 bc 14 e9 1e 0c 28 b5  |.{u=..........(.|
0000d0a0  72 63 32 f2 55 01 32 c5  1d 90 ec ca f0 0c 4f 70  |rc2.U.2.......Op|
0000d0b0  b8 e4 85 c1 f5 32 50 6d  65 3b 20 f0 50 39 88 75  |.....2Pme; .P9.u|
0000d0c0  c8 e5 2f 09 7a 8a 8b e2  15 6b 45 25 d8 7a 54 d3  |../.z....kE%.zT.|
0000d0d0  54 06 bc a8 48 bd 1b da  5c d1 50 08 f6 78 3f b9  |T...H...\.P..x?.|
0000d0e0  df 17 8c 89 69 1a a7 fe  f9 f6 09 29 a5 b7 63 40  |....i......)..c@|
0000d0f0  98 e4 d3 6f 25 25 97 00  cb c3 ad 31 f6 e5 ed a1  |...o%%.....1....|
0000d100  cc 48 4e bc 75 d4 ed 48  87 ec 00 00 01 65*00 00  |.HN.u..H.....e..|
0000d110  00 39 0a 06 73 74 64 6f  75 74 10 96 a9 f3 e4 e0  |.9..stdout......|

```

`00 00 01 65` and `00 00 00 39` (highlighted by `*`) are the record length headers. So seems Decode() is reading the middle of the record somehow.

[bad-7088503659120093909.log](https://github.com/moby/moby/files/7573350/bad-7088503659120093909.log)

Here is the logs around the panic.

```
Nov 19 23:07:05 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:05.375494976Z" level=info msg="handleRotate /var/lib/docker/containers/ef1973d73da5280e8f583e8b2208635f999be88d7d74
Nov 19 23:07:05 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:05.386052980Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536371120Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536415602Z" level=info msg=waitRead
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536432394Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.536441379Z" level=info msg=waitRead
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.551459454Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:06 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:06.552278411Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.047956265Z" level=info msg="handleRotate /var/lib/docker/containers/ef1973d73da5280e8f583e8b2208635f999be88d7d74
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048228185Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048443941Z" level=info msg="handleDecodeErr error reading log message length: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.048463066Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.050187068Z" level=info msg="handleDecodeErr could not decode log entry: EOF"
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: time="2021-11-19T23:07:07.050216651Z" level=info msg=waitRead
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: 0xc0009e63c0 make 2514523959+4=2514523963
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: panic: too large 95e09737
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: goroutine 235 [running]:
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/local.(*decoder).Decode(0xc0009e63c0, 0xc000b5f9e0, 0x0, 0x0)
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:149 +0x8f9
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/loggerutils.followLogs(0xc000010038, 0xc0000a53c0, 0xc000b5e180, 0xc000b5f9e0, 0x29a0370, 0xc0009e6
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/loggerutils/logfile.go:754 +0x502
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/loggerutils.(*LogFile).ReadLogs(0xc000fd3a40, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffffffffffff, 0x1
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/loggerutils/logfile.go:439 +0x4e8
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: github.com/docker/docker/daemon/logger/local.(*driver).readLogs(0xc0007ffbc0, 0xc0000a53c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffffffffff
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:35 +0xfa
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: created by github.com/docker/docker/daemon/logger/local.(*driver).ReadLogs
Nov 19 23:07:07 ip-172-31-8-18.us-west-2.compute.internal dockerd[4267]: /go/src/github.com/docker/docker/daemon/logger/local/read.go:24 +0x16f
```

When io.ReadFull() below doesn't read the bytes fully (returning ErrUnexpectedEOF), the next invocation of Decode() must not decode the record header.

https://github.com/moby/moby/blob/a17f288e65b45a9f4aa54526817ba83220a59709/daemon/logger/local/read.go#L179-L190
@kzys
> When io.ReadFull() below doesn't read the bytes fully (returning ErrUnexpectedEOF), the next invocation of Decode() must not decode the record header.

But when `ErrUnexpectedEOF` is returned from `readFull`, the `maxDecodeRetry` loop continues to read the bytes from the reader till the length is read fully, no?
The only thing I can imagine is that `readFull` returns `EOF` as shown in your log and now you have read half a msg length from the buffer? and now the next `Decode()` would be in the middle somewhere

EDIT:// EOF Should only be returned when no bytes are read at all, so this should not happen either.
Oh that could be it: What happens in `decodeLogEntry` might be the following. Assume there is a message length of 100.

 * The first `readFull` reads 50 bytes because there are only 50 bytes available and set `ErrUnexpectedEOF`
 * The second `readFull` reads 0 bytes and sets `EOF` because we are still at the end of the filestream.
 
Now we return with the error `EOF` and the next decode is in the middle of the stream and tries to read the message length again. Does that make any sense @kzys & @cpuguy83?
Working on the branch @kzys started I can get a stable behavior with the following diff:
```diff
diff --git a/daemon/logger/local/read.go b/daemon/logger/local/read.go
index 81c35902b9..1cbbaf4dc8 100644
--- a/daemon/logger/local/read.go
+++ b/daemon/logger/local/read.go
@@ -5,11 +5,11 @@ import (
        "encoding/binary"
        "io"
 
-       "fmt"
        "bytes"
+       "fmt"
+       "math/rand"
        "os"
        "os/exec"
-       "math/rand"
 
        "github.com/docker/docker/api/types/plugins/logdriver"
        "github.com/docker/docker/daemon/logger"
@@ -124,7 +124,7 @@ func (d *decoder) Decode() (*logger.Message, error) {
                var n int
                n, err = io.ReadFull(d.rdr, d.buf[read:encodeBinaryLen])
                if err != nil {
-                       if err != io.ErrUnexpectedEOF {
+                       if err != io.ErrUnexpectedEOF && err != io.EOF {
                                return nil, errors.Wrap(err, "error reading log message length")
                        }
                        read += n
@@ -189,13 +189,13 @@ func decodeLogEntry(rdr io.Reader, proto *logdriver.LogEntry, buf []byte, msgLen
        var (
                read int
                err  error
-               i int
+               i    int
        )
        for i = 0; i < maxDecodeRetry; i++ {
                var n int
                n, err = io.ReadFull(rdr, buf[read:msgLen+encodeBinaryLen])
                if err != nil {
-                       if err != io.ErrUnexpectedEOF {
+                       if err != io.ErrUnexpectedEOF && err != io.EOF {
                                return nil, errors.Wrap(err, "could not decode log entry")
                        }
                        read += n
```

This seems to suggest that much hunch was correct. I can still imagine edge cases with this patch, but I am running the provided example for minutes without a crash now.
Found an even better panic condition than the one @kzys added:
```diff
diff --git a/daemon/logger/local/read.go b/daemon/logger/local/read.go
index b28aa90651..ab9d21c3c3 100644
--- a/daemon/logger/local/read.go
+++ b/daemon/logger/local/read.go
@@ -3,6 +3,7 @@ package local
 import (
        "context"
        "encoding/binary"
+       "fmt"
        "io"
 
        "bytes"
@@ -121,6 +122,9 @@ func (d *decoder) Decode() (*logger.Message, error) {
                n, err = io.ReadFull(d.rdr, d.buf[read:encodeBinaryLen])
                if err != nil {
                        if err != io.ErrUnexpectedEOF {
+                               if err == io.EOF && read > 0 {
+                                       panic(fmt.Sprintf("(readMsgLen) Failing with EOF, read %d of %d", read, encodeBinaryLen))
+                               }
                                return nil, errors.Wrap(err, "error reading log message length")
                        }
                        read += n
@@ -181,6 +185,9 @@ func decodeLogEntry(rdr io.Reader, proto *logdriver.LogEntry, buf []byte, msgLen
                n, err = io.ReadFull(rdr, buf[read:msgLen+encodeBinaryLen])
                if err != nil {
                        if err != io.ErrUnexpectedEOF {
+                               if err == io.EOF {
+                                       panic(fmt.Sprintf("(decodeLogEntry) Failing with EOF, read %d of %d", read, msgLen+encodeBinaryLen))
+                               }
                                return nil, errors.Wrap(err, "could not decode log entry")
                        }
                        read += n
```

It exactly illustrates the problem, when reading the msgLen:
 * `EOF` when reading the length of the message is fatal when we already read more than one byte from the stream. The reason is that this would advance the stream and the next call to `Decode()` would read a new length from a starting position incremented by one
and when reading the message itself:
 * `EOF` here is not valid even if read=0 because the length has already been read so if we exit here the next `Decode` will try to start reading a new msg length from somewhere inside the message. 
This is kind of a strange condition.

> If an EOF happens after reading some but not all the bytes, ReadFull returns ErrUnexpectedEOF

But we write the whole record in one shot.
So maybe the cursor is getting off somewhere else, or perhaps some weird fs behavior.

I think we should likely use ReadAt, track the cursor ourselves, and only advance after the cursor after a successful proto unmarshal.
> I think we should likely use ReadAt, track the cursor ourselves, and only advance after the cursor after a successful proto unmarshal.

Yes, something like this is certainly the safest approach. Returning from `Decode` before the whole message is read just cries for issue (at least as soon as the reader state/seek position is advanced)

Fix patch:
diff --git a/daemon/logger/local/read.go b/daemon/logger/local/read.go
index b28aa90651bc3..d517995cff58d 100644
--- a/daemon/logger/local/read.go
+++ b/daemon/logger/local/read.go
@@ -1,12 +1,12 @@
 package local
 
 import (
+	"bytes"
 	"context"
 	"encoding/binary"
+	"fmt"
 	"io"
 
-	"bytes"
-
 	"github.com/docker/docker/api/types/plugins/logdriver"
 	"github.com/docker/docker/daemon/logger"
 	"github.com/docker/docker/daemon/logger/loggerutils"
@@ -14,6 +14,10 @@ import (
 	"github.com/pkg/errors"
 )
 
+// maxMsgLen is the maximum size of the logger.Message after serialization.
+// logger.defaultBufSize caps the size of Line field.
+const maxMsgLen int = 1e6 // 1MB.
+
 func (d *driver) ReadLogs(config logger.ReadConfig) *logger.LogWatcher {
 	logWatcher := logger.NewLogWatcher()
 
@@ -99,7 +103,35 @@ func getTailReader(ctx context.Context, r loggerutils.SizeReaderAt, req int) (io
 type decoder struct {
 	rdr   io.Reader
 	proto *logdriver.LogEntry
-	buf   []byte
+	// buf keeps bytes from rdr.
+	buf []byte
+	// offset is the position in buf.
+	// If offset > 0, buf[offset:] has bytes which are read but haven't used.
+	offset int
+	// nextMsgLen is the length of the next log message.
+	// If nextMsgLen = 0, a new value must be read from rdr.
+	nextMsgLen int
+}
+
+func (d *decoder) readRecord(size int) error {
+	var err error
+	for i := 0; i < maxDecodeRetry; i++ {
+		var n int
+		n, err = io.ReadFull(d.rdr, d.buf[d.offset:size])
+		d.offset += n
+		if err != nil {
+			if err != io.ErrUnexpectedEOF {
+				return err
+			}
+			continue
+		}
+		break
+	}
+	if err != nil {
+		return err
+	}
+	d.offset = 0
+	return nil
 }
 
 func (d *decoder) Decode() (*logger.Message, error) {
@@ -111,44 +143,35 @@ func (d *decoder) Decode() (*logger.Message, error) {
 	if d.buf == nil {
 		d.buf = make([]byte, initialBufSize)
 	}
-	var (
-		read int
-		err  error
-	)
 
-	for i := 0; i < maxDecodeRetry; i++ {
-		var n int
-		n, err = io.ReadFull(d.rdr, d.buf[read:encodeBinaryLen])
+	if d.nextMsgLen == 0 {
+		msgLen, err := d.decodeSizeHeader()
 		if err != nil {
-			if err != io.ErrUnexpectedEOF {
-				return nil, errors.Wrap(err, "error reading log message length")
-			}
-			read += n
-			continue
+			return nil, err
 		}
-		read += n
-		break
-	}
-	if err != nil {
-		return nil, errors.Wrapf(err, "could not read log message length: read: %d, expected: %d", read, encodeBinaryLen)
-	}
 
-	msgLen := int(binary.BigEndian.Uint32(d.buf[:read]))
+		if msgLen > maxMsgLen {
+			return nil, fmt.Errorf("log message is too large (%d > %d)", msgLen, maxMsgLen)
+		}
 
-	if len(d.buf) < msgLen+encodeBinaryLen {
-		d.buf = make([]byte, msgLen+encodeBinaryLen)
-	} else {
-		if msgLen <= initialBufSize {
+		if len(d.buf) < msgLen+encodeBinaryLen {
+			d.buf = make([]byte, msgLen+encodeBinaryLen)
+		} else if msgLen <= initialBufSize {
 			d.buf = d.buf[:initialBufSize]
 		} else {
 			d.buf = d.buf[:msgLen+encodeBinaryLen]
 		}
-	}
 
-	return decodeLogEntry(d.rdr, d.proto, d.buf, msgLen)
+		d.nextMsgLen = msgLen
+	}
+	return d.decodeLogEntry()
 }
 
 func (d *decoder) Reset(rdr io.Reader) {
+	if d.rdr == rdr {
+		return
+	}
+
 	d.rdr = rdr
 	if d.proto != nil {
 		resetProto(d.proto)
@@ -156,6 +179,8 @@ func (d *decoder) Reset(rdr io.Reader) {
 	if d.buf != nil {
 		d.buf = d.buf[:initialBufSize]
 	}
+	d.offset = 0
+	d.nextMsgLen = 0
 }
 
 func (d *decoder) Close() {
@@ -171,34 +196,32 @@ func decodeFunc(rdr io.Reader) loggerutils.Decoder {
 	return &decoder{rdr: rdr}
 }
 
-func decodeLogEntry(rdr io.Reader, proto *logdriver.LogEntry, buf []byte, msgLen int) (*logger.Message, error) {
-	var (
-		read int
-		err  error
-	)
-	for i := 0; i < maxDecodeRetry; i++ {
-		var n int
-		n, err = io.ReadFull(rdr, buf[read:msgLen+encodeBinaryLen])
-		if err != nil {
-			if err != io.ErrUnexpectedEOF {
-				return nil, errors.Wrap(err, "could not decode log entry")
-			}
-			read += n
-			continue
-		}
-		break
+func (d *decoder) decodeSizeHeader() (int, error) {
+	err := d.readRecord(encodeBinaryLen)
+	if err != nil {
+		return 0, errors.Wrap(err, "could not read a size header")
 	}
+
+	msgLen := int(binary.BigEndian.Uint32(d.buf[:encodeBinaryLen]))
+	return msgLen, nil
+}
+
+func (d *decoder) decodeLogEntry() (*logger.Message, error) {
+	msgLen := d.nextMsgLen
+	err := d.readRecord(msgLen + encodeBinaryLen)
 	if err != nil {
-		return nil, errors.Wrapf(err, "could not decode entry: read %d, expected: %d", read, msgLen)
+		return nil, errors.Wrapf(err, "could not read a log entry (size=%d+%d)", msgLen, encodeBinaryLen)
 	}
+	d.nextMsgLen = 0
 
-	if err := proto.Unmarshal(buf[:msgLen]); err != nil {
-		return nil, errors.Wrap(err, "error unmarshalling log entry")
+	if err := d.proto.Unmarshal(d.buf[:msgLen]); err != nil {
+		return nil, errors.Wrapf(err, "error unmarshalling log entry (size=%d)", msgLen)
 	}
 
-	msg := protoToMessage(proto)
+	msg := protoToMessage(d.proto)
 	if msg.PLogMetaData == nil {
 		msg.Line = append(msg.Line, '\n')
 	}
+
 	return msg, nil
 }
diff --git a/daemon/logger/loggerutils/follow.go b/daemon/logger/loggerutils/follow.go
new file mode 100644
index 0000000000000..755a483d7a10a
--- /dev/null
+++ b/daemon/logger/loggerutils/follow.go
@@ -0,0 +1,211 @@
+package loggerutils // import "github.com/docker/docker/daemon/logger/loggerutils"
+
+import (
+	"io"
+	"os"
+	"time"
+
+	"github.com/docker/docker/daemon/logger"
+	"github.com/docker/docker/pkg/filenotify"
+	"github.com/fsnotify/fsnotify"
+	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
+)
+
+var errRetry = errors.New("retry")
+var errDone = errors.New("done")
+
+type follow struct {
+	file                      *os.File
+	dec                       Decoder
+	fileWatcher               filenotify.FileWatcher
+	logWatcher                *logger.LogWatcher
+	notifyRotate, notifyEvict chan interface{}
+	oldSize                   int64
+	retries                   int
+}
+
+func (fl *follow) handleRotate() error {
+	name := fl.file.Name()
+
+	fl.file.Close()
+	fl.fileWatcher.Remove(name)
+
+	// retry when the file doesn't exist
+	var err error
+	for retries := 0; retries <= 5; retries++ {
+		f, err := open(name)
+		if err == nil || !os.IsNotExist(err) {
+			fl.file = f
+			break
+		}
+	}
+	if err != nil {
+		return err
+	}
+	if err := fl.fileWatcher.Add(name); err != nil {
+		return err
+	}
+	fl.dec.Reset(fl.file)
+	return nil
+}
+
+func (fl *follow) handleMustClose(evictErr error) {
+	fl.file.Close()
+	fl.dec.Close()
+	fl.logWatcher.Err <- errors.Wrap(evictErr, "log reader evicted due to errors")
+	logrus.WithField("file", fl.file.Name()).Error("Log reader notified that it must re-open log file, some log data may not be streamed to the client.")
+}
+
+func (fl *follow) waitRead() error {
+	select {
+	case e := <-fl.notifyEvict:
+		if e != nil {
+			err := e.(error)
+			fl.handleMustClose(err)
+		}
+		return errDone
+	case e := <-fl.fileWatcher.Events():
+		switch e.Op {
+		case fsnotify.Write:
+			fl.dec.Reset(fl.file)
+			return nil
+		case fsnotify.Rename, fsnotify.Remove:
+			select {
+			case <-fl.notifyRotate:
+			case <-fl.logWatcher.WatchProducerGone():
+				return errDone
+			case <-fl.logWatcher.WatchConsumerGone():
+				return errDone
+			}
+			if err := fl.handleRotate(); err != nil {
+				return err
+			}
+			return nil
+		}
+		return errRetry
+	case err := <-fl.fileWatcher.Errors():
+		logrus.Debugf("logger got error watching file: %v", err)
+		// Something happened, let's try and stay alive and create a new watcher
+		if fl.retries <= 5 {
+			fl.fileWatcher.Close()
+			fl.fileWatcher, err = watchFile(fl.file.Name())
+			if err != nil {
+				return err
+			}
+			fl.retries++
+			return errRetry
+		}
+		return err
+	case <-fl.logWatcher.WatchProducerGone():
+		return errDone
+	case <-fl.logWatcher.WatchConsumerGone():
+		return errDone
+	}
+}
+
+func (fl *follow) handleDecodeErr(err error) error {
+	if !errors.Is(err, io.EOF) {
+		return err
+	}
+
+	// Handle special case (#39235): max-file=1 and file was truncated
+	st, stErr := fl.file.Stat()
+	if stErr == nil {
+		size := st.Size()
+		defer func() { fl.oldSize = size }()
+		if size < fl.oldSize { // truncated
+			fl.file.Seek(0, 0)
+			fl.dec.Reset(fl.file)
+			return nil
+		}
+	} else {
+		logrus.WithError(stErr).Warn("logger: stat error")
+	}
+
+	for {
+		err := fl.waitRead()
+		if err == nil {
+			break
+		}
+		if err == errRetry {
+			continue
+		}
+		return err
+	}
+	return nil
+}
+
+func (fl *follow) mainLoop(since, until time.Time) {
+	for {
+		select {
+		case err := <-fl.notifyEvict:
+			if err != nil {
+				fl.handleMustClose(err.(error))
+			}
+			return
+		default:
+		}
+		msg, err := fl.dec.Decode()
+		if err != nil {
+			if err := fl.handleDecodeErr(err); err != nil {
+				if err == errDone {
+					return
+				}
+				// we got an unrecoverable error, so return
+				fl.logWatcher.Err <- err
+				return
+			}
+			// ready to try again
+			continue
+		}
+
+		fl.retries = 0 // reset retries since we've succeeded
+		if !since.IsZero() && msg.Timestamp.Before(since) {
+			continue
+		}
+		if !until.IsZero() && msg.Timestamp.After(until) {
+			return
+		}
+		// send the message, unless the consumer is gone
+		select {
+		case e := <-fl.notifyEvict:
+			if e != nil {
+				err := e.(error)
+				logrus.WithError(err).Debug("Reader evicted while sending log message")
+				fl.logWatcher.Err <- err
+			}
+			return
+		case fl.logWatcher.Msg <- msg:
+		case <-fl.logWatcher.WatchConsumerGone():
+			return
+		}
+	}
+}
+
+func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate, notifyEvict chan interface{}, dec Decoder, since, until time.Time) {
+	dec.Reset(f)
+
+	name := f.Name()
+	fileWatcher, err := watchFile(name)
+	if err != nil {
+		logWatcher.Err <- err
+		return
+	}
+	defer func() {
+		f.Close()
+		dec.Close()
+		fileWatcher.Close()
+	}()
+
+	fl := &follow{
+		file:         f,
+		oldSize:      -1,
+		logWatcher:   logWatcher,
+		fileWatcher:  fileWatcher,
+		notifyRotate: notifyRotate,
+		notifyEvict:  notifyEvict,
+		dec:          dec,
+	}
+	fl.mainLoop(since, until)
+}
diff --git a/daemon/logger/loggerutils/logfile.go b/daemon/logger/loggerutils/logfile.go
index 6b42d9dd30d72..d4f3f5e149b5b 100644
--- a/daemon/logger/loggerutils/logfile.go
+++ b/daemon/logger/loggerutils/logfile.go
@@ -17,7 +17,6 @@ import (
 	"github.com/docker/docker/pkg/filenotify"
 	"github.com/docker/docker/pkg/pools"
 	"github.com/docker/docker/pkg/pubsub"
-	"github.com/fsnotify/fsnotify"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 )
@@ -608,179 +607,6 @@ func tailFiles(files []SizeReaderAt, watcher *logger.LogWatcher, dec Decoder, ge
 	}
 }
 
-func followLogs(f *os.File, logWatcher *logger.LogWatcher, notifyRotate, notifyEvict chan interface{}, dec Decoder, since, until time.Time) {
-	dec.Reset(f)
-
-	name := f.Name()
-	fileWatcher, err := watchFile(name)
-	if err != nil {
-		logWatcher.Err <- err
-		return
-	}
-	defer func() {
-		f.Close()
-		dec.Close()
-		fileWatcher.Close()
-	}()
-
-	var retries int
-	handleRotate := func() error {
-		f.Close()
-		fileWatcher.Remove(name)
-
-		// retry when the file doesn't exist
-		for retries := 0; retries <= 5; retries++ {
-			f, err = open(name)
-			if err == nil || !os.IsNotExist(err) {
-				break
-			}
-		}
-		if err != nil {
-			return err
-		}
-		if err := fileWatcher.Add(name); err != nil {
-			return err
-		}
-		dec.Reset(f)
-		return nil
-	}
-
-	errRetry := errors.New("retry")
-	errDone := errors.New("done")
-
-	handleMustClose := func(evictErr error) {
-		f.Close()
-		dec.Close()
-		logWatcher.Err <- errors.Wrap(err, "log reader evicted due to errors")
-		logrus.WithField("file", f.Name()).Error("Log reader notified that it must re-open log file, some log data may not be streamed to the client.")
-	}
-
-	waitRead := func() error {
-		select {
-		case e := <-notifyEvict:
-			if e != nil {
-				err := e.(error)
-				handleMustClose(err)
-			}
-			return errDone
-		case e := <-fileWatcher.Events():
-			switch e.Op {
-			case fsnotify.Write:
-				dec.Reset(f)
-				return nil
-			case fsnotify.Rename, fsnotify.Remove:
-				select {
-				case <-notifyRotate:
-				case <-logWatcher.WatchProducerGone():
-					return errDone
-				case <-logWatcher.WatchConsumerGone():
-					return errDone
-				}
-				if err := handleRotate(); err != nil {
-					return err
-				}
-				return nil
-			}
-			return errRetry
-		case err := <-fileWatcher.Errors():
-			logrus.Debugf("logger got error watching file: %v", err)
-			// Something happened, let's try and stay alive and create a new watcher
-			if retries <= 5 {
-				fileWatcher.Close()
-				fileWatcher, err = watchFile(name)
-				if err != nil {
-					return err
-				}
-				retries++
-				return errRetry
-			}
-			return err
-		case <-logWatcher.WatchProducerGone():
-			return errDone
-		case <-logWatcher.WatchConsumerGone():
-			return errDone
-		}
-	}
-
-	oldSize := int64(-1)
-	handleDecodeErr := func(err error) error {
-		if !errors.Is(err, io.EOF) {
-			return err
-		}
-
-		// Handle special case (#39235): max-file=1 and file was truncated
-		st, stErr := f.Stat()
-		if stErr == nil {
-			size := st.Size()
-			defer func() { oldSize = size }()
-			if size < oldSize { // truncated
-				f.Seek(0, 0)
-				return nil
-			}
-		} else {
-			logrus.WithError(stErr).Warn("logger: stat error")
-		}
-
-		for {
-			err := waitRead()
-			if err == nil {
-				break
-			}
-			if err == errRetry {
-				continue
-			}
-			return err
-		}
-		return nil
-	}
-
-	// main loop
-	for {
-		select {
-		case err := <-notifyEvict:
-			if err != nil {
-				handleMustClose(err.(error))
-			}
-			return
-		default:
-		}
-		msg, err := dec.Decode()
-		if err != nil {
-			if err := handleDecodeErr(err); err != nil {
-				if err == errDone {
-					return
-				}
-				// we got an unrecoverable error, so return
-				logWatcher.Err <- err
-				return
-			}
-			// ready to try again
-			continue
-		}
-
-		retries = 0 // reset retries since we've succeeded
-		if !since.IsZero() && msg.Timestamp.Before(since) {
-			continue
-		}
-		if !until.IsZero() && msg.Timestamp.After(until) {
-			return
-		}
-		// send the message, unless the consumer is gone
-		select {
-		case e := <-notifyEvict:
-			if e != nil {
-				err := e.(error)
-				logrus.WithError(err).Debug("Reader evicted while sending log message")
-				logWatcher.Err <- err
-			}
-			return
-		case logWatcher.Msg <- msg:
-		case <-logWatcher.WatchConsumerGone():
-			return
-		}
-	}
-}
-
 func watchFile(name string) (filenotify.FileWatcher, error) {
 	var fileWatcher filenotify.FileWatcher
 


Test patch:
diff --git a/daemon/logger/local/read_test.go b/daemon/logger/local/read_test.go
new file mode 100644
index 0000000000000..21d8603649a25
--- /dev/null
+++ b/daemon/logger/local/read_test.go
@@ -0,0 +1,52 @@
+package local
+
+import (
+	"io"
+	"io/ioutil"
+	"os"
+	"testing"
+
+	"github.com/docker/docker/daemon/logger"
+	"github.com/pkg/errors"
+	"gotest.tools/v3/assert"
+)
+
+func TestDecode(t *testing.T) {
+	marshal := makeMarshaller()
+
+	buf, err := marshal(&logger.Message{Line: []byte("hello")})
+	assert.NilError(t, err)
+
+	for i := 0; i < len(buf); i++ {
+		testDecode(t, buf, i)
+	}
+}
+
+func testDecode(t *testing.T, buf []byte, split int) {
+	fw, err := ioutil.TempFile("", t.Name())
+	assert.NilError(t, err)
+	defer os.Remove(fw.Name())
+
+	fr, err := os.Open(fw.Name())
+	assert.NilError(t, err)
+
+	d := &decoder{rdr: fr}
+
+	if split > 0 {
+		_, err = fw.Write(buf[0:split])
+		assert.NilError(t, err)
+
+		_, err = d.Decode()
+		assert.Assert(t, errors.Is(err, io.EOF))
+
+		_, err = fw.Write(buf[split:])
+		assert.NilError(t, err)
+	} else {
+		_, err = fw.Write(buf)
+		assert.NilError(t, err)
+	}
+
+	message, err := d.Decode()
+	assert.NilError(t, err)
+	assert.Equal(t, "hello\n", string(message.Line))
+}
diff --git a/daemon/logger/loggerutils/follow_test.go b/daemon/logger/loggerutils/follow_test.go
new file mode 100644
index 0000000000000..224cd192e9eb1
--- /dev/null
+++ b/daemon/logger/loggerutils/follow_test.go
@@ -0,0 +1,37 @@
+package loggerutils // import "github.com/docker/docker/daemon/logger/loggerutils"
+
+import (
+	"io"
+	"os"
+	"testing"
+
+	"gotest.tools/v3/assert"
+)
+
+func TestHandleDecoderErr(t *testing.T) {
+	f, err := os.CreateTemp("", t.Name())
+	assert.NilError(t, err)
+	defer os.Remove(f.Name())
+
+	_, err = f.Write([]byte("hello"))
+	assert.NilError(t, err)
+
+	pos, err := f.Seek(0, io.SeekCurrent)
+	assert.NilError(t, err)
+	assert.Assert(t, pos != 0)
+
+	dec := &testDecoder{}
+
+	// Simulate "turncate" case, where the file was bigger before.
+	fl := &follow{file: f, dec: dec, oldSize: 100}
+	err = fl.handleDecodeErr(io.EOF)
+	assert.NilError(t, err)
+
+	// handleDecodeErr seeks to zero.
+	pos, err = f.Seek(0, io.SeekCurrent)
+	assert.NilError(t, err)
+	assert.Equal(t, int64(0), pos)
+
+	// Reset is called.
+	assert.Equal(t, 1, dec.resetCount)
+}
diff --git a/daemon/logger/loggerutils/logfile_test.go b/daemon/logger/loggerutils/logfile_test.go
index af951c75f5051..7578b425d9494 100644
--- a/daemon/logger/loggerutils/logfile_test.go
+++ b/daemon/logger/loggerutils/logfile_test.go
@@ -23,8 +23,9 @@ import (
 )
 
 type testDecoder struct {
-	rdr     io.Reader
-	scanner *bufio.Scanner
+	rdr        io.Reader
+	scanner    *bufio.Scanner
+	resetCount int
 }
 
 func (d *testDecoder) Decode() (*logger.Message, error) {
@@ -41,6 +42,7 @@ func (d *testDecoder) Decode() (*logger.Message, error) {
 func (d *testDecoder) Reset(rdr io.Reader) {
 	d.rdr = rdr
 	d.scanner = bufio.NewScanner(rdr)
+	d.resetCount++
 }
 
 func (d *testDecoder) Close() {