Caddy: ssl certs failure

Created on 1 Oct 2016 · 95Comments · Source: caddyserver/caddy

1. What version of Caddy are you running (`caddy -version`)?

Caddy (untracked dev build)
(last commit hash bbf954c)

2. What are you trying to do?

Rebooted my machine and let caddy run agin

3. What is your entire Caddyfile?

prolly not relevant (yet)

4. How did you run Caddy (give the full command and describe the execution environment)?

ExecStart=/opt/bin/caddy -pidfile /var/www/caddy.pid -agree=true -email \
    [email protected] -conf=/etc/caddy/Caddyfile -log stdout

5. What did you expect to see?

Not the following

6. What did you see instead (give full error messages and/or log)?

-- Logs begin at Fri 2016-09-30 19:54:00 UTC. --
Oct 01 20:23:39 deb caddy[5591]: 2016/10/01 20:23:39 http: TLS handshake error from 85.25.210.234:21233: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:23:40 deb caddy[5591]: 2016/10/01 20:23:40 http: TLS handshake error from 85.25.210.234:13864: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:23:40 deb caddy[5591]: 2016/10/01 20:23:40 http: TLS handshake error from 85.25.210.234:17874: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:24:36 deb caddy[5591]: 2016/10/01 20:24:36 http: TLS handshake error from 106.120.173.99:46438: tls: first record does not look like a TLS handshake
Oct 01 20:25:36 deb caddy[5591]: 2016/10/01 20:25:36 http: TLS handshake error from [2a02:908:b40:a0:5c79:4d07:c5a9:3d83]:61116: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:31:03 deb caddy[5591]: 2016/10/01 20:31:03 http: TLS handshake error from [2001:1a50:11:0:5f:8f:ac0c:1]:41341: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:34:11 deb caddy[5591]: 2016/10/01 20:34:11 http: TLS handshake error from 54.221.81.125:40546: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:34:11 deb caddy[5591]: 2016/10/01 20:34:11 http: TLS handshake error from 54.221.81.125:40625: tls: client offered an unsupported, maximum protocol version of 301
Oct 01 20:42:15 deb caddy[5591]: 2016/10/01 20:42:15 http: TLS handshake error from 173.48.168.206:51582: EOF
Oct 01 20:43:51 deb caddy[5591]: 2016/10/01 20:43:51 http: TLS handshake error from 180.153.73.63:45483: tls: unsupported SSLv2 handshake received
Oct 01 20:44:25 deb caddy[5591]: 2016/10/01 20:44:25 http: TLS handshake error from 113.160.154.138:44733: tls: unsupported SSLv2 handshake received

After which I restarted Caddy, resulting in the following:

