#2572 PR `closed`: Fixes docker_root_dir not being set when `docker info` writes to stderr.¶

Labels: enhancement, fixed / solved / done

grigutis opened issue at 2021-02-20 03:43:¶

Type: Bug Fix
Impact: Low
Reference to related issue (URL): https://github.com/rear/rear/issues/1989
How was this pull request tested?
Modified local installation, performed sudo rear -v mkbackup and observed the 'Docker Root Dir' was recognized as expected.
Brief description of the changes in this pull request:

On Ubuntu Server 20.04.2 LTS with Docker 19.03.13, rear "Cannot determine Docker Root Dir" even though 'Docker Root Dir' is found in docker info. This seems to be because docker also sends to stderr which interferes with the variable assignment:

$ timeout -k 2s 5s docker info | grep 'Docker Root Dir' | awk '{print $4}'
WARNING: No swap limit support
/var/lib/docker

redirecting stderr to null allows the 'Docker Root Dir' value to be assigned to the docker_root_dir variable correctly.

FYI: It appears that this redirection used to be there, but was omitted (probably by mistake) in https://github.com/rear/rear/pull/2021/commits/f6c32416dc9e1fffcf5090a4b52e11dd8cd61a15.

jsmeix commented at 2021-02-22 10:03:¶

@grigutis
I do not understand how 2>/dev/null could help here
because in a pipe PRODUCER_COMMAND | CONSUMER_COMMAND
the consumer command only gets stdout of the producer command
so in docker info | grep stderr of docker info does not reach grep.

An example:

# cat -n /etc/issue qqq
     1  Welcome to \S - Kernel \r (\l).
     2
     3
cat: qqq: No such file or directory

# cat -n /etc/issue qqq 1>/dev/null
cat: qqq: No such file or directory

# cat -n /etc/issue qqq 2>/dev/null
     1  Welcome to \S - Kernel \r (\l).
     2
     3

# cat -n /etc/issue qqq | grep Kernel
cat: qqq: No such file or directory
     1  Welcome to \S - Kernel \r (\l).

# var=$( cat -n /etc/issue qqq | grep Kernel )
cat: qqq: No such file or directory

# echo "'$var'"
'     1 Welcome to \S - Kernel \r (\l).'

# var=$( cat -n /etc/issue qqq | grep Kernel | awk '{print $6}' )
cat: qqq: No such file or directory

# echo "'$var'"
'Kernel'

grigutis commented at 2021-02-23 01:04:¶

Thank you for your explanation. After some more testing, it looks like I was wrong. After taking out the redirection, the variable was still being set correctly. I tested it a couple of times and it worked every time. I guess it was just hitting the timeout when I was seeing it earlier and the fact that it worked after adding the redirection was just a coincidence. I'll keep an eye on it though.

jsmeix commented at 2021-02-23 10:49:¶

@grigutis
let's not give up too early.
You wrote I guess it was just hitting the timeout.
I never used ReaR on a system with docker, cf.
https://github.com/rear/rear/issues/1989#issuecomment-456071787
so I can also only guess but I think we could simply make the timeout longer
to avoid that the timeout kills a valid ongoing operation.
The current 5 seconds timeout value is not because something
would go wrong if docker info did not finish within 5 seconds.
The timeout is there to avoid that docker info basically hangs up
(i.e. does not finish within a reasonable amount of time).
So increasing the timeout value to 10 seconds
(or perhaps even to 30 seconds if really needed in some cases)
should be ok.
Cf. the comment of @gdha in
https://github.com/rear/rear/pull/2021

@jsmeix do me a favor and replace docker info
with timeout 5s docker info - why? I have seen too many cripple
docker installation the last couple of months.

so the 5 seconds timeout value was just "some reasonable value"
at that time.

jsmeix commented at 2021-02-23 10:58:¶

With
https://github.com/rear/rear/commit/4b43f4396edd9d6c41955296fda522176f6200ae
I increased the 'docker info' timeout value from 5 seconds to 10 seconds
to (hopefully) avoid this issue here.

grigutis commented at 2021-02-24 14:01:¶

Thank you. Hopefully that fixes it, but in any case I'll monitor the logs and see if this ever pops up again.

jsmeix commented at 2021-02-24 14:10:¶

@grigutis
thank you for your issue report so that we know at least about it and
thank you in advance for monitoring if it works now sufficiently reliable.
If it pops up again we can look again what the root cause could be.

grigutis commented at 2021-03-14 14:22:¶

Well, the problem has reappeared. Last week, it was okay, but today it failed to find the docker dir. (I only run rear once a week.)

Successful rear.log:

2021-03-07 02:00:10.622860056 Saving filesystem layout (using the findmnt command).
* docker.service - Docker Application Container Engine
     Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2021-02-24 07:11:11 EST; 1 weeks 3 days ago
