Error "TLS alert, internal error (592)" (again)

matt · September 2, 2021, 5:21pm

Excellent. Yeah, these will be much more verbose now, but at some point if the bug resurfaces you should see that pattern break for that domain because it will magically not be available.

You might see logs with text like “cache full; evicting random certificate” and “added certificate to cache”. I’m hoping those will reveal something.

matt · September 3, 2021, 5:49pm

FYI @alban, v2.4.5 is being released now which contains 1 more debug log which could potentially be useful. If you prefer to deploy a tagged version, you’re welcome to upgrade and get that extra debug info as well: Release v2.4.5 · caddyserver/caddy · GitHub

However, part of me kind of wants you to keep what you have running so we can try to reproduce the problem ASAP. Up to you.

matt · September 15, 2021, 2:28pm

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

matt · September 15, 2021, 11:52pm

@alban Any updates on this?

alban · September 16, 2021, 6:55am

Hello @matt ,

I updated to 2.4.5 almost 2 weeks ago, since then nothing.
Be sure I will post here infos as soon as something new occure

alban · September 20, 2021, 10:54am

Hello @matt
I got some news !

It was a bit different than usual, but I thinks it’s quite interesting.
Since last issue, I now monitor “no certificate available for *.lemlist.com” logs.
Yesterday (Sunday) at 15:54:36 (local time), I received an alert , but the alert quickly disappeared by itself. (compared to last time when issue stays until we restarted caddy)

Here the logs when issue occurred:

logs | grep img.lemlist.com

2021-09-19 15:54:25 {"level":"debug","ts":1632059665.0088575,"logger":"tls.cache","msg":"cache full; evicting random certificate","removing_subjects":["img.lemlist.com"],"removing_hash":"b2a750ea0d50222f9263392bf012c0d5f4cb06c7b1fea651358b8df21e48bbb1","inserting_subjects":["trail.pixelpenguinmedia.live"],"inserting_hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.0088665,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["img.lemlist.com"],"expiration":1634652604,"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"b2a750ea0d50222f9263392bf012c0d5f4cb06c7b1fea651358b8df21e48bbb1"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.8161275,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"img.lemlist.com"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.816262,"logger":"tls.handshake","msg":"no certificate matching TLS ClientHello","server_name":"img.lemlist.com","remote":"54.36.63.50:33690","identifier":"img.lemlist.com","cipher_suites":[4866,4867,4865,49199,49195,49200,49196,158,49191,103,49192,107,163,159,52393,52392,52394,49327,49325,49315,49311,49245,49249,49239,49235,162,49326,49324,49314,49310,49244,49248,49238,49234,49188,106,49187,64,49162,49172,57,56,49161,49171,51,50,157,49313,49309,49233,156,49312,49308,49232,61,60,53,47,255],"cache_size":9999,"cache_capacity":10000,"load_if_necessary":true,"obtain_if_necessary":true,"on_demand":false}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.816341,"logger":"http.stdlib","msg":"http: TLS handshake error from 54.36.63.50:33690: no certificate available for 'img.lemlist.com'"}
2021-09-19 15:54:27 {"level":"debug","ts":1632059667.6216931,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"img.lemlist.com"}
2021-09-19 15:54:27 {"level":"debug","ts":1632059667.6217434,"logger":"tls.handshake","msg":"no certificate matching TLS ClientHello","server_name":"img.lemlist.com","remote":"54.36.63.50:34472","identifier":"img.lemlist.com","cipher_suites":[4866,4867,4865,49199,49195,49200,49196,158,49191,103,49192,107,163,159,52393,52392,52394,49327,49325,49315,49311,49245,49249,49239,49235,162,49326,49324,49314,49310,49244,49248,49238,49234,49188,106,49187,64,49162,49172,57,56,49161,49171,51,50,157,49313,49309,49233,156,49312,49308,49232,61,60,53,47,255],"cache_size":9998,"cache_capacity":10000,"load_if_necessary":true,"obtain_if_necessary":true,"on_demand":false}
2021-09-19 15:54:27 {"level":"debug","ts":1632059667.6217873,"logger":"http.stdlib","msg":"http: TLS handshake error from 54.36.63.50:34472: no certificate available for 'img.lemlist.com'"}
2021-09-19 15:54:29 {"level":"debug","ts":1632059669.28179,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"img.lemlist.com"}
2021-09-19 15:54:29 {"level":"debug","ts":1632059669.2818348,"logger":"tls.handshake","msg":"no certificate matching TLS ClientHello","server_name":"img.lemlist.com","remote":"54.36.63.50:37874","identifier":"img.lemlist.com","cipher_suites":[4866,4867,4865,49199,49195,49200,49196,158,49191,103,49192,107,163,159,52393,52392,52394,49327,49325,49315,49311,49245,49249,49239,49235,162,49326,49324,49314,49310,49244,49248,49238,49234,49188,106,49187,64,49162,49172,57,56,49161,49171,51,50,157,49313,49309,49233,156,49312,49308,49232,61,60,53,47,255],"cache_size":9999,"cache_capacity":10000,"load_if_necessary":true,"obtain_if_necessary":true,"on_demand":false}
2021-09-19 15:54:29 {"level":"debug","ts":1632059669.281859,"logger":"http.stdlib","msg":"http: TLS handshake error from 54.36.63.50:37874: no certificate available for 'img.lemlist.com'"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.1242878,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"img.lemlist.com"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.1250055,"logger":"tls","msg":"loading managed certificate","domain":"img.lemlist.com","expiration":1634652604,"issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.2856934,"logger":"tls.cache","msg":"added certificate to cache","subjects":["img.lemlist.com"],"expiration":1634652604,"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"b2a750ea0d50222f9263392bf012c0d5f4cb06c7b1fea651358b8df21e48bbb1"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.2857137,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["img.lemlist.com"],"managed":true,"expiration":1634652604,"hash":"b2a750ea0d50222f9263392bf012c0d5f4cb06c7b1fea651358b8df21e48bbb1"}
2

