Repository: moby/moby (language: go)

Issue:
Multiple parallel `docker build` runs leak disk space that can't be recovered (with reproduction)
### Description

My CI machines, that run lots of `docker build` and `docker run` commands, often in parallel, keep running out of disk space.

I have figured out that when running multiple `docker build` commands in parallel, Docker loses track of some directories and files it creates under the `/var/lib/docker/overlay2` directory. This issue does not occur when the "build" commands are run in sequence (e.g. remove the trailing `&` in `repro.sh`).

After the build, despite running `docker system prune -af --volumes` to delete all build cache/artifacts and using `docker system df` to verify that there should be no disk space in use, the size of Docker's `overlay2` directory grows every time with no limit.


### Reproduce

I have published a shell script and Dockerfile that systematically reproduces this issue at https://github.com/intgr/bug-reports/tree/main/docker-build-disk-space-leak

Run the `./repro.sh` shell script multiple times and notice `overlay2` directory increasing in size.

The script needs to run `docker` commands and uses `sudo` to monitor the size of the `overlay2` directory.

It can be tested in the public playground https://labs.play-with-docker.com/ for example.

```shell
git clone https://github.com/intgr/bug-reports
cd bug-reports/docker-build-disk-space-leak
./repro.sh
```

## Example output when running the script

Notice that the ACTUAL number of items and disk space keeps growing every time when running `./repro.sh`, despite Docker reporting 0 bytes used.

```
$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.4M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 12              <-- !!!

$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.5M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 21              <-- !!!

$ ./repro.sh
BUILDING...
build done!

pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 7.6M	/var/lib/docker/overlay2            <-- !!!
ACTUAL number of items in /var/lib/docker/overlay2: 30              <-- !!!
```


### Expected behavior

When I delete all containers, all images, volumes, caches, *everything*, then Docker disk usage should return back near to what it uses after a clean installation. 

### docker version

```bash
Client:
 Version:           24.0.2
 API version:       1.43
 Go version:        go1.20.4
 Git commit:        cb74dfc
 Built:             Thu May 25 21:50:49 2023
 OS/Arch:           linux/amd64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          24.0.2
  API version:      1.43 (minimum version 1.12)
  Go version:       go1.20.4
  Git commit:       659604f
  Built:            Thu May 25 21:35:04 2023
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          v1.7.1
  GitCommit:        1677a17964311325ed1c31e2c0a3589ce6d5c30d
 runc:
  Version:          1.1.7
  GitCommit:        v1.1.7-0-g860f061
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
```


### docker info

```bash
Client:
 Version:    24.0.2
 Context:    default
 Debug Mode: false
 Plugins:
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.10.5
    Path:     /usr/local/libexec/docker/cli-plugins/docker-buildx
  compose: Docker Compose (Docker Inc.)
    Version:  v2.18.1
    Path:     /usr/local/libexec/docker/cli-plugins/docker-compose

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 0
 Server Version: 24.0.2
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Using metacopy: false
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 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 io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 1677a17964311325ed1c31e2c0a3589ce6d5c30d
 runc version: v1.1.7-0-g860f061
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: builtin
 Kernel Version: 4.4.0-210-generic
 Operating System: Alpine Linux v3.18 (containerized)
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 31.42GiB
 Name: node2
 ID: 39aba340-eb4a-4ddf-b7bf-f2a4d3a52192
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 27
  Goroutines: 43
  System Time: 2023-08-01T15:48:58.988555479Z
  EventsListeners: 0
 Experimental: true
 Insecure Registries:
  127.0.0.1
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

WARNING: API is accessible on http://0.0.0.0:2375 without encryption.
         Access to the remote API is equivalent to root access on the host. Refer
         to the 'Docker daemon attack surface' section in the documentation for
         more information: https://docs.docker.com/go/attack-surface/
WARNING: No swap limit support
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled
```


### Additional Info

_No response_


Discussion / hints:
There are lots of other bug reports about leaked disk space that may or may not be related:

* https://github.com/moby/moby/issues/21925
* https://github.com/moby/moby/issues/31628
* https://github.com/moby/moby/issues/38848
* https://github.com/docker/for-linux/issues/1300
* https://github.com/docker/for-linux/issues/948
* https://github.com/docker/for-linux/issues/1423

Thanks for reporting; I'm indeed not sure if all would be directly related.

