Hooks fail to run when acmetool is run with cron as a non-root user, but succeed when run manually via "test-notify" as a non-root user

[cyrozap]

This has been happening on every certificate renewal since I started using acmetool, regardless of how up-to-date I keep it. acmetool runs and is able to update the certificates, but all the hooks fail.

Failure:

Apr 09 15:52:01 hostname CROND[5350]: (acme) CMD (/usr/local/bin/acmetool --xlog.journal --batch reconcile)
Apr 09 15:52:05 hostname acmetool[5350]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Apr 09 15:52:05 hostname acmetool[5350]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Apr 09 15:52:05 hostname acmetool[5350]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1

Success:

[cyrozap@hostname ~]$ sudo -u acme /usr/local/bin/acmetool --xlog.severity=debug test-notify custom.example.com
20170513010156 [DEBUG] acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
20170513010156 [DEBUG] acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
20170513010157 [DEBUG] acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom

/etc/sudoers:

acme ALL=(root) NOPASSWD: /usr/libexec/acme/hooks/

Hook permissions:

[cyrozap@hostname ~]$ ls -l /usr/libexec/acme/hooks/
total 16
-rwsr-xr-x 1 root root 4316 Oct 10  2016 haproxy
-rwsr-xr-x 1 root root 1730 Oct 10  2016 reload
-rwsr-xr-x 1 root root  339 Mar 13 20:37 custom

Version info:

[cyrozap@hostname ~]$ acmetool --version
go version go1.7 linux/amd64 gc cgo=true
built by travis
git github.com/alecthomas/template a0175ee3bccc567396460bf5acd36800cb10c49c heads/master
git github.com/alecthomas/units 2efee857e7cfd4f3d0138cc3cbb1b4966962b93a heads/master
git github.com/coreos/go-systemd e97b35f834b17eaa82afe3d44715c34736bfa12b heads/master
git github.com/godbus/dbus 4b24ebee04561bf8a3bcc09aead82062edc56778 heads/master
git github.com/hlandau/acme 3201252d3de450a556a33daedbb55b95689eb248 v0.0.59
git github.com/hlandau/buildinfo 337a29b5499734e584d4630ce535af64c5fe7813 heads/master
git github.com/hlandau/dexlogconfig 244f29bd260884993b176cd14ef2f7631f6f3c18 heads/master
git github.com/hlandau/goutils 0cdb66aea5b843822af6fdffc21286b8fe8379c4 heads/master
git github.com/hlandau/xlog 197ef798aed28e08ed3e176e678fda81be993a31 v1.0.0
git github.com/jmhodges/clock 880ee4c335489bc78d01e4d0a254ae880734bc15 tags/v1.1
git github.com/mattn/go-isatty dda3de49cbfcec471bd7a70e6cc01fcc3ff90109 heads/master
git github.com/mattn/go-runewidth 14207d285c6c197daabb5c9793d63e7af9ab2d50 heads/master
git github.com/mitchellh/go-wordwrap ad45545899c7b13c020ea92b2072220eefad42b8 heads/master
git github.com/ogier/pflag 45c278ab3607870051a2ea9040bb85fcb8557481 heads/master
git github.com/peterhellberg/link 24c1495e8c97c8c537f23307b2b8d2932051c1a9 heads/master
git github.com/satori/go.uuid b061729afc07e77a8aa4fad0a2fd840958f1942a heads/master
git github.com/shiena/ansicolor a422bbe96644373c5753384a59d678f7d261ff10 heads/master
git golang.org/x/crypto 453249f01cfeb54c3d549ddb75ff152ca243f9d8 heads/master
git golang.org/x/net b4690f45fa1cafc47b1c280c2e75116efe40cc13 heads/master
git gopkg.in/alecthomas/kingpin.v2 e9044be3ab2a8e11d4e1f418d12f0790d57e8d70 tags/v2.2.3
git gopkg.in/cheggaaa/pb.v1 d7e6ca3010b6f084d8056847f55d7f572f180678 v1.0.7
git gopkg.in/hlandau/configurable.v1 41496864a1fe3e0fef2973f22372b755d2897402 v1.0.1
git gopkg.in/hlandau/easyconfig.v1 33e53e2d08656ccad000531debbf2656a896b695 v1.0.15
git gopkg.in/hlandau/service.v2 b64b3467ebd16f64faec1640c25e318efc0c0d7b v2.0.16
git gopkg.in/hlandau/svcutils.v1 c25dac49e50cbbcbef8c81b089f56156f4067729 v1.0.10
git gopkg.in/square/go-jose.v1 aa2e30fdd1fe9dd3394119af66451ae790d50e0d v1.1.0
git gopkg.in/tylerb/graceful.v1 4654dfbb6ad53cb5e27f37d99b02e16c1872fbbb tags/v1.2.15
git gopkg.in/yaml.v2 a3f3340b5840cee44f372bddb5880fcbc419b46a heads/v2

