log without '\n' cause the docker-daemon's memory overload

Description of problem:

code here: https://github.com/docker/docker/blob/master/daemon/logger/copier.go#L47

if a container always print logs without `\n`, then docker will buffer the logs until it find the `\n`

this makes docker-daemon use up all the memory. 

I think the condition should be:  find a `\n` **or** the buffer reached `64k`(or smaller).  

How reproducible:

```
docker run -d --log-driver=syslog centos /bin/bash -c 'while true;do echo -n hello; done;'
```

Steps to Reproduce:
1. run the command above
2. `top` command to check the memory usage of docker, (wait a minute)
3. `docker stop xxxx` stop the container, memory usage will increased very high fastly during this step.
4. the docker-daemon crashed(if you waited enough minutes at step 2)

the debug log is:

```
Nov 18 07:20:13 node1 docker: time="2015-11-18T07:20:13.524208676Z" level=info msg="POST /v1.21/containers/elegant_morse/stop?t=10"
Nov 18 07:20:13 node1 docker: time="2015-11-18T07:20:13.524588079Z" level=debug msg="Sending 15 to 6e1b83ce397d5c35171c5e30a89d08376b7bf6a764a3661eab69aa0ae630e354"
Nov 18 07:20:23 node1 docker: time="2015-11-18T07:20:23.526866115Z" level=info msg="Container 6e1b83ce397d5c35171c5e30a89d08376b7bf6a764a3661eab69aa0ae630e354 failed to exit within 10 seconds of SIGTERM - using the force"
Nov 18 07:20:23 node1 docker: time="2015-11-18T07:20:23.526898079Z" level=debug msg="Sending 9 to 6e1b83ce397d5c35171c5e30a89d08376b7bf6a764a3661eab69aa0ae630e354"
Nov 18 07:21:00 node1 docker: fatal error: runtime: out of memory
Nov 18 07:21:01 node1 docker: runtime stack:
Nov 18 07:21:01 node1 docker: runtime.throw(0x1cb4af7)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/panic.go:491 +0xad fp=0x7fff632be650 sp=0x7fff632be620
Nov 18 07:21:01 node1 docker: runtime.SysMap(0xc2a38b0000, 0x12290000, 0x4dcb00, 0x1ce2b18)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/mem_linux.c:149 +0x98 fp=0x7fff632be688 sp=0x7fff632be650
Nov 18 07:21:01 node1 docker: runtime.MHeap_SysAlloc(0x1ce8200, 0x12290000, 0x4cbf42)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/malloc.c:284 +0x124 fp=0x7fff632be6e0 sp=0x7fff632be688
Nov 18 07:21:01 node1 docker: MHeap_Grow(0x1ce8200, 0x9148, 0x0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/mheap.c:398 +0x58 fp=0x7fff632be720 sp=0x7fff632be6e0
Nov 18 07:21:01 node1 docker: MHeap_AllocSpanLocked(0x1ce8200, 0x9141, 0x4cfa20)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/mheap.c:298 +0x365 fp=0x7fff632be760 sp=0x7fff632be720
Nov 18 07:21:01 node1 docker: mheap_alloc(0x1ce8200, 0x9141, 0x100000000, 0xc208d42810)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/mheap.c:190 +0x121 fp=0x7fff632be788 sp=0x7fff632be760
Nov 18 07:21:01 node1 docker: runtime.MHeap_Alloc(0x1ce8200, 0x9141, 0x100000000, 0x108012001)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/mheap.c:240 +0x66 fp=0x7fff632be7c0 sp=0x7fff632be788
Nov 18 07:21:01 node1 docker: runtime.largeAlloc_m()
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/malloc.c:388 +0xce fp=0x7fff632be810 sp=0x7fff632be7c0
Nov 18 07:21:01 node1 docker: runtime.onM(0x1cd1eb0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/asm_amd64.s:257 +0x68 fp=0x7fff632be818 sp=0x7fff632be810
Nov 18 07:21:01 node1 docker: runtime.mstart()
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/proc.c:818 fp=0x7fff632be820 sp=0x7fff632be818
Nov 18 07:21:01 node1 docker: goroutine 213 [running]:
Nov 18 07:21:01 node1 docker: runtime.switchtoM()
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/asm_amd64.s:198 fp=0xc21b4cbb28 sp=0xc21b4cbb20
Nov 18 07:21:01 node1 docker: runtime.mallocgc(0x122801f7, 0x0, 0x3, 0x1)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/malloc.go:199 +0x9f3 fp=0xc21b4cbbd8 sp=0xc21b4cbb28
Nov 18 07:21:01 node1 docker: runtime.rawstring(0x122801f7, 0x0, 0x0, 0x0, 0x0, 0x0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/string.go:195 +0x93 fp=0xc21b4cbc08 sp=0xc21b4cbbd8
Nov 18 07:21:01 node1 docker: runtime.slicebytetostring(0xc29151e000, 0x122801f7, 0x12282000, 0x0, 0x0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/string.go:69 +0x4b fp=0xc21b4cbc98 sp=0xc21b4cbc08
Nov 18 07:21:01 node1 docker: fmt.Sprint(0xc21b4cbd78, 0x1, 0x1, 0x0, 0x0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/fmt/print.go:240 +0x8c fp=0xc21b4cbce0 sp=0xc21b4cbc98
Nov 18 07:21:01 node1 docker: github.com/Sirupsen/logrus.(*Entry).Error(0xc208a80300, 0xc21b4cbd78, 0x1, 0x1)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/Sirupsen/logrus/entry.go:135 +0x4e fp=0xc21b4cbd20 sp=0xc21b4cbce0
Nov 18 07:21:01 node1 docker: github.com/Sirupsen/logrus.(*Entry).Errorf(0xc208a80300, 0x14d2a90, 0x26, 0xc21b4cbf80, 0x3, 0x3)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/Sirupsen/logrus/entry.go:183 +0x144 fp=0xc21b4cbda8 sp=0xc21b4cbd20
Nov 18 07:21:01 node1 docker: github.com/Sirupsen/logrus.(*Logger).Errorf(0xc208036000, 0x14d2a90, 0x26, 0xc21b4cbf80, 0x3, 0x3)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/Sirupsen/logrus/logger.go:97 +0x104 fp=0xc21b4cbdf8 sp=0xc21b4cbda8
Nov 18 07:21:01 node1 docker: github.com/Sirupsen/logrus.Errorf(0x14d2a90, 0x26, 0xc21b4cbf80, 0x3, 0x3)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/vendor/src/github.com/Sirupsen/logrus/exported.go:137 +0x5c fp=0xc21b4cbe30 sp=0xc21b4cbdf8
Nov 18 07:21:01 node1 docker: github.com/docker/docker/daemon/logger.(*Copier).copySrc(0xc208b73dc0, 0x13864f0, 0x6, 0x7f332c1e0110, 0xc2089b0a20)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/daemon/logger/copier.go:54 +0x66d fp=0xc21b4cbfb8 sp=0xc21b4cbe30
Nov 18 07:21:01 node1 docker: runtime.goexit()
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/asm_amd64.s:2232 +0x1 fp=0xc21b4cbfc0 sp=0xc21b4cbfb8
Nov 18 07:21:01 node1 docker: created by github.com/docker/docker/daemon/logger.(*Copier).Run
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/daemon/logger/copier.go:38 +0x11c
Nov 18 07:21:01 node1 docker: goroutine 1 [chan receive, 5 minutes]:
Nov 18 07:21:01 node1 docker: runtime.gopark(0x4d2060, 0xc20800cbf8, 0x13ba0b0, 0xc)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/proc.go:130 +0x105 fp=0xc2088fd6f0 sp=0xc2088fd6c0
Nov 18 07:21:01 node1 docker: runtime.goparkunlock(0xc20800cbf8, 0x13ba0b0, 0xc)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/proc.go:136 +0x48 fp=0xc2088fd718 sp=0xc2088fd6f0
Nov 18 07:21:01 node1 docker: runtime.chanrecv(0xf445c0, 0xc20800cba0, 0xc2088fdab0, 0xc20800c901, 0xc208a70000)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/chan.go:410 +0x452 fp=0xc2088fd7b8 sp=0xc2088fd718
Nov 18 07:21:01 node1 docker: runtime.chanrecv1(0xf445c0, 0xc20800cba0, 0xc2088fdab0)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/chan.go:311 +0x2b fp=0xc2088fd7e8 sp=0xc2088fd7b8
Nov 18 07:21:01 node1 docker: main.(*DaemonCli).CmdDaemon(0xc2084f9260, 0xc20800a020, 0xc, 0xc, 0x0, 0x0)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/docker/daemon.go:308 +0x20a7 fp=0xc2088fdbf8 sp=0xc2088fd7e8
Nov 18 07:21:01 node1 docker: runtime.call64(0x1256f18, 0xc208508000, 0x2000000030)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/runtime/asm_amd64.s:403 +0x45 fp=0xc2088fdc40 sp=0xc2088fdbf8
Nov 18 07:21:01 node1 docker: reflect.callMethod(0xc2084dbf80, 0xc2088fdce8)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/reflect/value.go:605 +0x179 fp=0xc2088fdcd0 sp=0xc2088fdc40
Nov 18 07:21:01 node1 docker: reflect.methodValueCall(0xc20800a020, 0xc, 0xc, 0x1, 0xc2084dbf80, 0x0, 0x0, 0xc2084dbf80, 0x0, 0x4e297f, ...)
Nov 18 07:21:01 node1 docker: /usr/local/go/src/reflect/asm_amd64.s:29 +0x36 fp=0xc2088fdce8 sp=0xc2088fdcd0
Nov 18 07:21:01 node1 docker: github.com/docker/docker/cli.(*Cli).Run(0xc2084dbec0, 0xc20800a010, 0xd, 0xd, 0x0, 0x0)
Nov 18 07:21:01 node1 docker: /root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/cli/cli.go:89 +0x38e fp=0xc2088fddd0 sp=0xc2088fdce8
Nov 18 07:21:01 node1 docker: main.main()
....... too long
```

Actual Results: None
Expected Results: None
Additional info: None

```
$ docker version
Client:
 Version:      1.9.0
 API version:  1.21
 Go version:   go1.4.2
 Git commit:   76d6bc9
 Built:        Tue Nov  3 18:00:05 UTC 2015
 OS/Arch:      linux/amd64

Server:
 Version:      1.9.0
 API version:  1.21
 Go version:   go1.4.2
 Git commit:   76d6bc9
 Built:        Tue Nov  3 18:00:05 UTC 2015
 OS/Arch:      linux/amd64
```

```
$ docker info
Containers: 1
Images: 5
Server Version: 1.9.0
Storage Driver: devicemapper
 Pool Name: docker-253:1-137634752-pool
 Pool Blocksize: 65.54 kB
 Base Device Size: 107.4 GB
 Backing Filesystem: xfs
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data Space Used: 2.025 GB
 Data Space Total: 107.4 GB
 Data Space Available: 32.1 GB
 Metadata Space Used: 1.741 MB
 Metadata Space Total: 2.147 GB
 Metadata Space Available: 2.146 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: false
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Data loop file: /data/docker/devicemapper/devicemapper/data
 Metadata loop file: /data/docker/devicemapper/devicemapper/metadata
 Library Version: 1.02.93-RHEL7 (2015-01-28)
Execution Driver: native-0.2
Logging Driver: json-file
Kernel Version: 3.10.0-123.el7.x86_64
Operating System: CentOS Linux 7 (Core)
CPUs: 1
Total Memory: 1.798 GiB
Name: node1
ID: VIPU:YZB2:5AHS:JM36:XICF:Z4UR:UNNG:672F:GKRG:ZAZY:RIXY:PW34
Debug mode (server): true
 File Descriptors: 18
 Goroutines: 27
 System Time: 2015-11-18T07:23:41.09190251Z
 EventsListeners: 0
 Init SHA1: 3f858d7291df745ff796d46a3d02cc7ee67962b5
 Init Path: /usr/libexec/docker/dockerinit
 Docker Root Dir: /data/docker
```

```
$ uname -a
Linux node1 3.10.0-123.el7.x86_64 #1 SMP Mon Jun 30 12:09:22 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
```


Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log without '\n' cause the docker-daemon's memory overload #18057

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development