On certificate_obtained hook is not executed

1. Output of caddy version:

v2.6.1 h1:EDqo59TyYWhXQnfde93Mmv4FJfYe00dO60zMiEt+pzo=

I believe I had to use the download page to build a caddy that includes the caddy-events-exec module.

2. How I run Caddy:

With the official systemd unit file.

a. System environment:

Ubuntu Xenial

d. My complete Caddy config:

{
  events {
    on certificate_obtained exec /etc/caddy/on_certificate_obtained.sh {event.data.domain}
  }
}

# Get certificates to be used by mosquitto
mqtt.webkr.de {
}

3. The problem I’m having:

The contents of /etc/caddy/on_certificate_obtained.sh is (for now):

#!/bin/bash
echo $1 >> /tmp/caddylog

From the file timestamps I can see the certificate was last renewed on 2022-12-04 but from /tmp/caddylog I can see that the event hook was never executed.

(The relevant logs have already been rotated out and I don’t know how to force a renewal.)

5. What I already tried:

I confirmed that the Caddyfile syntax is technically correct, if I introduce a spelling mistake caddy won’t start.

Other than that I don’t know how to debug this, especially since I don’t know how I could trigger this or any other event manually.

Hmm, does the Caddy binary have permission to execute scripts?

I’d be interested in the debug logs if you can get it to happen again.

You can force a renewal by renaming or deleting the cert file; but be aware that this can use up Let’s Encrypt rate limits, so best to enable the staging endpoint first if you’re going to be testing.

Caddy will be running as the caddy user, so the file needs to be executable (chmod +x) by that user.

Ok, I deleted the .crt file and did a caddy reload. (I can waste a few of the 50 requests per week on that domain.) There’s nothing in the log about the exec:

Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6666946,"logger":"tls.obtain","msg":"lock acquired","identifier":"mqtt.webkr.de"}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6673455,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6692238,"logger":"tls.obtain","msg":"obtaining certificate","identifier":"mqtt.webkr.de"}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242979.6696942,"logger":"events","msg":"event","name":"cert_obtaining","id":"c37d8308-aaba-40a9-a79c-f4460813d768","origin":"tls","data":{"identifier":"mqtt.webkr.de"}}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242979.6707277,"logger":"tls.obtain","msg":"trying issuer 1/2","issuer":"acme-v02.api.letsencrypt.org-directory"}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6712348,"logger":"admin.api","msg":"load complete"}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6782882,"logger":"http","msg":"waiting on internal rate limiter","identifiers":["mqtt.webkr.de"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":""}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.6788213,"logger":"http","msg":"done waiting on internal rate limiter","identifiers":["mqtt.webkr.de"],"ca":"https://acme-v02.api.letsencrypt.org/directory","account":""}
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal systemd[1]: Reloaded Caddy.
Jan 09 06:42:59 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242979.8095386,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242980.0951858,"logger":"http.acme_client","msg":"http request","method":"HEAD","url":"https://acme-v02.api.letsencrypt.org/acme/new-nonce","headers":{"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Cache-Control":["public, max-age=0, no-cache"],"Date":["Mon, 09 Jan 2023 05:43:00 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["5CA2NKwdlrj-A-FWByqwKOJ9knZNVp6kLNj9nLYxClpjRg4"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242980.3962514,"logger":"http.acme_client","msg":"http request","method":"POST","url":"https://acme-v02.api.letsencrypt.org/acme/new-order","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Boulder-Requester":["762064026"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["336"],"Content-Type":["application/json"],"Date":["Mon, 09 Jan 2023 05:43:00 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Location":["https://acme-v02.api.letsencrypt.org/acme/order/762064026/157740686277"],"Replay-Nonce":["371CtMtNCMkg3aC-9BA2DNWn3LvAU0lkDkXGbzYmWFFWygQ"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":201}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242980.5439649,"logger":"http.acme_client","msg":"http request","method":"POST","url":"https://acme-v02.api.letsencrypt.org/acme/authz-v3/193715674137","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Boulder-Requester":["762064026"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["645"],"Content-Type":["application/json"],"Date":["Mon, 09 Jan 2023 05:43:00 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Replay-Nonce":["1DFA7sNuGYBvg2uaFVpNEasfx9oxOIj5QD7UZruodWzs8II"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242980.544697,"logger":"http.acme_client","msg":"skipping challenge initiation because authorization is not pending","identifier":"mqtt.webkr.de","authz_status":"valid"}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242980.5447576,"logger":"http.acme_client","msg":"authorization finalized","identifier":"mqtt.webkr.de","authz_status":"valid"}
Jan 09 06:43:00 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242980.5447865,"logger":"http.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme-v02.api.letsencrypt.org/acme/order/762064026/157740686277"}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.163243,"logger":"http.acme_client","msg":"http request","method":"POST","url":"https://acme-v02.api.letsencrypt.org/acme/finalize/762064026/157740686277","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Boulder-Requester":["762064026"],"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["440"],"Content-Type":["application/json"],"Date":["Mon, 09 Jan 2023 05:43:01 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\""],"Location":["https://acme-v02.api.letsencrypt.org/acme/order/762064026/157740686277"],"Replay-Nonce":["371CAJAmFxZq-9IS6x4hIEvYaeleK8smRhZGU9fFOEeSNMk"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.3030584,"logger":"http.acme_client","msg":"http request","method":"POST","url":"https://acme-v02.api.letsencrypt.org/acme/cert/04c8cb437964d5ff55f26e82d35a4ef2fdcc","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["5317"],"Content-Type":["application/pem-certificate-chain"],"Date":["Mon, 09 Jan 2023 05:43:01 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\"","<https://acme-v02.api.letsencrypt.org/acme/cert/04c8cb437964d5ff55f26e82d35a4ef2fdcc/1>;rel=\"alternate\""],"Replay-Nonce":["5CA2X_uEt66i3SMDKWv9h3sBV8eilVH3VVADwnkjVRRbvy4"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.4446695,"logger":"http.acme_client","msg":"http request","method":"POST","url":"https://acme-v02.api.letsencrypt.org/acme/cert/04c8cb437964d5ff55f26e82d35a4ef2fdcc/1","headers":{"Content-Type":["application/jose+json"],"User-Agent":["Caddy/2.6.1 CertMagic acmez (linux; amd64)"]},"response_headers":{"Cache-Control":["public, max-age=0, no-cache"],"Content-Length":["3393"],"Content-Type":["application/pem-certificate-chain"],"Date":["Mon, 09 Jan 2023 05:43:01 GMT"],"Link":["<https://acme-v02.api.letsencrypt.org/directory>;rel=\"index\"","<https://acme-v02.api.letsencrypt.org/acme/cert/04c8cb437964d5ff55f26e82d35a4ef2fdcc/0>;rel=\"alternate\""],"Replay-Nonce":["371C5nUPmLxj_ZbUYRmGoHDeDJwJWRSIjNrjdJCVVh_5Mkc"],"Server":["nginx"],"Strict-Transport-Security":["max-age=604800"],"X-Frame-Options":["DENY"]},"status_code":200}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242981.4448843,"logger":"http.acme_client","msg":"successfully downloaded available certificate chains","count":2,"first_url":"https://acme-v02.api.letsencrypt.org/acme/cert/04c8cb437964d5ff55f26e82d35a4ef2fdcc"}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242981.4456117,"logger":"tls.obtain","msg":"certificate obtained successfully","identifier":"mqtt.webkr.de"}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.4456892,"logger":"events","msg":"event","name":"cert_obtained","id":"5e36df71-e02e-4358-9c5a-9278145926e0","origin":"tls","data":{"identifier":"mqtt.webkr.de","issuers":"acme-v02.api.letsencrypt.org-directory","renewal":false,"storage_key":"mqtt.webkr.de"}}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673242981.4457185,"logger":"tls.obtain","msg":"releasing lock","identifier":"mqtt.webkr.de"}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.4464214,"logger":"tls","msg":"loading managed certificate","domain":"mqtt.webkr.de","expiration":1681015380,"issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.606882,"logger":"tls.cache","msg":"added certificate to cache","subjects":["mqtt.webkr.de"],"expiration":1681015380,"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"f83ed29bf9898a8e3425f6a68a45eea2cd6016bd14292385df32dd15f7e2288f","cache_size":15,"cache_capacity":10000}
Jan 09 06:43:01 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673242981.6069868,"logger":"events","msg":"event","name":"cached_managed_cert","id":"4cba11e9-0ac6-4268-b097-2f3809c87a18","origin":"tls","data":{"sans":["mqtt.webkr.de"]}}