-- Logs begin at Fri 2016-09-30 19:54:00 UTC, end at Sat 2016-10-01 20:45:48 UTC. --
Sep 30 19:54:04 deb systemd[1]: Starting Caddy HTTP/2 web server...
Sep 30 19:54:04 deb systemd[1]: Started Caddy HTTP/2 web server.
Sep 30 19:54:05 deb caddy[5591]: 2016/09/30 19:54:04 [INFO] NLgids localhost: [email protected]
Sep 30 19:54:08 deb caddy[5591]: Activating privacy features... done.
Sep 30 19:54:08 deb caddy[5591]: https://miek.nl
Sep 30 19:54:08 deb caddy[5591]: https://www.miek.nl
Sep 30 19:54:08 deb caddy[5591]: https://archive.miek.nl
Sep 30 19:54:08 deb caddy[5591]: https://nlgids.london
Sep 30 19:54:08 deb caddy[5591]: https://www.nlgids.london
Sep 30 19:54:08 deb caddy[5591]: https://coredns.io
Sep 30 19:54:08 deb caddy[5591]: https://www.coredns.io
Sep 30 19:54:08 deb caddy[5591]: https://blog.coredns.io
Sep 30 19:54:08 deb caddy[5591]: https://dnssex.nl
Sep 30 19:54:08 deb caddy[5591]: https://www.dnssex.nl
Sep 30 19:54:08 deb caddy[5591]: https://www.berkestoffering.nl
Sep 30 19:54:08 deb caddy[5591]: https://berkestoffering.nl
Sep 30 19:54:08 deb caddy[5591]: https://atoom.net
Sep 30 19:54:08 deb caddy[5591]: https://www.atoom.net
Sep 30 19:54:08 deb caddy[5591]: https://isitinfra.net
Sep 30 19:54:08 deb caddy[5591]: https://www.isitinfra.net
Sep 30 19:54:08 deb caddy[5591]: http://wereldstadsgidsen.com
Sep 30 19:54:08 deb caddy[5591]: http://www.wereldstadsgiden.com
Sep 30 19:54:08 deb caddy[5591]: http://wereldstadgidsen.nl
Sep 30 19:54:08 deb caddy[5591]: http://www.wereldstadgidsen.nl
Sep 30 19:54:08 deb caddy[5591]: http://wereldstadgidsen.be
Sep 30 19:54:08 deb caddy[5591]: http://www.wereldstadgidsen.be
Sep 30 19:54:08 deb caddy[5591]: http://miek.nl
Sep 30 19:54:08 deb caddy[5591]: http://www.miek.nl
Sep 30 19:54:08 deb caddy[5591]: http://archive.miek.nl
Sep 30 19:54:08 deb caddy[5591]: http://nlgids.london
Sep 30 19:54:08 deb caddy[5591]: http://www.nlgids.london
Sep 30 19:54:08 deb caddy[5591]: http://coredns.io
Sep 30 19:54:08 deb caddy[5591]: http://www.coredns.io
Sep 30 19:54:08 deb caddy[5591]: http://blog.coredns.io
Sep 30 19:54:08 deb caddy[5591]: http://dnssex.nl
Sep 30 19:54:08 deb caddy[5591]: http://www.dnssex.nl
Sep 30 19:54:08 deb caddy[5591]: http://www.berkestoffering.nl
Sep 30 19:54:08 deb caddy[5591]: http://berkestoffering.nl
Sep 30 19:54:08 deb caddy[5591]: http://atoom.net
Sep 30 19:54:08 deb caddy[5591]: http://www.atoom.net
Sep 30 19:54:08 deb caddy[5591]: http://isitinfra.net
Sep 30 19:54:08 deb caddy[5591]: http://www.isitinfra.net
Sep 30 19:55:03 deb caddy[5591]: 92.12.221.148 - miek.nl GET /rss.xml HTTP/1.1 404 1252 -
Sep 30 19:55:30 deb caddy[5591]: 50.90.21.165 - miek.nl GET /images/apple.jpg HTTP/2.0 200 298876 https://www.google.com/
Sep 30 19:55:35 deb caddy[5591]: 2016/09/30 19:55:35 http: TLS handshake error from 65.19.138.35:27189: tls: client offered an unsupported, maximum protocol version of 30
Sep 30 19:55:36 deb caddy[5591]: 2016/09/30 19:55:36 http: TLS handshake error from 8.29.198.27:42107: tls: client offered an unsupported, maximum protocol version of 301
Sep 30 19:55:36 deb caddy[5591]: 2016/09/30 19:55:36 http: TLS handshake error from 8.29.198.27:14930: tls: client offered an unsupported, maximum protocol version of 300
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET / HTTP/2.0 200 1609 -
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /css/style.css HTTP/2.0 200 3557 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /css/monosocialiconsfont.css HTTP/2.0 200 368 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /css/highlight.css HTTP/2.0 200 629 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /images/avatar.jpg HTTP/2.0 200 35651 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /js/main.js HTTP/2.0 200 406 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /fonts/MonoSocialIconsFont-1.10.ttf HTTP/2.0 200 146660 https://miek.nl/css/monosoci
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /js/highlight.js HTTP/2.0 200 23415 https://miek.nl/
Sep 30 19:56:07 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /images/favicon.ico HTTP/2.0 200 5182 https://miek.nl/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET / HTTP/2.0 200 2660 -
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/coredns-logo.png HTTP/2.0 200 1347 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /css/landing-page.css HTTP/2.0 200 987 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /js/jquery.easing.min.js HTTP/2.0 200 1857 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /js/landing-page.js HTTP/2.0 200 471 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /font-awesome-4.1.0/css/font-awesome.min.css HTTP/2.0 200 4684 https://coredns.io
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /js/bootstrap.min.js HTTP/2.0 200 8544 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /css/bootstrap.min.css HTTP/2.0 200 18109 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /js/jquery-1.11.0.js HTTP/2.0 200 33391 https://coredns.io/
Sep 30 19:56:10 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/lava.jpg HTTP/2.0 200 198893 https://coredns.io/
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /font-awesome-4.1.0/fonts/fontawesome-webfont.woff HTTP/2.0 200 83760 https://cor
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/html-code.jpg HTTP/2.0 200 119296 https://coredns.io/
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/cloud.jpg HTTP/2.0 200 435545 https://coredns.io/
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/disk.jpg HTTP/2.0 200 757713 https://coredns.io/
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/intro-bg.jpg HTTP/2.0 200 435545 https://coredns.io/css/landing-page.css
Sep 30 19:56:11 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/contact-bg.jpg HTTP/2.0 200 544154 https://coredns.io/css/landing-page.css
Sep 30 19:56:12 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /img/mountain.jpg HTTP/2.0 200 1332881 https://coredns.io/
Sep 30 19:56:12 deb caddy[5591]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - coredns.io GET /favicon.ico HTTP/2.0 404 0 https://coredns.io/
Sep 30 19:56:56 deb caddy[5591]: 49.128.61.142 - miek.nl GET /favicon.ico HTTP/2.0 404 3919 https://miek.nl/downloads/2015/go.pdf
Sep 30 19:56:56 deb caddy[5591]: 80.100.158.12 - miek.nl GET /feeds/all.atom.xml HTTP/2.0 404 1252 -
Sep 30 19:56:57 deb caddy[5591]: 49.128.61.142 - miek.nl GET /downloads/2015/go.pdf HTTP/2.0 200 994890 http://dave.cheney.net/resources-for-new-go-programmers
Sep 30 19:56:57 deb caddy[5591]: 49.128.61.142 - miek.nl GET /downloads/2015/go.pdf HTTP/2.0 206 634442 https://miek.nl/downloads/2015/go.pdf
Sep 30 19:57:02 deb caddy[5591]: 2607:8400:2010:2:c90a:ae38:f60a:3756 - www.miek.nl GET /rss.xml HTTP/1.1 404 1252 -
Sep 30 19:57:05 deb caddy[5591]: 2016/09/30 19:57:05 http2: server: error reading preface from client 49.128.61.142:53745: timeout waiting for client preface
Sep 30 19:57:06 deb caddy[5591]: 2016/09/30 19:57:06 http: TLS handshake error from 49.128.61.142:53747: EOF
Sep 30 19:57:38 deb caddy[5591]: 86.105.55.25 - miek.nl GET /feeds/all.atom.xml HTTP/1.1 404 1252 -
Sep 30 19:58:14 deb caddy[5591]: 66.249.76.120 - www.nlgids.london GET /specials.html HTTP/1.1 200 4797 -
Sep 30 19:58:18 deb caddy[5591]: 180.76.15.7 - archive.miek.nl GET /downloads/pubs/secreg-report.pdf HTTP/1.1 200 94343 -
Sep 30 19:58:29 deb caddy[5591]: 49.128.61.142 - miek.nl GET / HTTP/2.0 200 1609 -
Sep 30 19:58:29 deb caddy[5591]: 49.128.61.142 - miek.nl GET /css/highlight.css HTTP/2.0 200 629 https://miek.nl/
Sep 30 19:58:29 deb caddy[5591]: 49.128.61.142 - miek.nl GET /css/style.css HTTP/2.0 200 3557 https://miek.nl/
...skipping...
Oct 01 20:23:36 deb caddy[5591]: 2016/10/01 20:23:36 http: TLS handshake error from 85.25.210.234:42145: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:36 deb caddy[5591]: 2016/10/01 20:23:36 http: TLS handshake error from 85.25.210.234:34234: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:37 deb caddy[5591]: 2016/10/01 20:23:37 http: TLS handshake error from 85.25.210.234:40256: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:38 deb caddy[5591]: 2016/10/01 20:23:38 http: TLS handshake error from 85.25.210.234:62341: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:38 deb caddy[5591]: 2016/10/01 20:23:38 http: TLS handshake error from 85.25.210.234:34146: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:38 deb caddy[5591]: 2016/10/01 20:23:38 http: TLS handshake error from 85.25.210.234:58432: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:39 deb caddy[5591]: 2016/10/01 20:23:39 http: TLS handshake error from 85.25.210.234:41085: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:39 deb caddy[5591]: 2016/10/01 20:23:39 http: TLS handshake error from 85.25.210.234:21233: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:40 deb caddy[5591]: 2016/10/01 20:23:40 http: TLS handshake error from 85.25.210.234:13864: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:23:40 deb caddy[5591]: 2016/10/01 20:23:40 http: TLS handshake error from 85.25.210.234:17874: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:24:36 deb caddy[5591]: 2016/10/01 20:24:36 http: TLS handshake error from 106.120.173.99:46438: tls: first record does not look like a TLS handshake
Oct 01 20:25:36 deb caddy[5591]: 2016/10/01 20:25:36 http: TLS handshake error from [2a02:908:b40:a0:5c79:4d07:c5a9:3d83]:61116: tls: client offered an unsupported, maxim
Oct 01 20:31:03 deb caddy[5591]: 2016/10/01 20:31:03 http: TLS handshake error from [2001:1a50:11:0:5f:8f:ac0c:1]:41341: tls: client offered an unsupported, maximum proto
Oct 01 20:34:11 deb caddy[5591]: 2016/10/01 20:34:11 http: TLS handshake error from 54.221.81.125:40546: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:34:11 deb caddy[5591]: 2016/10/01 20:34:11 http: TLS handshake error from 54.221.81.125:40625: tls: client offered an unsupported, maximum protocol version of 3
Oct 01 20:42:15 deb caddy[5591]: 2016/10/01 20:42:15 http: TLS handshake error from 173.48.168.206:51582: EOF
Oct 01 20:43:51 deb caddy[5591]: 2016/10/01 20:43:51 http: TLS handshake error from 180.153.73.63:45483: tls: unsupported SSLv2 handshake received
Oct 01 20:44:25 deb caddy[5591]: 2016/10/01 20:44:25 http: TLS handshake error from 113.160.154.138:44733: tls: unsupported SSLv2 handshake received
Oct 01 20:45:39 deb systemd[1]: Stopping Caddy HTTP/2 web server...
Oct 01 20:45:39 deb systemd[1]: Stopped Caddy HTTP/2 web server.
Oct 01 20:45:39 deb systemd[1]: Starting Caddy HTTP/2 web server...
Oct 01 20:45:39 deb systemd[1]: Started Caddy HTTP/2 web server.
Oct 01 20:45:39 deb caddy[26635]: 2016/10/01 20:45:39 [INFO] NLgids localhost: [email protected]
Oct 01 20:45:42 deb caddy[26635]: Activating privacy features...2016/10/01 20:45:42 [INFO] Certificate for [www.dnssex.nl] expires in 699h15m17.206609051s; attempting ren
Oct 01 20:45:43 deb caddy[26635]: 2016/10/01 20:45:43 [INFO][www.dnssex.nl] acme: Trying renewal with 699 hours remaining
Oct 01 20:45:43 deb caddy[26635]: 2016/10/01 20:45:43 [INFO][www.dnssex.nl] acme: Obtaining bundled SAN certificate
Oct 01 20:45:43 deb caddy[26635]: 2016/10/01 20:45:43 [INFO][www.dnssex.nl] acme: Trying to solve TLS-SNI-01
Oct 01 20:45:45 deb caddy[26635]: 2016/10/01 20:45:45 [INFO][www.dnssex.nl] The server validated our request
Oct 01 20:45:45 deb caddy[26635]: 2016/10/01 20:45:45 [INFO][www.dnssex.nl] acme: Validations succeeded; requesting certificates
Oct 01 20:45:45 deb caddy[26635]: 2016/10/01 20:45:45 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:45:46 deb caddy[26635]: 2016/10/01 20:45:46 [INFO][www.dnssex.nl] Server responded with a certificate.
Oct 01 20:45:46 deb caddy[26635]: 2016/10/01 20:45:46 [INFO] Certificate for [www.isitinfra.net] expires in 699h21m13.896591197s; attempting renewal
Oct 01 20:45:46 deb caddy[26635]: 2016/10/01 20:45:46 [INFO][www.isitinfra.net] acme: Trying renewal with 699 hours remaining
Oct 01 20:45:46 deb caddy[26635]: 2016/10/01 20:45:46 [INFO][www.isitinfra.net] acme: Obtaining bundled SAN certificate
Oct 01 20:45:46 deb caddy[26635]: 2016/10/01 20:45:46 [INFO][www.isitinfra.net] acme: Trying to solve HTTP-01
Oct 01 20:45:47 deb caddy[26635]: 2016/10/01 20:45:47 [INFO][www.isitinfra.net] Served key authentication
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO][www.isitinfra.net] The server validated our request
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO][www.isitinfra.net] acme: Validations succeeded; requesting certificates
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO][www.isitinfra.net] Server responded with a certificate.
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO] Certificate for [miek.nl ] expires in 699h14m11.202888651s; attempting renewal
Oct 01 20:45:48 deb caddy[26635]: 2016/10/01 20:45:48 [INFO][miek.nl] acme: Trying renewal with 699 hours remaining
Oct 01 20:45:49 deb caddy[26635]: 2016/10/01 20:45:49 [INFO][miek.nl] acme: Obtaining bundled SAN certificate
Oct 01 20:45:49 deb caddy[26635]: 2016/10/01 20:45:49 [INFO][miek.nl] acme: Trying to solve TLS-SNI-01
deb# journalctl -fu caddy
-- Logs begin at Fri 2016-09-30 19:54:00 UTC. --
Oct 01 20:46:00 deb caddy[26635]: 2016/10/01 20:46:00 [INFO][www.berkestoffering.nl] acme: Obtaining bundled SAN certificate
Oct 01 20:46:01 deb caddy[26635]: 2016/10/01 20:46:01 [INFO][www.berkestoffering.nl] acme: Trying to solve HTTP-01
Oct 01 20:46:01 deb caddy[26635]: 2016/10/01 20:46:01 [INFO][www.berkestoffering.nl] Served key authentication
Oct 01 20:46:02 deb caddy[26635]: 2016/10/01 20:46:02 [INFO][www.berkestoffering.nl] The server validated our request
Oct 01 20:46:02 deb caddy[26635]: 2016/10/01 20:46:02 [INFO][www.berkestoffering.nl] acme: Validations succeeded; requesting certificates
Oct 01 20:46:03 deb caddy[26635]: 2016/10/01 20:46:03 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:03 deb caddy[26635]: 2016/10/01 20:46:03 [INFO][www.berkestoffering.nl] Server responded with a certificate.
Oct 01 20:46:03 deb caddy[26635]: 2016/10/01 20:46:03 [INFO] Certificate for [www.atoom.net] expires in 699h18m56.277058473s; attempting renewal
Oct 01 20:46:03 deb caddy[26635]: 2016/10/01 20:46:03 [INFO][www.atoom.net] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:04 deb caddy[26635]: 2016/10/01 20:46:04 [INFO][www.atoom.net] acme: Obtaining bundled SAN certificate
Oct 01 20:46:04 deb caddy[26635]: 2016/10/01 20:46:04 [INFO][www.atoom.net] acme: Trying to solve HTTP-01
Oct 01 20:46:05 deb caddy[26635]: 2016/10/01 20:46:05 [INFO][www.atoom.net] Served key authentication
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO][www.atoom.net] The server validated our request
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO][www.atoom.net] acme: Validations succeeded; requesting certificates
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO][www.atoom.net] Server responded with a certificate.
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO] Certificate for [isitinfra.net] expires in 699h18m53.361987199s; attempting renewal
Oct 01 20:46:06 deb caddy[26635]: 2016/10/01 20:46:06 [INFO][isitinfra.net] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:07 deb caddy[26635]: 2016/10/01 20:46:07 [INFO][isitinfra.net] acme: Obtaining bundled SAN certificate
Oct 01 20:46:07 deb caddy[26635]: 2016/10/01 20:46:07 [INFO][isitinfra.net] acme: Trying to solve HTTP-01
Oct 01 20:46:07 deb caddy[26635]: 2016/10/01 20:46:07 [INFO][isitinfra.net] Served key authentication
Oct 01 20:46:08 deb caddy[26635]: 2016/10/01 20:46:08 [INFO][isitinfra.net] The server validated our request
Oct 01 20:46:08 deb caddy[26635]: 2016/10/01 20:46:08 [INFO][isitinfra.net] acme: Validations succeeded; requesting certificates
Oct 01 20:46:09 deb caddy[26635]: 2016/10/01 20:46:09 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:09 deb caddy[26635]: 2016/10/01 20:46:09 [INFO][isitinfra.net] Server responded with a certificate.
Oct 01 20:46:09 deb caddy[26635]: 2016/10/01 20:46:09 [INFO] Certificate for [archive.miek.nl] expires in 699h14m50.622164874s; attempting renewal
Oct 01 20:46:09 deb caddy[26635]: 2016/10/01 20:46:09 [INFO][archive.miek.nl] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:09 deb caddy[26635]: 2016/10/01 20:46:09 [INFO][archive.miek.nl] acme: Obtaining bundled SAN certificate
Oct 01 20:46:10 deb caddy[26635]: 2016/10/01 20:46:10 [INFO][archive.miek.nl] acme: Could not find solver for: dns-01
Oct 01 20:46:10 deb caddy[26635]: 2016/10/01 20:46:10 [INFO][archive.miek.nl] acme: Trying to solve TLS-SNI-01
Oct 01 20:46:11 deb caddy[26635]: 2016/10/01 20:46:11 [INFO][archive.miek.nl] The server validated our request
Oct 01 20:46:11 deb caddy[26635]: 2016/10/01 20:46:11 [INFO][archive.miek.nl] acme: Validations succeeded; requesting certificates
Oct 01 20:46:12 deb caddy[26635]: 2016/10/01 20:46:12 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:12 deb caddy[26635]: 2016/10/01 20:46:12 [INFO][archive.miek.nl] Server responded with a certificate.
Oct 01 20:46:12 deb caddy[26635]: 2016/10/01 20:46:12 [INFO] Certificate for [nlgids.london] expires in 699h14m47.650614623s; attempting renewal
Oct 01 20:46:12 deb caddy[26635]: 2016/10/01 20:46:12 [INFO][nlgids.london] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:12 deb caddy[26635]: 2016/10/01 20:46:12 [INFO][nlgids.london] acme: Obtaining bundled SAN certificate
Oct 01 20:46:13 deb caddy[26635]: 2016/10/01 20:46:13 [INFO][nlgids.london] acme: Trying to solve TLS-SNI-01
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO][nlgids.london] The server validated our request
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO][nlgids.london] acme: Validations succeeded; requesting certificates
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO][nlgids.london] Server responded with a certificate.
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO] Certificate for [berkestoffering.nl] expires in 699h14m44.235123573s; attempting renewal
Oct 01 20:46:15 deb caddy[26635]: 2016/10/01 20:46:15 [INFO][berkestoffering.nl] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:16 deb caddy[26635]: 2016/10/01 20:46:16 [INFO][berkestoffering.nl] acme: Obtaining bundled SAN certificate
Oct 01 20:46:16 deb caddy[26635]: 2016/10/01 20:46:16 [INFO][berkestoffering.nl] acme: Trying to solve HTTP-01
Oct 01 20:46:17 deb caddy[26635]: 2016/10/01 20:46:17 [INFO][berkestoffering.nl] Served key authentication
Oct 01 20:46:18 deb caddy[26635]: 2016/10/01 20:46:18 [INFO][berkestoffering.nl] The server validated our request
Oct 01 20:46:18 deb caddy[26635]: 2016/10/01 20:46:18 [INFO][berkestoffering.nl] acme: Validations succeeded; requesting certificates
Oct 01 20:46:20 deb caddy[26635]: 2016/10/01 20:46:20 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:20 deb caddy[26635]: 2016/10/01 20:46:20 [INFO][berkestoffering.nl] Server responded with a certificate.
Oct 01 20:46:20 deb caddy[26635]: 2016/10/01 20:46:20 [INFO] Certificate for [atoom.net] expires in 699h18m39.180178862s; attempting renewal
Oct 01 20:46:21 deb caddy[26635]: 2016/10/01 20:46:21 [INFO][atoom.net] acme: Trying renewal with 699 hours remaining
Oct 01 20:46:21 deb caddy[26635]: 2016/10/01 20:46:21 [INFO][atoom.net] acme: Obtaining bundled SAN certificate
Oct 01 20:46:21 deb caddy[26635]: 2016/10/01 20:46:21 [INFO][atoom.net] acme: Trying to solve HTTP-01
Oct 01 20:46:22 deb caddy[26635]: 2016/10/01 20:46:22 [INFO][atoom.net] Served key authentication
Oct 01 20:46:23 deb caddy[26635]: 2016/10/01 20:46:23 [INFO][atoom.net] The server validated our request
Oct 01 20:46:23 deb caddy[26635]: 2016/10/01 20:46:23 [INFO][atoom.net] acme: Validations succeeded; requesting certificates
Oct 01 20:46:23 deb caddy[26635]: 2016/10/01 20:46:23 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 01 20:46:23 deb caddy[26635]: 2016/10/01 20:46:23 [INFO][atoom.net] Server responded with a certificate.
Oct 01 20:46:26 deb caddy[26635]:  done.
Oct 01 20:46:26 deb caddy[26635]: https://miek.nl
Oct 01 20:46:26 deb caddy[26635]: https://www.miek.nl
Oct 01 20:46:26 deb caddy[26635]: https://archive.miek.nl
Oct 01 20:46:26 deb caddy[26635]: https://nlgids.london
Oct 01 20:46:26 deb caddy[26635]: https://www.nlgids.london
Oct 01 20:46:26 deb caddy[26635]: https://coredns.io
Oct 01 20:46:26 deb caddy[26635]: https://www.coredns.io
Oct 01 20:46:26 deb caddy[26635]: https://blog.coredns.io
Oct 01 20:46:26 deb caddy[26635]: https://dnssex.nl
Oct 01 20:46:26 deb caddy[26635]: https://www.dnssex.nl
Oct 01 20:46:26 deb caddy[26635]: https://www.berkestoffering.nl
Oct 01 20:46:26 deb caddy[26635]: https://berkestoffering.nl
Oct 01 20:46:26 deb caddy[26635]: https://atoom.net
Oct 01 20:46:26 deb caddy[26635]: https://www.atoom.net
Oct 01 20:46:26 deb caddy[26635]: https://isitinfra.net
Oct 01 20:46:26 deb caddy[26635]: https://www.isitinfra.net
Oct 01 20:46:26 deb caddy[26635]: http://wereldstadsgidsen.com
Oct 01 20:46:26 deb caddy[26635]: http://www.wereldstadsgiden.com
Oct 01 20:46:26 deb caddy[26635]: http://wereldstadgidsen.nl
Oct 01 20:46:26 deb caddy[26635]: http://www.wereldstadgidsen.nl
Oct 01 20:46:26 deb caddy[26635]: http://wereldstadgidsen.be
Oct 01 20:46:26 deb caddy[26635]: http://www.wereldstadgidsen.be
Oct 01 20:46:26 deb caddy[26635]: http://miek.nl
Oct 01 20:46:26 deb caddy[26635]: http://www.miek.nl
Oct 01 20:46:26 deb caddy[26635]: http://archive.miek.nl
Oct 01 20:46:26 deb caddy[26635]: http://nlgids.london
Oct 01 20:46:26 deb caddy[26635]: http://www.nlgids.london
Oct 01 20:46:26 deb caddy[26635]: http://coredns.io
Oct 01 20:46:26 deb caddy[26635]: http://www.coredns.io
Oct 01 20:46:26 deb caddy[26635]: http://blog.coredns.io
Oct 01 20:46:26 deb caddy[26635]: http://dnssex.nl
Oct 01 20:46:26 deb caddy[26635]: http://www.dnssex.nl
Oct 01 20:46:26 deb caddy[26635]: http://www.berkestoffering.nl
Oct 01 20:46:26 deb caddy[26635]: http://berkestoffering.nl
Oct 01 20:46:26 deb caddy[26635]: http://atoom.net
Oct 01 20:46:26 deb caddy[26635]: http://www.atoom.net
Oct 01 20:46:26 deb caddy[26635]: http://isitinfra.net
Oct 01 20:46:26 deb caddy[26635]: http://www.isitinfra.net

