Caddy - Context deadline exceeded

KaK · January 12, 2024, 12:51pm

1. The problem I’m having:

I am building a multi-tenant app with subdomains that people can point their CNAMEs to and have a white-label solution.

Everything worked fine until yesterday. Out of nowhere, the main domain and all subdomains become unreachable via browser. Upon inspecting the logs, it looks like Caddy is not able to get confirmation from the ask_endpoint.

It looks to me that caddy is unable to reach out to endpoint on my domain jatra.club/caddy/ask to figure out if it should allow jatra.club should be allowed; and therefore timing out.

How should I fix this issue? Would really appreciate your support.

Update: I’d also like it if an expert can review my Caddyfille and suggest improvements; while keeping the functionality. It’d be a good learning exercise for me.

2. Error messages and/or full log output:

{"level":"error","ts":1705062677.5662203,"logger":"tls","msg":"request to 'ask' endpoint failed","ask_endpoint":"https://jatra.club/caddy/ask","domain":"jatra.club","error":"error checking https://jatra.club/caddy/ask to determine if certificate for hostname 'jatra.club' should be allowed: Get \"https://jatra.club/caddy/ask?domain=jatra.club\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"}

{"level":"error","ts":1705062686.3597019,"logger":"tls","msg":"request to 'ask' endpoint failed","ask_endpoint":"https://jatra.club/caddy/ask","domain":"community.jatra.club","error":"error checking https://jatra.club/caddy/ask to determine if certificate for hostname 'community.jatra.club' should be allowed: Get \"https://jatra.club/caddy/ask?domain=community.jatra.club\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"}

{"level":"error","ts":1705062687.5675354,"logger":"tls","msg":"request to 'ask' endpoint failed","ask_endpoint":"https://jatra.club/caddy/ask","domain":"jatra.club","error":"error checking https://jatra.club/caddy/ask to determine if certificate for hostname 'jatra.club' should be allowed: Get \"https://jatra.club/caddy/ask?domain=jatra.club\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"}

3. Caddy version:

v2.7.5

4. How I installed and ran Caddy:

Simply followed the instructions here: Install — Caddy Documentation

a. System environment:

Ubuntu

b. Command:

PASTE OVER THIS, BETWEEN THE ``` LINES.
Please use the preview pane to ensure it looks nice.

c. Service/unit/compose file:

PASTE OVER THIS, BETWEEN THE ``` LINES.
Please use the preview pane to ensure it looks nice.

d. My complete Caddy config:

{
    on_demand_tls {
        ask https://jatra.club/caddy/ask
        interval 2m
        burst 5
    }

    # Global logging settings
    log {
        output file /var/log/caddy/jatra.club.log {
            roll_size 100mb       # Max size of a log file before it's rolled
            roll_keep 5           # Number of rolled files to keep
            roll_keep_for 720h    # Duration to keep rolled files
        }
    }
}

# Main domain and all subdomains
https://jatra.club, https://*.jatra.club {
    tls {
        on_demand
    }

    root * /home/forge/jatra.club/public
    encode gzip
    file_server
    php_fastcgi unix//run/php/php8.2-fpm.sock
    header {
        # Ensure the header specifying the original host is passed to PHP
        X-Original-Host {host}
    }
}

# Catch-all for any other domain (for your customer's custom domains)
https:// {
    tls {
        on_demand
    }

    root * /home/forge/jatra.club/public
    encode gzip
    file_server
    php_fastcgi unix//run/php/php8.2-fpm.sock
    header {
        # Ensure the header specifying the original host is passed to PHP
        X-Original-Host {host}
    }
}

5. Links to relevant resources:

francislavoie · January 12, 2024, 3:34pm

Oh geez, bit of a chicken and egg problem Caddy is trying to use jatra.club to ask, but jatra.club’s cert expired and needs renewal, so it can’t connect to your ask endpoint

You’ll need to move your jatra.club domain to a separate site block that doesn’t have on_demand enabled, otherwise Caddy won’t be able to connect to itself to hit the ask endpoint.

Or, change your ask config to something like http://localhost:5001/caddy/ask and add a :5001 { } site block with your PHP app routes in there, just so Caddy has a server that can’t break, and uses HTTP. It’s best to use HTTP instead of HTTPS for your ask endpoint anyway because it will reduce latency (HTTPS means the TLS handshake has to happen which adds a bit of latency to requests).

This is not passing this header to PHP, it’s adding it to all responses to the client.

Caddy already passes through the original host with X-Forwarded-Host, just use that in your app.

