Huge Logs and stale locks

I’ve setup a test caddy2 (2.1.1) Centos8 server to reverse proxy a few internal machines. It works great, and I left it running since then.

Today (a couple of months), I found the logs file taking 8GB space, with a lot of errors. e.g

[INFO][FileStorage:/var/lib/caddy/.local/share/caddy] Lock for 'cert_acme_testxx.xxxxxx.xxx_acme-v02.api.letsencrypt.org-directory' is stale (created: 2020-07-18 00:45:22.181777733 -0400 EDT, last update: 2020-07-18 03:08:59.655627293 -0400 EDT); removing then retrying: /var/lib/caddy/.local/share/caddy/locks/cert_acme_testxx.xxxxxx.xxx_acme-v02.api.letsencrypt.org-directory.lock

There’s a few lock files in /var/lib/caddy/.local/share/caddy/locks that I had to remove and updated caddy to latest 2.2.1 (wrong version previously), and it works now but I like to understand why this happened and how to prevent it in future.

cert_acme_testxx.xxxxxx.xxx_acme-v02.api.letsencrypt.org-directory.lock cert_acme_testxx.xxxxxx.xxx_acme-v02.api.letsencrypt.org-directory.lock

Hmm. Did you happen to run Caddy as a different user at some point? Maybe the caddy user didn’t have permissions to remove the files because they were created with the wrong permissions?

Also regarding the logs, I assume you’re using systemd, so you can look into configuring journald to only retain a certain amount of logs, say 30 days of logs, maybe with daily rotation.

Nope, I just let the system running there, no reboot. I wasn’t using it for very long time until today. As you see, the date in the log already shows the problem couple of months ago, my diskspace was used up all by the logs.

Can you fill out the help template so we can help you, please? :slight_smile:

1. Caddy version (caddy version): 2.1.1 (but I already upgraded)

2. How I run Caddy:systemctl start caddy

a. System environment: Centos 8, VM

d. My complete Caddyfile or JSON config:

// this machine is not running
xxxxx.xxx, www.xxxxx.xxx {
reverse_proxy 192.168.1.99:****
}
// this is running fine
testxx.xxxxx.xxx {
reverse_proxy 192.168.1.151:****
}
//this machine is not running
testyy.xxxxx.xxx {
reverse_proxy 192.168.1.185:****
}

4. Error messages and/or full log output:

This is the oldest log, I’m not sure if this when the error started or I was experimenting