I've since enabled debug logging in my crontab, so we'll be able to see more details of this failure in a few months when it auto-renews again.

[cyrozap]

I'm still having this problem. The debug log shows that all scripts exited with "error status 1" each time they were run:

Sep 10 15:52:01 hostname CROND[30561]: (acme) CMD (/usr/local/bin/acmetool --xlog.journal --batch reconcile --xlog.severity=debug)
Sep 10 15:52:01 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.116364674 994/993 994/993
Sep 10 15:52:01 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.782746361 994/993 994/993
Sep 10 15:52:01 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.470403588 994/993 994/993
Sep 10 15:52:01 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.072855955 994/993 994/993
Sep 10 15:52:01 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.084365270 994/993 994/993
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0): best certificate satisfying is Certificate(xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx), err=<nil>
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Certificate(xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) needsRenewing=true notAfter=2017-10-10 05:27:00 +0000 UTC
Sep 10 15:52:01 hostname acmetool[30561]: acme.storageops: Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0): requesting certificate
Sep 10 15:52:01 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/directory
Sep 10 15:52:01 hostname acmetool[30561]: acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Server:[nginx] Content-Length:[561] Expires:[Sun, 10 Sep 2017 19:52:01 GMT] Cache-Control:[max-age=0, no-cache, no-store] Date:[Sun, 10 Sep 2017 19:52:01 GMT] Connection:[keep-alive] Content-Type:[application/json] Boulder-Request-Id:[xnyy7lVIhghPbZekystau-eJd8ciayT4KK6frBUOfDY] Replay-Nonce:[-KL98szUlWax498BMVw2NRGJPAe6Aanl7gKMK5t8v_Q] X-Frame-Options:[DENY] Strict-Transport-Security:[max-age=604800] Pragma:[no-cache]] 0xc42004c840 561 [] false false map[] 0xc420152690 0xc4201384d0} <nil>
Sep 10 15:52:01 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-reg
Sep 10 15:52:01 hostname acmetool[30561]: acme.api: response: &{409 Conflict 409 HTTP/1.1 1 1 map[Server:[nginx] Content-Type:[application/problem+json] Location:[https://acme-v01.api.letsencrypt.org/acme/reg/1111111] Expires:[Sun, 10 Sep 2017 19:52:01 GMT] Pragma:[no-cache] Date:[Sun, 10 Sep 2017 19:52:01 GMT] Content-Length:[107] Boulder-Request-Id:[bshv0HethPbi_1XSCGTEImdBOapQ-vlgti0MbuZKVhQ] Boulder-Requester:[1111111] Replay-Nonce:[TyhfbJgVUkjg5DduML29kojuhcjDc-eL_8OaCViYHb8] Cache-Control:[max-age=0, no-cache, no-store]] 0xc42004cb80 107 [] true false map[] 0xc4201530e0 0xc4201384d0} <nil>
Sep 10 15:52:01 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/reg/1111111
Sep 10 15:52:02 hostname acmetool[30561]: acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Boulder-Request-Id:[I7NI-0Z1mpHuvI9DtXM5i568JYvhcm6nRoCbDjgS1VQ] Boulder-Requester:[1111111] Link:[<https://acme-v01.api.letsencrypt.org/acme/new-authz>;rel="next" <https://letsencrypt.org/documents/LE-SA-v1.1.1-August-1-2016.pdf>;rel="terms-of-service"] Replay-Nonce:[jNek432Jw8uATk2U9rf4j6a16SWcFBLRIoA1vlkrBWU] Cache-Control:[max-age=0, no-cache, no-store] Connection:[keep-alive] Server:[nginx] Content-Type:[application/json] Content-Length:[623] Expires:[Sun, 10 Sep 2017 19:52:02 GMT] Pragma:[no-cache] Date:[Sun, 10 Sep 2017 19:52:02 GMT]] 0xc420442580 623 [] false false map[] 0xc420153770 0xc420120630} <nil>
Sep 10 15:52:02 hostname acmetool[30561]: acme.storageops: trying to obtain authorization for "example.com"
Sep 10 15:52:02 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-authz
Sep 10 15:52:02 hostname acmetool[30561]: acme.api: response: &{201 Created 201 HTTP/1.1 1 1 map[Content-Type:[application/json] Boulder-Request-Id:[eMzXMRhJFYLIO7CYhSd5Q7u5jkSj_lBTUyjfwiavjdo] Boulder-Requester:[1111111] Link:[<https://acme-v01.api.letsencrypt.org/acme/new-cert>;rel="next"] X-Frame-Options:[DENY] Strict-Transport-Security:[max-age=604800] Cache-Control:[max-age=0, no-cache, no-store] Server:[nginx] Content-Length:[1003] Location:[https://acme-v01.api.letsencrypt.org/acme/authz/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM] Expires:[Sun, 10 Sep 2017 19:52:02 GMT] Pragma:[no-cache] Connection:[keep-alive] Replay-Nonce:[uTjsckMxoO6TNcHklCeur8UUUwUszW7j8EmmCliikYs] Date:[Sun, 10 Sep 2017 19:52:02 GMT]] 0xc420442980 1003 [] false false map[] 0xc420486d20 0xc420120630} <nil>
Sep 10 15:52:02 hostname acmetool[30561]: acme.solver: attempting challenge type tls-sni-01
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: failed to start TLS-SNI listener: listen tcp :443: bind: permission denied
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: tls-sni-01 self-test failed: dial tcp [2604:1234:5678::1]:443: getsockopt: connection refused
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.solver: challenge start failed: dial tcp [2604:1234:5678::1]:443: getsockopt: connection refused
Sep 10 15:52:02 hostname acmetool[30561]: acme.solver: attempting challenge type http-01
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: failed to listen on [::]:80: listen tcp [::]:80: bind: permission denied
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: failed to listen on :80: listen tcp :80: bind: permission denied
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: listening on [::1]:4402
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: listening on 127.0.0.1:4402
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: failed to listen on [::1]:402: listen tcp [::1]:402: bind: permission denied
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: failed to listen on 127.0.0.1:402: listen tcp 127.0.0.1:402: bind: permission denied
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: writing 1 webroot challenge files
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: writing webroot file /var/run/acme/acme-challenge/1111111111111111111111111111111111111111111
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom
Sep 10 15:52:02 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: http-01 self test
Sep 10 15:52:02 hostname acmetool[30561]: acme.responder: http-01 started
Sep 10 15:52:02 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/challenge/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM/0000000000
Sep 10 15:52:03 hostname acmetool[30561]: acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Connection:[keep-alive] Location:[https://acme-v01.api.letsencrypt.org/acme/challenge/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM/0000000000] Expires:[Sun, 10 Sep 2017 19:52:03 GMT] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Date:[Sun, 10 Sep 2017 19:52:03 GMT] Link:[<https://acme-v01.api.letsencrypt.org/acme/authz/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM>;rel="up"] Replay-Nonce:[fKaReDmeSsaXNDYkTafEmtyfJH0G-bYkIdAhKILeizg] Server:[nginx] Content-Type:[application/json] Content-Length:[336] Boulder-Request-Id:[DEG0x8Gcs3w6u1BFxtJfEc8Akz9n74BzeIsIAZOc6DY] Boulder-Requester:[1111111]] 0xc420443b40 336 [] false false map[] 0xc4204de0f0 0xc420120630} <nil>
Sep 10 15:52:03 hostname acmetool[30561]: acme.solver: waiting to poll challenge
Sep 10 15:52:08 hostname acmetool[30561]: acme.solver: querying challenge status
Sep 10 15:52:08 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/challenge/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM/0000000000
Sep 10 15:52:08 hostname acmetool[30561]: acme.api: response: &{202 Accepted 202 HTTP/1.1 1 1 map[Content-Length:[709] Link:[<https://acme-v01.api.letsencrypt.org/acme/authz/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM>;rel="up"] Location:[https://acme-v01.api.letsencrypt.org/acme/challenge/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM/0000000000] Replay-Nonce:[diZqbRkcgZhKpno4UY8Y-aDrxQcM-m-_e2ZH9l5h0JU] Cache-Control:[max-age=0, no-cache, no-store] Date:[Sun, 10 Sep 2017 19:52:08 GMT] Server:[nginx] Content-Type:[application/json] Pragma:[no-cache] Connection:[keep-alive] Boulder-Request-Id:[KYv3B8eVDHqpP1SsFrSZ39NtSrL_Tm_Zn-xB9OUP4xI] Expires:[Sun, 10 Sep 2017 19:52:08 GMT]] 0xc420443d40 709 [] false false map[] 0xc4204de2d0 0xc420120630} <nil>
Sep 10 15:52:08 hostname acmetool[30561]: acme.solver: challenge now in final state
Sep 10 15:52:08 hostname acmetool[30561]: acme.responder: removing webroot file /var/run/acme/acme-challenge/2222222222222222222222222222222222222222222
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom
Sep 10 15:52:08 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1
Sep 10 15:52:08 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/authz/T8oLP9SDAP7JuGh9U5-dKobENoSgaBYz_CkI4cl9msM
Sep 10 15:52:08 hostname acmetool[30561]: acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Server:[nginx] Content-Length:[1533] Link:[<https://acme-v01.api.letsencrypt.org/acme/new-cert>;rel="next"] Replay-Nonce:[OS2ZKyQE_tC5ff1O1G3hZl1Ym3gL3VsnvEZ65H2COGc] X-Frame-Options:[DENY] Expires:[Sun, 10 Sep 2017 19:52:08 GMT] Content-Type:[application/json] Boulder-Request-Id:[kYpG-CkGHgkwzEeDkPdABFQnp1AgY2mU94aaPyFwWfM] Strict-Transport-Security:[max-age=604800] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Date:[Sun, 10 Sep 2017 19:52:08 GMT] Connection:[keep-alive]] 0xc420443f00 1533 [] false false map[] 0xc4204de5a0 0xc420120630} <nil>
Sep 10 15:52:08 hostname acmetool[30561]: fdb: enforce permissions: accounts/acme-v01.api.letsencrypt.org%2fdirectory/cccccccccccccccccccccccccccccccccccccccccccccccccccc/privkey 994/993 994/993
Sep 10 15:52:08 hostname acmetool[30561]: fdb: enforce permissions: accounts/acme-v01.api.letsencrypt.org%2fdirectory/cccccccccccccccccccccccccccccccccccccccccccccccccccc/authorizations/example.com/expiry 994/993 994/993
Sep 10 15:52:08 hostname acmetool[30561]: fdb: enforce permissions: accounts/acme-v01.api.letsencrypt.org%2fdirectory/cccccccccccccccccccccccccccccccccccccccccccccccccccc/authorizations/example.com/url 994/993 994/993
Sep 10 15:52:09 hostname acmetool[30561]: fdb: enforce permissions: keys/dddddddddddddddddddddddddddddddddddddddddddddddddddd/privkey 994/993 994/993
Sep 10 15:52:09 hostname acmetool[30561]: acme.storageops: Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0): requesting certificate
Sep 10 15:52:09 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/new-cert
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: response: &{201 Created 201 HTTP/1.1 1 1 map[Server:[nginx] Pragma:[no-cache] Content-Length:[1541] Boulder-Request-Id:[oLAZ8TxO4YevQIhrDqvxUIxDavfrz33x-IWAXs5zyVU] Boulder-Requester:[1111111] Expires:[Sun, 10 Sep 2017 19:52:10 GMT] Connection:[keep-alive] Content-Type:[application/pkix-cert] Replay-Nonce:[z-3CZXl7AlvzLOkeibm70n3zpYw6zLDVHMu_wb-wH94] Strict-Transport-Security:[max-age=604800] Link:[<https://acme-v01.api.letsencrypt.org/acme/issuer-cert>;rel="up"] Location:[https://acme-v01.api.letsencrypt.org/acme/cert/333333333333333333333333333333333333] X-Frame-Options:[DENY] Cache-Control:[max-age=0, no-cache, no-store] Date:[Sun, 10 Sep 2017 19:52:10 GMT]] 0xc420442900 1541 [] false false map[] 0xc420487590 0xc420120630} <nil>
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Pragma:[no-cache] Connection:[keep-alive] Server:[nginx] Content-Length:[1174] X-Frame-Options:[DENY] Strict-Transport-Security:[max-age=604800] Expires:[Sun, 10 Sep 2017 19:52:10 GMT] Cache-Control:[max-age=0, no-cache, no-store] Content-Type:[application/pkix-cert] Boulder-Request-Id:[sFXhckDpeIGwqJYc2pbdn3TeTqnZCPsru0eAbpAdav0] Replay-Nonce:[r5Dj2Jn4caPIj4323---j4vcZ_5PRdFPgORV9du6TY0] Date:[Sun, 10 Sep 2017 19:52:10 GMT]] 0xc420442a80 1174 [] false false map[] 0xc420487c20 0xc420120630} <nil>
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: certs/NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN/url 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: downloading certificate Certificate(NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN)
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/cert/333333333333333333333333333333333333
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Replay-Nonce:[7X7a5vf5i-igaogxO_boJD3tGFSmnzdQUtQG-IyJIcU] X-Frame-Options:[DENY] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Connection:[keep-alive] Server:[nginx] Content-Length:[1541] Boulder-Request-Id:[vW9jCXADQHvVDE7Q_uzuCe3ZnaEh1ACqY05pTu1vZLM] Expires:[Sun, 10 Sep 2017 19:52:10 GMT] Date:[Sun, 10 Sep 2017 19:52:10 GMT] Content-Type:[application/pkix-cert] Link:[<https://acme-v01.api.letsencrypt.org/acme/issuer-cert>;rel="up"] Strict-Transport-Security:[max-age=604800]] 0xc420443140 1541 [] false false map[] 0xc420487ef0 0xc420120630} <nil>
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: request: https://acme-v01.api.letsencrypt.org/acme/issuer-cert
Sep 10 15:52:10 hostname acmetool[30561]: acme.api: response: &{200 OK 200 HTTP/1.1 1 1 map[Date:[Sun, 10 Sep 2017 19:52:10 GMT] Connection:[keep-alive] Server:[nginx] Content-Type:[application/pkix-cert] Replay-Nonce:[u7St2CekOhGssUk2bX9RpxbbhOf_xM4e24o7N0SPmfw] X-Frame-Options:[DENY] Cache-Control:[max-age=0, no-cache, no-store] Pragma:[no-cache] Content-Length:[1174] Boulder-Request-Id:[ClOmAuT5JMQVnJJ_vtxK5QwzKbDJZWCmYnqmURADPic] Strict-Transport-Security:[max-age=604800] Expires:[Sun, 10 Sep 2017 19:52:10 GMT]] 0xc420443340 1174 [] false false map[] 0xc420152a50 0xc420120630} <nil>
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: certs/NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN/cert 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: certs/NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN/chain 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: certs/NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN/fullchain 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: done processing targets, reconciliation complete, 0 errors occurred
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.864240957 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.936667000 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.372427383 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.598924138 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.715298241 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.459544108 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: disjoint hostname mapping: example.com -> Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: Certificate(xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) satisfies Target(example.com;https://acme-v01.api.letsencrypt.org/directory;0)
Sep 10 15:52:10 hostname acmetool[30561]: acme.storageops: relinking: example.com -> Certificate(NNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN) (was Certificate(xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx))
Sep 10 15:52:10 hostname acmetool[30561]: fdb: enforce permissions: tmp/symlink.088291739 994/993 994/993
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/haproxy
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/haproxy: exit status 1
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/reload
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/reload: exit status 1
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: calling hook script (with sudo): /usr/libexec/acme/hooks/custom
Sep 10 15:52:10 hostname acmetool[30561]: acme.hooks: hook script: /usr/libexec/acme/hooks/custom: exit status 1

Version info:

[cyrozap@hostname ~]$ acmetool --version
go version go1.7 linux/amd64 gc cgo=true
built by travis
git github.com/alecthomas/template a0175ee3bccc567396460bf5acd36800cb10c49c heads/master
git github.com/alecthomas/units 2efee857e7cfd4f3d0138cc3cbb1b4966962b93a heads/master
git github.com/coreos/go-systemd e97b35f834b17eaa82afe3d44715c34736bfa12b heads/master
git github.com/godbus/dbus 4b24ebee04561bf8a3bcc09aead82062edc56778 heads/master
git github.com/hlandau/acme 3201252d3de450a556a33daedbb55b95689eb248 v0.0.59
git github.com/hlandau/buildinfo 337a29b5499734e584d4630ce535af64c5fe7813 heads/master
git github.com/hlandau/dexlogconfig 244f29bd260884993b176cd14ef2f7631f6f3c18 heads/master
git github.com/hlandau/goutils 0cdb66aea5b843822af6fdffc21286b8fe8379c4 heads/master
git github.com/hlandau/xlog 197ef798aed28e08ed3e176e678fda81be993a31 v1.0.0
git github.com/jmhodges/clock 880ee4c335489bc78d01e4d0a254ae880734bc15 tags/v1.1
git github.com/mattn/go-isatty dda3de49cbfcec471bd7a70e6cc01fcc3ff90109 heads/master
git github.com/mattn/go-runewidth 14207d285c6c197daabb5c9793d63e7af9ab2d50 heads/master
git github.com/mitchellh/go-wordwrap ad45545899c7b13c020ea92b2072220eefad42b8 heads/master
git github.com/ogier/pflag 45c278ab3607870051a2ea9040bb85fcb8557481 heads/master
git github.com/peterhellberg/link 24c1495e8c97c8c537f23307b2b8d2932051c1a9 heads/master
git github.com/satori/go.uuid b061729afc07e77a8aa4fad0a2fd840958f1942a heads/master
git github.com/shiena/ansicolor a422bbe96644373c5753384a59d678f7d261ff10 heads/master
git golang.org/x/crypto 453249f01cfeb54c3d549ddb75ff152ca243f9d8 heads/master
git golang.org/x/net b4690f45fa1cafc47b1c280c2e75116efe40cc13 heads/master
git gopkg.in/alecthomas/kingpin.v2 e9044be3ab2a8e11d4e1f418d12f0790d57e8d70 tags/v2.2.3
git gopkg.in/cheggaaa/pb.v1 d7e6ca3010b6f084d8056847f55d7f572f180678 v1.0.7
git gopkg.in/hlandau/configurable.v1 41496864a1fe3e0fef2973f22372b755d2897402 v1.0.1
git gopkg.in/hlandau/easyconfig.v1 33e53e2d08656ccad000531debbf2656a896b695 v1.0.15
git gopkg.in/hlandau/service.v2 b64b3467ebd16f64faec1640c25e318efc0c0d7b v2.0.16
git gopkg.in/hlandau/svcutils.v1 c25dac49e50cbbcbef8c81b089f56156f4067729 v1.0.10
git gopkg.in/square/go-jose.v1 aa2e30fdd1fe9dd3394119af66451ae790d50e0d v1.1.0
git gopkg.in/tylerb/graceful.v1 4654dfbb6ad53cb5e27f37d99b02e16c1872fbbb tags/v1.2.15
git gopkg.in/yaml.v2 a3f3340b5840cee44f372bddb5880fcbc419b46a heads/v2

I'm not sure what I need to do to fix this. I'm sure I'm not the only one running acme as a non-root user, so I must be doing something wrong here.

[mnalis]

you could probably try to debug the scripts. For example, put some logging in beggining of them. If they are shell scripts, you can add something like (make up unique logfile name, and make sure it doesn't exist already as to avoid permission problems when hook tries to overwrite them):

/usr/bin/id > /tmp/logXXXX
/usr/bin/env >> /tmp/logXXXX

etc.

or even change shebang to /bin/sh -x to log all commands. It seems like they are doing equivalent of "exit 1" somewhere in them....

and if nothing gets logged to that logfile, it would seem that the sudo(8) itself is failing (with clue probably in /var/log/auth or such)