S3 Storage module. Certificate worker Panic when getting certificates first time

Hi guys.
Not really sure if this related directly to Caddy or more related to S3 module. Or maybe I’m doing something wrong, if so, please correct me

1. Caddy version (caddy version):

custom docker images based on Caddy 2.3.0, 2.4.0, 2.4.1 with certmagic-s3 and format-encoder modules

2. How I run Caddy:

a. System environment:

Ubuntu 18.04.5 LTS

b. Command:

/usr/bin/docker run --rm --name='proxy' \
--mount type=bind,source=/etc/caddy_config.json,destination=/caddy_config.json \
--publish 80:80 \
--publish 443:443 \
artemius/caddy:2.4.1 caddy run --config /caddy_config.json

c. Dockerfile:

FROM caddy:2.4.1-builder AS builder
RUN xcaddy build --output ./caddy \
    --with github.com/ss098/certmagic-s3 \
    --with github.com/caddyserver/format-encoder

FROM caddy:2.4.1
COPY --from=builder /usr/bin/caddy /usr/bin/caddy

Instructions taken from Caddy Docker Hub, section: “Adding custom Caddy modules”

d. My complete JSON config:

{
  "logging": {
    "sink": {"writer": {"output": "stdout"}},
    "logs": {
      "default": {"exclude": ["http.log.access"]},
      "app-logger": {
        "level": "INFO",
        "writer": {"output": "stdout"},
        "encoder": {
          "format": "formatted",
          "template": "{request>host} - {level} - [{time.now.common_log}] - \"{request>remote_addr} {request>method} {request>uri} {request>proto}\" {status} {size}"
        },
        "include": ["http.log.access"]
      }
    }
  },
  "apps": {
    "tls": {
      "certificates": {
        "automate": ["wp-test.dev-art.domain.com"]
      }
    },
    "http": {
      "servers": {
        "dev-art": {
          "logs": {"default_logger_name": "app-logger"},
          "listen": [":443"],
          "routes": [
            {
              "match": [{"host": ["wp-test.dev-art.domain.com"]}],
    "handle": [
                {
                  "handler": "reverse_proxy",
                  "upstreams": [{"dial": "<APPLICATION_NODE_IP>:3000"}]
                }
              ]
            }
          ]
        }
      }
    }
  },
  "storage": {
    "module": "s3",
    "host": "s3.amazonaws.com",
    "bucket": "test_bucket",
    "access_key": "<AWS_ACCESS_KEY>",
    "secret_key": "<AWS_SECRET_KEY>",
    "prefix": "test_folder",
    "redis_address": "<AWS_REDIS_IP>:<AWS_REDIS_PORT>",
    "redis_password": "",
    "redis_db": 0
  }
}

3. The problem I’m having:

Got an AWS cluster with next set:

  • Caddy node
  • Application node
  • Redis
  • s3 bucket

Redis and S3 bucket has correct configuration and accessible from node where Caddy is working.
Caddy and App working as a docker containers started by systemd service

Problem: At first start when I got no certs at all and bucket folder is empty I’m getting an error that is shown in a full log in a section below.
Second problem - current error does not stop/kill docker container and system think that everything is fine there. As a result systemd did not throw any on-failure notifications.

Simultaneously with error I can see that Bucket has next structure

test_bucket
  - test_folder/
    - acme/
      - acme-v02.api.letsencrypt.org-directory/
        - users/
          - default/
            - default.json
            - default.key
    - certificates/
      - acme-v02.api.letsencrypt.org-directory/
        - wp-test.dev-art.domain.com/
          - wp-test.dev-art.domain.com.crt
          - wp-test.dev-art.domain.com.json
          - wp-test.dev-art.domain.com.key

Problem gone when I log in to a caddy instance and restart the Caddy systemd service manually.

4. Error messages and/or full log output:

