nil error creating large logs

[tyler71]

When I restart docker, I will get a nil error that creates huge logs (about 30GB in size in about 10 minutes)

caddy version
v2.2.1 h1:Q62GWHMtztnvyRU+KPOpw6fNfeCD3SkwH7SfT1Tgt2c=

I'm not sure how to check the docker-proxy plugin version but I built it with a Dockerfile yesterday

Dockerfile

FROM caddy:builder AS builder

RUN xcaddy build  --with github.com/lucaslorentz/caddy-docker-proxy/plugin/v2

FROM caddy:2

ENV XDG_CONFIG_HOME /config
ENV XDG_DATA_HOME /data

COPY --from=builder /usr/bin/caddy /usr/bin/caddy

ENTRYPOINT ["/usr/bin/caddy"]
CMD ["docker-proxy"]

{"log":"{\"level\":\"info\",\"ts\":1606062537.97492,\"logger\":\"admin.api\",\"msg\":\"load complete\"}\n","stream":"stderr","time":"2020-11-22T16:28:57.975159907Z"}
{"log":"2020/11/22 16:28:57 [INFO] Successfully configured localhost\n","stream":"stderr","time":"2020-11-22T16:28:57.975443545Z"}
{"log":"{\"level\":\"info\",\"ts\":1606062538.4458172,\"logger\":\"admin\",\"msg\":\"stopped previous server\"}\n","stream":"stderr","time":"2020-11-22T16:28:58.446146668Z"}
{"log":"{\"level\":\"error\",\"ts\":1606065755.9069684,\"logger\":\"http.handlers.reverse_proxy\",\"msg\":\"aborting with incomplete response\",\"error\":\"http2: stream clos
ed\"}\n","stream":"stderr","time":"2020-11-22T17:22:35.907070825Z"}
{"log":"{\"level\":\"error\",\"ts\":1606065859.547961,\"logger\":\"http.handlers.reverse_proxy\",\"msg\":\"aborting with incomplete response\",\"error\":\"context canceled\"}
\n","stream":"stderr","time":"2020-11-22T17:24:19.548086513Z"}
{"log":"{\"level\":\"error\",\"ts\":1606065859.54858,\"logger\":\"http.handlers.reverse_proxy\",\"msg\":\"aborting with incomplete response\",\"error\":\"http2: stream closed
\"}\n","stream":"stderr","time":"2020-11-22T17:24:19.54866725Z"}
{"log":"{\"level\":\"error\",\"ts\":1606085443.2697084,\"logger\":\"http.handlers.reverse_proxy\",\"msg\":\"aborting with incomplete response\",\"error\":\"http2: stream clos
ed\"}\n","stream":"stderr","time":"2020-11-22T22:50:43.270040076Z"}
{"log":"{\"level\":\"error\",\"ts\":1606086455.1362236,\"logger\":\"http.handlers.reverse_proxy\",\"msg\":\"aborting with incomplete response\",\"error\":\"http2: stream clos
ed\"}\n","stream":"stderr","time":"2020-11-22T23:07:35.136390549Z"}
{"log":"2020/11/22 23:30:30 unexpected EOF\n","stream":"stderr","time":"2020-11-22T23:32:11.775852597Z"}
{"log":"2020/11/22 23:30:30 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:32:11.775875874Z"}
{"log":"2020/11/22 23:30:30 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:32:11.775887275Z"}

........
{"log":"2020/11/22 23:47:52 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:47:52.529123854Z"}
{"log":"2020/11/22 23:47:52 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:47:52.529125953Z"}
{"log":"2020/11/22 23:47:52 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:47:52.5291281Z"}
{"log":"2020/11/22 23:47:52 \u003cnil\u003e\n","stream":"stderr","time":"2020-11-22T23:47:52.529130239Z"}

[lucaslorentz]

Hey @tyler71 Did you configure CADDY_DOCKER_POLLING_INTERVAL or polling-interval? If docker API is not available, I do expect some errors to be logged. But probably every 30 seconds, the default polling interval configuration.

I will try to reproduce this later.

[piaste]

I occasionally run into the same issue, CADDY_DOCKER_POLLING_INTERVAL isn't set and it definitely logs far more often than every 30s. I'll add more details if I can pinpoint what circumstances trigger it.

Although, in my docker service logs, the actual string <nil> appears. Not sure if it's an artifact or a slightly different error.

@tyler71 As a mitigation, you can set a maximum log file size so it doesn't fill your disk and block your machine when it happens.

In fact, this is probably good practice whenever a Docker service uses the default logging driver, because a tight loop around a print statement can happen to just about any app:

    logging:
      driver: json-file
      options:
        max-file: '100'
        max-size: 1M

A better mitigation would be to have Docker's healthcheck command detect this state, but I'm not sure how one would do that.

[tyler71]

Did you configure CADDY_DOCKER_POLLING_INTERVAL or polling-interval?

Yes, but I'll get about 100k <nil> errors in a few seconds

CADDY_DOCKER_POLLING_INTERVAL: 30s

The error looks like this; I think I tee'd it to a file last time.

caddy_1  | 2020/12/30 17:03:50 <nil>

I can reproduce this on two machines when I restart docker

service docker restart

The last message before <nil> is this

{
  "log": "2020/12/30 17:20:40 unexpected EOF",
  "stream": "stderr",
  "time": "2020-12-30T17:20:40.270503443Z"
}

As a mitigation, you can set a maximum log file size so it doesn't fill your disk and block your machine when it happens.

I wish you could specify where to do logging. Having a endless stream of writing and rotating is probably bad for a SSD. Instead I set the logging driver to none for now in my docker-compose file

logging:
  driver: none

[lucaslorentz]

Fixed on version v2.3.3

Can you please try it and reopen the issue if you still face issues.

Now after losing connection to docker events, it will properly close everything and retry to connect every 30 seconds.

[tyler71]

This resolves the <nil> issue for me After a docker restart I now get this error, even after several minutes and looping of this error.

addy_1  | 2020/12/31 15:30:53 [ERROR] Swarm availability check failed: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
caddy_1  | 2020/12/31 15:31:00 [INFO] Connecting to docker events
caddy_1  | 2020/12/31 15:31:00 [ERROR] Docker events error: Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?

● docker.service - Docker Application Container Engine
     Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2020-12-31 07:31:21 PST; 2min 2s ago

Existing config works ok with these errors (I can load a website) Stopping and starting the container fixes the issue

[lucaslorentz]

It seems that after a daemon restart the previously mounted docker.sock file is not functional anymore.

For how long did you wait? Maybe docker API takes some time to become available after restart?

What happens if you run a container like this:

docker run -d -v /var/run/docker.sock:/var/run/docker.sock docker sh -c "while true; do docker stats; sleep 1; done"

And restart docker?

Can you share the logs of this container as well?

[lucaslorentz]

Or maybe this, so it will not have any sensitive information:

docker run -d -v /var/run/docker.sock:/var/run/docker.sock docker sh -c "while true; do docker version -f '{{json .Server.Platform.Name}}'; sleep 1; done"

[tyler71]

docker run -d -v /var/run/docker.sock:/var/run/docker.sock docker sh -c "while true; do docker version -f '{{json .Server.Platform.Name}}'; sleep 1; done"

It does seem to work right after.

gif

[lucaslorentz]

Seems to be mitigated by https://github.com/lucaslorentz/caddy-docker-proxy/pull/269