Volume driver plugin receives Mount requests with identical IDs when doing docker container cp on a running container

[kolayne]

Description

When a container is running and a volume is mounted with a volume driver plugin, running docker container cp results in the plugin receiving Mount requests with duplicate IDs (as well as the corresponding Unmount requests)

Reproduce

1. Compile and run with sufficient permissions the following dummy driver

   dummy_driver.go

   package main
   
   import (
       "errors"
       "os"
       "log"
   
       "github.com/docker/go-plugins-helpers/volume"
   )
   
   type Driver struct {}
   
   const FAKE_MOUNTPOINT = "/tmp/FAKE_MNTPT"
   
   func (d *Driver) Create(request *volume.CreateRequest) error {
       log.Printf("Request Create: Name=%s Options=%s", request.Name, request.Options)
       return nil
   }
   
   func (d *Driver) List() (*volume.ListResponse, error) {
       log.Print("Request List")
       return &volume.ListResponse{[]*volume.Volume{&volume.Volume{Name: "foo", Mountpoint: FAKE_MOUNTPOINT}}}, nil
   }
   
   func (d *Driver) Get(request *volume.GetRequest) (*volume.GetResponse, error) {
       log.Printf("Request Get: Name=%s", request.Name)
       if request.Name == "foo" {
   	    return &volume.GetResponse{Volume: &volume.Volume{Name: "foo", Mountpoint: FAKE_MOUNTPOINT}}, nil
       } else {
   	    return nil, errors.New("no such volume")
       }
   }
   
   func (d *Driver) Remove(request *volume.RemoveRequest) error {
       log.Printf("Request Remove: Name=%s", request.Name)
       return nil
   }
   
   func (d *Driver) Path(request *volume.PathRequest) (*volume.PathResponse, error) {
       log.Printf("Request Path: Name=%s", request.Name)
       return &volume.PathResponse{Mountpoint: FAKE_MOUNTPOINT}, nil
   }
   
   func (d *Driver) Mount(request *volume.MountRequest) (*volume.MountResponse, error) {
       log.Printf("Request Mount: ID=%s, Name=%s", request.ID, request.Name)
       return &volume.MountResponse{Mountpoint: FAKE_MOUNTPOINT}, nil
   }
   
   func (d *Driver) Unmount(request *volume.UnmountRequest) error {
       log.Printf("Request Unmount: ID=%s, Name=%s", request.ID, request.Name)
       return nil
   }
   
   func (d *Driver) Capabilities() *volume.CapabilitiesResponse {
       log.Print("Request Capabilities")
       return &volume.CapabilitiesResponse{Capabilities: volume.Capability{Scope: "volume"}}
   }
   
   
   func main() {
       _ = os.Mkdir("/tmp/FAKE_MNTPT", 0o777)
       handler := volume.NewHandler(&Driver{})
       handler.ServeUnix("/run/docker/plugins/dummy.sock", 0)
   }

2. docker run --rm -d -v foo:/foo --name my-alpine alpine:latest sleep 120

3. docker cp my-alpine:/bin/sh /tmp/

Expected behavior

The plugin should have received either one pair of Mount-Unmount requests or two pairs (as in Mount - Mount-Unmount - Unmount) requests with two distinct IDs.

docker version

Client:
 Version:           26.1.4
 API version:       1.45
 Go version:        go1.22.3
 Git commit:        5650f9b102
 Built:             Thu Jun  6 18:42:55 2024
 OS/Arch:           linux/amd64
 Context:           default

Server:
 Engine:
  Version:          dev
  API version:      1.46 (minimum version 1.24)
  Go version:       go1.22.4
  Git commit:       4fec999c1182face1fd9d2c25a5d6c0167603a77-unsupported
  Built:            Wed Jun 12 15:26:40 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.18
  GitCommit:        ae71819c4f5e67bb4d5ae76a6b735f29cc25774e.m
 runc:
  Version:          1.1.12
  GitCommit:        
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Version:    26.1.4
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  0.14.1
    Path:     /usr/lib/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  2.27.1
    Path:     /usr/lib/docker/cli-plugins/docker-compose