{"level":"info","ts":1622292835.266702,"msg":"using provided configuration","config_file":"/caddy_config.json","config_adapter":""}
2021/05/29 12:53:55 [INFO] Redirecting sink to: stdout
2021/05/29 12:53:55 [INFO] Redirected sink to here (stdout)
{"level":"info","ts":1622292835.2699473,"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":1622292835.271092,"logger":"http","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"dev-art","https_port":443}
{"level":"info","ts":1622292835.2714522,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"dev-art"}
{"level":"info","ts":1622292835.2722864,"logger":"caddy.storage.s3","msg":"Load: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292835.2732973,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0002fda40"}
{"level":"info","ts":1622292835.9622266,"logger":"caddy.storage.s3","msg":"Load: test_folder/certificates/acme.zerossl.com-v2-dv90/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.0014627,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["wp-test.dev-art.domain.com"]}
{"level":"info","ts":1622292836.0025342,"logger":"caddy.storage.s3","msg":"Load: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.00381,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.0050566,"logger":"tls","msg":"cleaning storage unit","description":"&{0xc00072f6e0 0xc00037d970 s3.amazonaws.com test_bucket <AWS_ACCESS_KEY> <AWS_SECRET_KEY> dev-art Redis<<AWS_REDIS_IP>:<AWS_REDIS_PORT> db:0> 0xc00073f230 map[] <AWS_REDIS_IP>:<AWS_REDIS_PORT>  0}"}
{"level":"info","ts":1622292836.0395818,"logger":"caddy.storage.s3","msg":"Load: test_folder/certificates/acme.zerossl.com-v2-dv90/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.0770361,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme.zerossl.com-v2-dv90/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.14719,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.1494465,"logger":"caddy.storage.s3","msg":"Store: test_folder/rw_test_4873102611796815485, 10240 bytes"}
{"level":"info","ts":1622292836.152547,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1622292836.153608,"msg":"serving initial configuration"}
{"level":"info","ts":1622292836.156261,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":1622292836.1844337,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme.zerossl.com-v2-dv90/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.2113404,"logger":"caddy.storage.s3","msg":"Load: test_folder/rw_test_4873102611796815485"}
{"level":"info","ts":1622292836.2222416,"logger":"caddy.storage.s3","msg":"Store: test_folder/rw_test_3162212477631280723, 10240 bytes"}
{"level":"info","ts":1622292836.2527869,"logger":"caddy.storage.s3","msg":"Delete: test_folder/rw_test_4873102611796815485"}
{"level":"info","ts":1622292836.2739127,"logger":"caddy.storage.s3","msg":"Load: test_folder/rw_test_3162212477631280723"}
{"level":"info","ts":1622292836.2978468,"logger":"tls.obtain","msg":"acquiring lock","identifier":"wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292836.2989197,"logger":"caddy.storage.s3","msg":"Lock: issue_cert_wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292836.3187115,"logger":"caddy.storage.s3","msg":"Delete: test_folder/rw_test_3162212477631280723"}
{"level":"info","ts":1622292836.3603976,"logger":"tls.obtain","msg":"acquiring lock","identifier":"wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292836.3625963,"logger":"caddy.storage.s3","msg":"Lock: issue_cert_wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292836.3638575,"logger":"tls.obtain","msg":"lock acquired","identifier":"wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292836.3648925,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"info","ts":1622292836.4058213,"logger":"caddy.storage.s3","msg":"Exists: test_folder/certificates/acme.zerossl.com-v2-dv90/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt"}
{"level":"error","ts":1622292836.424822,"logger":"caddy.storage.s3","msg":"Cannot lock key: issue_cert_wp-test.dev-art.domain.com"}
{"level":"error","ts":1622292836.425877,"logger":"tls","msg":"job failed","error":"wp-test.dev-art.domain.com: obtaining certificate: unable to acquire lock 'issue_cert_wp-test.dev-art.domain.com': redislock: not obtained"}
{"level":"info","ts":1622292836.4893322,"logger":"caddy.storage.s3","msg":"Load: test_folder/acme/acme-v02.api.letsencrypt.org-directory/users/default/default.json"}
{"level":"info","ts":1622292837.5782793,"logger":"caddy.storage.s3","msg":"Store: test_folder/acme/acme-v02.api.letsencrypt.org-directory/users/default/default.json, 141 bytes"}
{"level":"info","ts":1622292837.6305573,"logger":"caddy.storage.s3","msg":"Store: test_folder/acme/acme-v02.api.letsencrypt.org-directory/users/default/default.key, 227 bytes"}
{"level":"info","ts":1622292837.6845737,"logger":"tls.issuance.acme","msg":"waiting on internal rate limiter","identifiers":["wp-test.dev-art.domain.com"]}
{"level":"info","ts":1622292837.6846461,"logger":"tls.issuance.acme","msg":"done waiting on internal rate limiter","identifiers":["wp-test.dev-art.domain.com"]}
{"level":"info","ts":1622292838.1838276,"logger":"tls.issuance.acme.acme_client","msg":"trying to solve challenge","identifier":"wp-test.dev-art.domain.com","challenge_type":"tls-alpn-01","ca":"https://acme-v02.api.letsencrypt.org/directory"}
{"level":"info","ts":1622292838.1849308,"logger":"caddy.storage.s3","msg":"Store: test_folder/acme/acme-v02.api.letsencrypt.org-directory/challenge_tokens/wp-test.dev-art.domain.com.json, 350 bytes"}
{"level":"info","ts":1622292838.5495484,"logger":"tls","msg":"served key authentication certificate","server_name":"wp-test.dev-art.domain.com","challenge":"tls-alpn-01","remote":"3.120.130.29:36250","distributed":false}
{"level":"info","ts":1622292838.7121632,"logger":"tls","msg":"served key authentication certificate","server_name":"wp-test.dev-art.domain.com","challenge":"tls-alpn-01","remote":"66.133.109.36:23904","distributed":false}
{"level":"info","ts":1622292838.7668262,"logger":"tls","msg":"served key authentication certificate","server_name":"wp-test.dev-art.domain.com","challenge":"tls-alpn-01","remote":"54.189.22.122:31250","distributed":false}
{"level":"info","ts":1622292838.8055172,"logger":"tls","msg":"served key authentication certificate","server_name":"wp-test.dev-art.domain.com","challenge":"tls-alpn-01","remote":"18.116.86.117:13532","distributed":false}
{"level":"info","ts":1622292839.3147287,"logger":"caddy.storage.s3","msg":"Delete: test_folder/acme/acme-v02.api.letsencrypt.org-directory/challenge_tokens/wp-test.dev-art.domain.com.json"}
{"level":"info","ts":1622292839.363895,"logger":"tls.issuance.acme.acme_client","msg":"validations succeeded; finalizing order","order":"https://acme-v02.api.letsencrypt.org/acme/order/125255113/10033391100"}
{"level":"info","ts":1622292840.3172622,"logger":"tls.issuance.acme.acme_client","msg":"successfully downloaded available certificate chains","count":2,"first_url":"https://acme-v02.api.letsencrypt.org/acme/cert/0306c525ab0978c5477ce58df8d3020bb67e"}
{"level":"info","ts":1622292840.320495,"logger":"caddy.storage.s3","msg":"Store: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.crt, 5357 bytes"}
{"level":"info","ts":1622292840.372044,"logger":"caddy.storage.s3","msg":"Store: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.key, 227 bytes"}
{"level":"info","ts":1622292840.4263725,"logger":"caddy.storage.s3","msg":"Store: test_folder/certificates/acme-v02.api.letsencrypt.org-directory/wp-test.dev-art.domain.com/wp-test.dev-art.domain.com.json, 168 bytes"}
{"level":"info","ts":1622292840.496127,"logger":"tls.obtain","msg":"certificate obtained successfully","identifier":"wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292840.4964314,"logger":"tls.obtain","msg":"releasing lock","identifier":"wp-test.dev-art.domain.com"}
{"level":"info","ts":1622292840.496462,"logger":"caddy.storage.s3","msg":"Release lock: issue_cert_wp-test.dev-art.domain.com"}
2021/05/29 12:54:00 panic: certificate worker: runtime error: invalid memory address or nil pointer dereference
goroutine 53 [running]:
github.com/caddyserver/certmagic.(*jobManager).worker.func1()
  github.com/caddyserver/certmagic@v0.13.1/async.go:58 +0xa5
panic(0x179c840, 0x2a18990)
  runtime/panic.go:965 +0x1b9
github.com/bsm/redislock.(*Lock).Release(0x0, 0xc000ad5000, 0x36)
  github.com/bsm/redislock@v0.5.0/redislock.go:174 +0x40
github.com/ss098/certmagic-s3.(*S3).Unlock(0xc000106fa0, 0xc000885ad0, 0x28, 0xc000168380, 0x1)
  github.com/ss098/certmagic-s3@v0.0.0-20200912152559-4ebbdf3abccf/s3.go:115 +0x137
github.com/caddyserver/certmagic.releaseLock(0x1fab858, 0xc000106fa0, 0xc000885ad0, 0x28, 0x1, 0x1)
  github.com/caddyserver/certmagic@v0.13.1/storage.go:246 +0x49
github.com/caddyserver/certmagic.(*Config).obtainCert.func1(0xc000aabce0, 0xc000049f80, 0x1d, 0xc000107360, 0xc000885ad0, 0x28)
  github.com/caddyserver/certmagic@v0.13.1/config.go:448 +0x85
github.com/caddyserver/certmagic.(*Config).obtainCert(0xc000107360, 0x1f9c370, 0xc00053ea80, 0xc000049f80, 0x1d, 0xc000753600, 0x0, 0x0)
  github.com/caddyserver/certmagic@v0.13.1/config.go:532 +0x326
github.com/caddyserver/certmagic.(*Config).ObtainCert(0xc000107360, 0x1f9c370, 0xc00053ea80, 0xc000049f80, 0x1d, 0x100000000000000, 0x7ff88429bf40, 0x0)
  github.com/caddyserver/certmagic@v0.13.1/config.go:428 +0x135
github.com/caddyserver/certmagic.(*Config).manageOne.func1(0x0, 0x0)
  github.com/caddyserver/certmagic@v0.13.1/config.go:329 +0x95
github.com/caddyserver/certmagic.(*jobManager).worker(0x2a22720)
  github.com/caddyserver/certmagic@v0.13.1/async.go:73 +0x103
created by github.com/caddyserver/certmagic.(*jobManager).Submit
  github.com/caddyserver/certmagic@v0.13.1/async.go:50 +0x12d

Sorry, because of NDA, main domain was changed to domain.com, it was containing company name. Other parts/structure as it is

5. What I already tried:

  • tested several Caddy versions
  • tested several Redis versions available at AWS (4.0.10 and 5.0.6 )
  • drop all all available security credentials related to redis

6. Links to relevant resources:

Please open an issue on the s3 plugin’s GitHub repo for this.

ok. thank you

Yeah, agreed that’ll be the best way to get an answer. Of course we allow discussion (and bug reports, etc.) of plugins here, since this forum is for all things related to Caddy, but you’ll likely get the developers’ attention over on their GitHub repo.

Love git, but posted my question/report here because forum always shows nice activity at any questions.

Issue was already posted to certmagic-s3 git repo

ps.
Just in case somebody hit the same issue or just interested in how the thing goes, here is the Link

2 Likes

UPD:

Looks like Issue is fixed. At least it is working fine with Caddy 2.3.0, 2.4.0, 2.4.1 and Redis 5.0.6

2 Likes

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