BuildKit caching ignores file content when (m)Time changes

[Gaibhne]

This is an old bug that was fixed in Docker proper years ago, but seems to have made it into BuildKit: if a file has changed timing, but identical content, the cache is still invalidated. This means the common practice of git clone x, build, will always invalidate all file based caching, which is generally not what one wants.

[FernandoMiguel]

wonder if this is related to #1099

[Gaibhne]

Test case:

00:00:01.983 + git clone ssh://git@xxx:10022/xxx.git client
00:00:02.503 + stat client/package.json
00:00:02.510   Datei: „client/package.json“
00:00:02.510   Größe: 3824      	Blöcke: 8          EA Block: 4096   reguläre Datei
00:00:02.510 Gerät: fd11h/64785d	Inode: 35316393    Verknüpfungen: 1
00:00:02.510 Zugriff: (0644/-rw-r--r--)  Uid: (  997/ jenkins)   Gid: (  994/ jenkins)
00:00:02.510 Kontext: system_u:object_r:var_lib_t:s0
00:00:02.510 Zugriff    : 2019-08-01 12:16:46.018715497 +0200
00:00:02.510 Modifiziert: 2019-08-01 12:16:46.018715497 +0200
00:00:02.510 Geändert   : 2019-08-01 12:16:46.018715497 +0200
00:00:02.510  Geburt    : -
00:00:02.510 + sha256sum client/package.json
00:00:02.512 e0d8fc3a896ada5cf765eea0b3e292a80da17ea344ac8be0044858bf7c2831ff  client/package.json
00:00:02.512 + stat client/package-lock.json
00:00:02.520   Datei: „client/package-lock.json“
00:00:02.520   Größe: 494883    	Blöcke: 968        EA Block: 4096   reguläre Datei
00:00:02.520 Gerät: fd11h/64785d	Inode: 35316392    Verknüpfungen: 1
00:00:02.520 Zugriff: (0644/-rw-r--r--)  Uid: (  997/ jenkins)   Gid: (  994/ jenkins)
00:00:02.520 Kontext: system_u:object_r:var_lib_t:s0
00:00:02.520 Zugriff    : 2019-08-01 12:16:46.016715535 +0200
00:00:02.520 Modifiziert: 2019-08-01 12:16:46.018715497 +0200
00:00:02.520 Geändert   : 2019-08-01 12:16:46.018715497 +0200
00:00:02.520  Geburt    : -
00:00:02.520 + sha256sum client/package-lock.json
00:00:02.523 1d4bd7559b2a6f1118ed0cab826af21374d8fe774a9f2278d618d91d362c1693  client/package-lock.json
00:00:02.524 + docker build --target xxx . -t xxx
00:00:02.744 #2 [internal] load build definition from Dockerfile
00:00:02.744 #2 transferring dockerfile: 1.38kB 0.0s done
00:00:03.194 #2 DONE 0.4s
00:00:03.194 
00:00:03.194 #1 [internal] load .dockerignore
00:00:03.194 #1 transferring context: 2B 0.0s done
00:00:03.345 #1 DONE 0.6s
00:00:03.459 
00:00:03.459 #3 [internal] load metadata for docker.io/library/node:lts
00:00:03.459 #3 DONE 0.0s
00:00:03.459 
00:00:03.459 #5 [xxx-base 1/2] FROM docker.io/library/node:lts
00:00:03.459 #5 DONE 0.0s
00:00:03.459 
00:00:03.459 #4 [internal] helper image for file operations
00:00:03.459 #4 DONE 0.0s
00:00:03.459 
00:00:03.459 #6 [internal] load build context
00:00:04.227 #6 transferring context: 13.76MB 0.7s done
00:00:04.376 #6 DONE 1.0s
00:00:04.526 
00:00:04.526 #5 [ccc-base 1/2] FROM docker.io/library/node:lts
00:00:04.526 #5 CACHED
00:00:04.526 
00:00:04.526 #4 [internal] helper image for file operations
00:00:04.526 #4 CACHED
00:00:04.526 
00:00:04.526 #7 [ccc-base 2/2] COPY client/package*.json /client/
00:00:05.854 #7 DONE 1.4s

Next run:

