Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
Tottback opened this issue Sep 21, 2023 · 22 comments

Comments

@Tottback
Copy link

Tottback commented Sep 21, 2023

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
Copy link

njdsih commented Sep 27, 2023

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
Copy link
Member

mcm1957 commented Sep 30, 2023

@Tottback @njdsih
Please add all involved versions

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

@raintonr
Any idea whats going wrong?

@njdsih
Copy link

njdsih commented Sep 30, 2023 via email

@raintonr
Copy link
Contributor

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
Copy link
Author

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
Copy link
Contributor

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

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

@Tottback
Copy link
Author

Tottback commented Oct 4, 2023

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:[email protected]"],"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":"[email protected]","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:[email protected]"],"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
Copy link
Contributor

raintonr commented Oct 4, 2023

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
Copy link
Author

Tottback commented Oct 4, 2023

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
Copy link
Contributor

raintonr commented Oct 5, 2023

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
Copy link
Author

Tottback commented Oct 5, 2023

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
Copy link
Contributor

raintonr commented Oct 5, 2023

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
Copy link
Author

Tottback commented Oct 5, 2023

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
Copy link
Author

Tottback commented Oct 6, 2023

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
Copy link
Contributor

raintonr commented Oct 6, 2023

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
Copy link
Author

Tottback commented Oct 9, 2023

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
Copy link
Author

Tottback commented Oct 9, 2023

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
Copy link
Author

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":"[email protected]","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:[email protected]"],"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":"[email protected]","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
Copy link
Contributor

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
Copy link
Author

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":"[email protected]","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:[email protected]"],"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
Copy link
Contributor

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants