Certificate request failed: Error: Didn't finalize order: Unhandled status '403'

[Tottback]

Multihost with Master (Raspi3 node 18.17.1 ) and Slave (Raspi4 node 16.20.0), Host both 5.0.12 Port 80 is forwarded to the Raspi4 with ACME-0.1.0 instance. letsencrypt works before well in admin-instance.

When I activate the ACME-Adapter I get the following error code:

"Certificate request for xxx.hopto.org failed: Error: Didn't finalize order: Unhandled status '403'. This is not one of the known statuses... Requested: 'xxx.hopto.org' Validated: '' { "type": "urn:ietf:params:acme:error:orderNotReady", "detail": "Order's status (\"valid\") is not acceptable for finalization", "status": 403 } Please open an issue at https://git.rootprojects.org/root/acme.js

On https://git.rootprojects.org/root/acme.js it seems there is no activity.

[njdsih]

Hello, same for me. But Single iobroker Host. Letsencrypt works before well in web-instance. Now after Update need to use ACME. Same Error Code than Tottback. I'm using IPv6 only. Port 443 and 80 is forwarded to iobroker Host.

[mcm1957]

@Tottback @njdsih Please add all involved versions

adapter: admin: js-controller: node: O/S:

@raintonr Any idea whats going wrong?

[njdsih]

adapter: acme 0.1.0 admin: 6.10.1 js-controller: 5.0.12 node: v18.17.1 O/S: Ubuntu 22.04.3 LTS

Am Sa., 30. Sept. 2023 um 15:17 Uhr schrieb Martin M. < @.***>:

@Tottback https://github.com/Tottback @njdsih https://github.com/njdsih Please add all involved versions

adapter: admin: js-controller: node: O/S:

— Reply to this email directly, view it on GitHub https://github.com/iobroker-community-adapters/ioBroker.acme/issues/49#issuecomment-1741764852, or unsubscribe https://github.com/notifications/unsubscribe-auth/A2MIAOAIPM37GT3EUOH4MUDX5ALVZANCNFSM6AAAAAA5CCKEMM . You are receiving this because you were mentioned.Message ID: @.*** com>

[raintonr]

Assuming you are using HTTP challenge.

Is http://xxx.hopto.org/ reachable from the public internet? And forwarded to the port configured in ACME?

[Tottback]

Yes the xxx.hoptp.org ist reachable by Internet for sure. And the Port 80 is forwarded to ACME. There is a Connection to letsencrypt and the failure Message comes from ACME from my understanding. I tried also on raspi3 and when I dont forward the Port 80 to this raspi I get a "No Response" Error, as expected.

[raintonr]

Ok. Please run in debug and let us know the result.

You should see messages like challenge server starting, challenge request, etc.

[Tottback]

OK, here it is:

2023-10-04 21:39:50.217 - info: host.Raspi4 "system.adapter.acme.0" disabled 2023-10-04 21:39:50.218 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=false) 2023-10-04 21:39:50.229 - debug: acme.0 (9784) Init http-01 challenge server 2023-10-04 21:39:50.237 - debug: acme.0 (9784) Using URL: https://acme-staging-v02.api.letsencrypt.org/directory 2023-10-04 21:39:51.360 - debug: acme.0 (9784) Loaded existing ACME account: {"_id":"acme.0.account","type":"meta","common":{"name":"account","type":"json","role":"json"},"native":{"full":{"key":{"kty":"EC","crv":"P-256","x":"Dy2pAiM4Y6RvsaWDiH5ccJ6wCrhIjFrBEwP4nfumtnc","y":"MkjgKRJKFHvubFqBZEwrzjUnNZ4LrvRj3FXZ-4hKoeo","kid":"https://acme-staging-v02.api.letsencrypt.org/acme/acct/119007074"},"contact":["mailto:xxx.yyy@abc.de"],"initialIp":"93.244.148.226","createdAt":"2023-09-19T16:45:57.208054823Z","status":"valid"},"key":{"kty":"EC","crv":"P-256","d":"R3CXyakbpMF7mYTtg4pjVGSKLv_abZ9Kvu_wD4KMy8w","x":"Dy2pAiM4Y6RvsaWDiH5ccJ6wCrhIjFrBEwP4nfumtnc","y":"MkjgKRJKFHvubFqBZEwrzjUnNZ4LrvRj3FXZ-4hKoeo","kid":"2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI"}},"from":"system.adapter.acme.0","ts":1696448389642,"acl":{"object":1636,"owner":"system.user.admin","ownerGroup":"system.group.administrator"},"user":"system.user.admin"} 2023-10-04 21:39:51.365 - debug: acme.0 (9784) Collection: {"id":"yyy","commonName":"xxx.hopto.org","altNames":""} 2023-10-04 21:39:51.367 - debug: acme.0 (9784) domains: ["xxx.hopto.org"] 2023-10-04 21:39:51.379 - info: acme.0 (9784) Collection yyy does not exist - will create 2023-10-04 21:39:56.101 - debug: acme.0 (9784) init: {"type":"*"} 2023-10-04 21:39:56.120 - debug: acme.0 (9784) _set: {"challenge":{"identifier":{"type":"dns","value":"xxx.hopto.org"},"challenges":[{"type":"http-01","status":"pending","url":"https://acme-staging-v02.example.com/0","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-0"},{"type":"dns-01","status":"pending","url":"https://acme-staging-v02.example.com/1","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-1","_wildcard":true}],"expires":"2023-10-04T19:40:56.114Z","type":"http-01","status":"pending","url":"https://acme-staging-v02.example.com/0","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-0","hostname":"xxx.hopto.org","altname":"xxx.hopto.org","thumbprint":"2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","keyAuthorization":"test-07fcc60e819ae721fd9c9f3c60901ac0-0.2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","challengeUrl":"http://xxx.hopto.org/.well-known/acme-challenge/test-07fcc60e819ae721fd9c9f3c60901ac0-0"}} 2023-10-04 21:39:56.122 - debug: acme.0 (9784) Added test-07fcc60e819ae721fd9c9f3c60901ac0-0 - DB now contains: 1 2023-10-04 21:39:56.134 - info: acme.0 (9784) challengeServer listening on 0.0.0.0 port 80 2023-10-04 21:40:01.203 - debug: acme.0 (9784) challengeServer request: /.well-known/acme-challenge/test-07fcc60e819ae721fd9c9f3c60901ac0-0 2023-10-04 21:40:01.205 - debug: acme.0 (9784) Got challenge for test-07fcc60e819ae721fd9c9f3c60901ac0-0 2023-10-04 21:40:01.221 - debug: acme.0 (9784) remove: {"challenge":{"identifier":{"type":"dns","value":"xxx.hopto.org"},"challenges":[{"type":"http-01","status":"pending","url":"https://acme-staging-v02.example.com/0","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-0"},{"type":"dns-01","status":"pending","url":"https://acme-staging-v02.example.com/1","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-1","_wildcard":true}],"expires":"2023-10-04T19:40:56.114Z","type":"http-01","status":"pending","url":"https://acme-staging-v02.example.com/0","token":"test-07fcc60e819ae721fd9c9f3c60901ac0-0","hostname":"xxx.hopto.org","altname":"xxx.hopto.org","thumbprint":"2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","keyAuthorization":"test-07fcc60e819ae721fd9c9f3c60901ac0-0.2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","challengeUrl":"http://xxx.hopto.org/.well-known/acme-challenge/test-07fcc60e819ae721fd9c9f3c60901ac0-0"}} 2023-10-04 21:40:01.222 - debug: acme.0 (9784) DB now contains: 0 2023-10-04 21:40:02.241 - debug: acme.0 (9784) ACME: certificate_order: [object Object] 2023-10-04 21:40:11.103 - debug: acme.0 (9784) ACME: challenge_status: [object Object] 2023-10-04 21:40:11.104 - debug: acme.0 (9784) remove: {"challenge":{"identifier":{"type":"dns","value":"xxx.hopto.org"},"status":"valid","expires":"2023-10-19T16:51:27Z","challenges":[{"type":"http-01","status":"valid","url":"https://acme-staging-v02.api.letsencrypt.org/acme/chall-v3/8384334344/BEK_1w","token":"I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g","validationRecord":[{"url":"http://xxx.hopto.org/.well-known/acme-challenge/I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g","hostname":"xxx.hopto.org","port":"80","addressesResolved":["93.244.148.226"],"addressUsed":"93.244.148.226"}],"validated":"2023-09-19T16:51:27Z"}],"type":"http-01","url":"https://acme-staging-v02.api.letsencrypt.org/acme/chall-v3/8384334344/BEK_1w","token":"I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g","validationRecord":[{"url":"http://xxx.hopto.org/.well-known/acme-challenge/I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g","hostname":"xxx.hopto.org","port":"80","addressesResolved":["93.244.148.226"],"addressUsed":"93.244.148.226"}],"validated":"2023-09-19T16:51:27Z","hostname":"xxx.hopto.org","altname":"xxx.hopto.org","thumbprint":"2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","keyAuthorization":"I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g.2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI","challengeUrl":"http://xxx.hopto.org/.well-known/acme-challenge/I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g"}} 2023-10-04 21:40:11.107 - debug: acme.0 (9784) DB now contains: 0 2023-10-04 21:40:12.417 - debug: acme.0 (9784) ACME: certificate_status: [object Object] 2023-10-04 21:40:14.620 - debug: acme.0 (9784) ACME: certificate_status: [object Object] 2023-10-04 21:40:14.624 - error: acme.0 (9784) Certificate request for yyy (xxx.hopto.org) failed: Error: Didn't finalize order: Unhandled status '403'. This is not one of the known statuses... Requested: 'xxx.hopto.org' Validated: '' { "type": "urn:ietf:params:acme:error:orderNotReady", "detail": "Order's status (\"valid\") is not acceptable for finalization", "status": 403 } Please open an issue at https://git.rootprojects.org/root/acme.js 2023-10-04 21:40:14.626 - debug: acme.0 (9784) Done 2023-10-04 21:40:14.646 - debug: acme.0 (9784) No collections found 2023-10-04 21:40:14.705 - info: host.Raspi4 "system.adapter.acme.0" enabled 2023-10-04 21:40:14.705 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=false) 2023-10-04 21:40:14.739 - info: acme.0 (9784) Terminated (ADAPTER_REQUESTED_TERMINATION): Processing complete 2023-10-04 21:40:15.599 - debug: acme.0 (9784) Shutdown... 2023-10-04 21:40:16.114 - info: host.Raspi4 instance system.adapter.acme.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION) 2023-10-04 21:40:18.284 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 24 * * * 2023-10-04 21:40:18.331 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 10725 2023-10-04 21:40:24.272 - debug: acme.0 (10725) Redis Objects: Use Redis connection: 192.168.178.199:9001 2023-10-04 21:40:24.436 - debug: acme.0 (10725) Objects client ready ... initialize now 2023-10-04 21:40:24.442 - debug: acme.0 (10725) Objects create System PubSub Client 2023-10-04 21:40:24.446 - debug: acme.0 (10725) Objects create User PubSub Client 2023-10-04 21:40:24.644 - debug: acme.0 (10725) Objects client initialize lua scripts 2023-10-04 21:40:24.667 - debug: acme.0 (10725) Objects connected to redis: 192.168.178.199:9001 2023-10-04 21:40:24.799 - debug: acme.0 (10725) Redis States: Use Redis connection: 192.168.178.199:9000 2023-10-04 21:40:24.861 - debug: acme.0 (10725) States create System PubSub Client 2023-10-04 21:40:24.865 - debug: acme.0 (10725) States create User PubSub Client 2023-10-04 21:40:25.004 - debug: acme.0 (10725) States connected to redis: 192.168.178.199:9000 2023-10-04 21:40:25.644 - info: acme.0 (10725) starting. Version 0.1.0 in /opt/iobroker/node_modules/iobroker.acme, node: v16.20.0, js-controller: 5.0.12 2023-10-04 21:40:25.724 - debug: acme.0 (10725) config: {"maintainerEmail":"xxx.yyy@abc.de","useStaging":true,"http01Active":true,"port":80,"bind":"0.0.0.0","dns01Active":false,"dns01Module":"","dns01OapiUser":"","dns01OapiKey":"","dns01OclientIp":"","dns01Okey":"","dns01Osecret":"","dns01Otoken":"","dns01Ousername":"","dns01OverifyPropagation":false,"dns01PpropagationDelay":120000,"collections":[{"id":"yyy","commonName":"xxx.hopto.org","altNames":""}]} 2023-10-04 21:40:26.217 - info: host.Raspi4 "system.adapter.acme.0" disabled 2023-10-04 21:40:26.229 - debug: acme.0 (10725) Init http-01 challenge server 2023-10-04 21:40:26.218 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true) 2023-10-04 21:40:26.237 - debug: acme.0 (10725) Using URL: https://acme-staging-v02.api.letsencrypt.org/directory 2023-10-04 21:40:27.455 - debug: acme.0 (10725) Loaded existing ACME account: {"_id":"acme.0.account","type":"meta","common":{"name":"account","type":"json","role":"json"},"native":{"full":{"key":{"kty":"EC","crv":"P-256","x":"Dy2pAiM4Y6RvsaWDiH5ccJ6wCrhIjFrBEwP4nfumtnc","y":"MkjgKRJKFHvubFqBZEwrzjUnNZ4LrvRj3FXZ-4hKoeo","kid":"https://acme-staging-v02.api.letsencrypt.org/acme/acct/119007074"},"contact":["mailto:xxx.yyy@abc.de"],"initialIp":"93.244.148.226","createdAt":"2023-09-19T16:45:57.208054823Z","status":"valid"},"key":{"kty":"EC","crv":"P-256","d":"R3CXyakbpMF7mYTtg4pjVGSKLv_abZ9Kvu_wD4KMy8w","x":"Dy2pAiM4Y6RvsaWDiH5ccJ6wCrhIjFrBEwP4nfumtnc","y":"MkjgKRJKFHvubFqBZEwrzjUnNZ4LrvRj3FXZ-4hKoeo","kid":"2KyY8iAgg9Fmh0B0yWho3uxsiqBp4bhM5HxXbndubvI"}},"from":"system.adapter.acme.0","ts":1696448425627,"acl":{"object":1636,"owner":"system.user.admin","ownerGroup":"system.group.administrator"},"user":"system.user.admin"}

[raintonr]

Certificate request for yyy (xxx.hopto.org) failed: Error: Didn't finalize order: Unhandled status '403'

At first glance I believe this is saying when the certificate issuer tried to establish validity of the order by hitting the challenge URL (http://xxx.hopto.org/.well-known/acme-challenge/I77c82jOZmKxziisxg3PpU3P2ZL2L3nIzbE840S4s8g) a 403 error came back. Which seems to imply there's something wrong with your firewall or port forwarding.

[Tottback]

Port Forwarding in Router was not changed (TCP 80 -> Raspi4: 80) and worked well with LetsEncrypt-Handling in admin-instance. before,

Error 403: Forbidden – you don't have permission to access this resource is an HTTP status code that occurs when the web server understands the request but can't provide additional access

[raintonr]

I know what 403 means. When I get a chance will look in the code but I think the challenge server should be logging an incoming request and if that doesn't happen the request from certificate issuer can't be getting to the challenge server.

[Tottback]

Thanks, I didn't know 403 in details, therefore this was just for my documentation ;-) I tried with IP4 and IP6 access in ACME-instance, but see no difference. Should I try to use different access data ?

[raintonr]

Looking at the code/log more (and you should note that this would be much easier if your log was formatted correctly)... seems that challenge request is coming in correctly and being responded to. So error with issuer?

BTW, have you got both DNS-01 and HTTP-01 turned on? Not sure why 'dns-01' is being mentioned in the log or if having both challenge methods enabled works. If DNS-01 is also on you could try disabling it?

[Tottback]

Thanks for analyzing. I have only HTTP activated. I've copied the log to notepad++ for anomyzing. Seems the CRs get lost by that somehow, sorry.

[Tottback]

Now I have a different issue: I can't start the ACME adapter anymore because "already running". Already re-installed ACME and restarted IOB without change. Sorry for mixing up the issues here.

2023-10-06 18:16:58.175 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 24 * * *
2023-10-06 18:16:58.231 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 28609
2023-10-06 18:17:04.577 - error: acme.0 (28609) acme.0 already running
2023-10-06 18:17:04.585 - warn: acme.0 (28609) Terminated (ADAPTER_ALREADY_RUNNING): Without reason
2023-10-06 18:17:05.499 - error: host.Raspi4 instance system.adapter.acme.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
2023-10-06 18:17:59.348 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=false)
2023-10-06 18:18:02.927 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 24 * * *
2023-10-06 18:18:03.003 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 30485
2023-10-06 18:18:09.607 - error: acme.0 (30485) acme.0 already running
2023-10-06 18:18:09.616 - warn: acme.0 (30485) Terminated (ADAPTER_ALREADY_RUNNING): Without reason
2023-10-06 18:18:10.561 - error: host.Raspi4 instance system.adapter.acme.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
2023-10-06 18:18:12.154 - info: host.Raspi4 instance system.adapter.solarmanpv.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
2023-10-06 18:18:30.223 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=false)
2023-10-06 18:18:33.618 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 24 * * *
2023-10-06 18:18:33.657 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 31272
2023-10-06 18:18:40.119 - error: acme.0 (31272) acme.0 already running
2023-10-06 18:18:40.129 - warn: acme.0 (31272) Terminated (ADAPTER_ALREADY_RUNNING): Without reason
2023-10-06 18:18:41.071 - error: host.Raspi4 instance system.adapter.acme.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)

[raintonr]

Now I have a different issue: I can't start the ACME adapter anymore because "already running". Already re-installed ACME and restarted IOB without change. Sorry for mixing up the issues here.

Could be related to #43?

[Tottback]

Seems not to be similar: "ADAPTER_ALREADY_RUNNING" is not mentioned there. Error comes from host not acme-Instance ?! Changed the cronjob from 24 to 23 without change

host.Raspi4 | 2023-10-09 08:07:29.712 | error | instance system.adapter.acme.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
host.Raspi4 | 2023-10-09 08:07:22.329 | info | instance system.adapter.acme.0 started with pid 9119
host.Raspi4 | 2023-10-09 08:07:22.288 | info | instance scheduled system.adapter.acme.0 0 23 * * *
host.Raspi4 | 2023-10-09 08:07:18.710 | info | stopInstance system.adapter.acme.0 (force=false, process=false)
host.Raspi4 | 2023-10-09 08:06:28.781 | error | instance system.adapter.acme.0 terminated with code 7 (ADAPTER_ALREADY_RUNNING)
host.Raspi4 | 2023-10-09 08:06:21.117 | info | instance system.adapter.acme.0 started with pid 7547
host.Raspi4 | 2023-10-09 08:06:21.080 | info | instance scheduled system.adapter.acme.0 0 24 * * *
host.Raspi4 | 2023-10-09 08:06:17.649 | info | stopInstance system.adapter.acme.0 (force=false, process=false)

