Skip to content

Docker daemon crash with panic due to concurrent map read and map write #28237

New issue
New issue
Closed
Closed
Docker daemon crash with panic due to concurrent map read and map write#28237
Labels
area/volumesVolumeskind/bugBugs are bugs. The cause may or may not be known at triage time so debugging may be needed.version/1.12
Milestone
1.13.0
@hubo1016

Description

@hubo1016
hubo1016
opened on Nov 10, 2016

BUG REPORT INFORMATION

Docker daemon occasionally crashes with panic, and report a "fatal error: concurrent map read and map write" in the log.

Steps to reproduce the issue:

I believe there is a race condition so there is not a determined way to reproduce this, but it may be reproduced by:
1.Create many (more than 100) containers in parallel, each with a volume (-v option) (driver=local)
2.Remove the containers in parallel together with the volumes (-v)

Describe the results you received:

Docker daemon crashes with the following logs:

Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.017079547+08:00" level=debug msg="devmapper: Unmount done"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.017117451+08:00" level=debug msg="devmapper: deactivateDevice(7fed5bc81bd59
27bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.017205184+08:00" level=debug msg="devicemapper: RemoveDeviceDeferred START(
docker-253:0-166724644-7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.026795020+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&
filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.027450951+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&
filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.027467289+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&
filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.027477995+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&
filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.027554115+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&
filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.027938561+08:00" level=debug msg="Calling GET /v1.24/containers/f06afd11c68
12e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.028539837+08:00" level=debug msg="Calling GET /v1.24/containers/f06afd11c68
12e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.028787949+08:00" level=debug msg="Calling GET /v1.24/containers/f06afd11c68
12e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.060133516+08:00" level=debug msg="devicemapper: RemoveDeviceDeferred END(do
cker-253:0-166724644-7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.060171548+08:00" level=debug msg="devmapper: deactivateDevice END(7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.060196836+08:00" level=debug msg="devmapper: UnmountDevice(hash=7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init) END"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.060214172+08:00" level=debug msg="devmapper: AddDevice(hash=7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251 basehash=7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.061304458+08:00" level=debug msg="devmapper: registerDevice(1198, 7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.061935064+08:00" level=debug msg="devmapper: AddDevice(hash=7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251 basehash=7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251-init) END"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.063258176+08:00" level=debug msg="Calling GET /v1.24/containers/f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.063545764+08:00" level=debug msg="Calling GET /v1.24/containers/f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.066736590+08:00" level=debug msg="Calling GET /containers/f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.069140753+08:00" level=debug msg="devmapper: activateDeviceIfNeeded(7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.069161478+08:00" level=debug msg="devmapper: cancelDeferredRemoval START(docker-253:0-166724644-7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.069204513+08:00" level=debug msg="devmapper: cancelDeferredRemoval END(docker-253:0-166724644-7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251)"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.071506926+08:00" level=debug msg="Calling POST /v1.22/containers/f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/attach?stderr=1&logs=0&stream=1&stdout=1"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.071778638+08:00" level=debug msg="attach: stderr: begin"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.071841077+08:00" level=debug msg="attach: stdout: begin"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.072211565+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.072571301+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.072581765+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.072772582+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&filters=%7B%22id%22%3A%7B%22f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a%22%3Atrue%7D%7D&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.074905610+08:00" level=debug msg="Calling GET /containers/f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a/json"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 systemd: Device dev-disk-by\x2duuid-1c31d7f1\x2dc62f\x2d48e6\x2dafa6\x2dedcee3caec5d.device appeared twice with different sysfs paths /sys/devices/virtual/block/dm-4 and /sys/devices/virtual/block/dm-82
Nov 10 15:17:41 kvm-yz-dev-073-003-009 kernel: XFS (dm-82): Mounting V4 Filesystem
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.131329748+08:00" level=debug msg="Calling GET /v1.24/containers/json?all=1&limit=0"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.161736507+08:00" level=debug msg="container mounted via layerStore: /data/docker/devicemapper/mnt/7fed5bc81bd5927bbd8fc3b52a79df8ee617c6bbd90d21b1b0fb2ca11b5a4251/rootfs"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 kernel: XFS (dm-82): Ending clean mount
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.167228015+08:00" level=debug msg="Calling POST /v1.22/networks/3f7dd36d3c9bf9af95701e47dd7ec4bbf8b4f9b13fac264400618db76d59af8a/disconnect"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.167271043+08:00" level=debug msg="form data: {\"container\":\"f06afd11c6812e580eef549002a883762ff5e22e80dbc06bba51d8b50fe7c41a\"}"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.170062945+08:00" level=debug msg="Getting volume reference for name: e48a63c812bed06e34284637d0240b36f6d9b52479eed60383d8c94d8cb5bb33"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.170093701+08:00" level=debug msg="Probing all drivers for volume with name: e48a63c812bed06e34284637d0240b36f6d9b52479eed60383d8c94d8cb5bb33"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.170171665+08:00" level=debug msg="Registering new volume reference: driver \"local\", name \"e48a63c812bed06e34284637d0240b36f6d9b52479eed60383d8c94d8cb5bb33\""
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.181402344+08:00" level=debug msg="Calling GET /v1.24/volumes"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.181918149+08:00" level=debug msg="Getting volume reference for name: 04f62f17845f5e21e5d279434388b55a4d0ea19921499c7ae4c0fda284000c15"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.181943934+08:00" level=debug msg="Probing all drivers for volume with name: 04f62f17845f5e21e5d279434388b55a4d0ea19921499c7ae4c0fda284000c15"
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: time="2016-11-10T15:17:41.182046537+08:00" level=debug msg="Registering new volume reference: driver \"local\", name \"04f62f17845f5e21e5d279434388b55a4d0ea19921499c7ae4c0fda284000c15\""
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: fatal error: concurrent map read and map write
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: goroutine 500420 [running]:
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: runtime.throw(0x1f42fa0, 0x21)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/runtime/panic.go:547 +0x90 fp=0xc8250fb5e0 sp=0xc8250fb5c8
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: runtime.mapaccess1_faststr(0x16e6f00, 0xc8202d5740, 0xc8207d22b5, 0x40, 0xc821542bd0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/runtime/hashmap_fast.go:202 +0x5b fp=0xc8250fb640 sp=0xc8250fb5e0
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: github.com/docker/docker/volume/store.(*VolumeStore).list.func1(0xc823ff7da0, 0xc8202d5770, 0x7f6f5b9380c0, 0xc8201308c0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/volume/store/store.go:185 +0x381 fp=0xc8250fb7a0 sp=0xc8250fb640
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: runtime.goexit()
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8250fb7a8 sp=0xc8250fb7a0
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: created by github.com/docker/docker/volume/store.(*VolumeStore).list
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /root/rpmbuild/BUILD/docker-engine/.gopath/src/github.com/docker/docker/volume/store/store.go:189 +0x233
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: goroutine 1 [chan receive, 4580 minutes]:
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: main.(*DaemonCli).start(0xc820411560, 0x0, 0x0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /root/rpmbuild/BUILD/docker-engine/cmd/dockerd/daemon.go:308 +0x2274
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: main.main()
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /root/rpmbuild/BUILD/docker-engine/cmd/dockerd/docker.go:68 +0x491
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: goroutine 17 [syscall, 4581 minutes, locked to thread]:
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: runtime.goexit()
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: goroutine 6 [syscall, 4561 minutes]:
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: os/signal.signal_recv(0x7f6f5b91c190)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/runtime/sigqueue.go:116 +0x132
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: os/signal.loop()
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/os/signal/signal_unix.go:22 +0x18
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: created by os/signal.init.1
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/os/signal/signal_unix.go:28 +0x37
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: goroutine 14 [syscall, 4581 minutes]:
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: syscall.Syscall6(0x3d, 0x104ea, 0xc82005addc, 0x0, 0xc8200c50e0, 0x0, 0x0, 0x4465c1, 0x4465c1, 0xc820001bb8)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: syscall.wait4(0x104ea, 0xc82005addc, 0x0, 0xc8200c50e0, 0x90, 0x0, 0x0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/syscall/zsyscall_linux_amd64.go:172 +0x7f
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: syscall.Wait4(0x104ea, 0xc82005ae24, 0x0, 0xc8200c50e0, 0x41a243, 0x0, 0x0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/syscall/syscall_linux.go:256 +0x55
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: os.(*Process).wait(0xc820428c20, 0xc82000c0c0, 0x0, 0x0)
Nov 10 15:17:41 kvm-yz-dev-073-003-009 dockerd: /usr/local/go/src/os/exec_unix.go:22 +0x105
...

Describe the results you expected:

All process done without crash

Additional information you deem important (e.g. issue happens only occasionally):

issue happens only occasionally

Output of docker version:

Client:
 Version:      1.12.1
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   23cf638
 Built:
 OS/Arch:      linux/amd64
Server:
 Version:      1.12.1
 API version:  1.24
 Go version:   go1.6.3
 Git commit:   23cf638
 Built:
 OS/Arch:      linux/amd64

Output of docker info:

Containers: 110
 Running: 103
 Paused: 0
 Stopped: 7
Images: 99
Server Version: 1.12.1
Storage Driver: devicemapper
 Pool Name: docker-thinpool
 Pool Blocksize: 524.3 kB
 Base Device Size: 10.74 GB
 Backing Filesystem: xfs
 Data file:
 Metadata file:
 Data Space Used: 148.6 GB
 Data Space Total: 1.1 TB
 Data Space Available: 950.9 GB
 Metadata Space Used: 30.46 MB
 Metadata Space Total: 10.74 GB
 Metadata Space Available: 10.71 GB
 Thin Pool Minimum Free Space: 110 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: true
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Library Version: 1.02.107-RHEL7 (2016-06-09)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: null host overlay vlcp bridge
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Security Options: seccomp
Kernel Version: 3.10.0-327.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 48
Total Memory: 251.6 GiB
Name: kvm-yz-dev-073-003-009
ID: WOZR:LE5T:PPII:LGRJ:VOEB:UBGT:OFGG:ZMEQ:TEYW:3A3H:HHI2:UNU4
Docker Root Dir: /data/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 967
 Goroutines: 1512
 System Time: 2016-11-10T19:07:41.132487639+08:00
 EventsListeners: 30
Registry: https://index.docker.io/v1/
WARNING: bridge-nf-call-ip6tables is disabled
Cluster Store: zk://100.73.3.8:2181,100.73.3.9:2181,100.73.3.7:2181
Cluster Advertise: 100.73.3.9:2375
Insecure Registries:
 jdocker.me
 127.0.0.0/8

Additional environment details (AWS, VirtualBox, physical, etc.):
physical. We are using docker swarm (swarm standalone, not swarmkit) to manage the cluster.

It seems to be the same type of issue of #27486 The map used in (*VolumeStore).list.func1
in volume/store/store.go:

	for _, vd := range drivers {
		go func(d volume.Driver) {
			vs, err := d.List()
			if err != nil {
				chVols <- vols{driverName: d.Name(), err: &OpErr{Err: err, Name: d.Name(), Op: "list"}}
				return
			}
			for i, v := range vs {
				vs[i] = volumeWrapper{v, s.labels[v.Name()], d.Scope(), s.options[v.Name()]}
			}

			chVols <- vols{vols: vs}
		}(vd)
	}

seems the s.labels and s.options does not have locks surrounded which leads to this issue.

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/volumesVolumeskind/bugBugs are bugs. The cause may or may not be known at triage time so debugging may be needed.version/1.12

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions