Event hook doesn't appear to run on event.

[greigm]

caddy --version
v2.7.6 h1:w0NymbG2m9PcvKWsrXO6EEkY9Ru4FJK8uQbYcev1p3A=

Caddy built with: xcaddy build --with github.com/mholt/caddy-events-exec

Caddyfile section:

{
    #debug
    events {
        on cert_obtained exec /usr/local/sbin/on_cert_update.sh {event.data.certificate_path}
        #on cached_managed_cert exec /usr/local/sbin/on_cert_update.sh {event.data.certificate_path}
    }
}

As you can see above, I changed the event to something I can easily trigger with a simple restart to avoid having to keep renewing certs. The result is the same. In the debug output, I can see the event itself, but no mention of the hook being run.

Script permissions: -rwxr-xr-x 1 root root 613 Apr 18 08:49 /usr/local/sbin/on_cert_update.sh

caddy --list-modules
admin.api.load
admin.api.metrics
<snip>
tls.stek.standard

  Standard modules: 106

events.handlers.exec

  Non-standard modules: 1

  Unknown modules: 0

Example Debug output:

Apr 25 08:43:37 testsrv caddy[3547213]: {"level":"debug","ts":1713386617.0993721,"logger":"events","msg":"event","name":"cert_obtained","id":"09894d47-6749-4f57-9e52-4657d4351e37","origin":"tls","data":{"certificate_path":"certificates/acme-v02.api.letsencrypt.org-directory/www.redacted.co.nz/www.redacted.co.nz.crt","identifier":"www.redacted.co.nz","issuer":"acme-v02.api.letsencrypt.org-directory","metadata_path":"certificates/acme-v02.api.letsencrypt.org-directory/www.redacted.co.nz/www.redacted.co.nz.json","private_key_path":"certificates/acme-v02.api.letsencrypt.org-directory/www.redacted.co.nz/www.redacted.co.nz.key","renewal":false,"storage_path":"certificates/acme-v02.api.letsencrypt.org-directory/www.redacted.co.nz"}}
Apr 25 08:43:37 testsrv caddy[3547213]: {"level":"info","ts":1713386617.0995224,"logger":"tls.obtain","msg":"releasing lock","identifier":"www.redacted.co.nz"}
Apr 25 08:43:37 testsrv caddy[3547213]: {"level":"debug","ts":1713386617.1007128,"logger":"tls","msg":"loading managed certificate","domain":"www.redacted.co.nz","expiration":1721159016,"issuer_key":"acme-v02.api.letsencrypt.org-directory","storage":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Apr 25 08:43:37 testsrv caddy[3547213]: {"level":"debug","ts":1713386617.9157176,"logger":"tls.cache","msg":"added certificate to cache","subjects":["www.redacted.co.nz"],"expiration":1721159016,"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"6ee5b56001c43c16dbbe5374939f813e551af5a8d15c7c2174e7ac623c8f27b6","cache_size":17,"cache_capacity":10000}

I've googled a lot, and found one other person having a similar fault, but they had the event name incorrect. As you can see, I have it correct. Any ideas at all on how to debug this further would be appreciated as I am well and truly stuck!

Thanks.

[mholt]

Hmm, I'll take a look soon.

[mholt]

I can't seem to reproduce this...

Caddyfile:

{
    events {
        on cert_obtained exec /home/matt/Dev/caddy-event-exec/script.sh {event.data.certificate_path}
    }
    debug
}

localhost:9000 {
    respond "Site not served from here"
}

Script contents (an executable file):

#!/bin/bash

echo "**** RUNNING SCRIPT ****"
echo "***** $1"
touch /home/matt/Dev/caddy-event-exec/done

Then:

$ xcaddy run

Output:

...
2024/04/26 21:43:49.545 INFO    tls.obtain      certificate obtained successfully       {"identifier": "localhost"}
2024/04/26 21:43:49.545 DEBUG   events  event   {"name": "cert_obtained", "id": "126ada11-1ad1-4fc9-a9fa-9667445d6ce2", "origin": "tls", "data": {"certificate_path":"certificates/local/localhost/localhost.crt","identifier":"localhost","issuer":"local","metadata_path":"certificates/local/localhost/localhost.json","private_key_path":"certificates/local/localhost/localhost.key","renewal":false,"storage_path":"certificates/local/localhost"}}
2024/04/26 21:43:49.545 INFO    tls.obtain      releasing lock  {"identifier": "localhost"}
2024/04/26 21:43:49.545 WARN    tls     stapling OCSP   {"error": "no OCSP stapling for [localhost]: no OCSP server specified in certificate", "identifiers": ["localhost"]}
2024/04/26 21:43:49.545 DEBUG   tls.cache       added certificate to cache      {"subjects": ["localhost"], "expiration": "2024/04/27 09:43:50.000", "managed": true, "issuer_key": "local", "hash": "e1d58c589b35cb37fea9e2330528c4385a8b2d6d92dba3e447763421a7e56a92", "cache_size": 1, "cache_capacity": 10000}
2024/04/26 21:43:49.545 DEBUG   events  event   {"name": "cached_managed_cert", "id": "bde90d91-9bdf-4cd4-96a2-2b304b3a03d8", "origin": "tls", "data": {"sans":["localhost"]}}
**** RUNNING SCRIPT ****
***** certificates/local/localhost/localhost.crt
2024/04/26 21:43:49.558 INFO    pki.ca.local    root certificate is already trusted by system   {"path": "storage:pki/authorities/local/root.crt"}
2024/04/26 21:43:49.559 INFO    autosaved config (load with --resume flag)      {"file": "/home/matt/.config/caddy/autosave.json"}
2024/04/26 21:43:49.559 INFO    serving initial configuration

And the file done is found on the file system. I wanted to both echo and create a file in case maybe there was a permission issue with files, or I wasn't able to see stdout for some reason, but both worked for me.

Make sure you're running the config you think you are, I guess :man_shrugging: Make sure to look at all your logs, it may not be right next to those lines.

Closing, but if more evidence is brought forward, we can reopen.

[greigm]

Thanks, I appreciate it. At least I now have a complete set of logs for what a working scenario looks like. I'll keep hacking and report back - as you say, it almost HAS to be something dumb on my end! Apologies if this comment reopens the bug - I just wanted to thank you for the effort.

[mholt]

No worries. I know it's frustrating when someone can't reproduce the behavior. Good luck, let me know how it goes!

[greigm]

Oh dear... it was extreme stupidity on my part. Somehow, in 30 years of UNIX/Linux experience, I've never come across systemd's PrivateTmp setting. I had assumed my script wasn't running due to no log entry. I hadn't realised that no log entry is created unless the script itself echoes to stdout... thanks to you, I found that, and it worked immediately.

My problem was that all my script did was write $@ to /tmp/eventlog.txt... it wasn't being created! Thanks to PrivateTmp on by default in Ubuntu 22.04, it WAS being created, under /tmp/systemd-private-{some-guid}-caddy.service-{short-random-string}/tmp/eventlog.txt

Not sure if anyone else will hit this weird combination of events, but if nothing else, it might help to know that event hooks are NOT logged by default. Perhaps they should be? If nothing else, it might be helpful to add that fact to the documentation.

Anyway, thanks again!

[mholt]

@greigm Ah, gotcha. Thanks for the follow-up, that will surely be helpful to someone in the future. :100: Glad you figured it out! Definitely not an obvious thing.

I have just added a log for when individual event handlers are invoked, so you should see that in the next release.

[greigm]

Perfect, thanks!