7. How can someone who is starting from scratch reproduce this behavior as minimally as possible?

Good question.

bug help wanted

Source

miekg

👍3

Most helpful comment

To close this off. I saw a successful cert upgrade:
~
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO][www.isitinfra.net] Server responded with a certificate.
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO] Certificate for [www.miek.nl] expires in 716h56m25.933548018s; attempti
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO][www.miek.nl] acme: Trying renewal with 716 hours remaining
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO][www.miek.nl] acme: Obtaining bundled SAN certificate
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO][www.miek.nl] acme: Could not find solver for: dns-01
Nov 30 22:49:34 deb caddy[17021]: 2016/11/30 22:49:34 [INFO][www.miek.nl] acme: Trying to solve HTTP-01
Nov 30 22:49:35 deb caddy[17021]: 2016/11/30 22:49:35 [INFO][www.miek.nl] Served key authentication
Nov 30 22:49:36 deb caddy[17021]: 2016/11/30 22:49:36 [INFO][www.miek.nl] The server validated our request
Nov 30 22:49:36 deb caddy[17021]: 2016/11/30 22:49:36 [INFO][www.miek.nl] acme: Validations succeeded; requesting certificates
Nov 30 22:49:36 deb caddy[17021]: 2016/11/30 22:49:36 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/
Nov 30 22:49:36 deb caddy[17021]: 2016/11/30 22:49:36 [INFO][www.miek.nl] Server responded with a certificate.
~

This is thus due to running some random git release of the deps of caddy, which had "some" bug.

Thanks @mholt for you patience and this has nothing to do with systemd :+1:

miekg on 1 Dec 2016

👍2 🎉1

All 95 comments

Did the certificate cache get corrupted or something?

miekg on 1 Oct 2016

Sorry, but what exactly is wrong? (And why are the log lines truncated length-wise?) My head's a little stuffy today from allergies so maybe I'm missing something obvious...

mholt on 2 Oct 2016

(I cut and pasted the log - that might explain the cut-off)

As for what was wrong: I couldn't connect to any of sites - just hanging and and ssl error in the logs.

I just wanted to dump some evidence in this bug, because I have no idea what triggered this.

miekg on 2 Oct 2016

Well, the logs show that your client was only supporting old protocols (SSL) -- so that would probably be it. :-/

Not really sure what else to make of it, unfortunately! Looks like everything is fine.

mholt on 2 Oct 2016

So, it's not reboot related. It crapped out earlier: https://snapshot.raintank.io/dashboard/snapshot/B2bos4PfuMYItoQNoQYICrp374kfQRyL

This is at the logs at the points things went sour:

Oct 01 07:54:05 deb caddy[5591]: 2016/10/01 07:54:04 [INFO] Scanning for expiring certificates
Oct 01 07:54:05 deb caddy[5591]: 2016/10/01 07:54:04 [INFO] Certificate for [www.miek.nl] expires in 712h5m55.000638992s; attempting renewal
Oct 01 07:54:05 deb caddy[5591]: 2016/10/01 07:54:05 [INFO] acme: Registering account for
Oct 01 07:54:06 deb caddy[5591]: 2016/10/01 07:54:06 [INFO][www.miek.nl] acme: Trying renewal with 712 hours remaining
Oct 01 07:54:06 deb caddy[5591]: 2016/10/01 07:54:06 [INFO][www.miek.nl] acme: Obtaining bundled SAN certificate
Oct 01 07:54:06 deb caddy[5591]: 2016/10/01 07:54:06 [INFO][www.miek.nl] acme: Trying to solve TLS-SNI-01

after that it's mostly

tls: client offered an unsupported, maximum protocol version of 301

I would be nice if caddy-prometheus can track these errors, but I think it needs core caddy support to do this.

miekg on 2 Oct 2016

Oh, weird. Was there nothing relevant in the logs after that? Usually there would be some error message like "timeout" or something...

Anyway, what happens if you update to the latest HEAD? (Not just 0.9.3, but build from master in this case.)

But still... those are client errors, not server errors (about the client offering old protocol versions)...

mholt on 2 Oct 2016

[ Quoting [email protected] in "Re: [mholt/caddy] ssl certs failure..." ]

Oh, weird. Was there nothing relevant in the logs after that? Usually there would be some error message like "timeout" or something...

Anyway, what happens if you update to the latest HEAD? (Not just 0.9.3, but build from master in this case.)

But still... those are client errors, not server errors (about the client offering old protocol versions)...

True. But I couldn't connect (chrome on linux). After a second restart,
everything started working again.

I'll upgrade.

miekg on 2 Oct 2016

I haven't seen this before... very strange... if you see it again, let me know before you fix it and I'd like to take a look at it. Maybe set it up separately for just one of your sites that isn't important?

mholt on 2 Oct 2016

[ Quoting [email protected] in "Re: [mholt/caddy] ssl certs failure..." ]