Server:
 Containers: 1
  Running: 0
  Paused: 0
  Stopped: 1
 Images: 5
 Server Version: dev
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: true
  Native Overlay Diff: false
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: dummy local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 Runtimes: runc io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: ae71819c4f5e67bb4d5ae76a6b735f29cc25774e.m
 runc version: 
 init version: de40ad0
 Security Options:
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.9.3-arch1-1
 Operating System: Arch Linux
 OSType: linux
 Architecture: x86_64
 CPUs: 12
 Total Memory: 15.46GiB
 Name: KoLin
 ID: e8ca7750-f29c-485a-87c6-4dcfc78e87c8
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 24
  Goroutines: 42
  System Time: 2024-06-12T19:18:04.714464534+03:00
  EventsListeners: 0
 Username: kolay0ne
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional Info

No response

[thaJeztah]

I see you're running a build from master (4fec999); is this a regression, and did this work correctly with previously released versions?

[kolayne]

No, that's a side effect of my debugging attempt. Just checked with the released version:

docker version

Client:
 Version:           26.1.4
 API version:       1.45
 Go version:        go1.22.3
 Git commit:        5650f9b102
 Built:             Thu Jun  6 18:42:55 2024
 OS/Arch:           linux/amd64
 Context:           default

Server:
 Engine:
  Version:          26.1.4
  API version:      1.45 (minimum version 1.24)
  Go version:       go1.22.3
  Git commit:       de5c9cf0b9
  Built:            Thu Jun  6 18:42:55 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.7.18
  GitCommit:        ae71819c4f5e67bb4d5ae76a6b735f29cc25774e.m
 runc:
  Version:          1.1.12
  GitCommit:        
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

docker info

Client:
 Version:    26.1.4
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  0.14.1
    Path:     /usr/lib/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  2.27.1
    Path:     /usr/lib/docker/cli-plugins/docker-compose

Server:
 Containers: 2
  Running: 1
  Paused: 0
  Stopped: 1
 Images: 5
 Server Version: 26.1.4
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Using metacopy: true
  Native Overlay Diff: false
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 2
 Plugins:
  Volume: dummy local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: ae71819c4f5e67bb4d5ae76a6b735f29cc25774e.m
 runc version: 
 init version: de40ad0
 Security Options:
  seccomp
   Profile: builtin
  cgroupns
 Kernel Version: 6.9.3-arch1-1
 Operating System: Arch Linux
 OSType: linux
 Architecture: x86_64
 CPUs: 12
 Total Memory: 15.46GiB
 Name: KoLin
 ID: e8ca7750-f29c-485a-87c6-4dcfc78e87c8
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Username: kolay0ne
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

[kolayne]

Current state

I was trying to analyze the issue. Here is the call stack from the volumeDriverProxy.Mount method when it's the second mount (the one for docker container cp):

Full call stack

goroutine 364 [running]:
runtime/debug.Stack()
	/usr/local/go/src/runtime/debug/stack.go:24 +0x5e
runtime/debug.PrintStack()
	/usr/local/go/src/runtime/debug/stack.go:16 +0x13
github.com/docker/docker/volume/drivers.(*volumeDriverProxy).Mount(0xc00048a610, {0xc000e783c8, 0x3}, {0xc000f279c0, 0x40})
	/go/src/github.com/docker/docker/volume/drivers/proxy.go:131 +0xcb
github.com/docker/docker/volume/drivers.(*volumeAdapter).Mount(0xc000e7b0a0, {0xc000f279c0?, 0xc000966508?})
	/go/src/github.com/docker/docker/volume/drivers/adapter.go:153 +0x42
github.com/docker/docker/volume/service.(*VolumesService).Mount(0x0?, {0xd1e458?, 0x3de2e00?}, 0xc000966690?, {0xc000f279c0, 0x40})
	/go/src/github.com/docker/docker/volume/service/service.go:122 +0x108
github.com/docker/docker/daemon.(*volumeWrapper).Mount(0x0?, {0xc000f279c0?, 0x203dabe?})
	/go/src/github.com/docker/docker/daemon/volumes.go:301 +0x3c
github.com/docker/docker/volume/mounts.(*MountPoint).Setup(0xc0003148c0, {0xd1e458?, 0x3de2e00}, {0x0?, 0x0?}, {0x10000d1e490?, 0x725eb9fc0f20?, {0x0?, 0xc000966860?}}, 0xc000966910)
	/go/src/github.com/docker/docker/volume/mounts/mounts.go:177 +0x18d
github.com/docker/docker/daemon.(*Daemon).setupMounts(0xc00081b900, {0xd1e458?, 0x3de2e00}, 0xc00066e500)
	/go/src/github.com/docker/docker/daemon/volumes_unix.go:66 +0x490
github.com/docker/docker/daemon.(*Daemon).openContainerFS(0xc00081b900, 0xc00066e500)
	/go/src/github.com/docker/docker/daemon/containerfs_linux.go:69 +0xe5
github.com/docker/docker/daemon.(*Daemon).containerArchivePath(0xc00081b900?, 0xc00066e500, {0xc000c97bb0, 0x7})
	/go/src/github.com/docker/docker/daemon/archive_unix.go:51 +0xf6
github.com/docker/docker/daemon.(*Daemon).ContainerArchivePath(0xc0009f3800?, {0xc001006886, 0x9}, {0xc000c97bb0, 0x7})
	/go/src/github.com/docker/docker/daemon/archive.go:39 +0x5c
github.com/docker/docker/api/server/router/container.(*containerRouter).getContainersArchive(0xc000b74740, {0x9193e2?, 0x13?}, {0xd152b0, 0xc00090dec0}, 0x9193e2?, 0xc000bf84e0?)
	/go/src/github.com/docker/docker/api/server/router/container/copy.go:75 +0x8e
github.com/docker/docker/api/server/middleware.(*ExperimentalMiddleware).WrapHandler.ExperimentalMiddleware.WrapHandler.func1({0xd1e5e0, 0xc000bf86c0}, {0xd152b0?, 0xc00090dec0?}, 0x3854e0?, 0xc00074f9e0?)
	/go/src/github.com/docker/docker/api/server/middleware/experimental.go:26 +0xb4
github.com/docker/docker/api/server/middleware.(*VersionMiddleware).WrapHandler.VersionMiddleware.WrapHandler.func1({0xd1e5e0, 0xc000bf8690}, {0xd152b0, 0xc00090dec0}, 0x40?, 0x40?)
	/go/src/github.com/docker/docker/api/server/middleware/version.go:84 +0x2ae
github.com/docker/docker/pkg/authorization.(*Middleware).WrapHandler.func1({0xd1e5e0, 0xc000bf8690}, {0xd152b0?, 0xc00090dec0?}, 0xc0009f3800, 0xc00074f960?)
	/go/src/github.com/docker/docker/pkg/authorization/middleware.go:59 +0x683
github.com/docker/docker/api/server.(*Server).makeHTTPHandler.func1({0xd152b0, 0xc00090dec0}, 0xc0009f3700)
	/go/src/github.com/docker/docker/api/server/server.go:56 +0x1ce
net/http.HandlerFunc.ServeHTTP(0xd1e5e0?, {0xd152b0?, 0xc00090dec0?}, 0xce79f0?)
	/usr/local/go/src/net/http/server.go:2136 +0x29