For some extra context; these builds are running with BuildKit enabled (so not the classic builder?)
> For some extra context; these builds are running with BuildKit enabled (so not the classic builder?)

Yes, using BuildKit.
I've confirmed this is the case. Reproduces in all recent Moby versions.

Does not reproduce with buildx+container driver.
As a workaround, I configured all affected machines to only run 1 CI job with no concurrency. Since then I have not experienced "leaking" disk space any more. A "docker system prune" cron job always cleans up everything.

I did play around with this one and noticed multiple of these in log:

```
DEBU[2023-08-21T10:40:11.613782880Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=9d17dfc87b325405 traceID=d628a28fb035fc265155e003304dedf9
DEBU[2023-08-21T10:40:11.613943255Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=a121d92e7b470196 traceID=fe0d8b72ec091c10a9cd0bbb2bd43dde
```

I tracked where this message comes from and did a dirty workaround with retry mechanism:

```patch
diff --git a/vendor/github.com/moby/buildkit/source/local/local.go b/vendor/github.com/moby/buildkit/source/local/local.go
index d2cd9d989c..f6a855d053 100644
--- a/vendor/github.com/moby/buildkit/source/local/local.go
+++ b/vendor/github.com/moby/buildkit/source/local/local.go
@@ -133,7 +133,13 @@ func (ls *localSourceHandler) snapshot(ctx context.Context, caller session.Calle
                return nil, err
        }
        for _, si := range sis {
-               if m, err := ls.cm.GetMutable(ctx, si.ID()); err == nil {
+               m, err := ls.cm.GetMutable(ctx, si.ID())
+               for err != nil && errors.Is(err, cache.ErrLocked) {
+                       m, err = ls.cm.GetMutable(ctx, si.ID())
+                       time.Sleep(time.Millisecond * 1)
+               }
+
+               if err == nil {
                        bklog.G(ctx).Debugf("reusing ref for local: %s", m.ID())
                        mutable = m
                        break
```


and it seems to resolve the issue. It's not a solution though because it seems to causes deadlock in subsequent `./repro.sh` executions (but first one always finishes and doesn't leak any space).


Maybe the cache created here is not properly cleaned up later?
https://github.com/moby/buildkit/blob/832fdb5039b73992ee7e883e1322972373aeb5c1/source/local/local.go#L145-L152

I'm not very familiar with buildkit code, but maybe this can point @tonistiigi in the right direction?

@vvoland No, this shouldn't be related. Destination for local being locked is expected in parallel requests as it makes sure that one build does not overwrite the context files for another. The strategy is to just use a new directory when this happens instead of sleeping until the older build completes and releases its references.
I debugged this and the reason data leaks seems to be in incorrect reference count in the code path https://github.com/moby/moby/blob/fa517bb4206090f6af39225f5f8473efe520c3af/builder/builder-next/adapters/snapshot/snapshot.go#L370 -> https://github.com/moby/moby/blob/fa517bb4206090f6af39225f5f8473efe520c3af/layer/layer_store.go#L438 where the referenceCount does not go to zero in moby layerstore. 

It's not entirely clear to me yet why this is the case or why parallel builds affect this but after switching to https://github.com/moby/moby/pull/45966 to make sure I don't make changes in old version the issue does not reproduce anymore and I can track the `referenceCount` going zero as expected.

So #45966 fixes this issue. If there is a desire to understand the case in other versions better I can look more into it. My best guess is that it is related to the namespace changes in v0.12.

cc @neersighted 
Could it be that buildkitd when building multiple layers in parallel that have common layers like in the repro from @intgr, layers will be rebuilt because of 

```
DEBU[2023-08-21T10:40:11.613782880Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=9d17dfc87b325405 traceID=d628a28fb035fc265155e003304dedf9
DEBU[2023-08-21T10:40:11.613943255Z] not reusing ref xj6szckuxiojacjhkjym8tbdg for local: xj6szckuxiojacjhkjym8tbdg is locked: locked  span="[internal] load build context" spanID=a121d92e7b470196 traceID=fe0d8b72ec091c10a9cd0bbb2bd43dde
```

which are then not reference counted and thus leaking storage?

I am asking because I am experiencing the issue that common layers get rebuilt "randomly", even though everything is cached using registry and seeing a lot of `not reusing ref XX for local: XX`.

@tonistiigi When common layers are locked, is it supposed to just rebuild that layer instead of waiting for it to get unlocked?
> When common layers are locked, is it supposed to just rebuild that layer instead of waiting for it to get unlocked?