I haven't seen this before... very strange...

me neither...

if you see it again, let me know before you fix it and I'd like to take a look at it. Maybe set it up separately for just one of your sites that isn't important?

Ack. I'll try to figure something out.

/Miek

Miek Gieben

miekg on 2 Oct 2016

happened again. Had to restart, so no in progress debugging.

Oct 05 02:54:02 deb caddy[18174]: 2016/10/05 02:54:02 http: TLS handshake error from 202.175.135.148:4657: EOF
Oct 05 02:55:02 deb caddy[18174]: 2016/10/05 02:55:02 [INFO] Scanning for expiring certificates
Oct 05 02:55:02 deb caddy[18174]: 2016/10/05 02:55:02 [INFO] Certificate for [coredns.io] expires in 708h28m57.053589258s; attempting renewal
Oct 05 02:55:03 deb caddy[18174]: 2016/10/05 02:55:03 [INFO][coredns.io] acme: Trying renewal with 708 hours remaining
Oct 05 02:55:03 deb caddy[18174]: 2016/10/05 02:55:03 [INFO][coredns.io] acme: Obtaining bundled SAN certificate
Oct 05 02:55:04 deb caddy[18174]: 2016/10/05 02:55:04 [INFO][coredns.io] acme: Trying to solve HTTP-01
Oct 05 02:55:04 deb caddy[18174]: 2016/10/05 02:55:04 [INFO][coredns.io] Served key authentication
Oct 05 02:55:05 deb caddy[18174]: 2016/10/05 02:55:05 [INFO][coredns.io] The server validated our request
Oct 05 02:55:05 deb caddy[18174]: 2016/10/05 02:55:05 [INFO][coredns.io] acme: Validations succeeded; requesting certificates
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][coredns.io] Server responded with a certificate.
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO] Certificate for [www.coredns.io] expires in 708h29m53.655761033s; attempting renewal
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][www.coredns.io] acme: Trying renewal with 708 hours remaining
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][www.coredns.io] acme: Obtaining bundled SAN certificate
Oct 05 02:55:07 deb caddy[18174]: 2016/10/05 02:55:07 [INFO][www.coredns.io] acme: Trying to solve TLS-SNI-01
Oct 05 02:59:16 deb caddy[18174]: 2016/10/05 02:59:16 http: TLS handshake error from 162.210.196.100:43352: tls: client offered an unsupported, maximum protocol version of 301
Oct 05 02:59:25 deb caddy[18174]: 2016/10/05 02:59:25 http: TLS handshake error from 162.210.196.100:45117: tls: client offered an unsupported, maximum protocol version of 301
Oct 05 02:59:28 deb caddy[18174]: 2016/10/05 02:59:28 http: TLS handshake error from 162.210.196.100:45837: tls: client offered an unsupported, maximum protocol version of 301
Oct 05 02:59:31 deb caddy[18174]: 2016/10/05 02:59:31 http: TLS handshake error from 162.210.196.100:46728: tls: client offered an unsupported, maximum protocol version of 301
Oct 05 03:01:04 deb caddy[18174]: 2016/10/05 03:01:04 http: TLS handshake error from [2001:1a50:11:0:5f:8f:ac0c:1]:45689: tls: client offered an unsupported, maximum protocol version of

This then breaks all other sites

miekg on 5 Oct 2016

version running

62fde4e - Add middleware for miek (3 days ago) <Miek Gieben>
b766dab - tls: Reorder some logic to avoid subtle, undocumented behavior (6 days ago) <Matthew Holt>
c885edd - Version 0.9.3 (7 days ago) <Matthew Holt>

Can a middleware trigger this?

miekg on 5 Oct 2016

Any tips on how to debug this?

miekg on 5 Oct 2016

Is seems to hang in getting the cert:

Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][coredns.io] Server responded with a certificate.
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO] Certificate for [www.coredns.io] expires in 708h29m53.655761033s; attempting renewal
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][www.coredns.io] acme: Trying renewal with 708 hours remaining
Oct 05 02:55:06 deb caddy[18174]: 2016/10/05 02:55:06 [INFO][www.coredns.io] acme: Obtaining bundled SAN certificate
Oct 05 02:55:07 deb caddy[18174]: 2016/10/05 02:55:07 [INFO][www.coredns.io] acme: Trying to solve TLS-SNI-01

then when I restart, it still renew www.coredns.io (again?)

Oct 05 10:09:11 deb caddy[32129]: 2016/10/05 10:09:11 [INFO] NLgids localhost: [email protected]
Oct 05 10:09:14 deb caddy[32129]: Activating privacy features...2016/10/05 10:09:14 [INFO] Certificate for [www.coredns.io] expires in 701h15m45.401514381s; attempting renewal
Oct 05 10:09:14 deb caddy[32129]: 2016/10/05 10:09:14 [INFO][www.coredns.io] acme: Trying renewal with 701 hours remaining
Oct 05 10:09:15 deb caddy[32129]: 2016/10/05 10:09:15 [INFO][www.coredns.io] acme: Obtaining bundled SAN certificate
Oct 05 10:09:15 deb caddy[32129]: 2016/10/05 10:09:15 [INFO][www.coredns.io] acme: Could not find solver for: dns-01
Oct 05 10:09:15 deb caddy[32129]: 2016/10/05 10:09:15 [INFO][www.coredns.io] acme: Trying to solve HTTP-01
Oct 05 10:09:16 deb caddy[32129]: 2016/10/05 10:09:16 [INFO][www.coredns.io] Served key authentication
Oct 05 10:09:16 deb caddy[32129]: 2016/10/05 10:09:16 [INFO][www.coredns.io] The server validated our request
Oct 05 10:09:16 deb caddy[32129]: 2016/10/05 10:09:16 [INFO][www.coredns.io] acme: Validations succeeded; requesting certificates
Oct 05 10:09:17 deb caddy[32129]: 2016/10/05 10:09:17 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Oct 05 10:09:17 deb caddy[32129]: 2016/10/05 10:09:17 [INFO][www.coredns.io] Server responded with a certificate.

Maybe a go get -u to update all deps as well?

miekg on 5 Oct 2016

Pulled latest of the latest:

./caddy --version
2016/10/05 10:27:04 [INFO] NLgids localhost: [email protected]
Caddy 0.9.3 (+ad5b94e Wed Oct 05 10:23:45 UTC 2016)

NLgids is some personal middleware.

miekg on 5 Oct 2016

What happens if you run it without an init system?

mholt on 5 Oct 2016

Interesting question. I'll start it _without_ systemd when/if it happens again.

miekg on 5 Oct 2016

Yeah for metrics :-) So the first failure happenend soon after I rebooted and (prolly) started using a new version of systemd. Currently I'm runing Version: 231-9, and I justed rebooted again.

Let's see what happens.

miekg on 5 Oct 2016

Can I trigger this by sending a SIGUSR1 to caddy? AFAIK it reloads itself after refreshing the certs? I.e. a normal reload?

miekg on 6 Oct 2016

USR1 reloads the configuration file, but doesn't kill the process. So it depends what you're trying to do.

mholt on 7 Oct 2016

Well, we can blame systemd all we want, but the reality is that this is a scary failure mode

miekg on 8 Oct 2016

Is it still happening without systemd?

mholt on 8 Oct 2016

Dunno.. still running under systemd, but the cert refresh has happened yet.
This would be a nice feature request: force cert refresh on a signal.

Anyway, I've also changed the unit file and increased the monitoring.

I appreciate if you could keep this open for a bit, I'll try to add more
info as I get it.

On 8 Oct 2016 9:35 pm, "Matt Holt" [email protected] wrote:

Is it still happening without systemd?

—
You are receiving this because you modified the open/close state.
Reply to this email directly, view it on GitHub
https://github.com/mholt/caddy/issues/1157#issuecomment-252446921, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAVkWziFAjzaFDv6QLV9bWrdrSj6GEXEks5qx_6IgaJpZM4KL3Hp
.

miekg on 8 Oct 2016

This would be a nice feature request: force cert refresh on a signal.

Maybe the API will do that.

I appreciate if you could keep this open for a bit, I'll try to add more
info as I get it.

Sure thing, thanks for keeping it updated!

mholt on 8 Oct 2016

[ Quoting [email protected] in "Re: [mholt/caddy] ssl certs failure..." ]

This would be a nice feature request: force cert refresh on a signal.

Maybe the API will do that.

Uhm? What API?

/Miek

Miek Gieben

miekg on 9 Oct 2016

The Caddy API.

mholt on 9 Oct 2016

@miekg Any update on this?

mholt on 2 Nov 2016

