mTLS: tls internal error

1. Caddy version (caddy version):

Frontend Caddy reverse proxy server built with the Cloudflare module

root@caddy:~ # caddy version
v2.4.3 h1:Y1FaV2N4WO3rBqxSYA8UZsZTQdN+PwcoOcAiZTM8C0I=

Backend Caddy web server using a static binary

root@file:~ # caddy version
v2.4.3 h1:Y1FaV2N4WO3rBqxSYA8UZsZTQdN+PwcoOcAiZTM8C0I=

2. How I run Caddy:

a. System environment:

root@caddy:~ # freebsd-version
12.2-RELEASE-p6

b. Command:

service caddy start

c. Service/unit/compose file:

#!/bin/sh

# PROVIDE: caddy
# REQUIRE: LOGIN DAEMON NETWORKING
# KEYWORD: shutdown

# To enable caddy, add 'caddy_enable="YES"' to /etc/rc.conf or
# /etc/rc.conf.local

# Optional settings:
# caddy_config (string):      Full path to caddy config file
#                             (/usr/local/etc/caddy/Caddyfile)
# caddy_adapter (string):     Config adapter type (caddyfile)
# caddy_directory (string):   Root for caddy storage (ACME certs, etc.)
#                             (/var/db/caddy)
# caddy_extra_flags (string): Extra flags passed to caddy start
# caddy_logdir (string):      Where caddy logs are stored
#                             (/var/log/caddy)
# caddy_logfile (string):     Location of process log (${caddy_logdir}/caddy.log)
#                             This is for startup/shutdown/error messages.
#                             To create an access log, see:
#                             https://caddyserver.com/docs/caddyfile/directives/log
# caddy_user (user):          User to run caddy (root)
# caddy_group (group):        Group to run caddy (wheel)
#
# This script will honor XDG_CONFIG_HOME/XDG_DATA_HOME. Caddy will create a
# .../caddy subdir in each of those. By default, they are subdirs of /var/db/caddy.
# See https://caddyserver.com/docs/conventions#data-directory

. /etc/rc.subr

name=caddy
rcvar=caddy_enable
desc="Powerful, enterprise-ready, open source web server with automatic HTTPS written in Go"

load_rc_config $name

# Defaults
: ${caddy_enable:=NO}
: ${caddy_adapter:=caddyfile}
: ${caddy_config:=/usr/local/etc/caddy/Caddyfile}
: ${caddy_directory:=/var/db/caddy}
: ${caddy_extra_flags:=""}
: ${caddy_logdir:="/var/log/${name}"}
: ${caddy_logfile:="${caddy_logdir}/${name}.log"}
: ${caddy_user:="root"}
: ${caddy_group:="wheel"}

# Config and base directories
: ${XDG_CONFIG_HOME:="${caddy_directory}/config"}
: ${XDG_DATA_HOME:="${caddy_directory}/data"}
export XDG_CONFIG_HOME XDG_DATA_HOME

command="/usr/local/bin/${name}"
caddy_flags="--config ${caddy_config} --adapter ${caddy_adapter}"
pidfile="/var/run/${name}/${name}.pid"

required_files="${caddy_config} ${command}"

start_precmd="caddy_precmd"
start_cmd="caddy_start"
stop_cmd="caddy_stop"

# Extra Commands
extra_commands="configtest reload"
configtest_cmd="caddy_command validate ${caddy_flags}"
reload_cmd="caddy_command reload ${caddy_flags}"

caddy_command()
{
        /usr/bin/su -m "${caddy_user}" -c "${command} $*"
}

caddy_precmd()
{
        # Create required directories and set permissions
        /usr/bin/install -d -m 755 -o "${caddy_user}" -g "${caddy_group}" ${caddy_directory}
        /usr/bin/install -d -m 700 -o "${caddy_user}" -g "${caddy_group}" ${caddy_directory}/config
        /usr/bin/install -d -m 700 -o "${caddy_user}" -g "${caddy_group}" ${caddy_directory}/data
        /usr/bin/install -d -m 755 -o "${caddy_user}" -g "${caddy_group}" ${caddy_logdir}
        /usr/bin/install -d -m 700 -o "${caddy_user}" -g "${caddy_group}" /var/run/caddy
}

caddy_start()
{
        echo -n "Starting caddy... "
        /usr/bin/su -m ${caddy_user} -c "${command} start ${caddy_flags} \
                ${caddy_extra_flags} --pidfile ${pidfile}" >> ${caddy_logfile} 2>&1
        if [ $? -eq 0 ] && ps -ax -o pid | grep -q "$(cat ${pidfile})"; then
                echo "done"
                echo "Log: ${caddy_logfile}"
        else
                echo "Error: Caddy failed to start"
                echo "Check the caddy log: ${caddy_logfile}"
        fi
}

caddy_stop()
{
        echo -n "Stopping caddy... "
        if caddy_command stop; then
                echo "done"
        else
                echo "Error: Unable to stop caddy"
                echo "Check the caddy log: ${caddy_logfile}"
        fi
}

run_rc_command "$1"