go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*middleware).serveHTTP(0xc000834b00, {0xd0d050?, 0xc000a8e1c0}, 0xc0009f3500, {0xcf12a0, 0xc000bce648})
	/go/src/github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/handler.go:229 +0x1202
go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.NewMiddleware.func1.1({0xd0d050?, 0xc000a8e1c0?}, 0xce1201?)
	/go/src/github.com/docker/docker/vendor/go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/handler.go:81 +0x35
net/http.HandlerFunc.ServeHTTP(0xd1e5e0?, {0xd0d050?, 0xc000a8e1c0?}, 0xce1228?)
	/usr/local/go/src/net/http/server.go:2136 +0x29
net/http.HandlerFunc.ServeHTTP(0xc0009f3400?, {0xd0d050?, 0xc000a8e1c0?}, 0x725ebbd536d8?)
	/usr/local/go/src/net/http/server.go:2136 +0x29
github.com/gorilla/mux.(*Router).ServeHTTP(0xc000bde000, {0xd0d050, 0xc000a8e1c0}, 0xc0009f3300)
	/go/src/github.com/docker/docker/vendor/github.com/gorilla/mux/mux.go:212 +0x1c5
net/http.serverHandler.ServeHTTP({0xc000bd8f00?}, {0xd0d050?, 0xc000a8e1c0?}, 0x6?)
	/usr/local/go/src/net/http/server.go:2938 +0x8e
net/http.(*conn).serve(0xc000b4ca20, {0xd1e5e0, 0xc0003d2930})
	/usr/local/go/src/net/http/server.go:2009 +0x5f4
created by net/http.(*Server).Serve in goroutine 324
	/usr/local/go/src/net/http/server.go:3086 +0x5cb

So, Daemon.ContainerArchivePath calls some functions, they call Daemon.openContainerFS, it calls Daemon.setupMounts, and no one checks if things are already mounted or not (and volumes should already be mounted, unless the container is stopped, right?).

(for context: the only other function in the code base besides Daemon.openContainerFS that calls Daemon.setupMounts is Daemon.containerStart, which is called on container start, when, apparently, no volume can be mounted yet)

History

I tried going back with git blame, trying to find when the behavior was different (e.g., someone function would check if volumes are mounted already, or something like that). Skipping refactoring commits, so far I got to 3a49765, which was in 2015, 9 years ago! This seems like a long time, and it makes me feel confused that people did not notice it earlier. @thaJeztah, can you confirm that the behavior I described in the issue is a bug?

[kolayne]

Judging by the commit message of 2bdc7fb, it is not a bug that volumes are mounted again, even when a container is already running.

Based on the following comments from volume/mounts/mounts.go:
mounts.MountPoint.ID:

moby/volume/mounts/mounts.go

Lines 62 to 64 in 11179de

	// ID is the opaque ID used to pass to the volume driver.
	// This should be set by calls to `Mount` and unset by calls to `Unmount`
	ID string `json:",omitempty"`

mounts.MountPoint.active:

moby/volume/mounts/mounts.go

Lines 75 to 78 in 11179de

	// Track usage of this mountpoint
	// Specifically needed for containers which are running and calls to `docker cp`
	// because both these actions require mounting the volumes.
	active int

, it seems like the authors intended that mounts of a container are reused in operations like docker cp. However, this results in the behavior I described above, which contradicts the documentation.

ID is a unique ID for the caller that is requesting the mount.

So! In my understanding, there should not even exist a structure that combines the active mounts counter and a mount ID. It seems that there are two different entities (both currently represented with volume.mounts.MountPoint objects): a logical mount (which comprises the source (a volume or a bind mount source path), the destination path, mount options, etc) and a technical mount (which is, roughly, an instance of a logical mount, instantiated at either container start or the openContainerFS-family operations, such as docker cp). A logical mount can have a count, which is the number of their instances; a technical mount should have a unique ID.

@thaJeztah, what do you think? Does it make sense?
Do you think there is a better name for these two kinds of entities? 😅