Inconsistent logging output to the fluentd driver.

[tevjef]

Description

Docker does not produce logs for some or all containers after a fluentd logging container restarts.

Steps to reproduce the issue:

• Start a fluentd container with a config that writes all container output to stdout.

docker run -d -p 24224:24224 --name fluentd -v /test.conf:/fluentd/etc/test.conf -e FLUENTD_CONF=test.conf fluent/fluentd:latest

test.conf

<source>
  @type forward
</source>

<match docker.**>
  @type stdout
</match>

• Start some containers that produce logs to the fluentd logging driver, tag them to better identify them.

docker run -d --log-driver=fluentd --name ping-1 --log-opt tag="docker.ping-1" debian ping google.com

docker run -d --log-driver=fluentd --name ping-2 --log-opt tag="docker.ping-1" debian ping google.com

docker run -d --log-driver=fluentd --name ping-3 --log-opt tag="docker.ping-1" debian ping google.com

• Confirm logs were produced for all 3 containers with docker logs -f fluentd
• Restart the fluentd container and (after the buffer has been flushed) observe logs may be missing for some or all containers.
• If not, start a new container ping-4 and restart the fluentd container.

I've noticed that the last container started is always logged. Or rather, the last that were created before restarting the fluentd container. I've only noticed this issue since updating to 1.12.2 from 1.12.1. I would like to test this again on 1.12.1 but I don't know to get it.

I could not replicate this issue in 1.12.1

After a diff of the 1.12.1 and 1.12.2 releases, I noticed a change was made here in the fluentd dependancy.

Output of docker version:

$ docker version
Client:
 Version:      1.12.2
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   bb80604
 Built:        Tue Oct 11 17:43:41 2016
 OS/Arch:      linux/amd64

Server:
 Version:      1.12.2
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   bb80604
 Built:        Tue Oct 11 17:43:41 2016
 OS/Arch:      linux/amd64

Output of docker info:

$ docker info
Containers: 16
 Running: 4
 Paused: 0
 Stopped: 12
Images: 10
Server Version: 1.12.2
Storage Driver: devicemapper
 Pool Name: docker-8:0-243900-pool
 Pool Blocksize: 65.54 kB
 Base Device Size: 10.74 GB
 Backing Filesystem: ext4
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data Space Used: 1.165 GB
 Data Space Total: 107.4 GB
 Data Space Available: 22.5 GB
 Metadata Space Used: 2.99 MB
 Metadata Space Total: 2.147 GB
 Metadata Space Available: 2.144 GB
 Thin Pool Minimum Free Space: 10.74 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: false
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Data loop file: /var/lib/docker/devicemapper/devicemapper/data
 WARNING: Usage of loopback devices is strongly discouraged for production use. Use `--storage-opt dm.thinpooldev` to specify a custom block storage device.
 Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata
 Library Version: 1.02.90 (2014-09-01)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: null host bridge overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Security Options:
Kernel Version: 4.7.0-x86_64-linode72
Operating System: Debian GNU/Linux 8 (jessie)
OSType: linux
Architecture: x86_64
CPUs: 1
Total Memory: 1.951 GiB
Name: debian
ID: N7LH:HSR5:ZJTQ:VPTF:MTZD:2TL2:5XWS:3X32:CIRI:T77A:GI56:7PJE
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Username: tevjef
Registry: https://index.docker.io/v1/
WARNING: No swap limit support

Linode
uname -a
Linux debian 4.7.0-x86_64-linode72 #1 SMP Thu Aug 4 15:15:18 EDT 2016 x86_64 GNU/Linux

[tevjef]

Video reproducing the steps: https://www.youtube.com/watch?v=7CdffAAaA9o

[thaJeztah]

Change was merged in #26740

ping @tagomoris any ideas ?

[tagomoris]

I'm in vacation and almost apart from internet.
Will be back here some days later.

2016年10月15日土曜日、Sebastiaan van Stijnnotifications@github.comさんは書きました:

Change was merged in #26740 #26740

ping @tagomoris https://github.com/tagomoris any ideas ?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#27374 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAOE_m8xd_KXU4g3GEi3PlO07Z_N1KReks5q0C7KgaJpZM4KWt00
.

田籠 聡 (TAGOMORI Satoshi)
Mail: tagomoris@gmail.com

[thaJeztah]

no worries, thanks @tagomoris, enjoy your vacation!

[tagomoris]

I reproduced this issue in my development container with these commands:

# for fluentd
docker run -d -p 24224:24224 --name fluentd -v $PWD/test.conf:/fluentd/etc/test.conf -e FLUENTD_CONF=test.conf fluent/fluentd:latest

# for client containers
docker run -d --log-driver=fluentd --name ping-1 --log-opt tag="docker.ping-1" -- debian perl -e '$|=1; while(sleep 1){ print "yay\n"; }'
docker run -d --log-driver=fluentd --name ping-2 --log-opt tag="docker.ping-2" -- debian perl -e '$|=1; while(sleep 1){ print "yay\n"; }'
docker run -d --log-driver=fluentd --name ping-3 --log-opt tag="docker.ping-3" -- debian perl -e '$|=1; while(sleep 1){ print "yay\n"; }'

I ran 3 containers, and 1 container failed to reconnect to fluentd node after restart.
I'm still investigating for more details.

[tagomoris]

I identified the root cause and created a patch to fix it. I will create a pull-request for docker after merging it into fluent-logger-golang:master.
fluent/fluent-logger-golang#39

[thaJeztah]

Thanks for the quick turnaround @tagomoris

[LK4D4]

@tevjef Can you try to verify with master? Thanks!

[tevjef]

LGTM. Can't wait for 1.12.3!

$ ./docker version
Client:
 Version:      1.13.0-dev
 API version:  1.25
 Go version:   go1.7.1
 Git commit:   9f30c28
 Built:        Wed Oct 19 18:08:01 2016
 OS/Arch:      linux/amd64

Server:
 Version:      1.13.0-dev
 API version:  1.25
 Go version:   go1.7.1
 Git commit:   9f30c28
 Built:        Wed Oct 19 18:08:01 2016
 OS/Arch:      linux/amd64