00:00:02.056 + git clone ssh://git@xxx:10022/xxx.git client
00:00:02.447 + stat client/package.json
00:00:02.449   Datei: „client/package.json“
00:00:02.449   Größe: 3824      	Blöcke: 8          EA Block: 4096   reguläre Datei
00:00:02.449 Gerät: fd11h/64785d	Inode: 67908790    Verknüpfungen: 1
00:00:02.449 Zugriff: (0644/-rw-r--r--)  Uid: (  997/ jenkins)   Gid: (  994/ jenkins)
00:00:02.449 Kontext: system_u:object_r:var_lib_t:s0
00:00:02.449 Zugriff    : 2019-08-01 12:17:14.293181669 +0200
00:00:02.449 Modifiziert: 2019-08-01 12:17:14.293181669 +0200
00:00:02.449 Geändert   : 2019-08-01 12:17:14.293181669 +0200
00:00:02.449  Geburt    : -
00:00:02.449 + sha256sum client/package.json
00:00:02.451 e0d8fc3a896ada5cf765eea0b3e292a80da17ea344ac8be0044858bf7c2831ff  client/package.json
00:00:02.451 + stat client/package-lock.json
00:00:02.453   Datei: „client/package-lock.json“
00:00:02.453   Größe: 494883    	Blöcke: 968        EA Block: 4096   reguläre Datei
00:00:02.453 Gerät: fd11h/64785d	Inode: 67908785    Verknüpfungen: 1
00:00:02.453 Zugriff: (0644/-rw-r--r--)  Uid: (  997/ jenkins)   Gid: (  994/ jenkins)
00:00:02.453 Kontext: system_u:object_r:var_lib_t:s0
00:00:02.453 Zugriff    : 2019-08-01 12:17:14.291181707 +0200
00:00:02.453 Modifiziert: 2019-08-01 12:17:14.293181669 +0200
00:00:02.453 Geändert   : 2019-08-01 12:17:14.293181669 +0200
00:00:02.453  Geburt    : -
00:00:02.453 + sha256sum client/package-lock.json
00:00:02.456 1d4bd7559b2a6f1118ed0cab826af21374d8fe774a9f2278d618d91d362c1693  client/package-lock.json
00:00:02.457 + docker build --target xxx-test . -t xxx-test
00:00:02.533 #2 [internal] load .dockerignore
00:00:03.986 #2 transferring context: 2B 0.0s done
00:00:04.437 #2 ...
00:00:04.437 
00:00:04.437 #1 [internal] load build definition from Dockerfile
00:00:04.437 #1 transferring dockerfile: 1.38kB done
00:00:04.437 #1 DONE 1.8s
00:00:04.587 
00:00:04.587 #2 [internal] load .dockerignore
00:00:04.587 #2 DONE 2.0s
00:00:04.699 
00:00:04.699 #3 [internal] load metadata for docker.io/library/node:lts
00:00:04.699 #3 DONE 0.0s
00:00:04.849 
00:00:04.849 #4 [internal] helper image for file operations
00:00:04.849 #4 DONE 0.0s
00:00:04.849 
00:00:04.849 #5 [xxx-base 1/2] FROM docker.io/library/node:lts
00:00:04.849 #5 DONE 0.0s
00:00:04.849 
00:00:04.849 #6 [internal] load build context
00:00:06.843 #6 transferring context: 13.76MB 2.0s done
00:00:06.977 #6 DONE 2.3s
00:00:07.127 
00:00:07.127 #5 [xxx-base 1/2] FROM docker.io/library/node:lts
00:00:07.127 #5 CACHED
00:00:07.127 
00:00:07.127 #4 [internal] helper image for file operations
00:00:07.127 #4 CACHED
00:00:07.127 
00:00:07.127 #7 [xxx-base 2/2] COPY client/package*.json /client/
00:00:07.866 #7 DONE 0.8s

As you can see, step 7 should be cached, but isn't. Switching back to normal Docker build correctly does cache this step.

[Gaibhne]

Related bug/MR from Docker: moby/moby#12031

[tonistiigi]

You need to provide a reproducible testcase. Git clone is not guaranteed to be deterministic.

 # cat <<EOT > Dockerfile                                                                                                                               !10155
heredoc> from alpine
heredoc> copy . .
heredoc> run ls -l /foo && sleep 2
heredoc> EOT

 # echo bar > foo

 # ls -l foo
-rw-r--r-- 1 root root 4 Aug  1 15:47 foo
 # DOCKER_BUILDKIT=1 docker build --progress=plain .
#1 [internal] load .dockerignore
#1 transferring context: 2B done
#1 DONE 0.0s

#2 [internal] load build definition from Dockerfile
#2 transferring dockerfile: 84B 0.0s done
#2 DONE 0.0s

#3 [internal] load metadata for docker.io/library/alpine:latest
#3 DONE 0.0s

#4 [1/3] FROM docker.io/library/alpine
#4 CACHED

#5 [internal] load build context
#5 transferring context: 120B 0.4s done
#5 DONE 0.5s

#6 [2/3] COPY . .
#6 DONE 0.4s

#7 [3/3] RUN ls -l /foo && sleep 2
#7 1.022 -rw-r--r--    1 root     root             4 Aug  1 22:47 /foo
#7 DONE 3.1s

#8 exporting to image
#8 exporting layers 0.0s done
#8 writing image sha256:ec16974f4c6b4058e0c94765b0b52d3266af7043898ebef408e5d361b9b501aa done
#8 DONE 0.1s
 #
 # touch -m foo
 # ls -l
total 8
-rw-r--r-- 1 root root 47 Aug  1 15:47 Dockerfile
-rw-r--r-- 1 root root  4 Aug  1 15:49 foo
 # DOCKER_BUILDKIT=1 docker build --progress=plain .
#2 [internal] load .dockerignore
#2 transferring context: 2B done
#2 DONE 0.0s

#1 [internal] load build definition from Dockerfile
#1 transferring dockerfile: 31B 0.0s done
#1 DONE 0.0s

#3 [internal] load metadata for docker.io/library/alpine:latest
#3 DONE 0.0s

#4 [1/3] FROM docker.io/library/alpine
#4 DONE 0.0s

#5 [internal] load build context
#5 transferring context: 67B 0.0s done
#5 DONE 0.0s

#6 [2/3] COPY . .
#6 CACHED

#7 [3/3] RUN ls -l /foo && sleep 2
#7 CACHED

#8 exporting to image
#8 exporting layers done
#8 writing image sha256:ec16974f4c6b4058e0c94765b0b52d3266af7043898ebef408e5d361b9b501aa done
#8 DONE 0.0s

[tonistiigi]

Also, note that efficiently caching wildcards had issues in 18.09 that I assume you are using #573 . Fixed in 19.03

[Gaibhne]

Yes, thank you, an upgrade to 19.03 did indeed fix it (incidentally, the calling PC already had 19.03, but it used a remote Docker host which was still at 18.09, explaining why my initial go-to solution ("upgrade and see if it's still happening") didn't work. I'm closing this, since I guess my title was incorrect.