Very specific set of circumstances leads to zero-byte (empty) file being created

[pedantic-git]

• This is a bug report
• This is a feature request
• I searched existing issues before opening this one

The story

A few weeks ago, a bunch of tests in Rails code I have started failing in my Docker development environment. My dev environment is Arch so the actual set of libraries and things installed is very much a moving target.

Lots of digging around led me to create a repo that can reproduce the issue using only Ruby (no gems at all), at the lowest level possible. And it's really really weird. More information below.

Expected behavior

When copying a file in Ruby using the IO.copy_stream method, the file should be an identical copy.

Actual behavior

Under a very specific set of circumstances, the resulting file is 0 bytes.

I'm reasonably certain this is a Docker issue, because one of the conditions that needs to be true is that the source file is located on a mounted volume.

The conditions that need to be true for the IO.copy_stream operation to fail are:

1. The source file is located on a Docker mounted volume and not the Docker container's own filesystem.
2. The file is first copied into a Tempfile using the low-level Tempfile library.
3. The tempfile is not touched (e.g. by utime or chmod) after the copy happens.
4. That tempfile is then copied to another location using IO.copy_stream. Copying it using File.write and tempfile.read does not cause the issue.

Steps to reproduce the behavior

Please check out this repo: https://github.com/fishpercolator/reproduce-copystream and run the command in the README.

The output of this command on my env is:

open, local, File.write: 6744
open, local, IO.copy_stream: 6744

open, mounted, File.write: 6744
open, mounted, IO.copy_stream: 6744

tempfile + copy_file, local, File.write: 6744
tempfile + copy_file, local, IO.copy_stream: 6744

tempfile + copy_file, mounted, File.write: 6744
tempfile + copy_file, mounted, IO.copy_stream: 0

tempfile + copy_file + noop utime, mounted, File.write: 6744
tempfile + copy_file + noop utime, mounted, IO.copy_stream: 6744

tempfile + copy_file + noop chmod, mounted, File.write: 6744
tempfile + copy_file + noop chmod, mounted, IO.copy_stream: 6744

As you can see, the file is copied successfully if it is:

1. copied directly from the mounted filesystem (not via a tempfile)
2. copied via a tempfile from the container's own filesystem
3. copied via a tempfile that has been touched with utime or chmod after the contents were inserted
4. I do this same operation on an Ubuntu machine running Docker 19.03.9 ... i.e. it seems to be specific to something about my development machine

If any of the 4 statements above are true, the file copies fine. If all 4 are false, the file is created but it has a 0-byte size.

I've checked to see if the source filesystem of the mounted volume makes any difference but I get the same effect with eCryptfs, ext4 and tmpfs mountpoints.

Likewise I've tried different versions of Ruby to see if it was a regression in Ruby, but I can still reproduce the issue with the official Docker images of much older versions where I was certain it worked.

Does anyone have any ideas? Can anyone else reproduce this using my repo?

Output of docker version:

Client:
 Version:           19.03.9-ce
 API version:       1.40
 Go version:        go1.14.3
 Git commit:        9d988398e7
 Built:             Tue May 19 22:11:18 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          19.03.9-ce
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.14.3
  Git commit:       9d988398e7
  Built:            Tue May 19 22:11:01 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.3.4.m
  GitCommit:        d76c121f76a5fc8a462dc64594aea72fe18e1178.m
 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: 317
  Running: 0
  Paused: 0
  Stopped: 317
 Images: 415
 Server Version: 19.03.9-ce
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: false
 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: d76c121f76a5fc8a462dc64594aea72fe18e1178.m
 runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
 init version: fec3683
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 5.6.13-arch1-1
 Operating System: Arch Linux
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 15.53GiB
 Name: hulat
 ID: G7VK:VZOA:T4LI:ATNZ:G55B:TDEA:23J2:YM2A:MOLK:U5QY:5MVT:CU7P
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Username: pedanticgit
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.)

It's a physical Dell XPS-13 9360 running Arch Linux. Arch doesn't have version numbers but all packages are up to date. Docker was installed from the Arch package with is built using this PKGBUILD script from the official Docker sources.

[sarna]

I can reproduce this on current Manjaro (5.6.12-1-MANJARO), getting the exact same output.
docker version output:

Client:
 Version:           19.03.8-ce
 API version:       1.40
 Go version:        go1.14.1
 Git commit:        afacb8b7f0
 Built:             Thu Apr  2 00:04:36 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          19.03.8-ce
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.14.1
  Git commit:       afacb8b7f0
  Built:            Thu Apr  2 00:04:16 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.3.4.m
  GitCommit:        d76c121f76a5fc8a462dc64594aea72fe18e1178.m
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

docker info output:

Client:
 Debug Mode: false

Server:
 Containers: 6
  Running: 0
  Paused: 0
  Stopped: 6
 Images: 37
 Server Version: 19.03.8-ce
 Storage Driver: overlay2
  Backing Filesystem: <unknown>
  Supports d_type: true
  Native Overlay Diff: false
 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: d76c121f76a5fc8a462dc64594aea72fe18e1178.m
 runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
 init version: fec3683
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.6.12-1-MANJARO
 Operating System: Manjaro Linux
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 15.53GiB
 Name: mainframe
 ID: 2Y5C:436L:YDBV:YUH6:AW2M:EJ56:TIUI:I4ZO:ACZF:M64N:OQAG:LQBQ
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

[thaJeztah]

