Debugging a 500

1. Caddy version (caddy version):

v2.4.6 h1:HGkGICFGvyrodcqOOclHKfvJC0qTU7vny/7FhYp9hNw=

2. How I run Caddy:

/usr/bin/caddy run --environ --config /etc/caddy/Caddyfile

a. System environment:

Ubuntu 20.04

b. Command:

`/usr/bin/caddy run --environ --config /etc/caddy/Caddyfile`

c. Service/unit/compose file:

NA

d. My complete Caddyfile or JSON config:

(laravel) {
    {args.0} {
        root * {args.1}/public
        tls internal
        log
        encode zstd gzip
        php_fastcgi unix//run/php/php7.4-fpm.sock
        file_server
    }
}
{
    email "tcurdt@*****.org"
    acme_ca "https://acme-staging-v02.api.letsencrypt.org/directory"
}

import laravel "dev.jack.de" "/home/deploy/projects/dev.jack.de/current"
import laravel "jack.de" "/home/deploy/projects/jack.de/current"

3. The problem I’m having:

I am doing a curl and get a 500 - but I have no clue why.

curl -vk https://dev.jack.de
*   Trying 157.90.149.21:443...
* TCP_NODELAY set
* Connected to dev.jack.de (157.90.149.21) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: [NONE]
*  start date: Jan 10 19:42:36 2022 GMT
*  expire date: Jan 11 07:42:36 2022 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x5609f9645860)
> GET / HTTP/2
> Host: dev.jack.de
> user-agent: curl/7.68.0
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 500 
< content-type: text/html; charset=UTF-8
< server: Caddy
< status: 500 Internal Server Error
< content-length: 0
< date: Mon, 10 Jan 2022 20:13:12 GMT
< 
* Connection #0 to host dev.jack.de left intact

This could be just the php_fastcgi - but I am not seeing anything in the log at all. Not even the 500.

I don’t see a way to increase logging.

4. Error messages and/or full log output:

caddy.HomeDir=/var/lib/caddy
caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
caddy.AppConfigDir=/var/lib/caddy/.config/caddy
caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
caddy.Version=v2.4.6 h1:HGkGICFGvyrodcqOOclHKfvJC0qTU7vny/7FhYp9hNw=
runtime.GOOS=linux
runtime.GOARCH=amd64
runtime.Compiler=gc
runtime.NumCPU=1
runtime.GOMAXPROCS=1
runtime.Version=go1.17.2
os.Getwd=/
LANG=en_US.UTF-8
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
NOTIFY_SOCKET=/run/systemd/notify
HOME=/var/lib/caddy
LOGNAME=caddy
USER=caddy
INVOCATION_ID=8224b82dfc2f432492cdc27e36ce2b46
JOURNAL_STREAM=9:80291
{"level":"info","ts":1641845272.7592227,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}
{"level":"warn","ts":1641845272.7643106,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}
{"level":"info","ts":1641845272.769346,"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":1641845272.7703288,"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_p>
{"level":"info","ts":1641845272.7718556,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
{"level":"info","ts":1641845272.7944665,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc00027e150"}
{"level":"warn","ts":1641845272.8050685,"logger":"pki.ca.local","msg":"installing root certificate (you might be prompted for password)","path":"storage:pki/authorities/local/root.crt"}
2022/01/10 21:07:52 not NSS security databases found
2022/01/10 21:07:52 define JAVA_HOME environment variable to use the Java trust
{"level":"error","ts":1641845272.81687,"logger":"pki.ca.local","msg":"failed to install root certificate","error":"failed to execute sudo: exit status 1","certificate_file":"storage:pki/authorities>
{"level":"info","ts":1641845272.8179932,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["jack.de","dev.jack.de"]}
{"level":"warn","ts":1641845272.8185227,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [jack.de]: no OCSP server specified in certificate"}
{"level":"warn","ts":1641845272.818999,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [dev.jack.de]: no OCSP server specified in certificate"}
{"level":"info","ts":1641845272.8197517,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
{"level":"info","ts":1641845272.8231714,"msg":"serving initial configuration"}
{"level":"info","ts":1641845272.8234262,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}
{"level":"info","ts":1641845272.8239908,"logger":"tls","msg":"finished cleaning storage units"}

5. What I already tried:

I’ve tried to redirect the log into a file - but the file never got created. It seems like access logging is not working for some reason. My only possible conclusion is the host is not matching.

You have access logs enabled, so if nothing is getting logged when you make a request, then you’re not making the request to the caddy instance you think you are (or do not have the config loaded that you think you do). You can add debug to your global options to get even more logs, and use the admin endpoint’s GET /config/ endpoint to verify you have the right config loaded. Also check DNS.

Just writing down the debugging here.

From the curl output I can see it really is caddy that is answering.
Caddy is listening according to ss:

tcp                LISTEN              0                   4096                                      127.0.0.1:2019                                   0.0.0.0:*                  users:(("caddy",pid=22092,fd=3))                       
tcp                LISTEN              0                   4096                                              *:80                                           *:*                  users:(("caddy",pid=22092,fd=8))                       
tcp                LISTEN              0                   4096                                              *:443                                          *:*                  users:(("caddy",pid=22092,fd=7)) 

To rule out address resolution problems I changed the address to 127.0.0.1 - which gives the same result (just answering on 127.0.0.1).

To me this suggests a caddy configuration problem. But I don’t see the problem yet.

I dug deeper and found the failed to install root certificate suspicious. As a non-root sudo user I called

caddy trust
2022/01/10 23:24:48.396	INFO	ca.local	root certificate is already trusted by system	{"path": "storage:pki/authorities/local/root.crt"}

When running through systemd I see:

Jan 11 00:27:50 app sudo[24502]: pam_unix(sudo:auth): conversation failed
Jan 11 00:27:50 app sudo[24502]: pam_unix(sudo:auth): auth could not identify password for [caddy]
Jan 11 00:27:50 app sudo[24502]:    caddy : user NOT in sudoers ; TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /usr/local/share/ca-certificates/Caddy_Local_Authority_-_2022_ECC_Root_100377138300573002669035844181340857853>
Jan 11 00:27:50 app caddy[24482]: {"level":"error","ts":1641857270.7870884,"logger":"pki.ca.local","msg":"failed to install root certificate","error":"failed to execute sudo: exit status 1","certificate_file":"storage:pki/authoriti>
Jan 11 00:27:50 app caddy[24482]: {"level":"info","ts":1641857270.787941,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Jan 11 00:27:50 app systemd[1]: Started Caddy.
Jan 11 00:27:50 app caddy[24482]: {"level":"info","ts":1641857270.7914078,"msg":"serving initial configuration"}

Maybe the “serving initial configuration” is a clue? But why doesn’t it find the already trusted root cert? wrong user? wrong path? Not quite clear from the logs.

I then just switched from tls staging to production. The certs get obtained correctly and the root cert (of course) is not an issues anymore. It’s still “serving initial configuration” - so that is probably not the problem either?

Running via systemd or starting manually seems to make a difference. (Buffering?) When starting interactively I at least see the request:

http.log.access	handled request	{"request": {"remote_addr": "157.90.149.21:33360", "proto": "HTTP/2.0", "method": "GET", "host": "dev.paleocoran.de", "uri": "/", "headers": {"User-Agent": ["curl/7.68.0"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "proto_mutual": true, "server_name": "dev.paleocoran.de"}}, "common_log": "157.90.149.21 - - [11/Jan/2022:00:38:18 +0100] \"GET / HTTP/2.0\" 500 0", "user_id": "", "duration": 0.01820207, "size": 0, "status": 500, "resp_headers": {"Server": ["Caddy"], "Status": ["500 Internal Server Error"], "Content-Type": ["text/html; charset=UTF-8"]}}

but still no indication what might be causing it.

Adding debug is the game changer. Now I am seeing details of the request chain.

2022/01/10 23:43:45.666	DEBUG	http.handlers.rewrite	rewrote request	{"request": {"remote_addr": "157.90.149.21:33362", "proto": "HTTP/2.0", "method": "GET", "host": "dev.jack.de", "uri": "/", "headers": {"Accept": ["*/*"], "User-Agent": ["curl/7.68.0"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "proto_mutual": true, "server_name": "dev.jack.de"}}, "method": "GET", "uri": "/index.php"}
2022/01/10 23:43:45.666	DEBUG	http.reverse_proxy.transport.fastcgi	roundtrip	{"request": {"remote_addr": "157.90.149.21:33362", "proto": "HTTP/2.0", "method": "GET", "host": "dev.jack.de", "uri": "/index.php", "headers": {"User-Agent": ["curl/7.68.0"], "Accept": ["*/*"], "X-Forwarded-For": ["157.90.149.21"], "X-Forwarded-Proto": ["https"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "proto_mutual": true, "server_name": "dev.jack.de"}}, "dial": "/run/php/php7.4-fpm.sock", "env": {"AUTH_TYPE":"","CONTENT_LENGTH":"","CONTENT_TYPE":"","DOCUMENT_ROOT":"/home/deploy/projects/dev.jack.de/current/public","DOCUMENT_URI":"/index.php","GATEWAY_INTERFACE":"CGI/1.1","HTTPS":"on","HTTP_ACCEPT":"*/*","HTTP_HOST":"dev.jack.de","HTTP_USER_AGENT":"curl/7.68.0","HTTP_X_FORWARDED_FOR":"157.90.149.21","HTTP_X_FORWARDED_PROTO":"https","PATH_INFO":"","QUERY_STRING":"","REMOTE_ADDR":"157.90.149.21","REMOTE_HOST":"157.90.149.21","REMOTE_IDENT":"","REMOTE_PORT":"33362","REMOTE_USER":"","REQUEST_METHOD":"GET","REQUEST_SCHEME":"https","REQUEST_URI":"/","SCRIPT_FILENAME":"/home/deploy/projects/dev.jack.de/current/public/index.php","SCRIPT_NAME":"/index.php","SERVER_NAME":"dev.jack.de","SERVER_PROTOCOL":"HTTP/2.0","SERVER_SOFTWARE":"Caddy/v2.4.6","SSL_CIPHER":"TLS_AES_128_GCM_SHA256","SSL_PROTOCOL":"TLSv1.3"}}
2022/01/10 23:43:45.683	DEBUG	http.handlers.reverse_proxy	upstream roundtrip	{"upstream": "unix//run/php/php7.4-fpm.sock", "duration": 0.01652859, "request": {"remote_addr": "157.90.149.21:33362", "proto": "HTTP/2.0", "method": "GET", "host": "dev.jack.de", "uri": "/index.php", "headers": {"X-Forwarded-Proto": ["https"], "User-Agent": ["curl/7.68.0"], "Accept": ["*/*"], "X-Forwarded-For": ["157.90.149.21"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "proto_mutual": true, "server_name": "dev.jack.de"}}, "headers": {"Status": ["500 Internal Server Error"], "Content-Type": ["text/html; charset=UTF-8"]}, "status": 500}
2022/01/10 23:43:45.683	ERROR	http.log.access	handled request	{"request": {"remote_addr": "157.90.149.21:33362", "proto": "HTTP/2.0", "method": "GET", "host": "dev.jack.de", "uri": "/", "headers": {"User-Agent": ["curl/7.68.0"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4865, "proto": "h2", "proto_mutual": true, "server_name": "dev.jack.de"}}, "common_log": "157.90.149.21 - - [11/Jan/2022:00:43:45 +0100] \"GET / HTTP/2.0\" 500 0", "user_id": "", "duration": 0.016975641, "size": 0, "status": 500, "resp_headers": {"Content-Type": ["text/html; charset=UTF-8"], "Server": ["Caddy"], "Status": ["500 Internal Server Error"]}}

I then replaced the index.php with <?php phpinfo(); ?> … and tada - I see the phpinfo page.

So the 500 really is coming from php-fpm and not caddy. Besides the weird internal root cert issue caddy is doing what it should. :partying_face:

With what I learned I then turned back on the internal tls: Not being able to store the cert doesn’t seem to be a blocker - but not great. I guess the question is what folder storage:pki/authorities/local/root.crt is meant to be. I can see they get stored in .local/share/caddy/pki - which probably means caddy trust needs to be executed as the caddy user.

What I also learned: Just following a journalctl -u caddy does not seem to work as expected as requests might not show up right away (buffer flushing problem?)

Maybe this little writeup is helpful for someone else searching for similar problems.

1 Like

Yep, just another reason I kind of hate journald.

Correct. @francislavoie has an innovative solution using the API to make this easier.

Glad you made some progress! Thanks for documenting your effort, very good investigation.

Right, I have the PR which reworks how caddy trust works, which would solve the problem here with making it easier to install trust.

Essentially: elevated permissions are needed to install a root cert into the system’s trust store, but the caddy user does not have the right permissions. So you need to run the trust yourself by hand unfortunately, but you need to make sure the command you run actually uses the same storage as the caddy user uses otherwise you end up trusting the wrong root CA cert (you might be using the root user’s storage location, not the same place). The PR above will make it fetch the root CA cert over the admin API from a running Caddy instance so it removes the need for the caddy trust command to care about storage locations.

The storage: part refers to the caddy.AppDataDir=/var/lib/caddy/.local/share/caddy you see at the top of the logs when you start Caddy. So the full path would be /var/lib/caddy/.local/share/caddy/pki/authorities/local/root.crt

Hmm, I’ve not had that happen. You can find the command we recommend to use here, though:

You can hit Shift+G whenever you want to force it to display the latest logs again, or use Shift+F to “follow” the logs live as they stream in.

2 Likes

Thanks for the explanation.

Hm - but if it’s alway in /var/lib/caddy then running caddy trust as a sudo’er should have had enough permissions to write there. And caddy should have picked it up. Odd.

Yes, that’s “follow” I meant above.

No, the problem is that running sudo caddy trust will run as root, meaning it inherits the root user’s HOME, so it would try reading from /root/.local/share/caddy instead.

So you’d have to run sudo HOME=~caddy caddy trust which is kinda awkward (Basically, setting the HOME env var to the HOME of the caddy user, that’s what ~caddy is a shortcut for). It works though, for now. But the PR above will make just sudo caddy trust work by not even reading from disk, but instead making an API call to fetch the root cert, then installing that in the system’s trust store.

1 Like

In my previous reply I didn’t realize that /var/lib/caddy was the caddy HOME. That makes sense again.

So I was just missing the HOME=~caddy which makes totally sense - and I don’t find awkward at all btw. I just didn’t know about it.

Thanks for the explanation!

1 Like