The script and all its parent folders are 755.

What about cert_obtained vs certificate_obtained? Is that a literal key that has to match?

That was apparently part of the issue, now I get:

...
Jan 09 06:58:46 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"debug","ts":1673243926.31208,"logger":"events","msg":"event","name":"cert_obtained","id":"2a7eae7c-7a68-40f3-9e7e-8b35bbb2785b","origin":"tls","data":{"identifier":"mqtt.webkr.de","issuers":"acme-staging-v02.api.letsencrypt.org-directory","renewal":false,"storage_key":"mqtt.webkr.de"}}
Jan 09 06:58:46 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"info","ts":1673243926.3121552,"logger":"tls.obtain","msg":"releasing lock","identifier":"mqtt.webkr.de"}
Jan 09 06:58:46 Ubuntu-1604-xenial-64-minimal caddy[854]: {"level":"error","ts":1673243926.3134105,"logger":"events.handlers.exec","msg":"background command failed","error":"context canceled"}
...

Ok, I guess I’m running into "context canceled" when trying to run echo via cmd.exe on windows · Issue #3 · mholt/caddy-events-exec · GitHub now.

I’ll try building a new caddy binary, hopefully I’ll get the fix for that issue then.

Because I have no idea how I can set foreground: true with the on foo exec bar syntax.

Yup, that helped, the script is now executed. Last problem: {event.data.domain} seems to be empty

Ah, by the way, I found where I copied that wrong event name from: events: Begin implementing event system by mholt · Pull Request #4984 · caddyserver/caddy · GitHub

That’s also where I got {event.data.domain} from, maybe there’s another typo?

Ah, that makes sense. I just updated the PR description to update it so it uses the current names now.

FWIW, we do have cert_obtained documented here:

But I’m not seeing anywhere we document the data keys. We should probably do that somewhere.

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