[ Quoting [email protected] in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg Any update on this?

I haven't seen it anymore. Probably because I need to wait 90days...

Feel free to close - if I find a smoking gun I will update this (closed) bug.

miekg on 2 Nov 2016

👍1

So this happened again:

Nov 17 19:37:23 deb caddy[30909]: 2016/11/17 19:37:23 [INFO] Scanning for expiring certificates
Nov 17 19:37:23 deb caddy[30909]: 2016/11/17 19:37:23 [INFO] Certificate for [blog.coredns.io] expires in 712h1m36.395757971s; attempting renewal
Nov 17 19:37:23 deb caddy[30909]: 2016/11/17 19:37:23 [INFO][blog.coredns.io] acme: Trying renewal with 712 hours remaining
Nov 17 19:37:24 deb caddy[30909]: 2016/11/17 19:37:24 [INFO][blog.coredns.io] acme: Obtaining bundled SAN certificate
Nov 17 19:37:24 deb caddy[30909]: 2016/11/17 19:37:24 [INFO][blog.coredns.io] acme: Could not find solver for: dns-01
Nov 17 19:37:24 deb caddy[30909]: 2016/11/17 19:37:24 [INFO][blog.coredns.io] acme: Trying to solve TLS-SNI-01
Nov 17 19:37:48 deb caddy[30909]: 2016/11/17 19:37:48 http: TLS handshake error from 83.249.16.89:59590: EOF
Nov 17 19:44:51 deb caddy[30909]: 2016/11/17 19:44:51 http: TLS handshake error from 8.29.198.26:12755: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:52:26 deb caddy[30909]: 2016/11/17 19:52:26 http: TLS handshake error from 65.19.138.35:54836: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:36 deb caddy[30909]: 2016/11/17 19:54:36 http: TLS handshake error from 154.66.19.230:52682: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:36 deb caddy[30909]: 2016/11/17 19:54:36 http: TLS handshake error from 154.66.19.230:52684: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:37 deb caddy[30909]: 2016/11/17 19:54:37 http: TLS handshake error from 154.66.19.230:52690: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:37 deb caddy[30909]: 2016/11/17 19:54:37 http: TLS handshake error from 154.66.19.230:52691: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:40 deb caddy[30909]: 2016/11/17 19:54:40 http: TLS handshake error from 154.66.19.230:52694: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:40 deb caddy[30909]: 2016/11/17 19:54:40 http: TLS handshake error from 154.66.19.230:52695: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:42 deb caddy[30909]: 2016/11/17 19:54:42 http: TLS handshake error from 154.66.19.230:52696: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:42 deb caddy[30909]: 2016/11/17 19:54:42 http: TLS handshake error from 154.66.19.230:52697: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:44 deb caddy[30909]: 2016/11/17 19:54:44 http: TLS handshake error from 154.66.19.230:52698: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:44 deb caddy[30909]: 2016/11/17 19:54:44 http: TLS handshake error from 154.66.19.230:52699: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:45 deb caddy[30909]: 2016/11/17 19:54:45 http: TLS handshake error from 154.66.19.230:52700: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:54:45 deb caddy[30909]: 2016/11/17 19:54:45 http: TLS handshake error from 154.66.19.230:52701: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:56:34 deb caddy[30909]: 2016/11/17 19:56:34 http: TLS handshake error from 8.29.198.26:64626: tls: client offered an unsupported, maximum protocol version of 301
Nov 17 19:57:51 deb caddy[30909]: 2016/11/17 19:57:51 http: TLS handshake error from 5.139.35.28:56980: EOF

the PID don't change - so can this actually be an systemd issue?

@mholt does caddy (process wise) anything special here?

Also you mentioned the caddy API, what should I actually do then? Make a little binary that does this cert renewal all the time?

miekg on 17 Nov 2016

@miekg

the PID don't change - so can this actually be an systemd issue?

Not sure I follow this -- what's your reasoning?

Also you mentioned the caddy API, what should I actually do then? Make a little binary that does this cert renewal all the time?

No, I'd rather get to the bottom of this if it's a bug in Caddy, but first I want to confirm it is a Caddy bug. Does this happen without systemd?

mholt on 18 Nov 2016

the PID didn't change - so can this actually be an systemd issue?
Not sure I follow this -- what's your reasoning?

No PID change, not systemd interaction?

No, I'd rather get to the bottom of this if it's a bug in Caddy, but first I want to confirm it is a Caddy bug.
Does this happen without systemd?

I haven't tested without systemd, as I want to hook into the distro's of running a binary. Maybe i can run a "shadow" Caddy on a different port with tmux.

miekg on 18 Nov 2016

Ok, running under tmux now - let's see.

miekg on 18 Nov 2016

👍1

According to https://groups.google.com/forum/#!msg/vault-tool/U5hVR8vIE3s/1-Eqvu0oEAAJ

This happens when a client tries to connect with TLS 1.1 but Vault is
only configured for TLS 1.2. Often this is seen with ELB health
checks, although you said you have disabled them. I'm not sure what's
causing them as I don't know what is at the IP addresses specified,
but it's only a problem if your clients are having trouble connecting!

It looks like some TLS-y is messed up (for some reason)

miekg on 18 Nov 2016

Ok, suspecting that I'm not running up to date code (i.e. its pretty weird that only 1 user would experience this). Doing go get -u -v ./... to update _everything_ and recompiling.

miekg on 18 Nov 2016

I get similar issues, no matter what I do or what domain I try, it seems it doesn't even attempt to request a certificate, here is my Caddyfile:

mydomain.com {
  cors

  proxy / app:3000 {
    policy  ip_hash
    insecure_skip_verify
    transparent
    websocket
  }

  header / {
    Access-Control-Allow-Origin   *
    Access-Control-Allow-Methods  *

    -Server
  }

  tls {
    max_certs 10
  }

  log     stderr
  errors  stderr
}

Here is the log output:

2016/11/28 23:02:32 http: TLS handshake error from 10.140.0.8:54782: no certificate available for mydomain.com
2016/11/28 23:02:32 http: TLS handshake error from 10.140.0.8:54783: no certificate available for mydomain.com
2016/11/28 23:02:34 http: TLS handshake error from 10.140.0.8:54784: no certificate available for mydomain.com
2016/11/28 23:02:34 http: TLS handshake error from 10.140.0.8:54786: no certificate available for mydomain.com
2016/11/28 23:09:34 http: TLS handshake error from 10.140.0.8:54934: no certificate available for mydomain.com
2016/11/28 23:09:34 http: TLS handshake error from 10.140.0.8:54933: no certificate available for mydomain.com
2016/11/28 23:09:35 http: TLS handshake error from 10.140.0.8:54935: no certificate available for mydomain.com
2016/11/28 23:09:35 http: TLS handshake error from 10.140.0.8:54937: no certificate available for mydomain.com
2016/11/28 23:09:37 http: TLS handshake error from 10.140.0.8:54939: no certificate available for mydomain.com
2016/11/28 23:09:37 http: TLS handshake error from 10.140.0.8:54938: no certificate available for mydomain.com

I've tried 3 domains or so now and it's always the same output. I'm using the Caddy 0.9.3 version.

ghost on 29 Nov 2016

@cheersjosh Just wondering... why are you using on-demand TLS for a single domain name?

mholt on 29 Nov 2016

It's a test at this point, I originally was trying to use a wildcard because we have a multi-tenant setup. We dynamically load client data based on the host. The wildcard wasn't working either.

ghost on 29 Nov 2016

Huh. Strange. That error comes from https://github.com/mholt/caddy/blob/f2e999aab27d19a81d5063deab7e939aa4c6b8fe/caddytls/handshake.go#L123. Would be interesting to see if cfg.OnDemand is in fact set to true (it should be!). If you can get more details, including the value of cfg.OnDemand and a sure way to repro, please open a new issue so we can get it fixed.

mholt on 29 Nov 2016

Diving further into this, requests for single domains work fine now. Not sure what was going on, caching maybe. But there is still an issue with wildcards. I've tried the following:

*
*.*
*.*.*
0.0.0.0
:443

But none of them work.

ghost on 29 Nov 2016

Okay, I've made some head way. I am not sure if this is the entire reason but I've found that if you only have one address entry in your Caddyfile, I'm not having any luck with On-Demand TLS inside a single server block. For example, this is my new Caddy file:

:443

cors

proxy / base-app:3000 {
  policy ip_hash
  insecure_skip_verify
  transparent
  websocket
}

header / {
  Access-Control-Allow-Origin  *
  Access-Control-Allow-Methods *

  -Server
}

tls {
  max_certs 10
}

There is a problem that still remains though, I get an error suggesting the address is already in use:

2016/11/29 02:14:54 [INFO] Obtaining new certificate for mydomain.com
2016/11/29 02:14:54 [INFO][mydomain.com] acme: Obtaining bundled SAN certificate
2016/11/29 02:14:55 [INFO][mydomain.com] acme: Trying to solve TLS-SNI-01
2016/11/29 02:14:55 http: TLS handshake error from 10.140.0.8:58208: [mydomain.com] failed to get certificate: [mydomain.com] error presenting token: Could not start HTTPS server for challenge -> listen tcp 0.0.0.0:443: bind: address already in use
2016/11/29 02:14:55 http: TLS handshake error from 10.140.0.8:58207: no certificate available for mydomain.com

ghost on 29 Nov 2016

Oh, okay, that's new:

2016/11/29 02:14:55 http: TLS handshake error from 10.140.0.8:58208: [mydomain.com] failed to get certificate: [mydomain.com] error presenting token: Could not start HTTPS server for challenge -> listen tcp 0.0.0.0:443: bind: address already in use

And was fixed by @elcore in #1273.

Please, let's keep issues on-topic.

mholt on 29 Nov 2016

This is thus due to running some random git release of the deps of caddy, which had "some" bug.

Thanks @mholt for you patience and this has nothing to do with systemd :+1:

miekg on 1 Dec 2016

👍2 🎉1

@miekg Great, good to have closure. :) Sorry for the trouble -- glad you resolved it.

(Strange, I wonder what dependency was outdated or something that was causing your issue.)

mholt on 1 Dec 2016

👍1

We will never know... could be an interaction between deps...

miekg on 1 Dec 2016

Damn....
This worked:
~
Nov 29 22:49:28 deb caddy[17021]: 2016/11/29 22:49:28 [INFO] Scanning for expiring certificates
Nov 29 22:49:28 deb caddy[17021]: 2016/11/29 22:49:28 [INFO] Done checking certificates
Nov 29 22:49:28 deb caddy[17021]: 2016/11/29 22:49:28 [INFO] Scanning for stale OCSP staples
Nov 29 22:49:28 deb caddy[17021]: 2016/11/29 22:49:28 [INFO] Advancing OCSP staple for [blog.coredns.io] from 2016-12-02 20:00:00 +0000 UTC to 2016-12-06 21:00:00 +0000 UTC
Nov 29 22:49:28 deb caddy[17021]: 2016/11/29 22:49:28 [INFO] Done checking OCSP staples
~
Then later an actual renewal
~
Nov 30 22:49:28 deb caddy[17021]: 2016/11/30 22:49:28 [INFO] Scanning for expiring certificates
Nov 30 22:49:28 deb caddy[17021]: 2016/11/30 22:49:28 [INFO] Certificate for [www.dnssex.nl] expires in 716h56m31.550378096s; attempting renewal
~
For nlgids.london I never see the new certs in the logs:
~
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO][archive.miek.nl] The server validated our request
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO][archive.miek.nl] acme: Validations succeeded; requesting certificates
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO][archive.miek.nl] Server responded with a certificate.
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO] Certificate for [nlgids.london] expires in 716h56m20.429025513s; attempting renewal
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO][nlgids.london] acme: Trying renewal with 716 hours remaining
Nov 30 22:49:39 deb caddy[17021]: 2016/11/30 22:49:39 [INFO][nlgids.london] acme: Obtaining bundled SAN certificate
Nov 30 22:49:40 deb caddy[17021]: 2016/11/30 22:49:40 [INFO][nlgids.london] acme: Could not find solver for: dns-01
Nov 30 22:49:40 deb caddy[17021]: 2016/11/30 22:49:40 [INFO][nlgids.london] acme: Trying to solve TLS-SNI-01
~
there is no Server responded with a certificate.
After that I did a request that worked:
~
Nov 30 22:56:37 deb caddy[17021]: 2001:8b0:bf59:4c3f:a796:8189:437c:4729 - miek.nl GET /css/highlight.css HTTP/2.0 304 0 https://miek.nl/
~
Then a bunch of
~
Dec 01 03:26:37 deb caddy[17021]: 2016/12/01 03:26:37 http: TLS handshake error from 95.28.1.83:51489: tls: client offered an unsupported, maximum protocol version of 301
Dec 01 03:26:37 deb caddy[17021]: 2016/12/01 03:26:37 http: TLS handshake error from 95.28.1.83:49455: tls: client offered an unsupported, maximum protocol version of 300
~
And then
~
Dec 01 04:27:19 deb caddy[17021]: 2016/12/01 04:27:19 [INFO] 176.58.119.54 - No such site at :80 (Remote: 170.0.236.103, Referer: )
Dec 01 04:31:03 deb caddy[17021]: 2016/12/01 04:31:03 http: TLS handshake error from [2001:1a50:11:0:5f:8f:ac0c:1]:37502: tls: client offered an unsupported, maximum protocol version of 301
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 5ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 10ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 20ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 40ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 80ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 160ms
Dec 01 04:31:48 deb caddy[17021]: 2016/12/01 04:31:48 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 320ms
Dec 01 04:31:49 deb caddy[17021]: 2016/12/01 04:31:49 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 640ms
Dec 01 04:31:49 deb caddy[17021]: 2016/12/01 04:31:49 http: Accept error: accept tcp [::]:443: accept4: too many open files; retrying in 1s
~
Until I restarted caddy.

