Local certificates not renewing on demand

1. Caddy version (caddy version):

v2.2.0-rc.1.0.20200811172619-e385be922569 h1:nHT41ZpC4TVkQ656c55jTpMOFmEJd5oylK/icQYbs+c=

2. How I run Caddy:

Caddy is installed through Homebrew.
It uses the Caddyfile for configuration.

a. System environment:

MacOS Catalina
homebrew
caddy --HEAD

b. Command:

brew services start caddy

c. Service/unit/compose file:

//Not applicable

d. My complete Caddyfile or JSON config:

schc.local {
	root /* /Users/daniel/Sites/schc
	tls internal {
		on_demand
	}
	encode zstd gzip
	php_fastcgi 127.0.0.1:9000
	file_server
}

3. The problem I’m having:

Most of the time when going to schc.local the certificate is outdated. After some debugging, I recognized, that my computer is setup to deep sleep on lid close. Which means that obviously the background service that reloads the certificates is not running, and has no time to renew the certificates. Therefore, I added the on_demand functionality, which I thought would check the certificate at TLS handshake time, and renew them if needed. But as tested today this is not how it works, as caddy is still delivering the outdated certificate instead of renewing it “on demand”. This may be the planned functionality, but it would be great to have a real “on demand” functionality, that also checks if the certificate needs to be renewed during the TLS handshake.

4. Error messages and/or full log output:

2020/08/17 15:06:45 http: TLS handshake error from 127.0.0.1:63270: remote error: tls: unknown certificate
2020/08/17 15:06:45 http: TLS handshake error from 127.0.0.1:63272: remote error: tls: unknown certificate
2020/08/17 15:06:50 http: TLS handshake error from 127.0.0.1:63278: remote error: tls: unknown certificate
2020/08/17 15:06:57 http: TLS handshake error from 127.0.0.1:63293: remote error: tls: unknown certificate
2020/08/17 15:06:58 http: TLS handshake error from 127.0.0.1:63296: remote error: tls: unknown certificate
2020/08/17 15:06:58 http: TLS handshake error from 127.0.0.1:63298: remote error: tls: unknown certificate
2020/08/17 15:06:58 http: TLS handshake error from 127.0.0.1:63299: remote error: tls: unknown certificate
2020/08/17 15:06:59 http: TLS handshake error from 127.0.0.1:63301: remote error: tls: unknown certificate
2020/08/17 15:06:59 http: TLS handshake error from 127.0.0.1:63302: remote error: tls: unknown certificate
2020/08/17 15:07:29 http: TLS handshake error from 127.0.0.1:63343: remote error: tls: unknown certificate
2020/08/17 15:08:20 http: TLS handshake error from 127.0.0.1:63381: remote error: tls: unknown certificate
2020/08/17 15:10:13 http: TLS handshake error from 127.0.0.1:63400: remote error: tls: unknown certificate
2020/08/17 15:11:59 http: TLS handshake error from 127.0.0.1:63447: remote error: tls: unknown certificate
{"level":"info","ts":1597670042.988401,"logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["localhost"],"remaining":-61353.988388}
{"level":"info","ts":1597670042.988692,"logger":"tls.cache.maintenance","msg":"certificate expires soon; queuing for renewal","identifiers":["schc.local"],"remaining":-61353.98869}
{"level":"info","ts":1597670042.98877,"logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["localhost"],"remaining":-61353.988769}
{"level":"info","ts":1597670042.9888341,"logger":"tls.cache.maintenance","msg":"attempting certificate renewal","identifiers":["schc.local"],"remaining":-61353.988819}
{"level":"info","ts":1597670042.990061,"logger":"tls.renew","msg":"acquiring lock","identifier":"localhost"}
{"level":"info","ts":1597670042.990407,"logger":"tls.renew","msg":"acquiring lock","identifier":"schc.local"}
{"level":"info","ts":1597670042.990832,"logger":"tls.renew","msg":"lock acquired","identifier":"localhost"}
{"level":"info","ts":1597670042.991028,"logger":"tls.renew","msg":"lock acquired","identifier":"schc.local"}
{"level":"info","ts":1597670042.991918,"logger":"tls.renew","msg":"renewing certificate","identifier":"localhost","remaining":-61353.991916}
{"level":"info","ts":1597670042.991999,"logger":"tls.renew","msg":"renewing certificate","identifier":"schc.local","remaining":-61353.991992}
{"level":"info","ts":1597670042.9947891,"logger":"tls.renew","msg":"certificate renewed successfully","identifier":"localhost"}
{"level":"info","ts":1597670042.9948711,"logger":"tls.renew","msg":"releasing lock","identifier":"localhost"}
{"level":"info","ts":1597670042.9952068,"logger":"tls.renew","msg":"certificate renewed successfully","identifier":"schc.local"}
{"level":"info","ts":1597670042.9952378,"logger":"tls.renew","msg":"releasing lock","identifier":"schc.local"}
{"level":"info","ts":1597670042.995491,"logger":"tls","msg":"reloading managed certificate","identifiers":["localhost"]}
{"level":"info","ts":1597670042.9959738,"logger":"tls","msg":"reloading managed certificate","identifiers":["schc.local"]}
{"level":"warn","ts":1597670042.996657,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [localhost]: no OCSP server specified in certificate"}
{"level":"info","ts":1597670042.996725,"logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["localhost"],"new_expiration":1597713242}
{"level":"warn","ts":1597670042.9972858,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [schc.local]: no OCSP server specified in certificate"}
{"level":"info","ts":1597670042.997333,"logger":"tls.cache","msg":"replaced certificate in cache","identifiers":["schc.local"],"new_expiration":1597713242}
2020/08/17 15:18:29 http: TLS handshake error from 127.0.0.1:63570: local error: tls: bad record MAC
2020/08/17 15:18:29 http: TLS handshake error from 127.0.0.1:63571: local error: tls: bad record MAC
2020/08/17 15:18:29 http: TLS handshake error from 127.0.0.1:63572: local error: tls: bad record MAC

5. What I already tried:

Switched from automated background TLS renewal to on_demand TLS.

6. Links to relevant resources:

Not applicable

Thanks for the information. I’m not able to reproduce the issue. Using this config:

localhost {
	tls internal {
		on_demand
	}
	respond "Yahaha! You found me!"
}

The output is:

2020/08/17 16:56:02.408 INFO  using provided configuration  {"config_file": "/Users/matt/Dev/_scratch/Caddyfile_forum9482", "config_adapter": ""}
2020/08/17 16:56:02.424 INFO  admin admin endpoint started  {"address": "tcp/localhost:2019", "enforce_origin": false, "origins": ["localhost:2019", "[::1]:2019", "127.0.0.1:2019"]}
2020/08/17 16:56:02.424 INFO  tls.cache.maintenance started background certificate maintenance  {"cache": "0xc0003bd880"}
2020/08/17 16:56:02.432 INFO  http  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}
2020/08/17 16:56:02.432 INFO  http  enabling automatic HTTP->HTTPS redirects  {"server_name": "srv0"}
2020/08/17 16:56:02.534 INFO  pki.ca.local  root certificate is already trusted by system       {"path": "storage:pki/authorities/local/root.crt"}
2020/08/17 16:56:02.534 INFO  http  enabling automatic TLS certificate management       {"domains": ["localhost"]}
2020/08/17 16:56:02.535 INFO  autosaved config  {"file": "/Users/matt/Library/Application Support/Caddy/autosave.json"}
2020/08/17 16:56:02.535 INFO  serving initial configuration
2020/08/17 16:56:02.549 INFO  tls cleaned up storage units

And then when I make a request:

$ curl -v "https://localhost/"

This gets emitted to the logs:

2020/08/17 16:56:05.204 WARN  tls stapling OCSP {"error": "no OCSP stapling for [localhost]: no OCSP server specified in certificate"}

Indicating that it loaded the certificate on-demand.

Also, please note that this tls directive should be equivalent and is even simpler:

tls {
    on_demand
}

(removed “internal”) because *.local and localhost domains are ineligible for Let’s Encrypt certificates so by default Caddy will use its local authority.

So, as far as I can tell, it is working…

“bad record MAC” might mean that the client isn’t negotiating TLS where TLS is expected.

Hi,
Thanks for the reply. I am not quite sure if the steps you tested even lead to that issue, so here are the steps to reproduce:

  1. Use your config from above, load the page and get a valid certificate
  2. Check the expiration date of the certificate
  3. Turn off (or deep sleep) your computer until after the expiration date
  4. Turn on your computer after the expiration date and immediately load the website again (before the background service has time to renew the certificate). This presents me the expired certificate.

Best
Daniel

Oh… hmmm… that’s going to be difficult since I need to use my computer to get work done.

Anyone with an extra laptop around that can investigate?

Hi,
Totally see the challenge here :wink:

So in theory the expiration date should be checked during the TLS handshake? Can you hint me to the code part responsible for this on demand behavior? I didn’t yet work with Go but still could maybe have a look into it in the upcoming days…

Best

This was bothering me, so I went out on a limb and pushed this commit:

https://github.com/caddyserver/certmagic/commit/e7f9729bad6ca5c5948769826a2705e2ae633f42

That should save you some trouble. Could you please build Caddy with that version of CertMagic and see if it solves the problem for you? Thanks!

That is awesome :slight_smile: how can I specify the CertMagic version during build?

Best

Either a replace directive in go.mod, or just run go get github.com/caddyserver/certmagic@e7f9729bad6ca5c5948769826a2705e2ae633f42 from within your clone of the caddy repo. Then build.

Alright, will do and test if it works, and come back with the results. Thanks for your support.

Hi,
I now tested it through loading the page in the same tab after the certificate expired, as well as loading the page in another tab after the certificate expired. Interestingly, in both cases, Chrome shows the “Expired Error”-Page for a fraction of a second, before then loading the page with the new valid certificate. But thats probably because Chrome is just using the expired certificate for the duration of the TLS handshake, until it gets the new one.

For me, this solution solves my issue. It would be great if you could bump CertMagic version in the caddy master accordingly.

Best,
Daniel

Yes you shouldn’t use Chrome to test this. Please use curl -v instead and let me know how it goes!

Here we go, I used the following command

curl -vIs "https://schc.local"

curl before expiration

Date Time: 20.08.2020 15:50

*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to schc.local (127.0.0.1) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
} [224 bytes data]
* TLSv1.2 (IN), TLS handshake, Server hello (2):
{ [64 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [923 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [116 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [37 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
{ [1 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-ECDSA-AES256-GCM-SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: [NONE]
*  start date: Aug 20 07:01:34 2020 GMT
*  expire date: Aug 20 19:02:34 2020 GMT
*  subjectAltName: host "schc.local" matched cert's "schc.local"
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fa23080d600)
> HEAD / HTTP/2
> Host: schc.local
> User-Agent: curl/7.64.1
> Accept: */*
> 
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 200 
< content-type: text/html; charset=UTF-8
< link: <https://schc.local/wp-json/>; rel="https://api.w.org/"
< link: <https://schc.local/wp-json/wp/v2/pages/2>; rel="alternate"; type="application/json"
< link: <https://schc.local/>; rel=shortlink
< server: Caddy
< x-pingback: https://schc.local/wordpress/xmlrpc.php
< x-powered-by: PHP/7.4.8
< date: Thu, 20 Aug 2020 13:50:26 GMT
< 
* Connection #0 to host schc.local left intact
HTTP/2 200 
content-type: text/html; charset=UTF-8
link: <https://schc.local/wp-json/>; rel="https://api.w.org/"
link: <https://schc.local/wp-json/wp/v2/pages/2>; rel="alternate"; type="application/json"
link: <https://schc.local/>; rel=shortlink
server: Caddy
x-pingback: https://schc.local/wordpress/xmlrpc.php
x-powered-by: PHP/7.4.8
date: Thu, 20 Aug 2020 13:50:26 GMT

* Closing connection 0

curl after expiration

Date Time: 21.08.2020 14:07

*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to schc.local (127.0.0.1) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
} [224 bytes data]
* TLSv1.2 (IN), TLS handshake, Server hello (2):
{ [64 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [922 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [116 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [37 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS change cipher, Change cipher spec (1):
{ [1 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-ECDSA-AES256-GCM-SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: [NONE]
*  start date: Aug 21 12:06:45 2020 GMT
*  expire date: Aug 22 00:07:45 2020 GMT
*  subjectAltName: host "schc.local" matched cert's "schc.local"
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7ff8da008200)
> HEAD / HTTP/2
> Host: schc.local
> User-Agent: curl/7.64.1
> Accept: */*
> 
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 200 
< content-type: text/html; charset=UTF-8
< link: <https://schc.local/wp-json/>; rel="https://api.w.org/"
< link: <https://schc.local/wp-json/wp/v2/pages/2>; rel="alternate"; type="application/json"
< link: <https://schc.local/>; rel=shortlink
< server: Caddy
< x-pingback: https://schc.local/wordpress/xmlrpc.php
< x-powered-by: PHP/7.4.8
< date: Fri, 21 Aug 2020 12:07:45 GMT
< 
* Connection #0 to host schc.local left intact
HTTP/2 200 
content-type: text/html; charset=UTF-8
link: <https://schc.local/wp-json/>; rel="https://api.w.org/"
link: <https://schc.local/wp-json/wp/v2/pages/2>; rel="alternate"; type="application/json"
link: <https://schc.local/>; rel=shortlink
server: Caddy
x-pingback: https://schc.local/wordpress/xmlrpc.php
x-powered-by: PHP/7.4.8
date: Fri, 21 Aug 2020 12:07:45 GMT

* Closing connection 0

Best,
Daniel

1 Like

Excellent, thank you! You can see that curl doesn’t have any cert error shenanigans like browsers do.

1 Like

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