Jun 21 03:43:01 localhost rsyslogd[957]: [origin software="rsyslogd" swVersion="8.37.0-13.el8" x-pid="957" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Jun 21 03:44:25 localhost systemd[1]: Starting dnf makecache...
Jun 21 03:44:25 localhost dnf[21603]: CentOS-8 - AppStream                            9.7 kB/s | 4.3 kB     00:00
Jun 21 03:44:26 localhost dnf[21603]: CentOS-8 - Base                                 6.9 kB/s | 3.9 kB     00:00
Jun 21 03:44:27 localhost dnf[21603]: CentOS-8 - Extras                               3.6 kB/s | 1.5 kB     00:00
Jun 21 03:44:29 localhost dnf[21603]: Copr repo for caddy owned by @caddy             1.3 kB/s | 3.3 kB     00:02
Jun 21 03:44:30 localhost dnf[21603]: Copr repo for caddy owned by @caddy             1.6 kB/s | 1.4 kB     00:00
Jun 21 03:44:30 localhost dnf[21603]: Metadata cache created.
Jun 21 03:44:31 localhost systemd[1]: Started dnf makecache.
Jun 21 04:33:54 localhost caddy[904]: 2020/06/21 04:33:54 http: TLS handshake error from ***.***.***.***:59132: no certificate available for '192.168.1.181'
Jun 21 04:37:03 localhost caddy[904]: 2020/06/21 04:37:03 http: TLS handshake error from ***.***.***.***:53138: tls: first record does not look like a TLS handshake
Jun 21 04:45:15 localhost systemd[1]: Starting dnf makecache...
Jun 21 04:45:15 localhost dnf[21642]: Metadata cache refreshed recently.
Jun 21 04:45:15 localhost systemd[1]: Started dnf makecache.
Jun 21 04:45:59 localhost caddy[904]: 2020/06/21 04:45:59 http: TLS handshake error from ***.***.***.***:58436: no certificate available for '192.168.1.181'
Jun 21 05:45:25 localhost systemd[1]: Starting dnf makecache...
Jun 21 05:45:25 localhost dnf[21669]: Metadata cache refreshed recently.
Jun 21 05:45:25 localhost systemd[1]: Started dnf makecache.
Jun 21 06:46:25 localhost systemd[1]: Starting dnf makecache...
Jun 21 06:46:25 localhost dnf[21695]: CentOS-8 - AppStream                            9.5 kB/s | 4.3 kB     00:00
Jun 21 06:46:26 localhost dnf[21695]: CentOS-8 - Base                                 9.7 kB/s | 3.9 kB     00:00
Jun 21 06:46:26 localhost dnf[21695]: CentOS-8 - Extras                               3.8 kB/s | 1.5 kB     00:00
Jun 21 06:46:28 localhost dnf[21695]: Copr repo for caddy owned by @caddy             2.1 kB/s | 3.3 kB     00:01
Jun 21 06:46:28 localhost dnf[21695]: Metadata cache created.
Jun 21 06:46:28 localhost systemd[1]: Started dnf makecache.
Jun 21 06:52:23 localhost caddy[904]: 2020/06/21 06:52:23 http: TLS handshake error from ***.***.***.***:34724: no certificate available for '192.168.1.181'
Jun 21 06:53:02 localhost caddy[904]: 2020/06/21 06:53:02 http: TLS handshake error from ***.***.***.***:38252: no certificate available for '192.168.1.181'
Jun 21 06:53:09 localhost caddy[904]: 2020/06/21 06:53:09 http: TLS handshake error from ***.***.***.***:44942: no certificate available for '192.168.1.181'
Jun 21 06:54:15 localhost caddy[904]: 2020/06/21 06:54:15 http: TLS handshake error from ***.***.***.***:57148: EOF
Jun 21 06:54:59 localhost caddy[904]: 2020/06/21 06:54:59 http: TLS handshake error from ***.***.***.***:33774: no certificate available for '192.168.1.181'
Jun 21 07:14:01 localhost caddy[904]: 2020/06/21 07:14:01 http: TLS handshake error from ***.***.***.***:54166: no certificate available for '192.168.1.181'
Jun 21 07:20:57 localhost caddy[904]: 2020/06/21 07:20:57 http: TLS handshake error from ***.***.***.***:58038: no certificate available for '***.***.***.***'
Jun 21 07:47:20 localhost systemd[1]: Starting dnf makecache...
Jun 21 07:47:20 localhost dnf[21730]: Metadata cache refreshed recently.
Jun 21 07:47:20 localhost systemd[1]: Started dnf makecache.
Jun 21 08:02:22 localhost caddy[904]: 2020/06/21 08:02:22 http: TLS handshake error from ***.***.***.***:45114: no certificate available for '192.168.1.181'
Jun 21 08:10:12 localhost caddy[904]: 2020/06/21 08:10:12 http: TLS handshake error from ***.***.***.***:56882: no certificate available for '192.168.1.181'
Jun 21 08:47:21 localhost systemd[1]: Starting dnf makecache...
Jun 21 08:47:21 localhost dnf[21757]: Metadata cache refreshed recently.
Jun 21 08:47:21 localhost systemd[1]: Started dnf makecache.
Jun 21 09:00:29 localhost caddy[904]: 2020/06/21 09:00:29 http: TLS handshake error from ***.***.***.***:49668: tls: first record does not look like a TLS handshake
Jun 21 09:47:25 localhost systemd[1]: Starting dnf makecache...

Jun 29 05:39:44 localhost dnf[27714]: Copr repo for caddy owned by @caddy             1.2 kB/s | 3.3 kB     00:02
Jun 29 05:39:45 localhost dnf[27714]: Copr repo for caddy owned by @caddy             814  B/s | 1.4 kB     00:01
Jun 29 05:39:46 localhost dnf[27714]: Metadata cache created.
Jun 29 05:39:46 localhost systemd[1]: Started dnf makecache.
Jun 29 06:40:25 localhost systemd[1]: Starting dnf makecache...
Jun 29 06:40:25 localhost dnf[27752]: Metadata cache refreshed recently.
Jun 29 06:40:25 localhost systemd[1]: Started dnf makecache.
Jun 29 07:17:44 localhost caddy[904]: 2020/06/29 07:17:44 [INFO] [xxxxx.xxx] Maintenance routine: certificate expires in 719h50m26.109864758s; queueing for renewal
Jun 29 07:17:44 localhost caddy[904]: 2020/06/29 07:17:44 [INFO] [xxxxx.xxx] Maintenance routine: attempting renewal with 719h50m26.109477772s remaining
Jun 29 07:17:44 localhost caddy[904]: 2020/06/29 07:17:44 [INFO][xxxxx.xxx] Renew certificate; acquiring lock...
Jun 29 07:17:44 localhost caddy[904]: 2020/06/29 07:17:44 [INFO][xxxxx.xxx] Renew: Lock acquired; proceeding...
Jun 29 07:17:44 localhost caddy[904]: 2020/06/29 07:17:44 [INFO][xxxxx.xxx] Renew: 719h50m26.054843668s remaining
Jun 29 07:17:45 localhost caddy[904]: 2020/06/29 07:17:45 [INFO][xxxxx.xxx] Waiting on rate limiter...
Jun 29 07:17:45 localhost caddy[904]: 2020/06/29 07:17:45 [INFO][xxxxx.xxx] Done waiting
Jun 29 07:17:45 localhost caddy[904]: 2020/06/29 07:17:45 [INFO] [xxxxx.xxx] acme: Obtaining bundled SAN certificate given a CSR
Jun 29 07:17:46 localhost caddy[904]: 2020/06/29 07:17:46 [INFO] [xxxxx.xxx] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:46 localhost caddy[904]: 2020/06/29 07:17:46 [INFO] [xxxxx.xxx] acme: use tls-alpn-01 solver
Jun 29 07:17:46 localhost caddy[904]: 2020/06/29 07:17:46 [INFO] [xxxxx.xxx] acme: Trying to solve TLS-ALPN-01
Jun 29 07:17:46 localhost caddy[904]: 2020/06/29 07:17:46 http: TLS handshake error from 127.0.0.1:56508: EOF
Jun 29 07:17:50 localhost caddy[904]: 2020/06/29 07:17:50 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:51 localhost caddy[904]: 2020/06/29 07:17:51 [INFO] Unable to deactivate the authorization: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:51 localhost caddy[904]: 2020/06/29 07:17:51 [ERROR] error: one or more domains had a problem:
Jun 29 07:17:51 localhost caddy[904]: [xxxxx.xxx] acme: error: 400 :: urn:ietf:params:acme:error:connection :: Error getting validation data, url:
Jun 29 07:17:51 localhost caddy[904]: (challenge=tls-alpn-01 remaining=[http-01])
Jun 29 07:17:53 localhost caddy[904]: 2020/06/29 07:17:53 [INFO] [xxxxx.xxx] acme: Obtaining bundled SAN certificate given a CSR
Jun 29 07:17:53 localhost caddy[904]: 2020/06/29 07:17:53 [INFO] [xxxxx.xxx] AuthURL: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:53 localhost caddy[904]: 2020/06/29 07:17:53 [INFO] [xxxxx.xxx] acme: Could not find solver for: tls-alpn-01
Jun 29 07:17:53 localhost caddy[904]: 2020/06/29 07:17:53 [INFO] [xxxxx.xxx] acme: use http-01 solver
Jun 29 07:17:53 localhost caddy[904]: 2020/06/29 07:17:53 [INFO] [xxxxx.xxx] acme: Trying to solve HTTP-01
Jun 29 07:17:57 localhost caddy[904]: 2020/06/29 07:17:57 [INFO] Deactivating auth: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:58 localhost caddy[904]: 2020/06/29 07:17:58 [INFO] Unable to deactivate the authorization: https://acme-v02.api.letsencrypt.org/acme/authz-v3/*********
Jun 29 07:17:58 localhost caddy[904]: 2020/06/29 07:17:58 [ERROR] error: one or more domains had a problem:
Jun 29 07:17:58 localhost caddy[904]: [xxxxx.xxx] acme: error: 400 :: urn:ietf:params:acme:error:connection :: Fetching http://xxxxx.xxx/.well-known/acme-challenge/*****************************: Error getting validation data, url:

This topic was automatically closed after 30 days. New replies are no longer allowed.