@mholt : what is the correct/best/fastest way to debug this? Write a test program that tries to mimic this, add more logging (where?).

miekg on 1 Dec 2016

Refresh my memory. What kind of Caddy configuration are you using now? Are you running vanilla Caddy without plugins and without systemd? Are you using an official build or your own?

Frankly I'd say let's go back to square 0 by using an official build (currently version 0.9.3) from the website and with no plugins and no systemd and a simple infrastructure setup. Then use only cURL -v to make requests, to ensure browsers aren't doing anything funky.

mholt on 1 Dec 2016

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

Refresh my memory. What kind of Caddy configuration are you using now? Are you running vanilla Caddy without plugins and without systemd? Are you using an official build or your own?

No, from git - so nothing official there. And a number of plugins, among other
prometheus and a one that is a one-off for a website.

Frankly I'd say let's go back to square 0 by using an official build (currently
version 0.9.3) from the website and with no plugins and no systemd and a simple
infrastructure setup. Then use only cURL -v to make requests, to ensure
browsers aren't doing anything funky.

Yes, that would make sense, but is not currently possible as I'm sort of
running production with caddy. Or much rather have a quick way to reproduce - so
as force caddy to do the acme challenge while running.

/Miek

--
Miek Gieben

miekg on 1 Dec 2016