logs | grep trail.pixelpenguinmedia.live

2021-09-19 15:54:25 {"level":"debug","ts":1632059664.9676862,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059664.967935,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:25 {"level":"warn","ts":1632059665.0087621,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.0088575,"logger":"tls.cache","msg":"cache full; evicting random certificate","removing_subjects":["img.lemlist.com"],"removing_hash":"b2a750ea0d50222f9263392bf012c0d5f4cb06c7b1fea651358b8df21e48bbb1","inserting_subjects":["trail.pixelpenguinmedia.live"],"inserting_hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.0088732,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.008879,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"info","ts":1632059665.0088873,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309266.008885306}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.0984578,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"error","ts":1632059665.0984843,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.222143,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.2223792,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:25 {"level":"warn","ts":1632059665.2635639,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.2635863,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.2635963,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"info","ts":1632059665.2636049,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309266.263603222}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.3494341,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"error","ts":1632059665.3494928,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.4759164,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.476824,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:25 {"level":"warn","ts":1632059665.518483,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.5185623,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.5185988,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"info","ts":1632059665.518637,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309266.518631825}
2021-09-19 15:54:25 {"level":"debug","ts":1632059665.6272013,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:25 {"level":"error","ts":1632059665.6272252,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:30 {"level":"debug","ts":1632059670.7709398,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:30 {"level":"debug","ts":1632059670.7711987,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:30 {"level":"warn","ts":1632059670.8113856,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:30 {"level":"debug","ts":1632059670.8114069,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:30 {"level":"debug","ts":1632059670.811415,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:30 {"level":"info","ts":1632059670.811425,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309271.811423246}
2021-09-19 15:54:31 {"level":"debug","ts":1632059670.9139826,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:31 {"level":"error","ts":1632059670.9140458,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.048918,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.0491865,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:31 {"level":"warn","ts":1632059671.089311,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.0893378,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.0893695,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:31 {"level":"info","ts":1632059671.0893848,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309272.089382587}
2021-09-19 15:54:31 {"level":"debug","ts":1632059671.2050972,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:31 {"level":"error","ts":1632059671.2051272,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.344953,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.3452585,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:36 {"level":"warn","ts":1632059676.3887825,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.388804,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.388815,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"info","ts":1632059676.3888257,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309277.388824013}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.4603086,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"error","ts":1632059676.460333,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.5932777,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.5934837,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:36 {"level":"warn","ts":1632059676.6338751,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.6339047,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.6339223,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"info","ts":1632059676.6339362,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309277.633934441}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.7237735,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:36 {"level":"error","ts":1632059676.7237947,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.8481839,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:36 {"level":"debug","ts":1632059676.8484006,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:37 {"level":"warn","ts":1632059676.8900928,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059676.8901165,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059676.8901267,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"info","ts":1632059676.8901362,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309277.890134641}
2021-09-19 15:54:37 {"level":"debug","ts":1632059676.9931116,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"error","ts":1632059676.9931266,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.1291041,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.1293235,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:37 {"level":"warn","ts":1632059677.1711495,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.1712227,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.171264,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"info","ts":1632059677.1712997,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309278.171294399}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.331669,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"error","ts":1632059677.3317065,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.4557936,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.4561303,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:37 {"level":"warn","ts":1632059677.5002418,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.5002878,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.5003138,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"info","ts":1632059677.5003366,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309278.500333675}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.5923948,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"error","ts":1632059677.5924244,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.7198083,"logger":"tls.handshake","msg":"no matching certificates and no custom selection logic","identifier":"trail.pixelpenguinmedia.live"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.720025,"logger":"tls","msg":"loading managed certificate","domain":"trail.pixelpenguinmedia.live","expiration":1631750399,"issuer_key":"acme.zerossl.com-v2-DV90","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
2021-09-19 15:54:37 {"level":"warn","ts":1632059677.7681725,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [trail.pixelpenguinmedia.live]: parsing OCSP response: ocsp: error from server: unauthorized"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.7682037,"logger":"tls.cache","msg":"added certificate to cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.7682135,"logger":"tls.handshake","msg":"loaded certificate from storage","subjects":["trail.pixelpenguinmedia.live"],"managed":true,"expiration":1631750399,"hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"info","ts":1632059677.7682214,"logger":"tls.on_demand","msg":"attempting certificate renewal","server_name":"trail.pixelpenguinmedia.live","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"remaining":-309278.768220023}
2021-09-19 15:54:37 {"level":"debug","ts":1632059677.8403103,"logger":"tls.cache","msg":"removed certificate from cache","subjects":["trail.pixelpenguinmedia.live"],"expiration":1631750399,"managed":true,"issuer_key":"acme.zerossl.com-v2-DV90","hash":"debd059c9153d172ff0dc0b110d4b2adb62ed065af002601da25f0a8c285c1a6"}
2021-09-19 15:54:37 {"level":"error","ts":1632059677.8403325,"logger":"tls.handshake","msg":"maintining newly-loaded certificate","server_name":"trail.pixelpenguinmedia.live","error":"certificate for hostname 'trail.pixelpenguinmedia.live' not allowed; non-2xx status code 404 returned from http://localhost:8000/api/cname/validate"}

matt · September 20, 2021, 11:59pm

Great, thanks for the logs. Analyzing them now. Might take some time to follow the execution.

Interesting that there was about 6 seconds where the cert for img.lemlist.com wasn’t in the cache, hmm.

matt · September 21, 2021, 1:32am

Ok, I have a theory. This is a fun one, so try to keep up:

The in-memory cert cache fills up (maximum 10,000 let’s say), but an on-demand cert is needed for trail.pixelpenguinmedia.live. The cert for img.lemlist.com is chosen by random to be evicted, and is replaced by the cert for trail.pixelpenguinmedia.live which was already in storage.

Immediately after the certs are swapped in the cache (which happens atomically as a single critical section), maintenance occurs on the new cert because the cert for trail.pixelpenguinmedia.live is expired and must be renewed. However, the “ask” endpoint returns a non-200 status of 404, so Caddy is not allowed to obtain/renew that certificate. Thus, the cert is immediately removed from the cache as quickly as it was loaded.

So a cache that had 10,000 certs in it now has 9,999 because the 10,001st cert (trail.pixelpenguinmedia.live) didn’t actually replace img.lemlist.com – only for a moment. We removed one cert, added a different one, but then removed the different one without replacing the one we evicted to make room for it.

Most unfortunately, my patch was not 100% useful in this (IMO) unusual edge case, as I restricted loading certificates from storage that were not configured for on-demand (img.lemlist.com) to only be loaded from storage if the cache was completely full:

github.com

caddyserver/certmagic/blob/d9f599a2f7935f5d152a27f3100a96da2679dc93/handshake.go#L260

    
      
          	}
          
          
	name := cfg.getNameFromClientHello(hello)
          
          
	// We might be able to load or obtain a needed certificate. Load from
          	// storage even if OnDemand isn't enabled in case a statically-managed
          	// cert was evicted from a full cache.
          	cfg.certCache.mu.RLock()
          	cacheSize := len(cfg.certCache.cache)
          	cfg.certCache.mu.RUnlock()
          	loadDynamically := cfg.OnDemand != nil || cacheSize >= cfg.certCache.options.Capacity
          
          
	if loadDynamically && loadIfNecessary {
          		// Then check to see if we have one on disk
          		loadedCert, err := cfg.CacheManagedCertificate(name)
          		if _, ok := err.(ErrNotExist); ok {
          			// If no exact match, try a wildcard variant, which is something we can still use
          			labels := strings.Split(name, ".")
          			labels[0] = "*"
          			loadedCert, err = cfg.CacheManagedCertificate(strings.Join(labels, "."))
          		}

…which is sound logic, because a cert that is not managed “on-demand” should be loaded only at startup, and the only reason it would disappear from the cache is if the cache was full, to make room for another cert, should it draw the short straw.

…EXCEPT when a cert is removed for a reason other than the cache being full (for example, a non-200 response from the “ask” endpoint).

Does that make sense?

I think the easiest fix is for me to remove that “cache full” condition and just allow any cert to be loaded from storage at any time, regardless of on-demand being enabled or the cache being full. This might incur a slight performance hit for servers that are getting a lot of spammy handshakes especially if their storage is slow, but I think it would only slow down handshakes that are asking for certs that don’t exist or aren’t allowed: it shouldn’t slow down handshakes for recognized, managed hostnames. I think. Right?

(In this particular chunk of logs, it appears you were as lucky as you were unlucky: the reason img.lemlist.com got back into the cert cache was because of a lot of requests for trail.pixelpenguinmedia.live at the same time, so for a brief moment the cache was 100% full, so the condition was satisfied, so it re-loaded the cert. Hence the “only” 6 second period where your alert triggered.)

alban · September 22, 2021, 1:34pm

Hello,

Quite interesting.

I do not know the code base enough, but is doesn’t make more sens to 1st check for “ask” endpoint, then evict entry from cache if response is 200 ?

Also why not prevent “not on-demand cert” to be removed from cache ? ie: always pick an “on-demand cert” when cache is full

Thanks for the troubleshooting and the explanation

eva2000 · September 22, 2021, 6:06pm

@matt saw from my Twitter feed your Youtube live stream on this issue and had a though Why not smooth out the in-memory cache management so that it has both a hot/warm/cold cache segments?

hot = in-memory cache
warm = on-disk cache acts as a temp cache for auto evicted/purged in-memory cached certificates, so they’d still exist just in a slower cache and then have criteria to determine if it moves back into hot cache or moves permanently out via eviction/purge

Also what about adding the option to configure compressing the in-memory cached certificate files? even the lowest level compression would allow the in-memory cache to store more certificates before eviction threshold is even reached? Making the compression to be optionally configured and disabled by default, still allow users to enable the in-memory caching if their use case is for 10000+ SSL certificates. In which case they are more likely to have the memory and cpu resources on their server anyway to handle the extra compression?

And/or just make the in-memory cache threshold configurable, so folks can specify a larger size >10,000 if they need to and have the resources

Separately, isn’t there any mechanism to limit such spammy request/handshakes? edit: oh you have an ask endpoint option Global options (Caddyfile) — Caddy Documentation

matt · September 22, 2021, 8:35pm

@alban, those are great questions.

First, I have pushed a commit to CertMagic that I am pretty sure will solve this:

We now allow for loading any cert from storage if cache pressure is 90% or higher.

PS. As @eva2000 mentioned, I cover this issue in my first livestream:

Yes, that might be a good way to handle this. I’ll look into it.

Good question; the answer is, as explained in the video above, that it’s not very good to do this with random eviction. We might end up trying a lot of certificates before we find one we can evict. Or we can keep a separate list of evictable certs, but then we use more memory. And what if the whole cache is full of non-evictable certs? So, best to just be able to reload ones we evicted.

That is basically what we do already. Storage is the long-term “cache” and in-memory cache is what we serve certs from.

Encoded certs aren’t particularly big, it’s their decoded form that takes more memory, which we need in order to manage them. Plus the CPU overhead isn’t favorable.

It already is.

Yes, we strongly advise and warn against deploying into production without configuring this endpoint.

eva2000 · September 23, 2021, 12:07am

Ah must of overlooked that in the video!

francislavoie · September 23, 2021, 12:14am

@eva2000 it’s in the docs:

eva2000 · September 23, 2021, 12:20am

I saw that but didn’t see a setting i.e. to specify a number of certs as threshold or we’re expected to do that ourselves to limit or increase the number of certs to store in cache? Or because there’s no setting, then there is no limit as to number of certs to be stored in in-memory TLS cache? That 10,000 number is just an example and not a hardcoded preset limit?

francislavoie · September 23, 2021, 2:09am

10,000 is the default maximum size of the in-memory certificate cache. That number is configurable (currently only via JSON, we just forgot to add an option to the Caddyfile adapter and nobody really needed it so far until this bug was revealed recently). In general, this should be an implementation detail.

matt · September 23, 2021, 2:39am

Yeah, you should never really need to adjust it unless you’re on underpowered hardware or you are trying to tune very acutely for performance. But those are rare cases and in general I don’t recommend adjusting the capacity.

alban · September 24, 2021, 7:46am

Hello,

A small update to tell you I just deployed the v2.4.5 but with latest certmagic version.

matt · September 27, 2021, 8:00am

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