New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Overlayfs2 bug with tail as CMD #31587

Open
nvanheuverzwijn opened this Issue Mar 7, 2017 · 13 comments

Comments

Projects
None yet
8 participants
@nvanheuverzwijn

nvanheuverzwijn commented Mar 7, 2017

Description
With overlayfs2, tail -F /file cannot follow and print to stdout a file created at build time with RUN touch /file. I'm not sure where to report this issue so I humbly report it here.

More information this stackoverflow issue.

Steps to reproduce the issue:

  1. Build the Dockerfile below (docker build -t test-tail -f Dockerfile)
FROM debian:latest
RUN touch /var/log/mylog.log
CMD ["tail", "-F", "/var/log/mylog.log"]
  1. Run the freshly built Dockerfile (docker run -t --rm --name test-tail test-tail)
  2. In another terminal, execute docker exec test-tail bash -c "echo 'test' >> /var/log/mylog.log"

Describe the results you received:
No output at all.

Describe the results you expected:
The value test as output.

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

  • You need to use overlayfs2.
  • This only happens on the first run. Restarting the container without rebuilding it, will produce expected behavior.

Output of docker version:

Client:
 Version:      1.13.1
 API version:  1.26
 Go version:   go1.7.5
 Git commit:   092cba372
 Built:        Wed Feb  8 06:44:30 2017
 OS/Arch:      linux/amd64

Server:
 Version:      1.13.1
 API version:  1.26 (minimum version 1.12)
 Go version:   go1.7.5
 Git commit:   092cba372
 Built:        Wed Feb  8 06:44:30 2017
 OS/Arch:      linux/amd64
 Experimental: false

Output of docker info:

Containers: 18
 Running: 0
 Paused: 0
 Stopped: 18
Images: 207
Server Version: 1.13.1
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: aa8187dbd3b7ad67d8e5e3a15115d3eef43a7ed1
runc version: 9df8b306d01f59d3a8029be411de015b7304dd8f
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.0-1-amd64
Operating System: Debian GNU/Linux 9 (stretch)
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 15.56 GiB
Name: tremblay
ID: 47QN:G2GZ:ZYRW:YSGJ:NY2K:UWGU:46J7:PPXL:JHGE:DBZO:YA6C:LPI4
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.):
On a Debian Stretch.

@AkihiroSuda

This comment has been minimized.

Member

AkihiroSuda commented Mar 7, 2017

Seems already answered in http://stackoverflow.com/a/42618921 ?

@fntlnz

This comment has been minimized.

Member

fntlnz commented Mar 7, 2017

overlayfs2 does not support file watching and since tail needs inotify to work it can't get events.

If you strace the tail you can see that it does not receive events, after opening the file it just sleeps waiting for events that never occur

CMD ["strace", "tail", "-F", "/var/log/mylog.log"]
fcntl(3, F_GETFL)                       = 0x8000 (flags O_RDONLY|O_LARGEFILE)
fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
nanosleep({1, 0}, NULL)                 = ? ERESTART_RESTARTBLOCK (Interrupted by signal)
--- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} ---
restart_syscall(<... resuming interrupted call ...>) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
nanosleep({1, 0}, NULL)                 = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
nanosleep({1, 0}, NULL)                 = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
nanosleep({1, 0}, NULL)                 = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
nanosleep({1, 0}, NULL)                 = 0
@fntlnz

This comment has been minimized.

Member

fntlnz commented Mar 7, 2017

Looks like this has been fixed in the mainline kernel: torvalds/linux@f3fbbb0

Anyway changing the CMD to create the file at runtime as suggested by the so question posted by @AkihiroSuda works for me.

@nvanheuverzwijn

This comment has been minimized.

nvanheuverzwijn commented Mar 7, 2017

@fntlnz Looks like it's gonna be fixed so it's a no issue. Thanks for checking this out.

@AkihiroSuda

This comment has been minimized.

Member

AkihiroSuda commented Mar 7, 2017

@fntlnz Isn't it already included in the kernel @nvanheuverzwijn using? (4.9.0-1-amd64)

@nvanheuverzwijn

This comment has been minimized.

nvanheuverzwijn commented Mar 7, 2017

@AkihiroSuda You are right ! This is the kernel I am using so this would still be a problem in kernel 4.9.

The line in kernel 4.9 for reference : https://github.com/torvalds/linux/blob/v4.9/include/linux/fsnotify.h#L36

@fntlnz

This comment has been minimized.

Member

fntlnz commented Mar 7, 2017

@AkihiroSuda looks like the one I posted is in that kernel, but I can also see that there have been further improvements (regarding overlayfs and inotify) after that which are actually in 4.11-rc1 , like: torvalds/linux@e58bc92#diff-b2cbb2bacb9ecd4909c1ec2032dbfc48L296

I will check against that version if it's fixed

@deployable

This comment has been minimized.

Contributor

deployable commented Mar 7, 2017

That kernel fix makes it sound like coreutils < 8.26 should be able to pick up the file updates on a tail -F then.

The older versions of tail/coreutils don't know the overlay magic number and produce a warning to say it will default to polling. Then -F should be polling on the file name rather than a descriptor/inode which goes through the "copy up" but tail fails to pick up any updates.

@deployable

This comment has been minimized.

Contributor

deployable commented Mar 7, 2017

Following on from above, I produced a simple node.js test case that doesn't use inotify, just a simple file open (fs.open). The node process reading from an open file also doesn't get redirected to the new "copied up" inode when the open file is appended to out of process.

Repo is here: https://github.com/deployable/docker_overlay_issue_31587

Run ./make.sh:

Dockerfile

FROM mhart/alpine-node:7

COPY package.json /package.json
RUN set -uex; \
    npm install; \
    echo 'test1' > /file

COPY read.js /read.js
COPY read_write.js /read_write.js

CMD ["node","read.js"]
#CMD ["node","read_write.js"]

Output:

++ docker run -d docker_issue/31587
+ cid=6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77

+ sleep 2

+ docker logs 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
1488868826544 read 6 [test1
]

+ docker exec 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77 sh -c 'echo -e test2 >> /file'

+ docker exec 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77 cat /file
test1
test2

+ sleep 3
+ docker logs 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
1488868826544 read 6 [test1
]
1488868829553 read 6 [test1
]

As before with tail, file updates are picked up after a stop/start

+ docker stop 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
+ docker start 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
+ sleep 2
+ docker logs 6fc1e693e452c51d0ab4e71933a83905c06c1b8c5a838a796ee00499db71ab77
1488868826544 read 6 [test1
]
1488868829553 read 6 [test1
]
1488868833688 read 12 [test1
test2
]

There's also a read_write.js script in the repo to test the same concept of "open for read then append to the same file" but this time doing both the read and write in the same node process. This works as expected.

@tiborvass

This comment has been minimized.

Collaborator

tiborvass commented Mar 8, 2017

@dmcgowan is this a known issue and is it actionable?

@dmcgowan

This comment has been minimized.

Member

dmcgowan commented Mar 8, 2017

@tiborvass the inode changing on copy up is a known issue, it is fair to track the individual problems people face with it as it looks like the kernel is incrementally fixing these inode issues. The general solution is always touch to force a copy up then everything operates as expected.

@Berndinox

This comment has been minimized.

Berndinox commented Sep 22, 2017

chown in overlayfs2 is very, very slow? Anyone got that proboem?

@nvanheuverzwijn

This comment has been minimized.

nvanheuverzwijn commented Jun 14, 2018

Still an issue with kernel 4.16.0-2-amd64 and docker version 18.03.1-ce

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment