Dangling docker logs process on Linux

[SamLex]

Hi,

Firstly, thanks for the awesome tool!

Problem

I've encountered a small issue that there is a docker logs process that is not stopped after x11docker has been stopped (either by closing the container's X window, docker stop, or SIGINT/Ctrl+C on the x11docker process).

Command

x11docker --init=dockerinit patricknw/xaos

Output from pstee after stopping x11docker

[snip]
 |-+- 23710 XXX bash /home/XXX/.cache/x11docker/patricknw-xaos-3378334/dockerrc 
//g --- 23720 XXX sed s/
 |--- 23709 XXX /nix/store/qw44ld0z5546n3aj26jbzm7i7361xkym-docker-18.09.7/libexec/docker/docker logs -f 27bcdfc37bcbb281559223c90f4b03b5366f29bc7403443b547bc486041fb084
[snip]

Manually running kill 23709 (in this case) stops these three dangling processes.

Environment Details

x11docker version

6.1.1

Linux version (NixOS)

Linux XXX 4.19.61 #1-NixOS SMP Fri Jul 26 07:14:31 UTC 2019 x86_64 GNU/Linux 19.03.173198.aeeb30a3b29 (Koi)

Docker version

Client:
 Version:           18.09.7
 API version:       1.39
 Go version:        go1.11.6
 Git commit:        2d0083d657f82c47044c8d3948ba434b622fe2fd
 Built:             Sat Jul 20 11:01:01 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.09.7
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.11.6
  Git commit:       2d0083d657f82c47044c8d3948ba434b622fe2fd
  Built:            Thu Jan  1 00:00:01 1970
  OS/Arch:          linux/amd64
  Experimental:     false

Probable cause / proposed solution

Had a look into what might be causing this. This line in the generated dockerrc starts a logs process in the background but doesn't add it to the background pids list. https://github.com/mviereck/x11docker/blob/05fd4e99f18ed4d550e83d85257a692a2764e7c3/x11docker#L4516 So it hangs around even after everything else is finished. It also appears this is intended behaviour for docker logs to not exit when the container it is following stops.

So a possible fix for this would be to call storepid after the above docker logs call. If this seems like a reasonable solution, I can raise a PR if you wish.

[mviereck]

Thank you for the detailed report!

So it hangs around even after everything else is finished. It also appears this is intended behaviour for docker logs to not exit when the container it is following stops.

This is odd. I assumed docker logs would always stop if the container is removed. On my system (Debian 10, Docker version 19.03.1, build 74b1e89) there is no remaining docker logs process after terminating x11docker. Maybe it is a bug in Docker version 18.09.7?

So a possible fix for this would be to call storepid after the above docker logs call. If this seems like a reasonable solution, I can raise a PR if you wish.

Thank you! I've just included storepid as you suggested. No PR needed.

However, it might fail if the user is not in group docker and x11docker does not run as root. In that case docker logs would run as root and cannot be terminated without privileges. For now I just hope it is a (meanwhile fixed) bug in Docker.

[SamLex]

Thanks for the quick response.

Yeah, it is quite odd. I didn't find any official documentation about this behaviour, just some github issues that suggested it was intended, but could also be a bug.

Unfortunately those changes don't quite fix the issue (sorry, should have mentioned I hadn't tried the fix myself). The pid being stored isn't the one for docker logs (or the sed invoked by rmcr for that matter). Maybe the subshell running rmcr? Not sure how Bash handles these things.

Will see if I can find a fix locally since you can't reproduce it on your Docker version.

[mviereck]

I didn't find any official documentation about this behaviour, just some github issues that suggested it was intended, but could also be a bug.

I somewhere found that docker logs stays alive if a container is stopped and started again later. That is intended. However, x11docker runs with --rm to immediatly remove the stopped container. I did not find a behavior documentation for that case. I would expect it to terminate if there is no container anymore, and so it does here, but not on your system.

The pid being stored isn't the one for docker logs (or the sed invoked by rmcr for that matter). Maybe the subshell running rmcr?

You are right. I just checked it, too. The stored pid is invalid. I tried without rmcr, still invalid.

I assume docker logs forks itself immediatly and continues with another pid. Only few applications do that, e.g. gnome-shell. I am not aware of a proper way to track this fork behavior to get a valid pid.

I've reverted the storepid change yet because it does not work. I don't have a proper solution either except to update docker.

EDIT: Could you check if the container is stopped and removed properly with docker ps -a?

[SamLex]

Yes, the container is stopped and removed properly; docker ps -a shows no containers.

[SamLex]

Ok, think I've found a fix. Original fix had a typo missing the escape character for $! so the pid being stored was that of the generating script. Also replaced the pipe with a subshell redirect that apparently changes the order of execution* so that the pid in $! is that of docker logs. https://github.com/SamLex/x11docker/blob/58ccbaf815a08e0344bcc0195db6f5d2dea6798d/x11docker#L4523

* according to https://stackoverflow.com/a/8048493

[mviereck]

Thank you! An interesting construction to forward the output to a subshell instead of piping it. Did not see that before.

[mviereck]

Original fix had a typo missing the escape character for $! so the pid being stored was that of the generating script.

Indeed, this was a bug in my own implementation. Thanks for pointing that out!