Both Arch linux and Manjaro are distributions that are not officially supported. Packages distributed by those distributions are maintained by those distributions and use differences in both the build process, build-time dependencies, as well as different versions of (e.g.) containerd and runc.

I'd recommend opening a ticket in the corresponding distribution's issue tracker for that reason.

I'm closing this issue because of the above, but feel free to continue the conversation

[kthibodeaux]

@pedantic-git have you resolved this? did you create an issue elsewhere that I can follow? I'm seeing the same issue with the official ruby 2.6 docker image on an up to date manjaro install (updating an existing install doesnt seem to trigger the error)

[pedantic-git]

@kthibodeaux I didn't create an issue anywhere else because I didn't have time to test it with the official build of Docker - have you been able to do that? It seems like even though it's happening to everyone on Arch/Manjaro it won't be supported here if it's only the Arch build of Docker.

[ttrmw]

Did either of you get anywhere with this @pedantic-git @kthibodeaux? Got another example here, also on Arch.

[pedantic-git]

Sadly not. I never got past the "Arch isn't supported" message above. I guess taking it up with the maintainers of the Arch package is the way to go.

Looks like that's Morten Linderud foxboron@archlinux.org if you'd like to raise a case and copy me in (quinn at fishpercolator.co.uk) but I'm not really even sure how one goes about doing that.

[ahwatts]

I'm able to reproduce this on Fedora 33 using the package moby-engine-19.03.13-1.ce.git4484c46.fc33.x86_64.

I get the exact same output as @pedantic-git

My docker info:

awatts@ironic-mullet reproduce-copystream [master=] $ docker info
Client:
 Debug Mode: false

Server:
 Containers: 23
  Running: 21
  Paused: 0
  Stopped: 2
 Images: 64
 Server Version: 19.03.13
 Storage Driver: overlay2
  Backing Filesystem: btrfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: journald
 Cgroup Driver: systemd
 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: /usr/libexec/docker/docker-init
 containerd version: 
 runc version: c9a9ce0286785bef3f3c3c87cd1232e535a03e15
 init version: 
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 5.10.8-200.fc33.x86_64
 Operating System: Fedora 33 (Workstation Edition)
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 31.09GiB
 Name: ironic-mullet.eminorinc.com
 ID: SHFE:UOOW:MKUA:56MY:UHUL:QTQP:YZJX:C43V:XR4R:67RF:BWKS:22EM
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: true

[pedantic-git]

@thaJeztah Now that this issue can be reproduced in an official build (albeit of Moby Engine rather than CE) is it possible this issue could warrant reopening?

[AlexVKO]

@thaJeztah any chance to reopen this issue?

Same issue here(on ubunto 20.04), running images Ubuntu:18:04, Ubuntu:20.04, and Ruby:3.0.0.

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.0-docker)

Server:
 Containers: 40
  Running: 6
  Paused: 0
  Stopped: 34
 Images: 485
 Server Version: 20.10.1
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 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: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.8.0-43-generic
 Operating System: Ubuntu 20.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 128
 Total Memory: 125.7GiB
 Name: alexvko
 ID: N5L3:NVEW:VSYS:OSK6:JWAO:T6ZE:APR5:5XVM:OTMQ:BXSZ:DNBV:STUU
 Docker Root Dir: /mnt/md0/docker
 Debug Mode: false
 Username: alexvko
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No blkio weight support
WARNING: No blkio weight_device support

[bmhughes]

Same here on Fedora 33

[makmic]

I just encountered the same issue and hope that it will be reopened and addressed here as it was far from easy to debug.

In the meantime I'll have to add this (Ruby) monkey patch to my docker setup:

module FileUtils
  class Entry_
    def copy_file(dest)
      Open3.capture2('cp', path(), dest)
    end
  end
end

[pedantic-git]

@makmic There's actually no need to shell out to a separate and heavyweight cp binary to work around this issue. Even doing a no-op chmod or utime on the file before it is copied as in my example prevents this issue from occurring. Why, I have no idea, but it reliably does!

[ngoan98tv]

I'm facing to the same issue on CentOS.

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)

Server:
 Containers: 24
  Running: 22
  Paused: 0
  Stopped: 2
 Images: 51
 Server Version: 20.10.5
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Native Overlay Diff: true
 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: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 05f951a3781f4f2c1911b05e61c160e9c30eaa8e
 runc version: 12644e614e25b05da6fd08a38ffa0cfe1903fdec
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 4.18.0-240.15.1.el8_3.x86_64
 Operating System: CentOS Linux 8
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 15.65GiB
 Name: LMS-Server
 ID: DRNO:6ONC:XO6P:6ZAK:W6NI:R764:GT5Q:YTZD:QOEB:Y63W:JD6N:TW4Y
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

[dwarburt]

@makmic There's actually no need to shell out to a separate and heavyweight cp binary to work around this issue. Even doing a no-op chmod or utime on the file before it is copied as in my example prevents this issue from occurring. Why, I have no idea, but it reliably does!

@pedantic-git I don't suppose you have an example no-op chmod or utime that's effective? and do you think they'd be faster than my current workaround?

module FileUtilsPatch
  def copy_file(dest)
    FileUtils.touch(path())
    super
  end
end

module FileUtils
  class Entry_
    prepend FileUtilsPatch
  end
end

Could this be an interaction with LUKS Full Disk Encryption? That's the main disk related difference on the affected system I have, when the same project is fine on all others.