mTLS: tls internal error

Ah, indeed I did miss that. Sigh, I kinda wish chi would path.Clean when they do the join, but oh well.

Fixed in acmeserver: Trim slashes from path prefix · caddyserver/caddy@2de7e14 · GitHub.

1 Like

If I build Caddy from the master, will I be able to test the fix?

Yep. It’s on the master branch.

Yeeha! :cowboy_hat_face: I’m back in business. Thanks @francislavoie @matt

2 Likes

Just a heads up at this stage. For the last nine days, access to the backend file server over an encrypted local connection has worked flawlessly. Today, it’s come crashing down.

Here’s a process log extract around the time of the last certificate renewal.

2021/06/30 18:35:36 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/06/30 18:35:37 {"id":"ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs","status":"pending","expires":"2021-07-01T10:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T10:34:37Z","notAfter":"2021-06-30T22:35:37Z","authorizations":["https://acme.lan/acme/local/authz/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ"],"finalize":"https://acme.lan/acme/local/order/ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs/finalize"}
2021/06/30 18:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/bldyyF2BeQLOuUEmtXo8sKO4w5LqLgG3"},{"type":"http-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/GX0y4Iz8IUm5WhrAlfs9PlYUJr2gyn1F"},{"type":"tls-alpn-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}],"wildcard":false,"expires":"2021-07-01T10:35:37Z"}
2021/06/30 18:35:37 {"type":"tls-alpn-01","status":"valid","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","validated":"2021-06-30T10:35:37Z","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}
2021/06/30 18:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/bldyyF2BeQLOuUEmtXo8sKO4w5LqLgG3"},{"type":"http-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/GX0y4Iz8IUm5WhrAlfs9PlYUJr2gyn1F"},{"type":"tls-alpn-01","status":"valid","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","validated":"2021-06-30T10:35:37Z","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}],"wildcard":false,"expires":"2021-07-01T10:35:37Z"}
2021/06/30 18:35:37 {"id":"ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs","status":"valid","expires":"2021-07-01T10:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T10:34:37Z","notAfter":"2021-06-30T22:35:37Z","authorizations":["https://acme.lan/acme/local/authz/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ"],"finalize":"https://acme.lan/acme/local/order/ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs/finalize","certificate":"https://acme.lan/acme/local/certificate/pm5EYk3UoUA5RCntrEO7bD4UR27YOT5e"}

All looks fine. However, when trying to access the file server, I get a 502 error and this is what I see in the frontend Caddy log.