[Tottback]

Got that 2nd issue solved: I had an acme-instance running on the raspi3, alltough it was shown as not active in IOB. I tried acme-instance running on Raspi3 (master) and Raspi4 (slave) with same result, by that this instance survives somehow. I can now start acme again, but still get that failure also with other DNS

2023-10-09 13:20:55.847 - info: host.Raspi4 "system.adapter.acme.0" enabled
2023-10-09 13:20:55.849 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=false)
2023-10-09 13:20:59.302 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 22 * * *
2023-10-09 13:20:59.340 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 3747
2023-10-09 13:21:06.629 - info: acme.0 (3747) starting. Version 0.1.0 in /opt/iobroker/node_modules/iobroker.acme, node: v16.20.0, js-controller: 5.0.12
2023-10-09 13:21:07.194 - info: host.Raspi4 "system.adapter.acme.0" disabled
2023-10-09 13:21:07.195 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true)
2023-10-09 13:21:07.198 - info: host.Raspi4 stopInstance canceled schedule system.adapter.acme.0
2023-10-09 13:21:08.289 - warn: acme.0 (3747) Saved account does not match maintainer email, will recreate.
2023-10-09 13:21:08.292 - info: acme.0 (3747) Registering new ACME account...
2023-10-09 13:21:09.641 - info: acme.0 (3747) Collection Test does not exist - will create
2023-10-09 13:21:14.566 - info: acme.0 (3747) challengeServer listening on 0.0.0.0 port 80
2023-10-09 13:21:31.557 - error: acme.0 (3747) Certificate request for Test (yyy.zapto.org) failed: Error: Didn't finalize order: Unhandled status '403'. This is not one of the known statuses...
Requested: 'yyy.zapto.org'
Validated: ''
{
"type": "urn:ietf:params:acme:error:orderNotReady",
"detail": "Order's status (\"valid\") is not acceptable for finalization",
"status": 403
}
Please open an issue at https://git.rootprojects.org/root/acme.js
2023-10-09 13:21:31.582 - info: host.Raspi4 "system.adapter.acme.0" enabled

[Tottback]

I tried again after some minor adapter updates. Now it works suddenly, I get a certificate and the collection is available.

Status der Sammlungen ID Status Domänen Testumgebung Läuft ab
xxx OK xxxx.hopto.org 8.1.2024, 18:40:56

But now the adapter stuck in a loop and fill the log: I had to stop it manual. (see log)

And to be honest I have no clue how to use the certificates in the Web-instance. I created certifcate entries in the system settings and entered the certificates data from the log. I used this entries in the web-instace and this works, the certificate is accepted as valid. But this could not be the intended way, for sure.

2023-10-20 18:13:44.120 - info: host.Raspi4 "system.adapter.acme.0" enabled
2023-10-20 18:13:44.121 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true)
2023-10-20 18:13:44.133 - info: acme.0 (12625) Terminated (ADAPTER_REQUESTED_TERMINATION): Processing complete
2023-10-20 18:13:44.780 - debug: acme.0 (12625) Shutdown...
2023-10-20 18:13:45.213 - info: host.Raspi4 instance system.adapter.acme.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
2023-10-20 18:13:47.546 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 22 * * *
2023-10-20 18:13:47.580 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 13072
2023-10-20 18:13:53.557 - debug: acme.0 (13072) Redis Objects: Use Redis connection: 192.168.xxx.yyy:9001
2023-10-20 18:13:53.693 - debug: acme.0 (13072) Objects client ready ... initialize now
2023-10-20 18:13:53.708 - debug: acme.0 (13072) Objects create System PubSub Client
2023-10-20 18:13:53.715 - debug: acme.0 (13072) Objects create User PubSub Client
2023-10-20 18:13:53.975 - debug: acme.0 (13072) Objects client initialize lua scripts
2023-10-20 18:13:53.996 - debug: acme.0 (13072) Objects connected to redis: 192.168.xxx.yyy:9001
2023-10-20 18:13:54.138 - debug: acme.0 (13072) Redis States: Use Redis connection: 192.168.xxx.yyy:9000
2023-10-20 18:13:54.270 - debug: acme.0 (13072) States create System PubSub Client
2023-10-20 18:13:54.273 - debug: acme.0 (13072) States create User PubSub Client
2023-10-20 18:13:54.392 - debug: acme.0 (13072) States connected to redis: 192.168.xxx.yyy:9000
2023-10-20 18:13:55.104 - info: acme.0 (13072) starting. Version 0.1.0 in /opt/iobroker/node_modules/iobroker.acme, node: v16.20.0, js-controller: 5.0.12
2023-10-20 18:13:55.248 - debug: acme.0 (13072) config: {"maintainerEmail":"xyz@abc.de","useStaging":false,"http01Active":true,"port":80,"bind":"0.0.0.0","dns01Active":false,"dns01Module":"acme-dns-01-dnsimple","dns01OapiUser":"","dns01OapiKey":"","dns01OclientIp":"","dns01Okey":"","dns01Osecret":"","dns01Otoken":"","dns01Ousername":"","dns01OverifyPropagation":false,"dns01PpropagationDelay":120000,"collections":[{"id":"TestCert","commonName":"xxx.hopto.org","altNames":""}]}
2023-10-20 18:13:55.808 - info: host.Raspi4 "system.adapter.acme.0" disabled
2023-10-20 18:13:55.809 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true)
2023-10-20 18:13:55.810 - info: host.Raspi4 stopInstance canceled schedule system.adapter.acme.0
2023-10-20 18:13:55.825 - debug: acme.0 (13072) Init http-01 challenge server
2023-10-20 18:13:55.833 - debug: acme.0 (13072) Using URL: https://acme-v02.api.letsencrypt.org/directory
2023-10-20 18:13:57.230 - debug: acme.0 (13072) Loaded existing ACME account: {"_id":"acme.0.account","type":"meta","common":{"name":"account","type":"json","role":"json"},"native":{"full":{"key":{"kty":"EC","crv":"P-256","x":"9NtKVZytQYM1CpIcrJcMp3j8BpfEDO2ms6h5-Q99DVg","y":"td0UNs8xvHXYVSCDUsijstVouw8g_yEF5_nl1wF6qqY","kid":"https://acme-staging-v02.api.letsencrypt.org/acme/acct/121249004"},"contact":["mailto:xyz@abc.de"],"initialIp":"93.245.xx.yy","createdAt":"2023-10-09T11:21:09.49813702Z","status":"valid"},"key":{"kty":"EC","crv":"P-256","d":"Ib2QJKnOMu0T6zSwQIoRMDLhLSlP7XOvHpqQ7Evlmgw","x":"9NtKVZytQYM1CpIcrJcMp3j8BpfEDO2ms6h5-Q99DVg","y":"td0UNs8xvHXYVSCDUsijstVouw8g_yEF5_nl1wF6qqY","kid":"Hn9goYdSW6lpV_u7WfUM6ENU2M_32YUGWapVX3l4UF8"}},"from":"system.adapter.acme.0","ts":1697818435068,"acl":{"object":1636,"owner":"system.user.admin","ownerGroup":"system.group.administrator"},"user":"system.user.admin"}
2023-10-20 18:13:57.244 - debug: acme.0 (13072) Collection: {"id":"TestCert","commonName":"xxx.hopto.org","altNames":""}
2023-10-20 18:13:57.251 - debug: acme.0 (13072) domains: ["xxx.hopto.org"]
2023-10-20 18:13:57.309 - debug: acme.0 (13072) Existing: TestCert: {"from":"acme.0","key":"-----BEGIN RSA PRIVATE KEY-----xxx==\n-----END RSA PRIVATE KEY-----","cert":"-----BEGIN CERTIFICATE-----yyy-----END CERTIFICATE-----\n","chain":["-----BEGIN CERTIFICATE-----zzz-----END CERTIFICATE-----\n","-----BEGIN CERTIFICATE-----aaa-----END CERTIFICATE-----\n\n-----BEGIN CERTIFICATE-----bbb-----END CERTIFICATE-----\n"],"domains":["xxx.hopto.org"],"staging":false,"tsExpires":1704735656000}
2023-10-20 18:13:58.699 - debug: acme.0 (13072) Existing cert: {"publicModulus":"yyy","notBefore":"Oct 10 17:40:57 2023 GMT","notAfter":"Jan 8 17:40:56 2024 GMT","altNames":["xxx.hopto.org"],"ocspList":["http://r3.o.lencr.org"]}
2023-10-20 18:13:58.701 - debug: acme.0 (13072) Collection TestCert certificate already looks good
2023-10-20 18:13:58.722 - debug: acme.0 (13072) existingCollectionIds: ["TestCert"]
2023-10-20 18:13:58.744 - info: host.Raspi4 "system.adapter.acme.0" enabled
2023-10-20 18:13:58.745 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true)
2023-10-20 18:13:58.761 - info: acme.0 (13072) Terminated (ADAPTER_REQUESTED_TERMINATION): Processing complete
2023-10-20 18:13:59.354 - debug: acme.0 (13072) Shutdown...
2023-10-20 18:14:00.889 - info: host.Raspi4 instance system.adapter.acme.0 terminated with code 11 (ADAPTER_REQUESTED_TERMINATION)
2023-10-20 18:14:02.148 - info: host.Raspi4 instance scheduled system.adapter.acme.0 0 22 * * *
2023-10-20 18:14:02.186 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 13528
2023-10-20 18:14:07.973 - debug: acme.0 (13528) Redis Objects: Use Redis connection: 192.168.xxx.yyy:9001
2023-10-20 18:14:08.122 - debug: acme.0 (13528) Objects client ready ... initialize now
2023-10-20 18:14:08.129 - debug: acme.0 (13528) Objects create System PubSub Client
2023-10-20 18:14:08.133 - debug: acme.0 (13528) Objects create User PubSub Client
2023-10-20 18:14:08.378 - debug: acme.0 (13528) Objects client initialize lua scripts
2023-10-20 18:14:08.397 - debug: acme.0 (13528) Objects connected to redis: 192.168.xxx.yyy:9001
2023-10-20 18:14:08.539 - debug: acme.0 (13528) Redis States: Use Redis connection: 192.168.xxx.yyy:9000
2023-10-20 18:14:08.604 - debug: acme.0 (13528) States create System PubSub Client
2023-10-20 18:14:08.608 - debug: acme.0 (13528) States create User PubSub Client
2023-10-20 18:14:08.736 - debug: acme.0 (13528) States connected to redis: 192.168.xxx.yyy:9000
2023-10-20 18:14:09.593 - info: acme.0 (13528) starting. Version 0.1.0 in /opt/iobroker/node_modules/iobroker.acme, node: v16.20.0, js-controller: 5.0.12
2023-10-20 18:14:09.681 - debug: acme.0 (13528) config: {"maintainerEmail":"xyz@abc.de","useStaging":false,"http01Active":true,"port":80,"bind":"0.0.0.0","dns01Active":false,"dns01Module":"acme-dns-01-dnsimple","dns01OapiUser":"","dns01OapiKey":"","dns01OclientIp":"","dns01Okey":"","dns01Osecret":"","dns01Otoken":"","dns01Ousername":"","dns01OverifyPropagation":false,"dns01PpropagationDelay":120000,"collections":[{"id":"TestCert","commonName":"xxx.hopto.org","altNames":""}]}
2023-10-20 18:14:10.158 - info: host.Raspi4 "system.adapter.acme.0" disabled
2023-10-20 18:14:10.159 - info: host.Raspi4 stopInstance system.adapter.acme.0 (force=false, process=true)
2023-10-20 18:14:10.160 - info: host.Raspi4 stopInstance canceled schedule system.adapter.acme.0

[raintonr]

During my tests for #43 I'm also getting this. Using staging server. Put some logging in the HTTP challenge server and it appears to be functioning correctly. Maybe this is a timing issue with the CA?

@Tottback is this now working for you? The restart loop should be fixed in main branch so would be good if you can install direct from Github and let us know.

[Tottback]

Hello, I'm trying the ACME mainline version from Github and it seems to work fine now. Thanks. ACME is only activated one time as defined by the cronjob. Remark: According to log it seems there is one shutdown too much. "warn: acme.0 (xx) Shutdown called but nothing to do"

2023-11-13 22:00:04.275 - info: host.Raspi4 instance system.adapter.acme.0 started with pid 4367
2023-11-13 22:00:10.881 - debug: acme.0 (4367) Redis Objects: Use Redis connection: 192.xx:9001
2023-11-13 22:00:11.044 - debug: acme.0 (4367) Objects client ready ... initialize now
2023-11-13 22:00:11.051 - debug: acme.0 (4367) Objects create System PubSub Client
2023-11-13 22:00:11.055 - debug: acme.0 (4367) Objects create User PubSub Client
2023-11-13 22:00:11.291 - debug: acme.0 (4367) Objects client initialize lua scripts
2023-11-13 22:00:11.316 - debug: acme.0 (4367) Objects connected to redis: 192.xx:9001
2023-11-13 22:00:11.487 - debug: acme.0 (4367) Redis States: Use Redis connection: 192.xx:9000
2023-11-13 22:00:11.551 - debug: acme.0 (4367) States create System PubSub Client
2023-11-13 22:00:11.554 - debug: acme.0 (4367) States create User PubSub Client
2023-11-13 22:00:11.697 - debug: acme.0 (4367) States connected to redis: 192.xx:9000
2023-11-13 22:00:12.402 - info: acme.0 (4367) starting. Version 0.1.0 (non-npm: iobroker-community-adapters/ioBroker.acme) in /opt/iobroker/node_modules/iobroker.acme, node: v18.17.1, js-controller: 5.0.12
2023-11-13 22:00:12.494 - debug: acme.0 (4367) config: {"maintainerEmail":"xx@gmx.de","useStaging":false,"http01Active":true,"port":80,"bind":"0.0.0.0","dns01Active":false,"dns01Module":"acme-dns-01-dnsimple","dns01OapiUser":"","dns01OapiKey":"","dns01OclientIp":"","dns01Okey":"","dns01Osecret":"","dns01Otoken":"","dns01Ousername":"","dns01OverifyPropagation":false,"dns01PpropagationDelay":120000,"collections":[{"id":"xx","commonName":"xx.hopto.org","altNames":""}]}
2023-11-13 22:00:12.498 - debug: acme.0 (4367) Init http-01 challenge server
2023-11-13 22:00:12.507 - debug: acme.0 (4367) Using URL: https://acme-v02.api.letsencrypt.org/directory
2023-11-13 22:00:15.129 - debug: acme.0 (4367) Loaded existing ACME account: {"_id":"acme.0.account","type":"meta","common":{"name":"account","type":"json","role":"json"},"native":{"full":{"key":{"kty":"EC","crv":"P-256","x":"9NtKVZytQYM1CpIcrJcMp3j8BpfEDO2ms6h5-Q99DVg","y":"td0UNs8xvHXYVSCDUsijstVouw8g_yEF5_nl1wF6qqY","kid":"https://acme-staging-v02.api.letsencrypt.org/acme/acct/121249004"},"contact":["mailto:xx@gmx.de"],"initialIp":"xx","createdAt":"2023-10-09T11:21:09.49813702Z","status":"valid"},"key":{"kty":"EC","crv":"P-256","d":"Ib2QJKnOMu0T6zSwQIoRMDLhLSlP7XOvHpqQ7Evlmgw","x":"9NtKVZytQYM1CpIcrJcMp3j8BpfEDO2ms6h5-Q99DVg","y":"td0UNs8xvHXYVSCDUsijstVouw8g_yEF5_nl1wF6qqY","kid":"Hn9goYdSW6lpV_u7WfUM6ENU2M_32YUGWapVX3l4UF8"}},"from":"system.adapter.acme.0","ts":1699909212383,"acl":{"object":1636,"owner":"system.user.admin","ownerGroup":"system.group.administrator"},"user":"system.user.admin"}
2023-11-13 22:00:15.133 - debug: acme.0 (4367) Collection: {"id":"xx","commonName":"xx.hopto.org","altNames":""}
2023-11-13 22:00:15.135 - debug: acme.0 (4367) domains: ["xx.hopto.org"]
2023-11-13 22:00:15.151 - debug: acme.0 (4367) Existing: xx: {"from":"acme.0","key":"-----BEGIN RSA PRIVATE KEY-----\yy.hopto.org"],"staging":false,"tsExpires":1704735656000}
2023-11-13 22:00:16.581 - debug: acme.0 (4367) Existing cert: {"publicModulus":"xx","publicExponent":"010001","subject":{"commonName":"yy.hopto.org"},"issuer":{"commonName":"R3","countryName":"US","organizationName":"Let's Encrypt"},"serial":"0477A0A56850B9F01242721200CC036FBD01","notBefore":"Oct 10 17:40:57 2023 GMT","notAfter":"Jan 8 17:40:56 2024 GMT","altNames":["xx.hopto.org"],"ocspList":["http://r3.o.lencr.org"]}
2023-11-13 22:00:16.583 - debug: acme.0 (4367) Collection xx certificate already looks good
2023-11-13 22:00:16.628 - debug: acme.0 (4367) existingCollectionIds: ["xx"]
2023-11-13 22:00:16.631 - debug: acme.0 (4367) Shutdown...
2023-11-13 22:00:16.632 - warn: acme.0 (4367) Shutdown called but nothing to do
2023-11-13 22:00:16.634 - debug: acme.0 (4367) No previously shutdown adapters to restart

[raintonr]

Hello, I'm trying the ACME mainline version from Github and it seems to work fine now. Thanks.

Good to know, thanks.

Remark: According to log it seems there is one shutdown too much. "warn: acme.0 (xx) Shutdown called but nothing to do"

This isn't a problem. The HTTP challenge server was initialised but as a certificate wasn't ordered on this run it didn't actually start listening on the defined port and therefore didn't need to do anything on shutdown. Expected behaviour.

[Tottback]

OK. Seems that "warn" is then maybe not the appropriate level for that message, if it's no problem and expected behavior.