Possible race condition between RingLogger's Close() and run()
We are running Docker on AWS ECS with the fluentd log driver configured, and periodically notice the following panic:
github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent.(*Fluent).appendBuffer(0xc0043a11e0, 0xc0
084da1e0, 0xc0084da180, 0xc0084da1b0)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/vendor/github.com/fluent/fluent-
logger-golang/fluent/fluent.go:306 +0x4c
github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent.(*Fluent).postRawData(0xc0043a11e0, 0xc00
84da1e0, 0x1d, 0x1668656)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/vendor/github.com/fluent/fluent-
logger-golang/fluent/fluent.go:220 +0x3d
github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent.(*Fluent).EncodeAndPostData(0xc0043a11e0,
0xc00ab8fa80, 0x1d, 0x1668656, 0xed814becb, 0x0, 0x560000475460, 0xc0084da180, 0x98, 0xc003067a68)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/vendor/github.com/fluent/fluent-
logger-golang/fluent/fluent.go:210 +0x159
github.com/docker/docker/vendor/github.com/fluent/fluent-logger-golang/fluent.(*Fluent).PostWithTime(0xc0043a11e0, 0xc0
0ab8fa80, 0x1d, 0x1668656, 0xed814becb, 0x0, 0x56000047ab60, 0xc0084da150, 0x0, 0xc001770a80)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/vendor/github.com/fluent/fluent-
logger-golang/fluent/fluent.go:201 +0x753
github.com/docker/docker/daemon/logger/fluentd.(*fluentd).Log(0xc008573cc0, 0xc0001e4c40, 0x0, 0x0)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/daemon/logger/fluentd/fluentd.go
:177 +0x3cb
github.com/docker/docker/daemon/logger.(*RingLogger).run(0xc00d8e2a50)
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/daemon/logger/ring.go:119 +0x7d
created by github.com/docker/docker/daemon/logger.newRingLogger
/builddir/build/BUILD/docker-19.03.6ce-4.58.amzn1/src/github.com/docker/docker/daemon/logger/ring.go:43 +0x176
The panic arises from fluent-logger-golang when there is an attempt to log something after the logger has been closed.
This seems to be possible if the RingBuffer gets closed between ring.go:125 grabbing a message from the buffer and pushing it to the underlying logger a few lines later.
Steps to reproduce the issue:
don't have an easy reproduction, but we're getting about 4 instances of this per day in a moderately sized ECS fleet (50-100 EC2 instances running several hundred containers)
Describe the results you received:
see panic stacktrace above
Describe the results you expected:
smooth operation
Additional information you deem important (e.g. issue happens only occasionally):
n/a
Output of docker version:
Client:
Version: 19.03.6-ce
API version: 1.40
Go version: go1.13.4
Git commit: 369ce74
Built: Fri May 29 04:00:45 2020
OS/Arch: linux/amd64
Experimental: false
Server:
Engine:
Version: 19.03.6-ce
API version: 1.40 (minimum version 1.12)
Go version: go1.13.4
Git commit: 369ce74
Built: Fri May 29 04:02:31 2020
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.3.2
GitCommit: ff48f57fc83a8c44cf4ad5d672424a98ba37ded6
runc:
Version: 1.0.0-rc10
GitCommit: dc9208a3303feef5b3839f4323d9beb36df0a9dd
docker-init:
Version: 0.18.0
GitCommit: fec3683
Output of docker info:
Client:
Debug Mode: false
Server:
Containers: 1
Running: 1
Paused: 0
Stopped: 0
Images: 5
Server Version: 19.03.6-ce
Storage Driver: devicemapper
Pool Name: docker-docker--pool
Pool Blocksize: 524.3kB
Base Device Size: 10.74GB
Backing Filesystem: ext4
Udev Sync Supported: true
Data Space Used: 744MB
Data Space Total: 106.3GB
Data Space Available: 105.6GB
Metadata Space Used: 3.084MB
Metadata Space Total: 25.17MB
Metadata Space Available: 22.08MB
Thin Pool Minimum Free Space: 10.63GB
Deferred Removal Enabled: true
Deferred Deletion Enabled: true
Deferred Deleted Device Count: 0
Library Version: 1.02.135-RHEL7 (2016-11-16)
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: ff48f57fc83a8c44cf4ad5d672424a98ba37ded6
runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
init version: fec3683
Security Options:
seccomp
Profile: default
Kernel Version: 4.14.133-88.112.amzn1.x86_64
Operating System: Amazon Linux AMI 2018.03
OSType: linux
Architecture: x86_64
CPUs: 16
Total Memory: 30.41GiB
Name: ip-10-7-43-255
ID: EG5L:TJJG:VR2H:J7CP:WZ76:P2QS:PGWN:WEYP:SIRJ:A7ZM:5WIY:QSNN
Docker Root Dir: /var/lib/docker
Debug Mode: true
File Descriptors: 51
Goroutines: 74
System Time: 2021-04-24T00:13:59.352411722Z
EventsListeners: 1
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
WARNING: the devicemapper storage-driver is deprecated, and will be removed in a future release.
Additional environment details (AWS, VirtualBox, physical, etc.):
AWS ECS, with unmodified ECS-optimized Amazon Linux AMI (not Amazon Linux 2)
Possible race condition between RingLogger's Close() and run()
We are running Docker on AWS ECS with the fluentd log driver configured, and periodically notice the following panic:
The panic arises from
fluent-logger-golangwhen there is an attempt to log something after the logger has been closed.This seems to be possible if the RingBuffer gets closed between ring.go:125 grabbing a message from the buffer and pushing it to the underlying logger a few lines later.
Steps to reproduce the issue:
don't have an easy reproduction, but we're getting about 4 instances of this per day in a moderately sized ECS fleet (50-100 EC2 instances running several hundred containers)
Describe the results you received:
see panic stacktrace above
Describe the results you expected:
smooth operation
Additional information you deem important (e.g. issue happens only occasionally):
n/a
Output of
docker version:Output of
docker info:Additional environment details (AWS, VirtualBox, physical, etc.):
AWS ECS, with unmodified ECS-optimized Amazon Linux AMI (not Amazon Linux 2)