{"level":"error","ts":"2021-06-30T20:42:30.585+0800","logger":"http.log.error.log4","msg":"x509: certificate has expired or is not yet valid: current time 2021-06-30T20:42:30+08:00 is after 2021-06-27T04:24:01Z","request":{"remote_addr":"10.1.1.222:50758","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"Sec-Fetch-User":["?1"],"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"],"Sec-Gpc":["1"],"Sec-Ch-Ua-Mobile":["?0"],"Sec-Fetch-Site":["none"],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-Dest":["document"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["max-age=0"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"file.udance.com.au"}},"duration":0.004412005,"status":502,"err_id":"1v7pyrwc1","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}

This is the version of Caddy I’m running on the frontend Caddy reverse proxy server:

root@caddy:/var/log/caddy # caddy version
v2.4.4-0.20210621175641-2de7e14e1c5f h1:/Kzlg8YluMMiXJBPoL8MkmArv5yqieoLHqKUDNuHtjE=

For the Caddy webserver on the backend:

root@file:/var/log/caddy # caddy version
v2.4.3 h1:Y1FaV2N4WO3rBqxSYA8UZsZTQdN+PwcoOcAiZTM8C0I=

There’s no change to the outcome even if I restart both the frontend and backend servers. The only thing that’s noticeably different is the rollover of the certificate date across a month boundary (see first log extract). I can’t say for certain now that this is connected to the issue. What I’ll do is wait till the certificate is renewed tomorrow afternoon. If I can then access the file server again, this then at least strongly suggests there’s some sort of boundary issue…

Yup. Just tried accessing the site this morning and it kicked in straight away. There could be a boundary issue.

There were two groups of logged messages relating to the local CA since my last post. It’s hard to say after which one the file server would have become accessible again as this happened overnight. I can’t explain why, I have a feeling it’s the latter.

...
2021/07/01 02:37:26 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/07/01 02:37:26 {"id":"mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop","status":"pending","expires":"2021-07-01T18:37:26Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T18:36:26Z","notAfter":"2021-07-01T06:37:26Z","authorizations":["https://acme.lan/acme/local/authz/DnAVZRdu495gJyegNKKG0dIkYIr835Gs"],"finalize":"https://acme.lan/acme/local/order/mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop/finalize"}
2021/07/01 02:37:26 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/LBDkDWToQDVrtQV5HP6FLeJxa9OOoxhy"},{"type":"http-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/plUkj2GYoWf9rHWp7OBhcc9t1tL7hODu"},{"type":"tls-alpn-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}],"wildcard":false,"expires":"2021-07-01T18:37:26Z"}
2021/07/01 02:37:27 {"type":"tls-alpn-01","status":"valid","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","validated":"2021-06-30T18:37:27Z","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}
2021/07/01 02:37:27 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/LBDkDWToQDVrtQV5HP6FLeJxa9OOoxhy"},{"type":"http-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/plUkj2GYoWf9rHWp7OBhcc9t1tL7hODu"},{"type":"tls-alpn-01","status":"valid","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","validated":"2021-06-30T18:37:27Z","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}],"wildcard":false,"expires":"2021-07-01T18:37:26Z"}
2021/07/01 02:37:27 {"id":"mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop","status":"valid","expires":"2021-07-01T18:37:26Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T18:36:26Z","notAfter":"2021-07-01T06:37:26Z","authorizations":["https://acme.lan/acme/local/authz/DnAVZRdu495gJyegNKKG0dIkYIr835Gs"],"finalize":"https://acme.lan/acme/local/order/mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop/finalize","certificate":"https://acme.lan/acme/local/certificate/hlXzkzUPU0giyNLSTQ0y0z0GFZmp2ZhT"}
...
{"level":"info","ts":"2021-07-01T05:28:22.652+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14314.347578222}
{"level":"info","ts":"2021-07-01T05:28:22.723+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14314.276012295}
{"level":"info","ts":"2021-07-01T05:28:22.843+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.958+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.959+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14314.040548352}
{"level":"info","ts":"2021-07-01T05:28:22.961+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.961+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.968+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-01T05:28:22.985+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-01T05:28:22.985+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-01T09:28:22.000Z"}
...

So I filtered the frontend process log across an 18 hour window (two-thirds of 24 hours = cert renewal window) and basically looked for lines with acme.lan and added some context around those. There’s also a section of the log where I first detected the issue and unsuccessfully tried to bring up the file server again. I’ve excluded all log lines between the start and finish of that investigation so as not to clutter the extract below…

2021/06/30 10:35:37 {"id":"09DgWVtNhQNXcV4PgI52Yaz5DCas7Xar","status":"pending","expires":"2021-07-01T02:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T02:34:37Z","notAfter":"2021-06-30T14:35:37Z","authorizations":["https://acme.lan/acme/local/authz/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu"],"finalize":"https://acme.lan/acme/local/order/09DgWVtNhQNXcV4PgI52Yaz5DCas7Xar/finalize"}
2021/06/30 10:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/mpJr3EPXxi76xSIZ7N48KRAtWeKnnRoA"},{"type":"http-01","status":"pending","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/6rSw1ssp6N0J0WluuDcDFfuhxGz81hhs"},{"type":"tls-alpn-01","status":"pending","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/ftrkfFoZtLsHOwL2DcEM11UxfWKSckwe"}],"wildcard":false,"expires":"2021-07-01T02:35:37Z"}
2021/06/30 10:35:37 {"type":"tls-alpn-01","status":"valid","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","validated":"2021-06-30T02:35:37Z","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/ftrkfFoZtLsHOwL2DcEM11UxfWKSckwe"}
2021/06/30 10:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/mpJr3EPXxi76xSIZ7N48KRAtWeKnnRoA"},{"type":"http-01","status":"pending","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/6rSw1ssp6N0J0WluuDcDFfuhxGz81hhs"},{"type":"tls-alpn-01","status":"valid","token":"U003HJKNbfGUonEBac2iNjcQLtyPzBBw","validated":"2021-06-30T02:35:37Z","url":"https://acme.lan/acme/local/challenge/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu/ftrkfFoZtLsHOwL2DcEM11UxfWKSckwe"}],"wildcard":false,"expires":"2021-07-01T02:35:37Z"}
2021/06/30 10:35:37 {"id":"09DgWVtNhQNXcV4PgI52Yaz5DCas7Xar","status":"valid","expires":"2021-07-01T02:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T02:34:37Z","notAfter":"2021-06-30T14:35:37Z","authorizations":["https://acme.lan/acme/local/authz/jqJ7BtjabnCFZ8a8iP5motjvZi5Se8uu"],"finalize":"https://acme.lan/acme/local/order/09DgWVtNhQNXcV4PgI52Yaz5DCas7Xar/finalize","certificate":"https://acme.lan/acme/local/certificate/orUpCGrp8nQThY8F4ODzbIVbQ5GW6sUV"}

{"level":"info","ts":"2021-06-30T13:24:02.786+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14399.213169316}
{"level":"info","ts":"2021-06-30T13:24:02.786+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14399.213069391}
{"level":"info","ts":"2021-06-30T13:24:02.801+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-06-30T13:24:02.853+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-06-30T13:24:02.853+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14399.146228869}
{"level":"info","ts":"2021-06-30T13:24:02.854+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-06-30T13:24:02.854+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-06-30T13:24:02.854+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-06-30T13:24:02.855+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-06-30T13:24:02.855+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-06-30T17:24:02.000Z"}

2021/06/30 18:35:36 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/06/30 18:35:37 {"id":"ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs","status":"pending","expires":"2021-07-01T10:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T10:34:37Z","notAfter":"2021-06-30T22:35:37Z","authorizations":["https://acme.lan/acme/local/authz/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ"],"finalize":"https://acme.lan/acme/local/order/ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs/finalize"}
2021/06/30 18:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/bldyyF2BeQLOuUEmtXo8sKO4w5LqLgG3"},{"type":"http-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/GX0y4Iz8IUm5WhrAlfs9PlYUJr2gyn1F"},{"type":"tls-alpn-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}],"wildcard":false,"expires":"2021-07-01T10:35:37Z"}
2021/06/30 18:35:37 {"type":"tls-alpn-01","status":"valid","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","validated":"2021-06-30T10:35:37Z","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}
2021/06/30 18:35:37 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/bldyyF2BeQLOuUEmtXo8sKO4w5LqLgG3"},{"type":"http-01","status":"pending","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/GX0y4Iz8IUm5WhrAlfs9PlYUJr2gyn1F"},{"type":"tls-alpn-01","status":"valid","token":"NzDVlFflpPE2o7YJXQSi1ZBCjqlKEf41","validated":"2021-06-30T10:35:37Z","url":"https://acme.lan/acme/local/challenge/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ/sGeqmQjNXD9wyqk0E8jCky5tXSbAtME5"}],"wildcard":false,"expires":"2021-07-01T10:35:37Z"}
2021/06/30 18:35:37 {"id":"ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs","status":"valid","expires":"2021-07-01T10:35:37Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T10:34:37Z","notAfter":"2021-06-30T22:35:37Z","authorizations":["https://acme.lan/acme/local/authz/3eknNjI5K0PQcavZ0RXVIrvSZzbJ2hwJ"],"finalize":"https://acme.lan/acme/local/order/ZrzzKoWkK0btnp4yOPrFhqPGviECg9cs/finalize","certificate":"https://acme.lan/acme/local/certificate/pm5EYk3UoUA5RCntrEO7bD4UR27YOT5e"}

{"level":"error","ts":"2021-06-30T20:42:26.933+0800","logger":"http.log.error.log4","msg":"x509: certificate has expired or is not yet valid: current time 2021-06-30T20:42:26+08:00 is after 2021-06-27T04:24:01Z","request":{"remote_addr":"10.1.1.222:50758","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Mode":["navigate"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Upgrade-Insecure-Requests":["1"],"Sec-Fetch-Site":["none"],"Sec-Fetch-User":["?1"],"Sec-Fetch-Dest":["document"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"],"Sec-Gpc":["1"],"Sec-Ch-Ua-Mobile":["?0"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"file.udance.com.au"}},"duration":0.096850394,"status":502,"err_id":"7exn25xxe","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}
>>> testing
{"level":"error","ts":"2021-07-01T01:49:34.825+0800","logger":"http.log.error.log4","msg":"x509: certificate has expired or is not yet valid: current time 2021-07-01T01:49:34+08:00 is after 2021-06-27T04:24:01Z","request":{"remote_addr":"10.1.1.222:56300","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Site":["none"],"Sec-Fetch-Dest":["document"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-GB,en;q=0.9"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Sec-Ch-Ua-Mobile":["?0"],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-User":["?1"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"file.udance.com.au"}},"duration":0.004760954,"status":502,"err_id":"sr7esqhx7","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}

2021/07/01 02:37:26 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/07/01 02:37:26 {"id":"mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop","status":"pending","expires":"2021-07-01T18:37:26Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T18:36:26Z","notAfter":"2021-07-01T06:37:26Z","authorizations":["https://acme.lan/acme/local/authz/DnAVZRdu495gJyegNKKG0dIkYIr835Gs"],"finalize":"https://acme.lan/acme/local/order/mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop/finalize"}
2021/07/01 02:37:26 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/LBDkDWToQDVrtQV5HP6FLeJxa9OOoxhy"},{"type":"http-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/plUkj2GYoWf9rHWp7OBhcc9t1tL7hODu"},{"type":"tls-alpn-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}],"wildcard":false,"expires":"2021-07-01T18:37:26Z"}
2021/07/01 02:37:27 {"type":"tls-alpn-01","status":"valid","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","validated":"2021-06-30T18:37:27Z","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}
2021/07/01 02:37:27 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/LBDkDWToQDVrtQV5HP6FLeJxa9OOoxhy"},{"type":"http-01","status":"pending","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/plUkj2GYoWf9rHWp7OBhcc9t1tL7hODu"},{"type":"tls-alpn-01","status":"valid","token":"gXHNUMoHiUdvf9L9XAmt9kbpjPPrGR5M","validated":"2021-06-30T18:37:27Z","url":"https://acme.lan/acme/local/challenge/DnAVZRdu495gJyegNKKG0dIkYIr835Gs/ucLl8foNdQIE1iDCGe8qlqrDfV77Kwjz"}],"wildcard":false,"expires":"2021-07-01T18:37:26Z"}
2021/07/01 02:37:27 {"id":"mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop","status":"valid","expires":"2021-07-01T18:37:26Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-06-30T18:36:26Z","notAfter":"2021-07-01T06:37:26Z","authorizations":["https://acme.lan/acme/local/authz/DnAVZRdu495gJyegNKKG0dIkYIr835Gs"],"finalize":"https://acme.lan/acme/local/order/mpEeaLdEfaWWFXJZgrgv6EojGvXaLgop/finalize","certificate":"https://acme.lan/acme/local/certificate/hlXzkzUPU0giyNLSTQ0y0z0GFZmp2ZhT"}

{"level":"info","ts":"2021-07-01T05:28:22.652+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14314.347578222}
{"level":"info","ts":"2021-07-01T05:28:22.723+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14314.276012295}
{"level":"info","ts":"2021-07-01T05:28:22.843+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.958+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.959+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14314.040548352}
{"level":"info","ts":"2021-07-01T05:28:22.961+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.961+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-01T05:28:22.968+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-01T05:28:22.985+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-01T05:28:22.985+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-01T09:28:22.000Z"

I think this is going to be one of those tricky ones to resolve because the evidence, at this stage, suggests that it only occurs during a relatively short window when the month rolls over. So, there are only 12 times a year to do any sort of testing.

What I’ll do at this stage is a daily check during the month to make sure I can still access the file server. I’ll increase the frequency of those checks around the last day of July. If I can’t access the file server during the month, that blows out of the water the theory about a boundary issue. However, if I can access the file server during the month, but not sometime during the last day of the month, that almost
certainly confirms a boundary issue exists. If we get to that point, then the question is going to be ‘Is it a Caddy issue or a Smallstep issue?’.

Well, my theory that there might be an end-of-month boundary issue has been dashed. I haven’t been able to contact the file server for almost two days now (since 3-Jul AM). I had hoped it would recover itself, but it hasn’t.

I rolled back to non-secure backend comms and I’m able to contact the file server. Rolling forward to secure backend comms and I end up with the 502 error. This is the error message I notice in the frontend log when I try to access the file server.

{"level":"error","ts":"2021-07-04T19:57:05.883+0800","logger":"http.log.error.log4","msg":"x509: certificate has expired or is not yet valid: current time 2021-07-04T19:57:05+08:00 is after 2021-07-02T18:54:16Z","request":{"remote_addr":"10.1.1.222:58030","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"Sec-Fetch-Dest":["document"],"Sec-Gpc":["1"],"Cache-Control":["max-age=0"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Sec-Ch-Ua-Mobile":["?0"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Sec-Fetch-Site":["none"],"Sec-Fetch-User":["?1"],"Upgrade-Insecure-Requests":["1"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Mode":["navigate"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"file.udance.com.au"}},"duration":0.006338362,"status":502,"err_id":"z4r2ffd8a","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}

I think the clue could be in this error message, but I don’t understand what it means "x509: certificate has expired or is not yet valid: current time 2021-07-04T19:57:05+08:00 is after 2021-07-02T18:54:16Z". What is the after time? What does that refer to?

@basil the mTLS certs from Caddy’s PKI module have a 7 day lifetime, whereas public ACME has 90 day lifetimes. So they should renew every 5-ish days. The time there is probably the “expires at” time on the certificate. I don’t understand why it wouldn’t have renewed in time.

@matt got any ideas?

Edit: Sorry, 7 days is the lifetime of the intermediate CA cert. The leaf certs should have 12 hour lifetimes. So you should see a renewal every 8 hours I think.

And that’s certainly the evidence in the frontend process log for both acme.lan and file.lan. There’s a pattern that clearly repeats and certs are being renewed every eight hours. Something is going awry though.

2021/07/04 02:37:21 {"id":"T1HjnYPKUGvT7mk4cEiitoQlxIfzyLUn","status":"pending","expires":"2021-07-04T18:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-03T18:36:21Z","notAfter":"2021-07-04T06:37:21Z","authorizations":["https://acme.lan/acme/local/authz/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk"],"finalize":"https://acme.lan/acme/local/order/T1HjnYPKUGvT7mk4cEiitoQlxIfzyLUn/finalize"}
2021/07/04 02:37:22 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/4sSzBcr5WVtgS75dKrQp4EAqQBsDFumn"},{"type":"http-01","status":"pending","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/Kq4UvkDergdCjHlSCQHByfLf5OnzWl7J"},{"type":"tls-alpn-01","status":"pending","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/fzMD2evl1qvZriUzZ9WIjv3jMSy7owpP"}],"wildcard":false,"expires":"2021-07-04T18:37:21Z"}
2021/07/04 02:37:22 {"type":"tls-alpn-01","status":"valid","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","validated":"2021-07-03T18:37:22Z","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/fzMD2evl1qvZriUzZ9WIjv3jMSy7owpP"}
2021/07/04 02:37:22 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/4sSzBcr5WVtgS75dKrQp4EAqQBsDFumn"},{"type":"http-01","status":"pending","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/Kq4UvkDergdCjHlSCQHByfLf5OnzWl7J"},{"type":"tls-alpn-01","status":"valid","token":"6mtYDVKkEC6aVII8e0AVp6HkHlMLFSUM","validated":"2021-07-03T18:37:22Z","url":"https://acme.lan/acme/local/challenge/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk/fzMD2evl1qvZriUzZ9WIjv3jMSy7owpP"}],"wildcard":false,"expires":"2021-07-04T18:37:21Z"}
2021/07/04 02:37:22 {"id":"T1HjnYPKUGvT7mk4cEiitoQlxIfzyLUn","status":"valid","expires":"2021-07-04T18:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-03T18:36:21Z","notAfter":"2021-07-04T06:37:21Z","authorizations":["https://acme.lan/acme/local/authz/0SOORDJruK2wbMNjomCpFUTp4a1W2Uyk"],"finalize":"https://acme.lan/acme/local/order/T1HjnYPKUGvT7mk4cEiitoQlxIfzyLUn/finalize","certificate":"https://acme.lan/acme/local/certificate/M8Ia0CbXl93jxsZcwmgXPEvL5h5slrJw"}
...
{"level":"info","ts":"2021-07-04T05:38:22.620+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14399.379036839}
{"level":"info","ts":"2021-07-04T05:38:22.621+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14399.378902302}
{"level":"info","ts":"2021-07-04T05:38:22.639+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T05:38:22.670+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T05:38:22.670+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14399.329581281}
{"level":"info","ts":"2021-07-04T05:38:22.671+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T05:38:22.671+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T05:38:22.671+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-04T05:38:22.688+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-04T05:38:22.688+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-04T09:38:22.000Z"}
...
2021/07/04 10:37:21 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/07/04 10:37:21 {"id":"RVVxm90thsFPCfjb6gpdEZG1N7f7UmSL","status":"pending","expires":"2021-07-05T02:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T02:36:21Z","notAfter":"2021-07-04T14:37:21Z","authorizations":["https://acme.lan/acme/local/authz/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN"],"finalize":"https://acme.lan/acme/local/order/RVVxm90thsFPCfjb6gpdEZG1N7f7UmSL/finalize"}
2021/07/04 10:37:21 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/l4mXQiNjp3RkBEqSSFYuuZcQtT5UvGiy"},{"type":"http-01","status":"pending","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/xvrZe5BQrPzqoHBFjOeS1bQ9f9YwDBJ2"},{"type":"tls-alpn-01","status":"pending","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/RzFNw8MpvhtE0KoTxEGzxG6B6bXnFFfQ"}],"wildcard":false,"expires":"2021-07-05T02:37:21Z"}
2021/07/04 10:37:21 {"type":"tls-alpn-01","status":"valid","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","validated":"2021-07-04T02:37:21Z","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/RzFNw8MpvhtE0KoTxEGzxG6B6bXnFFfQ"}
2021/07/04 10:37:22 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/l4mXQiNjp3RkBEqSSFYuuZcQtT5UvGiy"},{"type":"http-01","status":"pending","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/xvrZe5BQrPzqoHBFjOeS1bQ9f9YwDBJ2"},{"type":"tls-alpn-01","status":"valid","token":"mnx0euR30bQGQNysQdxLzkiQcUBk5Mgk","validated":"2021-07-04T02:37:21Z","url":"https://acme.lan/acme/local/challenge/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN/RzFNw8MpvhtE0KoTxEGzxG6B6bXnFFfQ"}],"wildcard":false,"expires":"2021-07-05T02:37:21Z"}
2021/07/04 10:37:22 {"id":"RVVxm90thsFPCfjb6gpdEZG1N7f7UmSL","status":"valid","expires":"2021-07-05T02:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T02:36:21Z","notAfter":"2021-07-04T14:37:21Z","authorizations":["https://acme.lan/acme/local/authz/iGRiujsYOPXZEjATuGsLSkXatNvbmOQN"],"finalize":"https://acme.lan/acme/local/order/RVVxm90thsFPCfjb6gpdEZG1N7f7UmSL/finalize","certificate":"https://acme.lan/acme/local/certificate/NCEkqZJFKTYSAGcibxyChuVU4fyFUCGX"}
...
{"level":"info","ts":"2021-07-04T13:38:22.590+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14399.409813269}
{"level":"info","ts":"2021-07-04T13:38:22.590+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14399.409738217}
{"level":"info","ts":"2021-07-04T13:38:22.641+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T13:38:22.668+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T13:38:22.668+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14399.331104107}
{"level":"info","ts":"2021-07-04T13:38:22.669+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T13:38:22.669+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-04T13:38:22.669+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-04T13:38:22.685+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-04T13:38:22.686+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-04T17:38:22.000Z"}
...
2021/07/04 18:37:21 {"id":"dBJB7m71as9ddveHi8dWdyuaavChivgE","status":"pending","expires":"2021-07-05T10:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T10:36:21Z","notAfter":"2021-07-04T22:37:21Z","authorizations":["https://acme.lan/acme/local/authz/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN"],"finalize":"https://acme.lan/acme/local/order/dBJB7m71as9ddveHi8dWdyuaavChivgE/finalize"}
2021/07/04 18:37:21 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/YkoKR47aXa4P9XqaQBB5D1eFX1Mhh8rB"},{"type":"http-01","status":"pending","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/hMBboFcVIS2dyAhOyafbdQtaFDW5WmLc"},{"type":"tls-alpn-01","status":"pending","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/KEJRXBI6Cl3Majh21brSyY6IpVC6QCJk"}],"wildcard":false,"expires":"2021-07-05T10:37:21Z"}
2021/07/04 18:37:21 {"type":"tls-alpn-01","status":"valid","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","validated":"2021-07-04T10:37:21Z","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/KEJRXBI6Cl3Majh21brSyY6IpVC6QCJk"}
2021/07/04 18:37:21 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/YkoKR47aXa4P9XqaQBB5D1eFX1Mhh8rB"},{"type":"http-01","status":"pending","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/hMBboFcVIS2dyAhOyafbdQtaFDW5WmLc"},{"type":"tls-alpn-01","status":"valid","token":"74ZcYvXGhIzkfYcEVYM2v7GFMHhn7lPc","validated":"2021-07-04T10:37:21Z","url":"https://acme.lan/acme/local/challenge/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN/KEJRXBI6Cl3Majh21brSyY6IpVC6QCJk"}],"wildcard":false,"expires":"2021-07-05T10:37:21Z"}
2021/07/04 18:37:22 {"id":"dBJB7m71as9ddveHi8dWdyuaavChivgE","status":"valid","expires":"2021-07-05T10:37:21Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T10:36:21Z","notAfter":"2021-07-04T22:37:21Z","authorizations":["https://acme.lan/acme/local/authz/rZJ60AHxulqaKQrbLzP12B6v7nn7J6rN"],"finalize":"https://acme.lan/acme/local/order/dBJB7m71as9ddveHi8dWdyuaavChivgE/finalize","certificate":"https://acme.lan/acme/local/certificate/7sgy7CUXxrKXLmREauT2YK7Zs8NfKqkc"}

I’ve stumbled across something I didn’t quite expect.

I restarted the frontend Caddy server. This is what I saw in the logs. All looks pretty normal.

{"level":"info","ts":"2021-07-04T21:50:33.656+0800","logger":"http.log.access","msg":"handled request","request":{"remote_addr":"172.70.42.60:12274","proto":"HTTP/1.1","method":"HEAD","host":"www.caffigoalkeeping.com.au","uri":"/","headers":{"Cf-Connecting-Ip":["192.0.101.226"],"Cf-Ipcountry":["US"],"X-Forwarded-For":["192.0.101.226"],"Cf-Ray":["6698d2c00de5058b-IAD"],"X-Forwarded-Proto":["https"],"Cf-Visitor":["{\"scheme\":\"https\"}"],"User-Agent":["jetmon/1.0 (Jetpack Site Uptime Monitor by WordPress.com)"],"Cdn-Loop":["cloudflare"],"Connection":["Keep-Alive"],"Accept-Encoding":["gzip"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"www.caffigoalkeeping.com.au"}},"common_log":"172.70.42.60 - - [04/Jul/2021:21:50:33 +0800] \"HEAD / HTTP/1.1\" 301 0","duration":0.000037952,"size":0,"status":301,"resp_headers":{"Server":["Caddy"],"Location":["https://caffigoalkeeping.com.au/"],"Content-Type":[]}}
{"level":"info","ts":"2021-07-04T21:52:12.193+0800","logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/stop","remote_addr":"127.0.0.1:22325","headers":{"Accept-Encoding":["gzip"],"Content-Length":["0"],"Origin":["localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"warn","ts":"2021-07-04T21:52:12.213+0800","logger":"admin.api","msg":"exiting; byeee!! 👋"}
{"level":"info","ts":"2021-07-04T21:52:12.773+0800","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0006d28c0"}
{"level":"info","ts":"2021-07-04T21:52:12.775+0800","logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
{"level":"info","ts":"2021-07-04T21:52:12.775+0800","logger":"admin.api","msg":"shutdown complete","exit_code":0}
{"level":"info","ts":1625406732.8427608,"msg":"using provided configuration","config_file":"/usr/local/www/Caddyfile","config_adapter":"caddyfile"}
{"level":"warn","ts":1625406732.8823333,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/usr/local/www/Caddyfile","line":2}
{"level":"info","ts":"2021-07-04T21:52:12.885+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
{"level":"info","ts":"2021-07-04T21:52:12.885+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0003a67e0"}
{"level":"info","ts":"2021-07-04T21:52:12.895+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-07-04T21:52:12.895+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":"2021-07-04T21:52:19.113+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["readymcgetty.com.au","xenografix.com.au","*.udance.com.au","caffigoalkeeping.com","www.udance.com.au","udance.com.au","www.readymcgetty.com.au","www.xenografix.com.au","caffigoalkeeping.com.au","acme.lan","www.caffigoalkeeping.com","www.caffigoalkeeping.com.au"]}
{"level":"info","ts":"2021-07-04T21:52:19.113+0800","logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"warn","ts":"2021-07-04T21:52:19.139+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-04T21:52:19.265+0800","logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"info","ts":"2021-07-04T21:52:19.265+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-07-04T21:52:19.265+0800","msg":"serving initial configuration"}
Successfully started Caddy (pid=48184) - Caddy is running in the background
{"level":"info","ts":"2021-07-04T21:52:19.479+0800","logger":"tls","msg":"finished cleaning storage units"}

By chance, i happened to then do a caddy validate and got this unexpected result in the last line.

root@caddy:/var/log/caddy # service caddy configtest
2021/07/04 14:00:29.931 INFO    using provided configuration    {"config_file": "/usr/local/www/Caddyfile", "config_adapter": "caddyfile"}
2021/07/04 14:00:29.937 WARN    input is not formatted with 'caddy fmt' {"adapter": "caddyfile", "file": "/usr/local/www/Caddyfile", "line": 2}
{"level":"info","ts":"2021-07-04T22:00:29.938+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000287260"}
{"level":"info","ts":"2021-07-04T22:00:29.947+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-07-04T22:00:29.947+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":"2021-07-04T22:00:39.092+0800","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc000287260"}
validate: loading http app module: provision http: server srv0: setting up route handlers: route 8: loading handler modules: position 0: loading module 'subroute': provision http.handlers.subroute: setting up subroutes: route 0: loading handler modules: position 0: loading module 'acme_server': provision http.handlers.acme_server: Error opening database of Type bbolt with source /var/db/caddy/data/caddy/acme_server/local/db: timeout

Hmm, I think Bolt DB has an exclusive lock on the file maybe, so if you try to validate the config while Caddy is already running, it won’t let you? I think smallstep uses GitHub - etcd-io/bbolt: An embedded key/value database for Go. for storing its data (or we configured it to use Bolt rather, I think).

Ok, so I can safely ignore that message.

Last night, I tried anything and everything I could think of to re-establish contact with the file server. I failed! This evening, the file server magically reappeared. I’ve tried everything I can to break it and I can’t!

Somewhere between the hours of 23:25:26 last night and 18:12:28 this evening, mutual authentication started to work again. I did leave debug on overnight so there’s more verbose information in the log. To avoid clutter, I’ve filtered out what I thought might be relevant. Hopefully, there’s something here that may be helpful in pinpointing the issue.

Note: I’ve had to split the log across two posts due to post size limits.

{"level":"error","ts":"2021-07-04T23:25:26.615+0800","logger":"http.log.error.log5","msg":"x509: certificate has expired or is not yet valid: current time 2021-07-04T23:25:26+08:00 is after 2021-07-02T18:54:16Z","request":{"remote_addr":"10.1.1.222:58025","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"],"Sec-Gpc":["1"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Sec-Fetch-Site":["none"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-User":["?1"],"Sec-Ch-Ua-Mobile":["?0"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Purpose":["prefetch"],"Sec-Fetch-Dest":["document"],"Accept-Encoding":["gzip, deflate, br"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"cloud.udance.com.au"}},"duration":0.00574175,"status":502,"err_id":"e8wjs1ekn","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}
...
2021/07/05 02:38:06 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/07/05 02:38:06 {"id":"6BX4BkdCSpbsCYElQF6HU7IvDYQkuqyW","status":"pending","expires":"2021-07-05T18:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T18:37:06Z","notAfter":"2021-07-05T06:38:06Z","authorizations":["https://acme.lan/acme/local/authz/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V"],"finalize":"https://acme.lan/acme/local/order/6BX4BkdCSpbsCYElQF6HU7IvDYQkuqyW/finalize"}
2021/07/05 02:38:06 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/NvWTu2P3ED0bTrPbAEMrnCQe9XsGJzFv"},{"type":"http-01","status":"pending","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/iywvORZIXuXjJpVAOLlnBoY0D0USlNEK"},{"type":"tls-alpn-01","status":"pending","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/GkfKoaZQhDdFX1RUZKKMAzqc3JpNVaXi"}],"wildcard":false,"expires":"2021-07-05T18:38:06Z"}
2021/07/05 02:38:07 {"type":"tls-alpn-01","status":"valid","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","validated":"2021-07-04T18:38:07Z","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/GkfKoaZQhDdFX1RUZKKMAzqc3JpNVaXi"}
2021/07/05 02:38:07 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/NvWTu2P3ED0bTrPbAEMrnCQe9XsGJzFv"},{"type":"http-01","status":"pending","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/iywvORZIXuXjJpVAOLlnBoY0D0USlNEK"},{"type":"tls-alpn-01","status":"valid","token":"hf9fgcK9ORTqK7dhWoUnJfLQw3PfyfEl","validated":"2021-07-04T18:38:07Z","url":"https://acme.lan/acme/local/challenge/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V/GkfKoaZQhDdFX1RUZKKMAzqc3JpNVaXi"}],"wildcard":false,"expires":"2021-07-05T18:38:06Z"}
2021/07/05 02:38:07 {"id":"6BX4BkdCSpbsCYElQF6HU7IvDYQkuqyW","status":"valid","expires":"2021-07-05T18:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-04T18:37:06Z","notAfter":"2021-07-05T06:38:06Z","authorizations":["https://acme.lan/acme/local/authz/TkT96O1Tlvf3LHzzNldoyuOxTAdx6x8V"],"finalize":"https://acme.lan/acme/local/order/6BX4BkdCSpbsCYElQF6HU7IvDYQkuqyW/finalize","certificate":"https://acme.lan/acme/local/certificate/vIBHPcHs1rTcx1q7oHctAnJWCG5f5S3k"}
...
{"level":"info","ts":"2021-07-05T04:10:05.518+0800","logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_addr":"127.0.0.1:18983","headers":{"Accept-Encoding":["gzip"],"Content-Length":["11335"],"Content-Type":["application/json"],"Origin":["localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"info","ts":"2021-07-05T04:10:05.520+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
{"level":"info","ts":"2021-07-05T04:10:05.520+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0003a7f80"}
{"level":"info","ts":"2021-07-05T04:10:05.607+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-07-05T04:10:05.607+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"debug","ts":"2021-07-05T04:10:09.841+0800","logger":"http.handlers.acme_server","msg":"loaded preexisting CA database","db_key":"local"}
{"level":"info","ts":"2021-07-05T04:10:11.197+0800","logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"debug","ts":"2021-07-05T04:10:11.197+0800","logger":"http","msg":"starting server loop","address":"[::]:443","http3":false,"tls":true}
{"level":"debug","ts":"2021-07-05T04:10:11.197+0800","logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
{"level":"info","ts":"2021-07-05T04:10:11.197+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["www.xenografix.com.au","acme.lan","www.caffigoalkeeping.com.au","www.caffigoalkeeping.com","xenografix.com.au","www.readymcgetty.com.au","caffigoalkeeping.com.au","readymcgetty.com.au","udance.com.au","caffigoalkeeping.com","www.udance.com.au","*.udance.com.au"]}
{"level":"debug","ts":"2021-07-05T04:10:11.247+0800","logger":"tls","msg":"loading managed certificate","domain":"www.xenografix.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.294+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com.au","expiration":"2021-08-30T18:17:55.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.365+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com","expiration":"2021-08-30T18:24:18.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.426+0800","logger":"tls","msg":"loading managed certificate","domain":"xenografix.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.460+0800","logger":"tls","msg":"loading managed certificate","domain":"www.readymcgetty.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.527+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.574+0800","logger":"tls","msg":"loading managed certificate","domain":"readymcgetty.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.628+0800","logger":"tls","msg":"loading managed certificate","domain":"udance.com.au","expiration":"2021-08-30T18:17:51.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.684+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.745+0800","logger":"tls","msg":"loading managed certificate","domain":"www.udance.com.au","expiration":"2021-08-30T18:18:02.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T04:10:11.819+0800","logger":"tls","msg":"loading managed certificate","domain":"*.udance.com.au","expiration":"2021-08-30T19:06:12.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"warn","ts":"2021-07-05T04:10:11.876+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-05T04:10:11.885+0800","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0007b8070"}
{"level":"info","ts":"2021-07-05T04:10:11.885+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-07-05T04:10:11.885+0800","logger":"admin.api","msg":"load complete"}
{"level":"info","ts":"2021-07-05T04:10:12.404+0800","logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
...
{"level":"info","ts":"2021-07-05T05:50:05.594+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14250.405354898}
{"level":"info","ts":"2021-07-05T05:50:05.614+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14250.385307552}
{"level":"info","ts":"2021-07-05T05:50:05.654+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T05:50:05.750+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T05:50:05.751+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14250.248951765}
{"level":"info","ts":"2021-07-05T05:50:05.802+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T05:50:05.802+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T05:50:05.802+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-05T05:50:05.803+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-05T05:50:05.803+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-05T09:50:05.000Z"}
{"level":"debug","ts":"2021-07-05T05:50:19.129+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:47848: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:19.885+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:40126: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:20.476+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:44750: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:20.651+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:60894: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:21.247+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:36686: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:21.471+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:52148: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:22.300+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:43984: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:22.751+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:55484: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:23.066+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:54840: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:23.501+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:35694: no certificate available for '10.1.1.4'"}
{"level":"debug","ts":"2021-07-05T05:50:23.816+0800","logger":"http.stdlib","msg":"http: TLS handshake error from 45.146.164.110:33820: no certificate available for '10.1.1.4'"}
...
2021/07/05 10:38:06 {"id":"hXKTKf0TWvKayuXayc2je9vUA6zFgKVr","status":"pending","expires":"2021-07-06T02:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-05T02:37:06Z","notAfter":"2021-07-05T14:38:06Z","authorizations":["https://acme.lan/acme/local/authz/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx"],"finalize":"https://acme.lan/acme/local/order/hXKTKf0TWvKayuXayc2je9vUA6zFgKVr/finalize"}
2021/07/05 10:38:06 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/hDEenqrH9YO7e5EwnLwoveOhpTn1UDNr"},{"type":"http-01","status":"pending","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/XgvWR8o8FZqt2P41WkxJsT2AZR9xpUHe"},{"type":"tls-alpn-01","status":"pending","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/dKsUrtuFOvbQhKGvMuMoiHJIDIZWXPuO"}],"wildcard":false,"expires":"2021-07-06T02:38:06Z"}
2021/07/05 10:38:06 {"type":"tls-alpn-01","status":"valid","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","validated":"2021-07-05T02:38:06Z","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/dKsUrtuFOvbQhKGvMuMoiHJIDIZWXPuO"}
2021/07/05 10:38:06 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/hDEenqrH9YO7e5EwnLwoveOhpTn1UDNr"},{"type":"http-01","status":"pending","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/XgvWR8o8FZqt2P41WkxJsT2AZR9xpUHe"},{"type":"tls-alpn-01","status":"valid","token":"5x2A0HO0PldVCtGC89Nout2KxvvZCQS8","validated":"2021-07-05T02:38:06Z","url":"https://acme.lan/acme/local/challenge/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx/dKsUrtuFOvbQhKGvMuMoiHJIDIZWXPuO"}],"wildcard":false,"expires":"2021-07-06T02:38:06Z"}
2021/07/05 10:38:07 {"id":"hXKTKf0TWvKayuXayc2je9vUA6zFgKVr","status":"valid","expires":"2021-07-06T02:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-05T02:37:06Z","notAfter":"2021-07-05T14:38:06Z","authorizations":["https://acme.lan/acme/local/authz/xMEzvSmL9NYS3g87z2lQBiBHTpB6iKxx"],"finalize":"https://acme.lan/acme/local/order/hXKTKf0TWvKayuXayc2je9vUA6zFgKVr/finalize","certificate":"https://acme.lan/acme/local/certificate/3lemMXnwSnNUC2uYsUkO3zlVK7oU1Uly"}
...
{"level":"info","ts":"2021-07-05T13:50:05.550+0800","logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["acme.lan"],"remaining":14399.449195622}
{"level":"info","ts":"2021-07-05T13:50:05.550+0800","logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["acme.lan"],"remaining":14399.44912152}
{"level":"info","ts":"2021-07-05T13:50:05.571+0800","logger":"tls.renew","msg":"acquiring lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T13:50:05.611+0800","logger":"tls.renew","msg":"lock acquired","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T13:50:05.611+0800","logger":"tls.renew","msg":"renewing certificate","identifier":"acme.lan","remaining":14399.388319021}
{"level":"info","ts":"2021-07-05T13:50:05.612+0800","logger":"tls.renew","msg":"certificate renewed successfully","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T13:50:05.612+0800","logger":"tls.renew","msg":"releasing lock","identifier":"acme.lan"}
{"level":"info","ts":"2021-07-05T13:50:05.612+0800","logger":"tls","msg":"reloading managed certificate","identifiers":["acme.lan"]}
{"level":"warn","ts":"2021-07-05T13:50:05.633+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-05T13:50:05.633+0800","logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["acme.lan"],"new_expiration":"2021-07-05T17:50:05.000Z"}
...
{"level":"info","ts":"2021-07-05T13:51:59.409+0800","logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_addr":"127.0.0.1:52703","headers":{"Accept-Encoding":["gzip"],"Content-Length":["11827"],"Content-Type":["application/json"],"Origin":["localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"info","ts":"2021-07-05T13:51:59.412+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
{"level":"info","ts":"2021-07-05T13:51:59.412+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0000c39d0"}
{"level":"info","ts":"2021-07-05T13:51:59.469+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-07-05T13:51:59.469+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"debug","ts":"2021-07-05T13:52:03.629+0800","logger":"http.handlers.acme_server","msg":"loaded preexisting CA database","db_key":"local"}
{"level":"info","ts":"2021-07-05T13:52:05.163+0800","logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"debug","ts":"2021-07-05T13:52:05.164+0800","logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
{"level":"debug","ts":"2021-07-05T13:52:05.164+0800","logger":"http","msg":"starting server loop","address":"[::]:443","http3":false,"tls":true}
{"level":"info","ts":"2021-07-05T13:52:05.164+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["www.caffigoalkeeping.com","www.readymcgetty.com.au","xenografix.com.au","*.udance.com.au","www.caffigoalkeeping.com.au","caffigoalkeeping.com.au","acme.lan","caffigoalkeeping.com","www.xenografix.com.au","office.udance.com.au","www.udance.com.au","udance.com.au","readymcgetty.com.au"]}
{"level":"info","ts":"2021-07-05T13:52:05.164+0800","logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.211+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com","expiration":"2021-08-30T18:24:18.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.265+0800","logger":"tls","msg":"loading managed certificate","domain":"www.readymcgetty.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.330+0800","logger":"tls","msg":"loading managed certificate","domain":"xenografix.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.382+0800","logger":"tls","msg":"loading managed certificate","domain":"*.udance.com.au","expiration":"2021-08-30T19:06:12.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.423+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com.au","expiration":"2021-08-30T18:17:55.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.472+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.522+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.574+0800","logger":"tls","msg":"loading managed certificate","domain":"www.xenografix.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.617+0800","logger":"tls","msg":"loading managed certificate","domain":"office.udance.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.674+0800","logger":"tls","msg":"loading managed certificate","domain":"www.udance.com.au","expiration":"2021-08-30T18:18:02.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.688+0800","logger":"tls","msg":"loading managed certificate","domain":"udance.com.au","expiration":"2021-08-30T18:17:51.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T13:52:05.713+0800","logger":"tls","msg":"loading managed certificate","domain":"readymcgetty.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"warn","ts":"2021-07-05T13:52:05.713+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-07-05T13:52:05.717+0800","logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":"2021-07-05T13:52:05.787+0800","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0003a7f80"}
{"level":"info","ts":"2021-07-05T13:52:05.787+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-07-05T13:52:05.787+0800","logger":"admin.api","msg":"load complete"}
{"level":"info","ts":"2021-07-05T13:52:05.854+0800","logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
{"level":"info","ts":"2021-07-05T13:52:23.172+0800","logger":"http.log.access","msg":"handled request","request":{"remote_addr":"172.70.34.18:42300","proto":"HTTP/1.1","method":"HEAD","host":"www.caffigoalkeeping.com.au","uri":"/","headers":{"Connection":["Keep-Alive"],"Cf-Ipcountry":["US"],"X-Forwarded-Proto":["https"],"Cf-Connecting-Ip":["192.0.101.226"],"Cdn-Loop":["cloudflare"],"Accept-Encoding":["gzip"],"X-Forwarded-For":["192.0.101.226"],"Cf-Ray":["669e53ac3acc5a28-IAD"],"Cf-Visitor":["{\"scheme\":\"https\"}"],"User-Agent":["jetmon/1.0 (Jetpack Site Uptime Monitor by WordPress.com)"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"www.caffigoalkeeping.com.au"}},"common_log":"172.70.34.18 - - [05/Jul/2021:13:52:23 +0800] \"HEAD / HTTP/1.1\" 301 0","duration":0.000045343,"size":0,"status":301,"resp_headers":{"Server":["Caddy"],"Location":["https://caffigoalkeeping.com.au/"],"Content-Type":[]}}
...
{"level":"info","ts":"2021-07-05T14:02:03.071+0800","logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_addr":"127.0.0.1:12767","headers":{"Accept-Encoding":["gzip"],"Content-Length":["11532"],"Content-Type":["application/json"],"Origin":["localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"info","ts":"2021-07-05T14:02:03.074+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["[::1]:2019","127.0.0.1:2019","localhost:2019"]}
{"level":"info","ts":"2021-07-05T14:02:03.074+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0003b5420"}
{"level":"info","ts":"2021-07-05T14:02:03.074+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-07-05T14:02:03.074+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"debug","ts":"2021-07-05T14:02:07.216+0800","logger":"http.handlers.acme_server","msg":"loaded preexisting CA database","db_key":"local"}
{"level":"info","ts":"2021-07-05T14:02:08.448+0800","logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"debug","ts":"2021-07-05T14:02:08.448+0800","logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
{"level":"debug","ts":"2021-07-05T14:02:08.448+0800","logger":"http","msg":"starting server loop","address":"[::]:443","http3":false,"tls":true}
{"level":"info","ts":"2021-07-05T14:02:08.448+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["www.caffigoalkeeping.com.au","udance.com.au","*.udance.com.au","www.caffigoalkeeping.com","office.udance.com.au","readymcgetty.com.au","www.udance.com.au","www.readymcgetty.com.au","www.xenografix.com.au","xenografix.com.au","caffigoalkeeping.com","caffigoalkeeping.com.au","acme.lan"]}
{"level":"warn","ts":"2021-07-05T14:02:08.448+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"debug","ts":"2021-07-05T14:02:08.448+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com.au","expiration":"2021-08-30T18:17:55.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.449+0800","logger":"tls","msg":"loading managed certificate","domain":"udance.com.au","expiration":"2021-08-30T18:17:51.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.450+0800","logger":"tls","msg":"loading managed certificate","domain":"*.udance.com.au","expiration":"2021-08-30T19:06:12.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.450+0800","logger":"tls","msg":"loading managed certificate","domain":"www.caffigoalkeeping.com","expiration":"2021-08-30T18:24:18.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.451+0800","logger":"tls","msg":"loading managed certificate","domain":"office.udance.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.451+0800","logger":"tls","msg":"loading managed certificate","domain":"readymcgetty.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.452+0800","logger":"tls","msg":"loading managed certificate","domain":"www.udance.com.au","expiration":"2021-08-30T18:18:02.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.452+0800","logger":"tls","msg":"loading managed certificate","domain":"www.readymcgetty.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.453+0800","logger":"tls","msg":"loading managed certificate","domain":"www.xenografix.com.au","expiration":"2021-08-30T18:17:57.000Z","issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.453+0800","logger":"tls","msg":"loading managed certificate","domain":"xenografix.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.454+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"debug","ts":"2021-07-05T14:02:08.465+0800","logger":"tls","msg":"loading managed certificate","domain":"caffigoalkeeping.com.au","expiration":"2021-08-30T23:59:59.000Z","issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"info","ts":"2021-07-05T14:02:09.025+0800","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0000c39d0"}
{"level":"info","ts":"2021-07-05T14:02:09.025+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-07-05T14:02:09.025+0800","logger":"admin.api","msg":"load complete"}
{"level":"info","ts":"2021-07-05T14:02:09.405+0800","logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}
...
{"level":"info","ts":"2021-07-05T15:02:03.638+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["www.udance.com.au"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
{"level":"info","ts":"2021-07-05T15:02:04.007+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["www.xenografix.com.au"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
{"level":"info","ts":"2021-07-05T15:02:04.358+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["www.caffigoalkeeping.com.au"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
{"level":"info","ts":"2021-07-05T15:02:04.703+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["udance.com.au"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
{"level":"info","ts":"2021-07-05T15:02:05.073+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["readymcgetty.com.au"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
{"level":"info","ts":"2021-07-05T15:02:05.453+0800","logger":"tls.cache.maintenance","msg":"advancing OCSP staple","identifiers":["www.caffigoalkeeping.com"],"from":"2021-07-08T19:00:00.000Z","to":"2021-07-11T19:00:00.000Z"}
...
{"level":"debug","ts":"2021-07-05T18:12:27.106+0800","logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"{backend}","request":{"remote_addr":"10.1.1.222:65001","proto":"HTTP/2.0","method":"GET","host":"file.lan:443","uri":"/","headers":{"Sec-Fetch-Site":["none"],"Sec-Ch-Ua-Mobile":["?0"],"Upgrade-Insecure-Requests":["1"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-User":["?1"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Dest":["document"],"X-Forwarded-Host":["file.udance.com.au"],"Purpose":["prefetch"],"Sec-Gpc":["1"],"X-Forwarded-Proto":["https"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"],"X-Forwarded-For":["10.1.1.222"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"cloud.udance.com.au"}},"headers":{"Content-Type":["text/html; charset=utf-8"],"Server":["Caddy"],"Date":["Mon, 05 Jul 2021 10:12:27 GMT"]},"status":200}
{"level":"debug","ts":"2021-07-05T18:12:28.578+0800","logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"{backend}","request":{"remote_addr":"10.1.1.222:65001","proto":"HTTP/2.0","method":"GET","host":"file.lan:443","uri":"/favicon.ico","headers":{"X-Forwarded-For":["10.1.1.222"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Google Chrome\";v=\"91\", \"Chromium\";v=\"91\""],"Sec-Fetch-Mode":["no-cors"],"Sec-Gpc":["1"],"X-Forwarded-Host":["file.udance.com.au"],"Sec-Ch-Ua-Mobile":["?0"],"Accept-Language":["en-AU,en-GB;q=0.9,en-US;q=0.8,en;q=0.7"],"Referer":["https://file.udance.com.au/"],"X-Forwarded-Proto":["https"],"Accept":["image/avif,image/webp,image/apng,image/svg+xml,image/*,*/*;q=0.8"],"Sec-Fetch-Dest":["image"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.124 Safari/537.36"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Site":["same-origin"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"cloud.udance.com.au"}},"headers":{"Server":["Caddy"],"Content-Length":["0"],"Date":["Mon, 05 Jul 2021 10:12:28 GMT"]},"status":404}
...
2021/07/05 18:38:06 {"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}
2021/07/05 18:38:06 {"id":"4t4YKQDdCjyBKhBXbla9otMgam1mrW1Z","status":"pending","expires":"2021-07-06T10:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-05T10:37:06Z","notAfter":"2021-07-05T22:38:06Z","authorizations":["https://acme.lan/acme/local/authz/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK"],"finalize":"https://acme.lan/acme/local/order/4t4YKQDdCjyBKhBXbla9otMgam1mrW1Z/finalize"}
2021/07/05 18:38:06 {"identifier":{"type":"dns","value":"file.lan"},"status":"pending","challenges":[{"type":"dns-01","status":"pending","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/4x2CMHwGCmLGIUnavr5zJOsLJEHXoV3p"},{"type":"http-01","status":"pending","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/2PT0X8UdxyUvpvVveOySs2Dp2CsmhztI"},{"type":"tls-alpn-01","status":"pending","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/Kp3lOu183VgIgsJtjdKszFeVfT9pV3PF"}],"wildcard":false,"expires":"2021-07-06T10:38:06Z"}
2021/07/05 18:38:06 {"type":"tls-alpn-01","status":"valid","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","validated":"2021-07-05T10:38:06Z","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/Kp3lOu183VgIgsJtjdKszFeVfT9pV3PF"}
2021/07/05 18:38:06 {"identifier":{"type":"dns","value":"file.lan"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/4x2CMHwGCmLGIUnavr5zJOsLJEHXoV3p"},{"type":"http-01","status":"pending","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/2PT0X8UdxyUvpvVveOySs2Dp2CsmhztI"},{"type":"tls-alpn-01","status":"valid","token":"HP2CSp169TSHhzcZQyy56A0Pfwt8AbNQ","validated":"2021-07-05T10:38:06Z","url":"https://acme.lan/acme/local/challenge/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK/Kp3lOu183VgIgsJtjdKszFeVfT9pV3PF"}],"wildcard":false,"expires":"2021-07-06T10:38:06Z"}
2021/07/05 18:38:06 {"id":"4t4YKQDdCjyBKhBXbla9otMgam1mrW1Z","status":"valid","expires":"2021-07-06T10:38:06Z","identifiers":[{"type":"dns","value":"file.lan"}],"notBefore":"2021-07-05T10:37:06Z","notAfter":"2021-07-05T22:38:06Z","authorizations":["https://acme.lan/acme/local/authz/2QORAb6nQkDiBDxVNiUSsDVWRqwilmxK"],"finalize":"https://acme.lan/acme/local/order/4t4YKQDdCjyBKhBXbla9otMgam1mrW1Z/finalize","certificate":"https://acme.lan/acme/local/certificate/Ukg9luJjqAi4YKOVmuGdxDHYgLYFwxJB"}

I’m cautiously optimistic that mTLS is now stable for me as it’s been up for more than a few days. So what’s changed? As a result of the thread Load balancing queries, I’ve reverted from this structure (from post mTLS under FreeBSD - #9 by francislavoie)…

# Secure backend communication
    @mtls expression `{mtls} == "yes"`
    reverse_proxy @mtls {backend} {
      header_up Host {http.reverse_proxy.upstream.hostport}
      header_up X-Forwarded-Host {host}
      transport http {
        tls
      }
    }

…to this structure (from post Load balancing queries - #19 by basil)…

(proxy-mtls) {
  @{args.0} host {args.0}.udance.com.au
  reverse_proxy @{args.0} https://{args.1} {
    header_up Host {http.reverse_proxy.upstream.hostport}
    header_up X-Forwarded-Host {host}
  }
}

I’ll keep monitoring mTLS, but with each passing day, I’m feeling more confident that mTLS hasn’t gone loopy for me. If it’s still stable in a week or so, then it could be that there is something flaky with the long way of configuring the transport. I report back again just before this thread gets locked.

I extended the lock date just in case

1 Like

@francislavoie Over the month of July, since moving away from this structure…

    reverse_proxy @mtls {backend} {
      header_up Host {http.reverse_proxy.upstream.hostport}
      header_up X-Forwarded-Host {host}
      transport http {
        tls
      }
    }

…to this structure…

(proxy-mtls) {
  @{args.0} host {args.0}.udance.com.au
  reverse_proxy @{args.0} https://{args.1} {
    header_up Host {http.reverse_proxy.upstream.hostport}
    header_up X-Forwarded-Host {host}
  }
}

mTLS has been rock solid. Not relying on a fix, but I’ll leave you with the observation that mTLS is unreliable under the former structure.

1 Like

Strange. Well the main difference is that in the former, the upstream is dynamic, and in the latter, it’s known upfront. I’ll need to follow up and read the code to see if I can glean anything from that regarding mTLS. I’m afk for the weekend.

3 Likes

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