TriggeredBy: * docker.socket
       Docs: https://docs.docker.com
   Main PID: 1122 (dockerd)
      Tasks: 41
     Memory: 37.7M
     CGroup: /system.slice/docker.service
             |-1122 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
             |-1625 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 50443 -container-ip 172.17.0.3 -container-port 443
             |-1648 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 50080 -container-ip 172.17.0.3 -container-port 80
             `-1666 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 3122 -container-ip 172.17.0.3 -container-port 22

Feb 24 07:10:49 ubuntu dockerd[1122]: time="2021-02-24T07:10:49.319485816-05:00" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::8844]"
Feb 24 07:10:50 ubuntu dockerd[1122]: time="2021-02-24T07:10:50.292999220-05:00" level=info msg="/etc/resolv.conf does not exist"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444345205-05:00" level=info msg="/etc/resolv.conf does not exist"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444402288-05:00" level=info msg="No non-localhost DNS nameservers are left in resolv.conf. Using default external servers: [nameserver 8.8.8.8 nameserver 8.8.4.4]"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444427540-05:00" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::8844]"
Feb 24 07:11:07 ubuntu dockerd[1122]: time="2021-02-24T07:11:07.128486095-05:00" level=info msg="Loading containers: done."
Feb 24 07:11:10 ubuntu dockerd[1122]: time="2021-02-24T07:11:10.122344416-05:00" level=info msg="Docker daemon" commit=4484c46d9d graphdriver(s)=overlay2 version=19.03.13
Feb 24 07:11:10 ubuntu dockerd[1122]: time="2021-02-24T07:11:10.161669632-05:00" level=info msg="Daemon has completed initialization"
Feb 24 07:11:11 ubuntu dockerd[1122]: time="2021-02-24T07:11:11.528387884-05:00" level=info msg="API listen on /run/docker.sock"
Feb 24 07:11:11 ubuntu systemd[1]: Started Docker Application Container Engine.
WARNING: No swap limit support
2021-03-07 02:00:18.896576080 Docker is running, skipping filesystems mounted below Docker Root Dir /var/lib/docker

Failed rear.log:

2021-03-14 03:00:20.442222620 Saving filesystem layout (using the findmnt command).
* docker.service - Docker Application Container Engine
     Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2021-02-24 07:11:11 EST; 2 weeks 3 days ago
TriggeredBy: * docker.socket
       Docs: https://docs.docker.com
   Main PID: 1122 (dockerd)
      Tasks: 41
     Memory: 33.8M
     CGroup: /system.slice/docker.service
             |-1122 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
             |-1625 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 50443 -container-ip 172.17.0.3 -container-port 443
             |-1648 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 50080 -container-ip 172.17.0.3 -container-port 80
             `-1666 /usr/bin/docker-proxy -proto tcp -host-ip 0.0.0.0 -host-port 3122 -container-ip 172.17.0.3 -container-port 22

Feb 24 07:10:49 ubuntu dockerd[1122]: time="2021-02-24T07:10:49.319485816-05:00" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::8844]"
Feb 24 07:10:50 ubuntu dockerd[1122]: time="2021-02-24T07:10:50.292999220-05:00" level=info msg="/etc/resolv.conf does not exist"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444345205-05:00" level=info msg="/etc/resolv.conf does not exist"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444402288-05:00" level=info msg="No non-localhost DNS nameservers are left in resolv.conf. Using default external servers: [nameserver 8.8.8.8 nameserver 8.8.4.4]"
Feb 24 07:10:53 ubuntu dockerd[1122]: time="2021-02-24T07:10:53.444427540-05:00" level=info msg="IPv6 enabled; Adding default IPv6 external servers: [nameserver 2001:4860:4860::8888 nameserver 2001:4860:4860::8844]"
Feb 24 07:11:07 ubuntu dockerd[1122]: time="2021-02-24T07:11:07.128486095-05:00" level=info msg="Loading containers: done."
Feb 24 07:11:10 ubuntu dockerd[1122]: time="2021-02-24T07:11:10.122344416-05:00" level=info msg="Docker daemon" commit=4484c46d9d graphdriver(s)=overlay2 version=19.03.13
Feb 24 07:11:10 ubuntu dockerd[1122]: time="2021-02-24T07:11:10.161669632-05:00" level=info msg="Daemon has completed initialization"
Feb 24 07:11:11 ubuntu dockerd[1122]: time="2021-02-24T07:11:11.528387884-05:00" level=info msg="API listen on /run/docker.sock"
Feb 24 07:11:11 ubuntu systemd[1]: Started Docker Application Container Engine.
2021-03-14 03:00:55.389203425 Cannot determine Docker Root Dir - things may go wrong - check /var/lib/rear/layout/disklayout.conf

I found that others have run into this problem of docker commands taking an unusually long time to complete. In any case, I just wanted to report this. Thank you for your help.

[Export of Github issue for rear/rear.]

#2572 PR closed: Fixes docker_root_dir not being set when docker info writes to stderr.¶