KaK · January 12, 2024, 3:50pm

Thank you, @francislavoie .

Did you mean I should use this:

Approach #1

https://jatra.club, https://*.jatra.club {
    
    // --What should I put here? --

    root * /home/forge/jatra.club/public
    encode gzip
    file_server
    php_fastcgi unix//run/php/php8.2-fpm.sock
    header {
        # Ensure the header specifying the original host is passed to PHP
        X-Original-Host {host}
    }
}

Approach #2

Or, change your ask config to something like http://localhost:5001/caddy/ask and add a :5001 { } site block with your PHP app routes in there, just so Caddy has a server that can’t break, and uses HTTP

Does this mean that PHP needs to respond to the request over 5001 port? Do you have any clue how to do this in Laravel?

francislavoie · January 12, 2024, 3:54pm

Nothing!

Though you’d need to remove the wildcard on this site block, because wildcard OR the DNS challenge is needed for that.

But anyway, the approach using HTTP is better, so use that…

Not exactly. Basically just add this to your config:

:5001 {
	root * /home/forge/jatra.club/public
	php_fastcgi unix//run/php/php8.2-fpm.sock
}

Then change your ask endpoint to http://localhost:5001/caddy/ask

This will have Caddy serve on port 5001 (just a random port I came up with, you can use a different port number if you prefer, doesn’t really matter) for HTTP requests, and handle them by passing it to your PHP app as normal. It would only handle your ask endpoint as long as you don’t open port 5001 on your firewall (you shouldn’t).

KaK · January 12, 2024, 4:03pm

@francislavoie - I’ve updated my caddyfile as follows:

{
	on_demand_tls {
		ask http://localhost:5001/caddy/ask
		interval 2m
		burst 5
	}
}

# Main domain and all subdomains
:5001 {
	root * /home/forge/jatra.club/public
	encode gzip
	file_server
	php_fastcgi unix//run/php/php8.2-fpm.sock
	header {
		# Ensure the header specifying the original host is passed to PHP
		X-Original-Host {host}
	}
}

# Catch-all for any other domain (for your customer's custom domains)
https:// {
	tls {
		on_demand
	}

	root * /home/forge/jatra.club/public
	encode gzip
	file_server
	php_fastcgi unix//run/php/php8.2-fpm.sock
	header {
		# Ensure the header specifying the original host is passed to PHP
		X-Original-Host {host}
	}
}

My main domain: jatra.club is still not accessible.

francislavoie · January 12, 2024, 4:04pm

Keep your original Caddyfile from your top post, and only add the :5001 block as I wrote above (you only need root + php_fastcgi, the rest is unnecessary for the ask endpoint to work).

Edit: Looks like your port 80 might be closed? When making a request to port 80, I get a timeout (curl hangs) but port 443 returns a TLS error (expected if your cert expired). Check your firewall, both ports should be open.

$ curl -v http://jatra.club                                                                                     
*   Trying 3.7.152.143:80...
^C

$ curl -v https://jatra.club                                                                             
*   Trying 3.7.152.143:443...
* Connected to jatra.club (3.7.152.143) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.0 (OUT), TLS header, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS header, Unknown (21):
* TLSv1.3 (IN), TLS alert, internal error (592):
* error:0A000438:SSL routines::tlsv1 alert internal error
* Closing connection 0
curl: (35) error:0A000438:SSL routines::tlsv1 alert internal error

KaK · January 12, 2024, 4:16pm

@francislavoie - You are right. Port 80 was closed; and I updated firewall rules to allow traffic from all IPs. Here’s my updated Caddyfile.

PS: I am feeling a bit stupid as I really don’t know if I’m doing this right.

{
	on_demand_tls {
		ask http://localhost:5001/caddy/ask
		interval 2m
		burst 5
	}
}

:5001 {
	root * /home/forge/jatra.club/public
	php_fastcgi unix//run/php/php8.2-fpm.sock
}

# Main domain and all subdomains
https://jatra.club, https://*.jatra.club {
	tls {
		on_demand
	}

	root * /home/forge/jatra.club/public
	encode gzip
	file_server
	php_fastcgi unix//run/php/php8.2-fpm.sock
	header {
		# Ensure the header specifying the original host is passed to PHP
		X-Original-Host {host}
	}
}

# Catch-all for any other domain (for your customer's custom domains)
https:// {
	tls {
		on_demand
	}

	root * /home/forge/jatra.club/public
	encode gzip
	file_server
	php_fastcgi unix//run/php/php8.2-fpm.sock
	header {
		# Ensure the header specifying the original host is passed to PHP
		X-Original-Host {host}
	}
}