d. My complete Caddyfile or JSON config:

This is based on the thread mTLS under FreeBSD. Only mTLS components are shown.

mTLS constructs for the frontend Caddyfile:

...
# Internal CA
acme.lan {
  acme_server
  tls internal
}
...
*.udance.com.au {
  ...
  map {labels.3} {backend} {online} {mtls} {phpmyadmin} {

#   HOSTNAME     BACKEND         ONLINE mTLS PHPMYADMIN #COMMENT
#---------------------------------------------------------------
    ...
    file         file.lan:443    yes    yes  no         # file.udance.com.au
    ...
  route {
    ...
# Secure backend communication
    @mtls expression `{mtls} == "yes"`
    reverse_proxy @mtls {backend} {
      header_up Host {http.reverse_proxy.upstream.hostport}
      header_up X-Forwarded-Host {host}
      transport http {
        tls
      }
    }
    ...
  }
}

mTLS constructs for the backend Caddyfile:

{
  ...
  acme_ca https://acme.lan/acme/local/directory
  acme_ca_root /etc/ssl/certs/root.crt
}
file.lan {
  root * /usr/local/www/caddy
  file_server browse
}

3. The problem I’m having:

mTLS has broken :scream: seemingly since upgrading from Caddy 2.4.1 to 2.4.3.

pc01

4. Error messages and/or full log output:

Frontend process log extract:

{"level":"info","ts":1624176356.910208,"msg":"using provided configuration","config_file":"/usr/local/www/Caddyfile","config_adapter":"caddyfile"}
{"level":"warn","ts":1624176356.9237509,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/usr/local/www/Caddyfile","line":2}
{"level":"info","ts":"2021-06-20T16:05:56.931+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}
{"level":"info","ts":"2021-06-20T16:05:56.931+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00036e070"}
{"level":"info","ts":"2021-06-20T16:05:56.953+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-06-20T16:05:56.953+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":"2021-06-20T16:06:09.419+0800","logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"info","ts":"2021-06-20T16:06:09.419+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["*.udance.com.au","caffigoalkeeping.com","www.xenografix.com.au","udance.com.au","acme.lan","caffigoalkeeping.com.au","readymcgetty.com.au","www.udance.com.au","www.caffigoalkeeping.com.au","www.readymcgetty.com.au","xenografix.com.au","www.caffigoalkeeping.com"]}
{"level":"info","ts":"2021-06-20T16:06:09.419+0800","logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"info","ts":"2021-06-20T16:06:09.439+0800","logger":"tls","msg":"finished cleaning storage units"}
{"level":"warn","ts":"2021-06-20T16:06:10.275+0800","logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [acme.lan]: no OCSP server specified in certificate"}
{"level":"info","ts":"2021-06-20T16:06:10.275+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-06-20T16:06:10.275+0800","msg":"serving initial configuration"}
Successfully started Caddy (pid=34502) - Caddy is running in the background
2021/06/20 16:06:15 {"newNonce":"https://acme.lan/acme//local/new-nonce","newAccount":"https://acme.lan/acme//local/new-account","newOrder":"https://acme.lan/acme//local/new-order","revokeCert":"https://acme.lan/acme//local/revoke-cert","keyChange":"https://acme.lan/acme//local/key-change"}
{"level":"error","ts":"2021-06-20T16:08:59.307+0800","logger":"http.log.error.log4","msg":"remote error: tls: internal error","request":{"remote_addr":"10.1.1.222:60492","proto":"HTTP/2.0","method":"GET","host":"file.udance.com.au","uri":"/","headers":{"Sec-Fetch-Dest":["document"],"Accept-Language":["en-US,en;q=0.9"],"Upgrade-Insecure-Requests":["1"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Sec-Fetch-Site":["none"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-User":["?1"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["max-age=0"],"Sec-Ch-Ua":["\" Not;A Brand\";v=\"99\", \"Microsoft Edge\";v=\"91\", \"Chromium\";v=\"91\""],"Sec-Ch-Ua-Mobile":["?0"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.101 Safari/537.36 Edg/91.0.864.48"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","proto_mutual":true,"server_name":"file.udance.com.au"}},"duration":0.003891467,"status":502,"err_id":"1k867wnxe","err_trace":"reverseproxy.statusError (reverseproxy.go:857)"}

Backend process log extract:

{"level":"info","ts":1624176375.1738176,"msg":"using provided configuration","config_file":"/usr/local/etc/caddy/Caddyfile","config_adapter":"caddyfile"}
{"level":"warn","ts":1624176375.1766913,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/usr/local/etc/caddy/Caddyfile","line":12}
{"level":"info","ts":"2021-06-20T16:06:15.178+0800","logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["[::1]:2019","127.0.0.1:2019","localhost:2019"]}
{"level":"info","ts":"2021-06-20T16:06:15.179+0800","logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv0","https_port":443}
{"level":"info","ts":"2021-06-20T16:06:15.179+0800","logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":"2021-06-20T16:06:15.180+0800","logger":"http","msg":"enabling automatic TLS certificate management","domains":["file.lan"]}
{"level":"info","ts":"2021-06-20T16:06:15.181+0800","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
{"level":"info","ts":"2021-06-20T16:06:15.181+0800","msg":"serving initial configuration"}
{"level":"info","ts":"2021-06-20T16:06:15.182+0800","logger":"tls.obtain","msg":"acquiring lock","identifier":"file.lan"}
Successfully started Caddy (pid=30213) - Caddy is running in the background
{"level":"info","ts":"2021-06-20T16:06:15.183+0800","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00015aaf0"}
{"level":"info","ts":"2021-06-20T16:06:15.184+0800","logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/db/caddy/data/caddy"}
{"level":"info","ts":"2021-06-20T16:06:15.184+0800","logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":"2021-06-20T16:06:15.207+0800","logger":"tls.obtain","msg":"lock acquired","identifier":"file.lan"}
{"level":"info","ts":"2021-06-20T16:06:15.231+0800","logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["file.lan"],"ca":"https://acme.lan/acme/local/directory","account":""}
{"level":"info","ts":"2021-06-20T16:06:15.232+0800","logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["file.lan"],"ca":"https://acme.lan/acme/local/directory","account":""}
{"level":"error","ts":"2021-06-20T16:06:15.246+0800","logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"file.lan","issuer":"acme.lan-acme-local-directory","error":"[file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)"}
{"level":"error","ts":"2021-06-20T16:06:15.246+0800","logger":"tls.obtain","msg":"will retry","error":"[file.lan] Obtain: [file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)","attempt":1,"retrying_in":60,"elapsed":0.038701051,"max_duration":2592000}
{"level":"error","ts":"2021-06-20T16:09:15.293+0800","logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"file.lan","issuer":"acme.lan-acme-local-directory","error":"[file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)"}
{"level":"error","ts":"2021-06-20T16:09:15.293+0800","logger":"tls.obtain","msg":"will retry","error":"[file.lan] Obtain: [file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)","attempt":3,"retrying_in":120,"elapsed":180.085689977,"max_duration":2592000}
{"level":"error","ts":"2021-06-20T16:11:15.304+0800","logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"file.lan","issuer":"acme.lan-acme-local-directory","error":"[file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)"}
{"level":"error","ts":"2021-06-20T16:11:15.304+0800","logger":"tls.obtain","msg":"will retry","error":"[file.lan] Obtain: [file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)","attempt":4,"retrying_in":300,"elapsed":300.097287785,"max_duration":2592000}
{"level":"error","ts":"2021-06-20T16:16:15.315+0800","logger":"tls.obtain","msg":"could not get certificate from issuer","identifier":"file.lan","issuer":"acme.lan-acme-local-directory","error":"[file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)"}
{"level":"error","ts":"2021-06-20T16:16:15.315+0800","logger":"tls.obtain","msg":"will retry","error":"[file.lan] Obtain: [file.lan] creating new order: fetching new nonce from server: HTTP 404:  (ca=https://acme.lan/acme/local/directory)","attempt":5,"retrying_in":600,"elapsed":600.108134007,"max_duration":2592000}

5. What I already tried:

Cross-referenced against post #65 in thread mTLS under FreeBSD

I tried deleting backend storage and restarting Caddy, but no change to the result. Similar error messages logged in the backend.

6. Links to relevant resources:

  1. mTLS under FreeBSD

I notice under the thread mTLS under FreeBSD, the newNonce message in the log looks like the following:

{"newNonce":"https://acme.lan/acme/local/new-nonce","newAccount":"https://acme.lan/acme/local/new-account","newOrder":"https://acme.lan/acme/local/new-order","revokeCert":"https://acme.lan/acme/local/revoke-cert","keyChange":"https://acme.lan/acme/local/key-change"}

If you check the frontend log above, the message looks like:

2021/06/20 16:06:15 {"newNonce":"https://acme.lan/acme//local/new-nonce","newAccount":"https://acme.lan/acme//local/new-account","newOrder":"https://acme.lan/acme//local/new-order","revokeCert":"https://acme.lan/acme//local/revoke-cert","keyChange":"https://acme.lan/acme//local/key-change"}

There’s now a double forward-slash (//) within the address. Could this be contributing to the issue I’m seeing?

Sounds like either a bug in github.com/smallstep/certificates introduced somewhere between versions v0.15.4 and v0.15.15 (Caddy updated the dependency recently) or some change in that library which required a change in Caddy which wasn’t done.

Actually – took a look at the commit where the dependency was updated in Caddy…

https://github.com/caddyserver/caddy/commit/ecd5eeab3857a0d6903a85bf52183171bda1920c

@matt I think this was incorrect, you removed the strings.Trim but I think it should still do that. Or at least a right-trim.

1 Like

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

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

1 Like

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

Yep. It’s on the master branch.

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

2 Likes

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

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

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

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

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

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

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

For the Caddy webserver on the backend:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

@matt got any ideas?

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

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

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

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

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

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

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

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

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

Ok, so I can safely ignore that message.

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

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

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

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

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

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

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

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

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

I extended the lock date just in case

1 Like