So, on a hunch I build -race binary:
~
Dec 01 19:47:09 deb caddy[24969]: ==================
Dec 01 19:47:09 deb caddy[24969]: WARNING: DATA RACE
Dec 01 19:47:09 deb caddy[24969]: Read at 0x00c42018e4c4 by goroutine 36:
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Config).serverInit()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/common.go:458 +0x9d
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Config).(crypto/tls.serverInit)-fm()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0x41
Dec 01 19:47:09 deb caddy[24969]: sync.(Once).Do()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/sync/once.go:44 +0xf2
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Conn).serverHandshake()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0xca
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Conn).Handshake()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/conn.go:1262 +0x4f5
Dec 01 19:47:09 deb caddy[24969]: net/http.(conn).serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/net/http/server.go:1507 +0xfbd
Dec 01 19:47:09 deb caddy[24969]: Previous write at 0x00c42018e4c4 by goroutine 33:
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddytls.standaloneTLSTicketKeyRotation()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:274 +0x155
Dec 01 19:47:09 deb caddy[24969]: Goroutine 36 (running) created at:
Dec 01 19:47:09 deb caddy[24969]: net/http.(Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/net/http/server.go:2293 +0x540
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddyhttp/httpserver.(Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:191 +0x1e0
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy.startServers.func1.1()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56
Dec 01 19:47:09 deb caddy[24969]: Goroutine 33 (running) created at:
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddytls.RotateSessionTicketKeys()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:240 +0xb4
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddyhttp/httpserver.(Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:179 +0x38a
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy.startServers.func1.1()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56
Dec 01 19:47:09 deb caddy[24969]: ==================
Dec 01 19:47:09 deb caddy[24969]: ==================
Dec 01 19:47:09 deb caddy[24969]: WARNING: DATA RACE
Dec 01 19:47:09 deb caddy[24969]: Write at 0x00c42018e550 by goroutine 36:
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Config).serverInit()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/common.go:472 +0x1f4
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Config).(crypto/tls.serverInit)-fm()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0x41
Dec 01 19:47:09 deb caddy[24969]: sync.(Once).Do()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/sync/once.go:44 +0xf2
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Conn).serverHandshake()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0xca
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Conn).Handshake()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/conn.go:1262 +0x4f5
Dec 01 19:47:09 deb caddy[24969]: net/http.(conn).serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/net/http/server.go:1507 +0xfbd
Dec 01 19:47:09 deb caddy[24969]: Previous write at 0x00c42018e550 by goroutine 33:
Dec 01 19:47:09 deb caddy[24969]: crypto/tls.(Config).SetSessionTicketKeys()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/crypto/tls/common.go:500 +0x22a
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddytls.standaloneTLSTicketKeyRotation()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:275 +0x203
Dec 01 19:47:09 deb caddy[24969]: Goroutine 36 (running) created at:
Dec 01 19:47:09 deb caddy[24969]: net/http.(Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/upstream/go/src/net/http/server.go:2293 +0x540
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddyhttp/httpserver.(Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:191 +0x1e0
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy.startServers.func1.1()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56
Dec 01 19:47:09 deb caddy[24969]: Goroutine 33 (running) created at:
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddytls.RotateSessionTicketKeys()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:240 +0xb4
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy/caddyhttp/httpserver.(*Server).Serve()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:179 +0x38a
Dec 01 19:47:09 deb caddy[24969]: github.com/mholt/caddy.startServers.func1.1()
Dec 01 19:47:09 deb caddy[24969]: /home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56
Dec 01 19:47:09 deb caddy[24969]: ==================
~

miekg on 1 Dec 2016

Okay, well, I don't have time to look into this, so it's up to you for now.

mholt on 1 Dec 2016

So with a clean master checkout, a go build -race build, and this Caddyfile:
~
https://test.dnssex.nl {
root /
}
~
Starting with:
~
% sudo ./caddy -conf ~/Caddyfile -log stdout ~/g/src/github.com/mholt/caddy/caddy master
Activating privacy features... done.
https://test.dnssex.nl
2016/12/01 21:17:10 https://test.dnssex.nl
http://test.dnssex.nl
2016/12/01 21:17:10 http://test.dnssex.nl
WARNING: File descriptor limit 1024 is too low for production servers. At least 8192 is recommended. Fix with "ulimit -n 8192".
~
Gives this when I query it:

~~~

WARNING: DATA RACE
Read at 0x00c4201b8784 by goroutine 21:
crypto/tls.(Config).serverInit()
/home/miek/upstream/go/src/crypto/tls/common.go:458 +0x9d
crypto/tls.(Config).(crypto/tls.serverInit)-fm()
/home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0x41
sync.(Once).Do()
/home/miek/upstream/go/src/sync/once.go:44 +0xf2
crypto/tls.(Conn).serverHandshake()
/home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0xca
crypto/tls.(Conn).Handshake()
/home/miek/upstream/go/src/crypto/tls/conn.go:1234 +0x238
net/http.(conn).serve()
/home/miek/upstream/go/src/net/http/server.go:1507 +0xfbd

Previous write at 0x00c4201b8784 by goroutine 20:
github.com/mholt/caddy/caddytls.standaloneTLSTicketKeyRotation()
/home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:274 +0x155

Goroutine 21 (running) created at:
net/http.(Server).Serve()
/home/miek/upstream/go/src/net/http/server.go:2293 +0x540
github.com/mholt/caddy/caddyhttp/httpserver.(Server).Serve()
/home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:191 +0x1e0
github.com/mholt/caddy.startServers.func1.1()
/home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56

Goroutine 20 (running) created at:
github.com/mholt/caddy/caddytls.RotateSessionTicketKeys()
/home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:240 +0xb4
github.com/mholt/caddy/caddyhttp/httpserver.(*Server).Serve()
/home/miek/g/src/github.com/mholt/caddy/caddyhttp/httpserver/server.go:179 +0x38a
github.com/mholt/caddy.startServers.func1.1()

/home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56

~~~
And even more:

~~~

WARNING: DATA RACE
Write at 0x00c4201b8810 by goroutine 21:
crypto/tls.(Config).serverInit()
/home/miek/upstream/go/src/crypto/tls/common.go:472 +0x1f4
crypto/tls.(Config).(crypto/tls.serverInit)-fm()
/home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0x41
sync.(Once).Do()
/home/miek/upstream/go/src/sync/once.go:44 +0xf2
crypto/tls.(Conn).serverHandshake()
/home/miek/upstream/go/src/crypto/tls/handshake_server.go:44 +0xca
crypto/tls.(Conn).Handshake()
/home/miek/upstream/go/src/crypto/tls/conn.go:1234 +0x238
net/http.(conn).serve()
/home/miek/upstream/go/src/net/http/server.go:1507 +0xfbd

Previous write at 0x00c4201b8810 by goroutine 20:
crypto/tls.(*Config).SetSessionTicketKeys()
/home/miek/upstream/go/src/crypto/tls/common.go:500 +0x22a
github.com/mholt/caddy/caddytls.standaloneTLSTicketKeyRotation()
/home/miek/g/src/github.com/mholt/caddy/caddytls/crypto.go:275 +0x203

/home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56

^C2016/12/01 21:19:09 [INFO] SIGINT: Shutting down
Found 2 data race(s)
~~~

miekg on 1 Dec 2016

Hmmpf. I tried to apply some simple fixes, but this looks like a quite fundamental data race in caddytls/crypto.go.

I would love to be proved wrong here though!

miekg on 1 Dec 2016

There is unfortunately no (known) way to "properly" rotate TLS session ticket keys; but this race is effectively harmless. I would be very surprised if it had anything to do with the issue you're experiencing.

mholt on 2 Dec 2016

Why do you say it is harmless, that PR talks about setting a bool, the errors I see in the race detection are concerning the actual key rotation? To be fair L274 is before the endless loop, but this still triggers the race detection. And this the code called (is it?) after a new acme challenge which is where I see my problems. But questions remain, why I'm I the only one seeing this?
I believe to fix this race we have return a *tls.Config and set that in the server which would be an automaic operation.

I'll try to make this change to see if that works and doesn't destroy the web serving capabilities of caddy and solves this issue.

miekg on 2 Dec 2016

@miekg I hit #1279 that may be related to the issue you're facing. In my logs I also had a bunch of logs about unsupported maximum protocol and renewal stuck on Trying to solve TLS-SNI-01. I'm currently pressed with other things but would otherwise like to build my server with -race enabled and see what's going on.

radomirml on 2 Dec 2016

Yes, sure looks like. The in-fly-cert-updates look racy and Caddy doesn't deal well if things don't work, which is bad. It should at least hold on to some last good state or something.

Glad I'm not the only one seeing this anymore.

miekg on 2 Dec 2016

@radomirml I'm now running Caddy with the session key rotation disabled. This removes all the race detection warnings (the full diff below, adds some extra plugins). Still running a binary build with -race

~~~
diff --git a/caddy/caddymain/run.go b/caddy/caddymain/run.go
index a6dd83d..ba9aa26 100644
--- a/caddy/caddymain/run.go
+++ b/caddy/caddymain/run.go
@@ -22,8 +22,6 @@ import (

    "github.com/mholt/caddy/caddytls"
    // This is where other plugins get plugged in (imported)

_ "github.com/miekg/nlgids"
_ "github.com/miekg/caddy-prometheus"
)

func init() {
diff --git a/caddyhttp/httpserver/plugin.go b/caddyhttp/httpserver/plugin.go
index f5b85c3..8105a57 100644
--- a/caddyhttp/httpserver/plugin.go
+++ b/caddyhttp/httpserver/plugin.go
@@ -439,7 +439,6 @@ var directives = []string{
"mailout", // github.com/SchumacherFM/mailout
"awslambda", // github.com/coopernurse/caddy-awslambda
"filter", // github.com/echocat/caddy-filter

"nlgids", // github.com/miekg/nlgids
}

const (
diff --git a/caddyhttp/httpserver/server.go b/caddyhttp/httpserver/server.go
index fb25941..c435b0a 100644
--- a/caddyhttp/httpserver/server.go
+++ b/caddyhttp/httpserver/server.go
@@ -176,7 +176,7 @@ func (s *Server) Serve(ln net.Listener) error {
ln = tls.NewListener(ln, s.Server.TLSConfig)

            // Rotate TLS session ticket keys

- // s.tlsGovChan = caddytls.RotateSessionTicketKeys(s.Server.TLSConfig)
+ s.tlsGovChan = caddytls.RotateSessionTicketKeys(s.Server.TLSConfig)
}

    if QUIC {

~~~

miekg on 2 Dec 2016

Just an update: after running three days with the patch above things look good (I've claimed that before though), so I'm not claiming victory (yet).

@mholt can you explain why you think that having the key rotation setup like it is, is harmless? The documentation clearly states "you are not supposed to do that":

A Config structure is used to configure a TLS client or server. After
one has been passed to a TLS function it must not be modified. A Config
may be reused; the tls package will also not modify it.

Which, I think, makes key rotation, sadly, not an option with the current stb libs.

miekg on 5 Dec 2016

Caddy has been running super stable since Dec 05.

miekg on 13 Dec 2016

can you explain why you think that having the key rotation setup like it is, is harmless?

If you follow the link I posted, you'll see that @wmark actually said it, and I think I agree since the "race" happens once only at the very beginning before serving.

mholt on 13 Dec 2016

But Matt, that only talks about the boolean that gets set:

c.SessionTicketsDisabled = true // bail if we don't have the entropy for the first one

There is no discussion in that thread about the sessions keys themselves.

I think I saw the race detector also go off when I queried caddy - but I'll double check.

miekg on 13 Dec 2016

If our key rotation does not kick in, Go populates the array itself, with random values. All what happens after that is that the former TLS ticket does not result in a resumed session, and the usual key agreement takes place.

A nil value effectively disables the feature, and uncontrolled values result in unusable TLS tickets, back to the first paragraph then.

I think finding the cause of tls: client offered an unsupported, maximum protocol version of 301 will be more worthwhile. Let's Encrypt won't use a TLS ticket when renewing, because by then it has long expired or has not been saved in the first place.

wmark on 13 Dec 2016

Yes, I'm trying to find out where that error comes from - It's hard, and I'm trying to weed out things that may cause it :-)

In answer to your comments: our key rotation does kick in....

In caddytls/crypto.go we create a slice of arrays: keys := make([][32]byte, 1, NumTickets)

We then call c.SetSessionTicketKeys(setSessionTicketKeysTestHook(keys)) which sets these in the tls.config. So far so good and even the docs for SetSessionTicketKeys say this function may be called when the server is running. But then our goroutine standaloneTLSTicketKeyRotation keeps manipulating the allocated slice...

That just looks dangerous. Again; I'm not claiming that that yields that error, but it does seems suspicious.

And I'm all open to find other ways to debug this, but so far I haven't come up with a good way to replay this :(

miekg on 13 Dec 2016

Go doesn't use our data structure directly. Another is derived from it:
https://github.com/golang/go/blob/a9ce0f96e1f2ab69ce3319c5a97c1d01beb9472c/src/crypto/tls/common.go#L640-L653
Reading ticketKeyFromBytes think »hash.«

The reason we stick with the one array and don't go the convenient path of just creating a new one in the for-loop is to avoid scattering copies of those values. Usually you'd prefer to keep secrets in one place. (Yes, Go's TLS stack makes copies when computing derivative values, but you might find this implementation handy with other TLS stacks.)

I still think you're on the wrong path, due to the output of -race.

wmark on 13 Dec 2016

I might have a report of this happening as well with another user. Maybe this possible race condition merits more observation/investigation.

mholt on 3 Jan 2017

Private conversations with other Gophers hinted towards Go 1.7 http/tls doing the wrong thing. If you follow the code at some point *tls.Config turns nil leading to the observed behavior. Doing the key updates like we discussed, might trigger this.

Note: I've not been able to reproduce this in a test. Also the binary that runs miek.nl (among other things) is rock stable (but I've disabled the session key updating there).

miekg on 3 Jan 2017

@miekg I'd quite like to learn more about this -- what part of the std lib are you referring to exactly? I can't find a reference to any line of code that, after starting, would set the *tls.Config to nil. Could you clue me in? I want to get to the bottom of this without disabling key rotation -- find a proper fix. :) Glad to hear that, at least by disabling it, your production setup is rock solid. That means we probably know the cause, roughly.

mholt on 3 Jan 2017

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg I'd quite like to learn more about this -- what part of the std lib are
you referring to exactly? I can't find a reference to any line of code that,
after starting, would set the *tls.Config to nil. Could you clue me in?

No there is no root cause yet, but the only way this can trigger (as I can see)
is if *tls.Config is nil (I'll retrace that code when I have time). How that
thing can be nil is a mystery to me as of yet.

I want
to get to the bottom of this without disabling key rotation -- find a proper
fix. :) Glad to hear that, at least by disabling it, your production setup is
rock solid. That means we probably know the cause, roughly.

Yes. What would be extremely helpful is a test/command to trigger this, but
again I haven't found the time to properly debug this.

/Miek

--
Miek Gieben

miekg on 3 Jan 2017

Private conversations with other Gophers hinted towards Go 1.7 http/tls doing the wrong thing.

This might make sense, since I don't remember having this issue with Go 1.6, but I wouldn't have suspected an issue with Go itself.

I just built Caddy on Go 1.6 and deployed it into production on one particular server that I saw suspicious behavior that reminds me of this (more than once!), I will see if it happens again. If not, maybe it _is_ a bug in the standard library.

mholt on 8 Jan 2017

@miekg If the issue I'm seeing is the same one as here, then it's not Go 1.7 causing it. Seeing the issue built on Go 1.6 too. Gonna try 1.8 beta 2 next. (The error reported this time was during the TLS handshake: http: TLS handshake error from <other ip>:19451: write tcp <ip>:443-><other ip>:19451: i/o timeout)

mholt on 8 Jan 2017

Can you tell me how you reproduce the error?

miekg on 8 Jan 2017

Ok, just got the error with my don't-touch-the-session-keys-binary:

(lines capped due to cut and paste), but same issue.
~
Jan 08 22:41:21 deb caddy[5691]: 188.25.30.133 - miek.nl GET /images/favicon.ico HTTP/2.0 200 5182 https://miek.nl/2014/August/16/go-dns-package/
Jan 08 22:41:23 deb caddy[5691]: 173.61.198.52 - www.miek.nl GET /favicon.ico HTTP/2.0 404 3958 https://www.miek.nl/go/
Jan 08 22:41:29 deb caddy[5691]: 2017/01/08 22:41:29 http: TLS handshake error from 173.61.198.52:42846: EOF
Jan 08 22:41:30 deb caddy[5691]: 2017/01/08 22:41:30 http2: server: error reading preface from client 188.25.30.133:59753: timeout waiting for client preface
Jan 08 22:42:16 deb caddy[5691]: 2017/01/08 22:42:16 [INFO] Scanning for expiring certificates
Jan 08 22:42:16 deb caddy[5691]: 2017/01/08 22:42:16 [INFO] Certificate for [20in20.london] expires in 715h54m43.937891712s; attempting renewal
Jan 08 22:42:16 deb caddy[5691]: 2017/01/08 22:42:16 [INFO][20in20.london] acme: Trying renewal with 715 hours remaining
Jan 08 22:42:16 deb caddy[5691]: 2017/01/08 22:42:16 [INFO][20in20.london] acme: Obtaining bundled SAN certificate
Jan 08 22:42:16 deb caddy[5691]: 2017/01/08 22:42:16 [INFO][20in20.london] acme: Trying to solve TLS-SNI-01
Jan 08 22:44:23 deb caddy[5691]: 188.25.30.133 - miek.nl GET /2016/November/28/coredns-monitoring-with-stunnel/ HTTP/2.0 200 2601 https://miek.nl/2014/August/16/go-dns-pa
Jan 08 22:44:23 deb caddy[5691]: 188.25.30.133 - miek.nl GET /images/2016/grafana-coredns-proxy.png HTTP/2.0 200 71880 https://miek.nl/2016/November/28/coredns-monitoring
Jan 08 22:44:28 deb caddy[5691]: 188.25.30.133 - miek.nl GET /2016/August/07/coredns.io/ HTTP/2.0 200 1806 https://miek.nl/2014/August/16/go-dns-package/
Jan 08 22:44:30 deb caddy[5691]: 188.25.30.133 - miek.nl GET /2016/May/22/debug-queries-in-coredns-with-the-etcd-middleware/ HTTP/2.0 200 3391 https://miek.nl/2014/August
Jan 08 22:59:27 deb caddy[5691]: 188.25.30.133 - miek.nl GET /favicon.ico HTTP/2.0 404 3958 https://miek.nl/images/2016/grafana-coredns-proxy.png
Jan 08 23:01:08 deb caddy[5691]: 2017/01/08 23:01:08 http: TLS handshake error from [2001:1a50:11:0:5f:8f:ac0c:1]:37597: tls: client offered an unsupported, maximum proto
~

miekg on 9 Jan 2017

@miekg Unfortunately I'm not sure how to reproduce it :( It just happens on this one server after some time.

Are you sure that TLS handshake error isn't legitimate?

mholt on 9 Jan 2017

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg Unfortunately I'm not sure how to reproduce it :( It just happens on this one server after some time.

Are you sure that TLS handshake error isn't legitimate?

Yep. This is me with Chrome reaching to the website; restart Caddy -> works.

There seems to be a race (deep in the Go code) whereby, once, you fiddle with
*tls.Config it turns to nil at that point your websites are dead in the water.

I itching to compile from Golang-HEAD to get the latest fixes, esp. that
superweird one from Rob Pike.

miekg on 9 Jan 2017

@miekg Thanks for the clarification. Hmm... I'm running with Go 1.8 beta 2 in production now and for a few days it has been working okay. Will give it another few weeks and see if anything goes haywire. (Which super weird fix from Rob Pike are you referring to?)

mholt on 10 Jan 2017

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg Thanks for the clarification. Hmm... I'm running with Go 1.8 beta 2 in production now and for a few days it has been working okay. Will give it another few weeks and see if anything goes haywire. (Which super weird fix from Rob Pike are you referring to?)

https://github.com/golang/go/commit/b902a63ade47cf69218c9b38c9a783fc8cfc3041

/Miek

--
Miek Gieben

miekg on 11 Jan 2017

running mine under go1.8rc1 now

miekg on 11 Jan 2017

Hm, dang, I think it happened again. :-/ But I didn't see anything in the logs from my IP.

mholt on 12 Jan 2017

Run the webserver with GC disabled, if your target environment allows for it.

wmark on 12 Jan 2017

@miekg I think it's strange that some, but not all, of those errors happen after (during?) a TLS-SNI-01 challenge. I started digging into the lego/acme package which facilitates this for Caddy, and found what I think is a couple of leaked file descriptors. Maybe? Feel free to verify or debunk my claim: https://github.com/xenolf/lego/pull/341

So, I don't know if that has anything to do with what you're seeing. It seems unlikely, and it definitely wouldn't resolve a race that might be happening between Caddy and the Go standard library.

@wmark Unfortunately I'm not in a position to disable GC on this instance... but I can see why you'd suggest it: if a *tls.Config is getting set to nil somehow, it's probably the GC thinking that the value is no longer referenced, so disabling GC might let it stay around. I highly doubt it's the race on that SessionTicketKey field causing that, though. Yes, we technically do an unsynchronized write. But only once, and definitely before the server is started.

I'm continuing to investigate any other aspect of the TLS-SNI challenge that might be buggy.

mholt on 14 Jan 2017

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg I think it's strange that some, but not all, of those errors happen after (during?) a TLS-SNI-01 challenge. I started digging into the lego/acme package which facilitates this for Caddy, and found what I think is a couple of leaked file descriptors. Maybe? Feel free to verify or debunk my claim: https://github.com/xenolf/lego/pull/341

Thanks. That PR def. fixes a leak. I left a comment.

So, I don't know if that has anything to do with what you're seeing. It seems unlikely, and it definitely wouldn't resolve a race that might be happening between Caddy and the Go standard library.

I my current test with go1.8rc1 also fails, I will proceed in instrumenting the
go std lib as well, and hopefully get more debugging info.

I'm continuing to investigate any other aspect of the TLS-SNI challenge that might be buggy.

Thanks!

/Miek

--
Miek Gieben

miekg on 14 Jan 2017

👍1

Unfortunately I'm not in a position to disable GC on this instance... but I can see why you'd suggest it: if a *tls.Config is getting set to nil somehow, it's probably the GC thinking that the value is no longer referenced, so disabling GC might let it stay around.

While developing something unrelated I've wanted to utilize some kernel functions, for example to prevent memory pages with the TLS configuration from being moved to swap and to clear/overwrite it deliberately. One thing to get this to work is to exclude said memory pages from GC's compaction.

wmark on 14 Jan 2017

@wmark Can you elaborate on the comment on this line? https://sourcegraph.com/github.com/mholt/caddy@0155b0c5fb958d5692aaa5678716dabc9a9ae76d/-/blob/caddytls/crypto.go#L274-275

I'm wondering why this is necessary. A search on golang.org for keysAlreadySet doesn't bring up any results.

mholt on 15 Jan 2017

This has been due to this (link goes to an old version, not the most recent one!):
https://github.com/golang/go/blob/release-branch.go1.6/src/crypto/tls/common.go#L392-L396

Without the line you've highlighted, come the first connection, Go will ignore the values which we control and use an random array of its own, until we perform our first rotation.

I've reported this back then as golang/go#15421.

wmark on 15 Jan 2017

Ah, excellent. So we can remove that line come Go 1.8. :+1: @miekg That should fix the race condition. I wonder if it will resolve the underlying issue though.

mholt on 15 Jan 2017

See https://github.com/mholt/caddy/pull/1354 for a patch for the race condition, at least. I think there's still something else going on here.

mholt on 15 Jan 2017

K, there's something wrong here. I'm devoting all my energies to fixing this ASAP.

mholt on 18 Jan 2017

@miekg I have a new theory. When this happens, sudo lsof | grep caddy | wc -l shows a high number (in the thousands?) and most of these open files are sockets in CLOSE_WAIT. Thus, the standard lib can't read the handshake data properly, so the clientHelloMsg is a struct with (mostly? all?) "zero" values. I suspect the vers field is 0 (default value), which results in the client offered an unsupported, maximum protocol version of 301 message. (The standard library defaults to a minimum of TLS 1.0 or 301, but Caddy defaults to a minimum of 302 or TLS 1.1.) This error message is only caused, like you said, by either the tls.Config being nil or, as I suspect, the vers on the client hello is still 0 (unset). https://golang.org/src/crypto/tls/common.go?h=mutualVersion#L553 -- this is just a theory, but there's honestly not many paths in the immediate way that the code can arrive at this alert.

I'm having a really hard time reproducing this locally. But I don't think a high amount of traffic is required; I saw this happen on a low-traffic site. I have also seen this happen on a host that was being attacked from some sort of botnet on a compromised machine. Continuing to investigate.

mholt on 18 Jan 2017

[ Quoting notifications@github.com in "Re: [mholt/caddy] ssl certs failure..." ]

@miekg I have a new theory. When this happens, sudo lsof | grep caddy | wc -l
shows a high number (in the thousands?) and most of these open files are
sockets in CLOSE_WAIT. Thus, the standard lib can't open a socket to read the
handshake, so the clientHelloMsg is a struct with (mostly? all?) "zero" values.
I suspect the vers field is 0 (default value), which results in the client offered an unsupported, maximum protocol version of 301 message. (The standard
library defaults to a minimum of TLS 1.0 or 301, but Caddy defaults to a
minimum of 302 or TLS 1.1.) This error message is only caused, like you said,
by either the tls.Config being nil or, as I suspect, the vers on the client
hello is still 0 (unset).
https://golang.org/src/crypto/tls/common.go?h=mutualVersion#L553

Hmmpf I didn't check that. but I have monitoring :-) And indeed I see a spike
going up to 2+K open file descriptors 9th of January - at the time I saw the
issue (I think).

Your theory makes sense to to me.

I'm having a really hard time reproducing this locally. But I don't think a
high amount of traffic is required; I saw this happen on a low-traffic site. I
have also seen this happen on a host that was being attacked from some sort of
botnet on a compromised machine. Continuing to investigate.

Looking at the open fd graph, there does not seem to be a leak it just jumps up
all of a sudden.

/Miek

--
Miek Gieben

miekg on 18 Jan 2017

goroutines spikes at the same time, no increase in #requests. And 9th of Jan is def. the day I saw this issue.

miekg on 18 Jan 2017

Turns out that having the vers value I was referring to left unset isn't really an issue, since the error message pulls the vers directly from the TLS handshake state, which is set on line 302: https://golang.org/src/crypto/tls/handshake_messages.go?h=.vers+%3D

I'm beginning to think we are looking at symptoms of a bug here, not the actual bug itself...

mholt on 18 Jan 2017

@miekg What's your Caddyfile? More specifically, are the site addresses enumerated in the Caddyfile, or are you using some sort of wildcard like :443 or *? Are you using on-demand TLS? I was just re-reading this whole thread and indeed I somehow missed @cheersjosh's replies. I have seen this issue happen on instances that don't use on-demand TLS but it's worth investigating if there's a connection.

mholt on 20 Jan 2017

This stanza repeated for different sites a couple of times (nothing special, nothing on demand):

~~~
https://miek.nl https://www.miek.nl https://archive.miek.nl {
root /opt/www/miek.nl

log / stdout "{remote} - {host} {method} {path} {proto} {status} {size} {>Referer}"
errors / stderr "{remote} - {host} {method} {path} {proto} {status} {size} {>Referer}"
errors {
    404 404.html
}

redir /downloads/Go/Learning-Go-latest.pdf /go 301

ext .html
gzip
prometheus

}
~~~

miekg on 20 Jan 2017

Thanks for the info.

I'm fairly confident #1366 is related to this (it _definitely_ was a bug), but I was never able to verify that the lock contention caused the symptoms we're seeing.

mholt on 22 Jan 2017

Upgraded to latest git (+all deps). And running this now for all my domains.

miekg on 24 Jan 2017

I do think this is finally fixed, so I will close now. 🤞

mholt on 27 Jan 2017

Full renewel seen, everything looks good !

~
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Scanning for expiring certificates
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [miek.nl] expires in 718h2m22.986286409s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [dnssex.nl] expires in 718h2m22.985427385s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [www.dnssex.nl] expires in 709h29m22.985405469s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [miek.nl ] expires in 718h2m22.985389262s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [www.berkestoffering.nl] expires in 718h2m22.985373744s; attempting renewa
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [atoom.net] expires in 718h2m22.985276862s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [nlgids.london] expires in 718h2m22.985267275s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [archive.miek.nl] expires in 709h29m22.985261929s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [www.nlgids.london] expires in 718h2m22.985253253s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [www.atoom.net] expires in 718h2m22.985151733s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [www.miek.nl] expires in 709h29m22.985137867s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO] Certificate for [berkestoffering.nl] expires in 718h2m22.985132931s; attempting renewal
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO][miek.nl] acme: Trying renewal with 718 hours remaining
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO][miek.nl] acme: Obtaining bundled SAN certificate
Jan 30 08:20:37 deb caddy[14281]: 2017/01/30 08:20:37 [INFO][miek.nl] acme: Trying to solve HTTP-01
Jan 30 08:20:39 deb caddy[14281]: 2017/01/30 08:20:39 [INFO][miek.nl] Served key authentication
Jan 30 08:20:39 deb caddy[14281]: 2017/01/30 08:20:39 [INFO][miek.nl] The server validated our request
Jan 30 08:20:39 deb caddy[14281]: 2017/01/30 08:20:39 [INFO][miek.nl] acme: Validations succeeded; requesting certificates
Jan 30 08:20:39 deb caddy[14281]: 2017/01/30 08:20:39 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Jan 30 08:20:40 deb caddy[14281]: 2017/01/30 08:20:40 [INFO][miek.nl] Server responded with a certificate.
Jan 30 08:20:40 deb caddy[14281]: 2017/01/30 08:20:40 [INFO][dnssex.nl] acme: Trying renewal with 718 hours remaining
Jan 30 08:20:40 deb caddy[14281]: 2017/01/30 08:20:40 [INFO][dnssex.nl] acme: Obtaining bundled SAN certificate
Jan 30 08:20:41 deb caddy[14281]: 2017/01/30 08:20:41 [INFO][dnssex.nl] acme: Trying to solve TLS-SNI-01
Jan 30 08:20:42 deb caddy[14281]: 2017/01/30 08:20:42 [INFO][dnssex.nl] The server validated our request
Jan 30 08:20:42 deb caddy[14281]: 2017/01/30 08:20:42 [INFO][dnssex.nl] acme: Validations succeeded; requesting certificates
Jan 30 08:20:43 deb caddy[14281]: 2017/01/30 08:20:43 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Jan 30 08:20:43 deb caddy[14281]: 2017/01/30 08:20:43 [INFO][dnssex.nl] Server responded ....
...
~

miekg on 30 Jan 2017

🎉2

Was this page helpful?

0 / 5 - 0 ratings

Related issues

Feature: Reload Config on signal

pastjean · 40Comments

Caddy sometimes serving stale PHP page content

adamwathan · 37Comments

Caddy ignores -https-port and breaks custom port mapping with recent change

rmoriz · 58Comments

Full caddy production environment in a single command.

calebmer · 45Comments

Proposal: Permanently change all proprietary licensing to open source

mholt · 72Comments

Caddy: ssl certs failure

1. What version of Caddy are you running (caddy -version)?

2. What are you trying to do?

3. What is your entire Caddyfile?

4. How did you run Caddy (give the full command and describe the execution environment)?

5. What did you expect to see?

6. What did you see instead (give full error messages and/or log)?

7. How can someone who is starting from scratch reproduce this behavior as minimally as possible?

Most helpful comment

All 95 comments

~~~

/home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56

~~~

/home/miek/g/src/github.com/mholt/caddy/caddy.go:645 +0x56

goroutines spikes at the same time, no increase in #requests. And 9th of Jan is def. the day I saw this issue.

Related issues

1. What version of Caddy are you running (`caddy -version`)?