A warning message gets output into systemd journal for docker.service every 20 seconds

[aki-k]

I installed oci-add-hooks and oci-systemd-hook (https://github.com/projectatomic/oci-systemd-hook) to work together with docker-ce-19.03.1-3.el7.x86_64.rpm.

Now I'm able to run systemd in a docker container when dockerd is configured for userns-remap.

But now I'm getting this message in the host's systemd journal for docker.service:

Sep 16 09:21:17 hostname dockerd[14752]: time="2019-09-16T09:21:17.636681872Z" level=warning msg="failed to retrieve /opt/docker/oci-add-hooks/oci-add-hooks version: exit status 1"

The message is printed every 20 seconds. I don't think this is a selinux issue as no AVC denials show up in /var/log/audit/audit.log.

Host distro: CentOS 7.6 Kernel: Linux hostname 5.1.16-1.el7.elrepo.x86_64 #1 SMP Wed Jul 3 10:53:38 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux Selinux: enforcing docker-ce: docker-ce-19.03.1-3.el7.x86_64.rpm dockerd options:

/usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock --default-runtime=oci-add-hooks

dockerd daemon.json:

{
    "selinux-enabled": true,
    "exec-opts": [ "native.cgroupdriver=systemd" ],
    "cgroup-parent": "system.slice",
    "userns-remap": "userns",
    "runtimes": {
        "oci-add-hooks": {
            "path": "/opt/docker/oci-add-hooks/oci-add-hooks",
            "runtimeArgs": ["--hook-config-path",
                "/etc/docker/hook-config.json",
                "--runtime-path",
                "/bin/runc"]
        }
    }
}

/etc/docker/hook-config.json:

{
        "hooks": {
                "prestart": [
                        { 
                                "path": "/usr/libexec/oci/hooks.d/oci-systemd-hook",
                                "args": [ "prestart" ]
                        }
                ],
                "poststop": [
                        { 
                                "path": "/usr/libexec/oci/hooks.d/oci-systemd-hook",
                                "args": [ "poststop" ]
                        }
                ]
        },
        "process": {
                "env": [
                        "container=oci"
                ],
                "capabilities": [
                        "CAP_AUDIT_WRITE",
                        "CAP_KILL",
                        "CAP_NET_BIND_SERVICE",
                        "CAP_AUDIT_WRITE",
                        "CAP_KILL",
                        "CAP_NET_BIND_SERVICE",
                        "CAP_MKNOD",
                        "CAP_CHOWN",
                        "CAP_DAC_OVERRIDE",
                        "CAP_FSETID",
                        "CAP_FOWNER",
                        "CAP_NET_RAW",
                        "CAP_SETGID",
                        "CAP_SETUID",
                        "CAP_SETFCAP",
                        "CAP_SETPCAP",
                        "CAP_SYS_CHROOT"
                ]
        }
}

[IRCody]

@aki-k Thanks for this well described issue.

Are you able to try running dockerd without setting the default runtime to oci-add-hooks and running the containers with --runtime=oci-add-hooks? I think it might be an issue with having oci-add-hooks as the default runtime but want to confirm.

Looking around it seems like moby is making the assumption that runc is the default binary. I think there are a few ways to make this work better if we confirm this is the issue.

[aki-k]

I have a Docker swarm configured and use Docker compose files to define the stacks. Docker compose v3 doesn't support the runtime keyword so that's why I needed to change the default runtime to oci-add-hooks.

Should oci-add-hooks tell the version with --version? I don't see any options in it.

[aki-k]

Your hunch was right. I took out the option --default-runtime=oci-add-hooks and the warning messages don't come up any more.

One thing I forgot to mention is that after I changed the default runtime to oci-add-hooks, docker info fails to find the runc version and just displays N/A.

[IRCody]

It doesn't currently support --version but it could. We'd need to decide what the expected behaviour would be though.

From looking at the code in moby I think it'd be enough to have oci-add-hooks --version that had an output that included a line like:

commit: <hash>

It does look like docker-compose 2.3 supports runtime keyword. Not sure why it wasn't included in more recent versions.

Your hunch was right. I took out the option --default-runtime=oci-add-hooks and the warning messages don't come up any more.

One thing I forgot to mention is that after I changed the default runtime to oci-add-hooks, docker info fails to find the runc version and just displays N/A.

I think this code is hit when the /info endpoint is hit so that makes sense. I will play around with it to see what sort of changes make sense. I think adding the --version option like mentioned above will get rid of the warning but I'm not sure how that would impact the runc version reported by docker info or if it would cause that output to no longer make sense.

I should have time to look deeper into this later this afternoon.

[IRCody]

I confirmed that adding the commit: <hash> response to running oci-add-hooks --version gets rid of this warning message when running docker info. The problem is that this causes runc version to be incorrect.

I created an issue on moby https://github.com/moby/moby/issues/39944 and it looks like there is a PR to address this issue by making the version parsing less tied to runc (https://github.com/moby/moby/issues/39944).

If that PR implements a more generic way to report the version I will update oci-add-hooks to follow that which should get rid of this warning. Do you know off-hand if something has been calling docker info or its equivalent so frequently (every 20 seconds?) for you or if it's something internal to docker doing that? I forgot to test that when I was looking at it.

[aki-k]

I don't know too much about go coding but grepping "20.*time.Second" in moby/moby code shows some possibilites where it could come from. I haven't created any kind of scheduled tasks that would do it myself.

integration/service/inspect_test.go:    const threshold = 20 * time.Second

vendor/github.com/docker/swarmkit/agent/agent.go:       nodeUpdatePeriod             = 20 * time.Second

daemon/health_test.go:  handleResult(c.State.StartedAt.Add(20*time.Second), 1)

daemon/cluster/cluster.go:const swarmConnectTimeout = 20 * time.Second

daemon/discovery/discovery_test.go:     assert.Check(t, is.Equal(20*time.Second, ttl))

integration-cli/docker_cli_swarm_unix_test.go:  time.Sleep(20 * time.Second)

[IRCody]

Are you using swarm?

[aki-k]

Yes, three hosts.

[IRCody]

I think it's the swarm node update then. I think that ultimately ends up calling into the SystemInfo() defined in daemon/info.go.

I created #4 that should get rid of the error you're seeing. This is separate from docker reporting the version of the default-runtime incorrectly as the runc version. Hopefully that issue will get resolved in moby also.

[aki-k]

Thank you very much. Now docker info looks like this:

 Runtimes: oci-add-hooks runc
 Default Runtime: oci-add-hooks
 Init Binary: docker-init
 containerd version: 894b81a4b802e4eb2a91d1ce216b8817763c29fb
 runc version: oci-add-hooks-b25d3bd0678c9812f7bdd6807209dbb89145a1cd
 init version: fec3683

And you were correct about the runc vs oci-add-hooks version discrepancy (in the above output). I'll keep my eye on the docker.service journal for those warning messages.

Edit: No more msg="failed to retrieve /opt/docker/oci-add-hooks/oci-add-hooks version in the journal.

[IRCody]

Sorry for the Delay but #4 is merged now.

[aki-k]

I ran execsnoop of bcc-tools and it showed that these two processes are ran every 20 seconds:

/opt/docker/oci-add-hooks/oci-add-hooks --version /usr/bin/docker-init --version

The parent process is /usr/bin/dockerd.

# /opt/docker/oci-add-hooks/oci-add-hooks --version
commit: oci-add-hooks-b25d3bd0678c9812f7bdd6807209dbb89145a1cd
# /usr/bin/docker-init --version
tini version 0.18.0 - git.fec3683

[IRCody]

Yep it seems like docker calls it frequently, I'm not sure why.

Related, there is a PR open on moby that modifies the way version is parsed here: https://github.com/moby/moby/pull/39940 but it looks like it just expands what it supports and the method here should still be supported iiuc.