Yep, that’s what I did.
Okay, a new build should is ready here:
Please turn on the debug global option in your frontend config.
In particular, watch for these logs messages:
-
INFOlevelrenewed intermediate, and note thenew_expirationtime… it’ll probably appear as a unix timestamp, in this case. -
DEBUGlevelusing intermediate signer, note the times on that log as well, this is the new one I just added, which should be called each time a cert is issued withacme_server. You can test that this gets logged right away by deleting a cert from the backend and reloading, to make sure it does indeed appear in the frontend logs.
Then we’ll have to wait again until the intermediate expires 
I’m not sure how else to accelerate the process.
1 Like
Wow, thanks for the quick reaction.
I’m running now the latest commit. Will keep you posted.
1 Like
Alright, so here’s what I see in the logs:
(Caddy was started ~ 03 April 13:00.)
03 April ~18:00
2022-04-03T18:09:23.130382955Z 2022/04/03 18:09:23 {"identifier":{"type":"dns","value":"ncweb"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"M1arbDXoQoJZX2GpPcVUlfjpnx5OpBKo","url":"https://proxy/acme/local/challenge/qUePFeDRQ6iZDLhV9FA28yeqPOxuyerE/baDQLUJ5OvTme3gEeC9tNh6VsVnzTdDL"},{"type":"http-01","status":"pending","token":"M1arbDXoQoJZX2GpPcVUlfjpnx5OpBKo","url":"https://proxy/acme/local/challenge/qUePFeDRQ6iZDLhV9FA28yeqPOxuyerE/BGcnWUgeLTKc7LfckEXjpzOwDugmYBDE"},{"type":"tls-alpn-01","status":"valid","token":"M1arbDXoQoJZX2GpPcVUlfjpnx5OpBKo","validated":"2022-04-03T18:09:22Z","url":"https://proxy/acme/local/challenge/qUePFeDRQ6iZDLhV9FA28yeqPOxuyerE/D2yfkYVqKAK0659rXpAoHxY3g3QE5Lw8"}],"wildcard":false,"expires":"2022-04-04T18:09:22Z"}
2022-04-03T18:09:23.157191854Z {"level":"debug","ts":1649009363.1568086,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
2022-04-03T18:09:23.177759461Z 2022/04/03 18:09:23 {"id":"s6F6WdN9Orfzud9cw3myRH08okpdC5yh","status":"valid","expires":"2022-04-04T18:09:22Z","identifiers":[{"type":"dns","value":"ncweb"}],"notBefore":"2022-04-03T18:08:22Z","notAfter":"2022-04-04T06:09:22Z","authorizations":["https://proxy/acme/local/authz/qUePFeDRQ6iZDLhV9FA28yeqPOxuyerE"],"finalize":"https://proxy/acme/local/order/s6F6WdN9Orfzud9cw3myRH08okpdC5yh/finalize","certificate":"https://proxy/acme/local/certificate/FwXn4D5ieLrYpPikilB95aSqaUyb8Cxx"}
This continues to happen every 8 hours …
Also I see this happening every 8 hours (cert renewal for the local hostnames)
2022-04-06T08:27:55.239804759Z {"level":"info","ts":1649233675.2394435,"logger":"tls.renew","msg":"renewing certificate","identifier":"localhost","remaining":14399.760567147}
2022-04-06T08:27:55.240253054Z {"level":"info","ts":1649233675.2400103,"logger":"tls.renew","msg":"renewing certificate","identifier":"rowena","remaining":14399.759996075}
2022-04-06T08:27:55.240925071Z {"level":"info","ts":1649233675.2400022,"logger":"tls.renew","msg":"renewing certificate","identifier":"proxy","remaining":14399.760006038}
2022-04-06T08:27:55.242435066Z {"level":"info","ts":1649233675.2420373,"logger":"tls.renew","msg":"renewing certificate","identifier":"rowena.local","remaining":14399.757973303}
2022-04-06T08:27:55.245275299Z {"level":"debug","ts":1649233675.244931,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
2022-04-06T08:27:55.245580890Z {"level":"debug","ts":1649233675.2453473,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
2022-04-06T08:27:55.246204814Z {"level":"debug","ts":1649233675.2459235,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
2022-04-06T08:27:55.247654180Z {"level":"debug","ts":1649233675.2473228,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
On 06 April ~16:30 (yesterday), the intermediate got renewed
2022-04-06T16:37:55.449409784Z {"level":"info","ts":1649263075.4488118,"logger":"pki","msg":"intermediate expires soon; renewing","ca":"local","time_remaining":120613.551192399}
2022-04-06T16:37:55.454900118Z {"level":"info","ts":1649263075.4544039,"logger":"pki","msg":"renewed intermediate","ca":"local","new_expiration":1649867875}
// "new_expiration":1649867875 --> Wed Apr 13 16:37:55 2022 UTC
At ~18:00 (1,5 hours later) ncweb (backend caddy) is doing the ACME challenge and is receiving new cert but with the old intermediate
2022-04-06T18:09:23.130272802Z 2022/04/06 18:09:23 {"identifier":{"type":"dns","value":"ncweb"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"rBDO9yeARjY1eX6zgoes3QWLitGJdcFH","url":"https://proxy/acme/local/challenge/G2hX5l5SWnaT9pIHsPRikVsRlCNi2GYr/qwMGiTZQB6BVLafttPE9BDnrJ5VJcWgn"},{"type":"http-01","status":"pending","token":"rBDO9yeARjY1eX6zgoes3QWLitGJdcFH","url":"https://proxy/acme/local/challenge/G2hX5l5SWnaT9pIHsPRikVsRlCNi2GYr/5gAkIxg6yi2x5294BEj2YAYOanDw2dXn"},{"type":"tls-alpn-01","status":"valid","token":"rBDO9yeARjY1eX6zgoes3QWLitGJdcFH","validated":"2022-04-06T18:09:22Z","url":"https://proxy/acme/local/challenge/G2hX5l5SWnaT9pIHsPRikVsRlCNi2GYr/YQIBsMCObYsNa9pQLqamf9t41ILjd0RS"}],"wildcard":false,"expires":"2022-04-07T18:09:22Z"}
2022-04-06T18:09:23.155063850Z {"level":"debug","ts":1649268563.1546729,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"86202430300835002853549355422544456805","not_before":"2022-04-01 02:08:09 +0000 UTC","not_after":"2022-04-08 02:08:09 +0000 UTC"}
2022-04-06T18:09:23.172988962Z 2022/04/06 18:09:23 {"id":"X9ZUZFuKrgEETVkxGb2C7h3KUa7htGqe","status":"valid","expires":"2022-04-07T18:09:22Z","identifiers":[{"type":"dns","value":"ncweb"}],"notBefore":"2022-04-06T18:08:22Z","notAfter":"2022-04-07T06:09:22Z","authorizations":["https://proxy/acme/local/authz/G2hX5l5SWnaT9pIHsPRikVsRlCNi2GYr"],"finalize":"https://proxy/acme/local/order/X9ZUZFuKrgEETVkxGb2C7h3KUa7htGqe/finalize","certificate":"https://proxy/acme/local/certificate/EQjkgbSbwmqpaVCufazYiHcqWt9QSwWP"}
A few hours later (07 April ~00:27) the cert renewal for the local hostnames kicks in, with new intermediate.
2022-04-07T00:27:55.241928758Z {"level":"info","ts":1649291275.2416236,"logger":"tls.renew","msg":"renewing certificate","identifier":"rowena.local","remaining":14399.758386038}
2022-04-07T00:27:55.242236109Z {"level":"info","ts":1649291275.2416239,"logger":"tls.renew","msg":"renewing certificate","identifier":"proxy","remaining":14399.75838363}
2022-04-07T00:27:55.250864289Z {"level":"info","ts":1649291275.2458465,"logger":"tls.renew","msg":"renewing certificate","identifier":"localhost","remaining":14399.754158586}
2022-04-07T00:27:55.250916159Z {"level":"info","ts":1649291275.2458467,"logger":"tls.renew","msg":"renewing certificate","identifier":"rowena","remaining":14399.754161512}
2022-04-07T00:27:55.250961326Z {"level":"debug","ts":1649291275.2462163,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"131921930849369217822990708607228533826","not_before":"2022-04-06 16:37:55 +0000 UTC","not_after":"2022-04-13 16:37:55 +0000 UTC"}
2022-04-07T00:27:55.251183029Z {"level":"debug","ts":1649291275.2462165,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"131921930849369217822990708607228533826","not_before":"2022-04-06 16:37:55 +0000 UTC","not_after":"2022-04-13 16:37:55 +0000 UTC"}
2022-04-07T00:27:55.251279195Z {"level":"debug","ts":1649291275.25029,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"131921930849369217822990708607228533826","not_before":"2022-04-06 16:37:55 +0000 UTC","not_after":"2022-04-13 16:37:55 +0000 UTC"}
2022-04-07T00:27:55.251328880Z {"level":"debug","ts":1649291275.2509491,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"131921930849369217822990708607228533826","not_before":"2022-04-06 16:37:55 +0000 UTC","not_after":"2022-04-13 16:37:55 +0000 UTC"}
So it seems that only the acme_server has this problem. But maybe you assumed that already?
Anything I can do to further support here?
1 Like
Right, that looks good.
So, now that we’re a few days later, what does a recent one look like? Can you search the logs to see if there was a renewed intermediate since, and if so, look for a using intermediate signer after that point. Basically, looking to see if the serial/not_before/not_after changed.
1 Like
Yeah, that was included in the logs above already. But it wasn’t formatted very well. I updated the post to make more clear the different events within the last days.
As you can see, the intermediate cert got renewed yesterday. Afterwards, the acme_server still handed out the old intermediate (expiring tomorrow) when the other caddy (ncweb) was doing the ACME challenge.
For the local hostnames, however, it works fine and the renewed cert chains do contain the new intermediate.
1 Like
Ah geez. Okay.
WELL, I have another hunch. Try this build?
This is literally a single character change, lol.
1 Like
Thanks a lot! New build is running now. Will keep you posted.
2 Likes
This topic was automatically closed after 11 days. New replies are no longer allowed.
Alright, so I’ve got some good news.
Here’s the most recent renewal of the intermediate cert:
2022-04-12T07:07:54.048745920Z {"level":"info","ts":1649747274.0444179,"logger":"pki","msg":"intermediate expires soon; renewing","ca":"local","time_remaining":120600.955587527}
2022-04-12T07:07:54.050287506Z {"level":"info","ts":1649747274.0500102,"logger":"pki","msg":"renewed intermediate","ca":"local","new_expiration":1650352074}
// "new_expiration":1650352074 --> Tue Apr 19 07:07:54 2022 UTC
About an hour later, the acme server reissued the backend caddy’s certificate, this time with the new intermediate:
2022-04-12T08:28:04.507624329Z 2022/04/12 08:28:04 {"identifier":{"type":"dns","value":"ncweb"},"status":"valid","challenges":[{"type":"dns-01","status":"pending","token":"zegOBYXjMY48ilWYT9EM9kuSKqGK9BNq","url":"https://proxy/acme/local/challenge/UyFrjLuKuAoGqN33ceUb9UlalBYmKH5z/CKmJj2P8zJs9RzMLkX88MOj7aAUITX3i"},{"type":"http-01","status":"pending","token":"zegOBYXjMY48ilWYT9EM9kuSKqGK9BNq","url":"https://proxy/acme/local/challenge/UyFrjLuKuAoGqN33ceUb9UlalBYmKH5z/mxboo6kGWQbBkBbdmRphYaNtOHba5DwD"},{"type":"tls-alpn-01","status":"valid","token":"zegOBYXjMY48ilWYT9EM9kuSKqGK9BNq","validated":"2022-04-12T08:28:04Z","url":"https://proxy/acme/local/challenge/UyFrjLuKuAoGqN33ceUb9UlalBYmKH5z/Ho0KMzMtyIMHcQSMbLOsMt1GYR77n4bI"}],"wildcard":false,"expires":"2022-04-13T08:28:04Z"}
2022-04-12T08:28:04.533885727Z {"level":"debug","ts":1649752084.5334518,"logger":"pki.ca.local","msg":"using intermediate signer","serial":"66872705317182381873319979057422166194","not_before":"2022-04-12 07:07:54 +0000 UTC","not_after":"2022-04-19 07:07:54 +0000 UTC"}
2022-04-12T08:28:04.552909529Z 2022/04/12 08:28:04 {"id":"iyh5mQuRMxoQHREHnh80P8BcrOD5iO3l","status":"valid","expires":"2022-04-13T08:28:04Z","identifiers":[{"type":"dns","value":"ncweb"}],"notBefore":"2022-04-12T08:27:04Z","notAfter":"2022-04-12T20:28:04Z","authorizations":["https://proxy/acme/local/authz/UyFrjLuKuAoGqN33ceUb9UlalBYmKH5z"],"finalize":"https://proxy/acme/local/order/iyh5mQuRMxoQHREHnh80P8BcrOD5iO3l/finalize","certificate":"https://proxy/acme/local/certificate/Lqdb4L0XwhXPKTnNKDYavo313p8ZO2T4"}
So seems like the issue is actually fixed now. 
Thank you so much for investigating and eventually fixing this issue. I’m very happy that my local setup is going to be even more robust now. 
2 Likes
Sorry for the late reply. I can finally also confirm that the renewal is working using Caddy v2.5.1
2 Likes