Yes. Also this is not a layer but a destination directory for context upload. If you are debugging this issue then try https://github.com/moby/moby/pull/45966 per https://github.com/moby/moby/issues/46136#issuecomment-1687080031
@tonistiigi fix is part of buildkit v0.12, so will be in moby v25.0, correct? Or is there a fix that can be backported to v0.11 that you know of?
Only v0.12 afaik
I'm still seeing this exact issue with docker 25 / buildkit 0.12, using the repro script from the original post.

Docker thinks everything is pruned, but overlay2 keeps growing almost every time I run the script.  Only occurs if builds are run in parallel.


Docker version
```
$ docker --version
Docker version 25.0.3, build 4debf41
$ docker builder version
github.com/docker/buildx v0.12.1 30feaa1
```

Initial State:
```
docker system df
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

$ du -hs /var/lib/docker/overlay2
4.0K     /var/lib/docker/overlay2
```

After several runs of the script, with parallel disabled:
```
pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 8.0K    /var/lib/docker/overlay2
ACTUAL number of items in /var/lib/docker/overlay2: 1
```



After several runs of the script, with parallel enabled:
```
pruned everything. Docker THINKS this much disk space is in use:
TYPE            TOTAL     ACTIVE    SIZE      RECLAIMABLE
Images          0         0         0B        0B
Containers      0         0         0B        0B
Local Volumes   0         0         0B        0B
Build Cache     0         0         0B        0B

ACTUAL disk space used: 14M     /var/lib/docker/overlay2
ACTUAL number of items in /var/lib/docker/overlay2: 155
```


Not sure about etiquette here, if I'm supposed to open a new issue or just post to this one, but it doesn't seem like it is actually fixed in docker 25 / buildkit 0.12.


Fix patch:
diff --git a/builder/builder-next/adapters/snapshot/layer.go b/builder/builder-next/adapters/snapshot/layer.go
index ed13def16fdee..e7724d20102f5 100644
--- a/builder/builder-next/adapters/snapshot/layer.go
+++ b/builder/builder-next/adapters/snapshot/layer.go
@@ -22,6 +22,9 @@ func (s *snapshotter) GetDiffIDs(ctx context.Context, key string) ([]layer.DiffI
 }
 
 func (s *snapshotter) EnsureLayer(ctx context.Context, key string) ([]layer.DiffID, error) {
+	s.layerCreateLocker.Lock(key)
+	defer s.layerCreateLocker.Unlock(key)
+
 	diffIDs, err := s.GetDiffIDs(ctx, key)
 	if err != nil {
 		return nil, err
diff --git a/builder/builder-next/adapters/snapshot/snapshot.go b/builder/builder-next/adapters/snapshot/snapshot.go
index 656c79ec20bfd..8f8df8f06be16 100644
--- a/builder/builder-next/adapters/snapshot/snapshot.go
+++ b/builder/builder-next/adapters/snapshot/snapshot.go
@@ -16,6 +16,7 @@ import (
 	"github.com/docker/docker/pkg/idtools"
 	"github.com/moby/buildkit/identity"
 	"github.com/moby/buildkit/snapshot"
+	"github.com/moby/locker"
 	"github.com/opencontainers/go-digest"
 	"github.com/pkg/errors"
 	bolt "go.etcd.io/bbolt"
@@ -48,10 +49,11 @@ type checksumCalculator interface {
 type snapshotter struct {
 	opt Opt
 
-	refs map[string]layer.Layer
-	db   *bolt.DB
-	mu   sync.Mutex
-	reg  graphIDRegistrar
+	refs              map[string]layer.Layer
+	db                *bolt.DB
+	mu                sync.Mutex
+	reg               graphIDRegistrar
+	layerCreateLocker *locker.Locker
 }
 
 // NewSnapshotter creates a new snapshotter
@@ -68,10 +70,11 @@ func NewSnapshotter(opt Opt, prevLM leases.Manager) (snapshot.Snapshotter, lease
 	}
 
 	s := &snapshotter{
-		opt:  opt,
-		db:   db,
-		refs: map[string]layer.Layer{},
-		reg:  reg,
+		opt:               opt,
+		db:                db,
+		refs:              map[string]layer.Layer{},
+		reg:               reg,
+		layerCreateLocker: locker.New(),
 	}
 
 	lm := newLeaseManager(s, prevLM)


Test patch: