Growing nodejs stdout queue depends on logs string view

[3g0r]

Description

The write queue in stdout is constantly growing when printing multiline logs. But if one execute docker run with allocated pseudo-tty then queue wont grow - mem and cpu usage will be normal. But over time the process enter wait_w state.

ps l
F   UID   PID  PPID PRI  NI    VSZ   RSS WCHAN  STAT TTY        TIME COMMAND
4     0     1     0  20   0 876184 36816 wait_w Ssl+ pts/0      0:04 node index.

Steps to reproduce the issue

index.js

gist

const [exePath, scriptPath, lines, repeats, usageNewline] = process.argv;
const log = Array
  .apply(null, Array(parseInt(lines)))
  .map((v, i) => i)
  .join(usageNewline === '1' ? '\n' : '.') + '\n';

const main = () => {
  setTimeout(main, 0);
  for(let i = 0; i < repeats; i++) { 
    process.stdout.write(log);
  }
}

setImmediate(main);

Reference of script args

$1 - count of lines in log

$2 - number of synchronously write operation to stdout

$3 - lines concatenation method: 1 - concatenate through \n, other values - concatenate through .

Run container without leaks

docker run -d --name=test -v $(pwd)/index.js:/index.js node:8 node /index.js 100 30 0

Run container with leaks

docker run -d --name=test -v $(pwd)/index.js:/index.js node:8 node /index.js 100 30 1

Results valid for my 4xCore Intel(R) Core(TM) i5-5200U CPU @ 2.20GHz

value of args in examples may be have no effect for another CPU

Output of docker version:

Client:
 Version:	18.01.0-ce
 API version:	1.35
 Go version:	go1.9.2
 Git commit:	03596f5
 Built:	Wed Jan 10 20:09:13 2018
 OS/Arch:	linux/amd64
 Experimental:	false
 Orchestrator:	swarm

Server:
 Engine:
  Version:	18.01.0-ce
  API version:	1.35 (minimum version 1.12)
  Go version:	go1.9.2
  Git commit:	03596f5
  Built:	Wed Jan 10 20:07:43 2018
  OS/Arch:	linux/amd64
  Experimental:	false

Output of docker info:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 429
Server Version: 18.01.0-ce
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 495
 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: 89623f28b87a6004d4b785663257362d1658a729
runc version: b2567b37d7b75eb4cf325b77297b140ea686ce8f
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.10.0-42-generic
Operating System: Linux Mint 18.2
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 7.708GiB
Name: bathyscaphe
ID: H3PZ:AHOH:WMCM:APHF:PYN6:34JE:AWY4:W7MZ:ISXL:KP6M:NY4L:QZ4N
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
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

[chorrell]

Apologies for the delay in responding.

Has this been raise as an issue with Node.js core? It's not clear to me if this is a Node issue that just happens to manifest in docker or something else. What version of Node.js 8 was this happening on and does it happen under newer versions?

[3g0r]

Hello.

Yes, the problem did not dare to update the version of docker.

I think that this is due to the nodejs streams. Nodejs streaming flush to stdout. But i don’t reproduce that leak in shell without docker. I was run this test same in node: 11 image - leak.

Maybe there are no problems here - i don’t understand very well what is buffered streams in terminal, but it seems like a docker.

2,5 GHz Intel Core i7

Output of docker version:

Client: Docker Engine - Community
 Version:           18.09.0
 API version:       1.39
 Go version:        go1.10.4
 Git commit:        4d60db4
 Built:             Wed Nov  7 00:47:43 2018
 OS/Arch:           darwin/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          18.09.0
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.4
  Git commit:       4d60db4
  Built:            Wed Nov  7 00:55:00 2018
  OS/Arch:          linux/amd64
  Experimental:     true

Output of docker info:

Containers: 15
 Running: 0
 Paused: 0
 Stopped: 15
Images: 458
Server Version: 18.09.0
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
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: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 468a545b9edcd5932818eb9de8e72413e616e86e
runc version: 69663f0bd4b60df09991c08812a60108003fa340
init version: fec3683
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.125-linuxkit
Operating System: Docker for Mac
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 3.855GiB
Name: linuxkit-025000000001
ID: EYFR:KZGA:56UR:5RFU:JJFZ:TW5E:RNTY:Z54V:QPKG:Z4O3:XZAA:DQ3B
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 28
 Goroutines: 59
 System Time: 2018-12-10T20:49:38.7274633Z
 EventsListeners: 2
HTTP Proxy: gateway.docker.internal:3128
HTTPS Proxy: gateway.docker.internal:3129
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false
Product License: Community Engine