francislavoie · January 12, 2024, 4:17pm

Looks right. What’s in your logs at this point?

KaK · January 12, 2024, 4:18pm

Logs:

{"level":"info","ts":1705072824.860473,"logger":"admin.api","msg":"received request","method":"POST","host":"localhost:2019","uri":"/load","remote_ip":"127.0.0.1","remote_port":"38350","headers":{"Accept-Encoding":["gzip"],"Content-Length":["2223"],"Content-Type":["application/json"],"Origin":["http://localhost:2019"],"User-Agent":["Go-http-client/1.1"]}}
{"level":"info","ts":1705072824.8611672,"msg":"redirected default logger","from":"/var/log/caddy/jatra.club.log","to":"stderr"}
{"level":"info","ts":1705072824.8624783,"logger":"http","msg":"servers shutting down with eternal grace period"}

Update: tail -f isn’t throwing anything new if I access the site.

francislavoie · January 12, 2024, 4:20pm

That just looks like the logs from a config load. There should be more.

Did you reload or restart Caddy after your config change?

KaK · January 12, 2024, 4:20pm

I did caddy reload after every update.

francislavoie · January 12, 2024, 4:22pm

Try a restart this time. It’ll force evict certain caches and hopefully allow retrying cert issuance.

KaK · January 12, 2024, 4:23pm

2024/01/12 16:23:20.881	INFO	http.auto_https	enabling automatic HTTP->HTTPS redirects	{"server_name": "srv0"}
2024/01/12 16:23:20.882	INFO	tls.cache.maintenance	started background certificate maintenance	{"cache": "0x400054c180"}
2024/01/12 16:23:20.883	INFO	tls	cleaning storage unit	{"description": "FileStorage:/home/forge/.local/share/caddy"}
2024/01/12 16:23:20.883	INFO	tls	finished cleaning storage units
2024/01/12 16:23:20.883	INFO	tls.cache.maintenance	stopped background certificate maintenance	{"cache": "0x400054c180"}
Error: loading initial config: loading new config: http app module: start: listening on :443: listen tcp :443: bind: permission denied
Error: caddy process exited with error: exit status 1

francislavoie · January 12, 2024, 4:24pm

What did you run? That means either you already have another Caddy instance running, or another server entirely that isn’t Caddy.

KaK · January 12, 2024, 4:24pm

Strange. I did caddy stop and then caddy start. Is there any other way to do that?

francislavoie · January 12, 2024, 4:25pm

Never use caddy start if Caddy is running as a systemd service.

Follow these instructions:

KaK · January 12, 2024, 4:26pm

caddy.service - Caddy
     Loaded: loaded (/lib/systemd/system/caddy.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2024-01-12 16:26:06 UTC; 10s ago
       Docs: https://caddyserver.com/docs/
   Main PID: 5616 (caddy)
      Tasks: 8 (limit: 2203)
     Memory: 8.9M
        CPU: 58ms
     CGroup: /system.slice/caddy.service
             └─5616 /usr/bin/caddy run --environ --config /etc/caddy/Caddyfile

Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.674426,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.674438,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.6747599,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.674855,"logger":"http.log","msg":"server running","name":"srv1","protocols":["h1","h2","h3"]}
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.6749332,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2",>
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.674948,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["jatra.club","*.jatra.club>
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.6751552,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.6752563,"msg":"serving initial configuration"}
Jan 12 16:26:06 jatra.club systemd[1]: Started Caddy.
Jan 12 16:26:06 jatra.club caddy[5616]: {"level":"info","ts":1705076766.677346,"logger":"tls","msg":"finished cleaning storage units"}

francislavoie · January 12, 2024, 4:27pm

That’s just the startup logs. Try making some requests to trigger on-demand. You should see more logs.

Also, enable the debug global option, it’ll show more logs.

KaK · January 12, 2024, 4:31pm

Have enabled debug mode and restarted caddy using sudo systemctl restart caddy command. Logs have not been updated in /var/log/caddy/

tail -f isn’t updating anything on the console.

{"level":"info","ts":1705072824.8611672,"msg":"redirected default logger","from":"/var/log/caddy/jatra.club.log","to":"stderr"}
{"level":"info","ts":1705072824.8624783,"logger":"http","msg":"servers shutting down with eternal grace period"}

What am I doing wrong?

francislavoie · January 12, 2024, 4:32pm

You removed that from your config last time you posted your config.

Use journalctl -u caddy --no-pager | less +G to see your logs (as per the docs as I linked above)