Issue in stdout logging from child process in node specific images only

[shaunwarman]

Description https://github.com/shaunwarman/docker-child-proc

I have a simple nodejs script that spawns a child process and runs ping google.com. If I run this locally outside of container it runs fine with expected stdout logging every second or so. Within the container it seems the child pid logs standard output maybe once a minute or so.

Steps to reproduce the issue: https://github.com/shaunwarman/docker-child-proc

Describe the results you received: Common ping output every second.

Describe the results you expected: stdout from child process is happening about once every minute.

Output of docker version:

Client:
 Version:      17.06.0-ce
 API version:  1.30
 Go version:   go1.8.3
 Git commit:   02c1d87
 Built:        Fri Jun 23 21:31:53 2017
 OS/Arch:      darwin/amd64

Server:
 Version:      17.06.0-ce
 API version:  1.30 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   02c1d87
 Built:        Fri Jun 23 21:51:55 2017
 OS/Arch:      linux/amd64
 Experimental: true
Output of docker info:

Containers: 5
 Running: 1
 Paused: 0
 Stopped: 4
Images: 181
Server Version: 17.06.0-ce
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 logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: cfb82a876ecc11b5ca0977d1733adbe58599088a
runc version: 2d41c047c83e09a6d61d464906feb2a2f3c52aa4
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.31-moby
Operating System: Alpine Linux v3.5
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 1.952GiB
Name: moby
ID: BIDK:ZIOT:7HVA:RVXM:R4BW:YZ5A:BN3T:W42W:YTCW:3ULS:CGM2:CWDD
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 25
 Goroutines: 39
 System Time: 2017-07-08T23:22:58.461423036Z
 EventsListeners: 1
Registry: https://index.docker.io/v1/
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

[shaunwarman]

Something seems up with pipe from child process. Seems to buffer completely.

FROM node:7

# strace -p 1
Process 1 attached
clock_gettime(CLOCK_MONOTONIC, {27232, 111901229}) = 0
epoll_wait(5, {{EPOLLIN, {u32=12, u64=12}}}, 1024, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {27249, 722996103}) = 0
read(12, "PING google.com (172.217.8.174):"..., 65536) = 4096
clock_gettime(CLOCK_MONOTONIC, {27249, 723143828}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723362668}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723393631}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723419700}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723532566}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723562630}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723588399}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723620961}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723744014}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723853284}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723882849}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723908818}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 723974840}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724003206}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724033670}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724065133}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724107782}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724290664}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724320429}) = 0
clock_gettime(CLOCK_MONOTONIC, {27249, 724345699}) = 0
mmap(0x1fdb29b00000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x1fdb29b00000
mprotect(0x1fdb29b03000, 4096, PROT_NONE) = 0
mmap(0x1fdb29b04000, 503808, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x1fdb29b04000
mprotect(0x1fdb29b7f000, 4096, PROT_NONE) = 0

FROM mhart/alpine-node:base-8

# strace -p 1
strace: Process 1 attached
clock_gettime(CLOCK_MONOTONIC, {tv_sec=27722, tv_nsec=229971466}) = 0
epoll_wait(5, [{EPOLLIN, {u32=12, u64=12}}], 1024, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {tv_sec=27722, tv_nsec=576268221}) = 0
read(12, "64 bytes from 172.217.1.46: seq="..., 65536) = 57
write(11, "{\"data\":\"{\\\"event\\\":\\\"log\\\",\\\"da"..., 52) = 52

[indutny]

Including my comments, FWIW: it appears that somehow the pipe between ping and node is not ready to be read until it is full. I have no idea why!