Order's status ("valid") is not acceptable for finalization

Hey there,
using https://github.com/analogic/lescript as LE Client in our CMS.
Lately it’s throwing those 403 Errors from time to time:

403
{
  "type": "urn:ietf:params:acme:error:orderNotReady",
  "detail": "Order's status ("valid") is not acceptable for finalization",
  "status": 403
}

I’m not quite sure why it’s throwing it … as far as I understand the Protocoll this is thrown when I try to finalize the Order more than once - but there is only 1 call for finalization I’m firing … ?

How can I get this Status in return on the first fall fo /finalize/? Any ideas on that?
Thank you, bye from sunny Austria
Andreas

Hi @futureweb

your order must be “ready”, not valid. Wait some seconds.

Hi @JuergenAuer,
why I’m a bit puzzled (what I don’t understand) is why it’s returning VALID - isn’t valid returned AFTER the Cert has already been issued according to the RFC?

https://datatracker.ietf.org/doc/rfc8555/?include_text=1

  o  "invalid": The certificate will not be issued.  Consider this
      order process abandoned.

   o  "pending": The server does not believe that the client has
      fulfilled the requirements.  Check the "authorizations" array for
      entries that are still pending.

   o  "ready": The server agrees that the requirements have been
      fulfilled, and is awaiting finalization.  Submit a finalization
      request.

   o  "processing": The certificate is being issued.  Send a POST-as-GET
      request after the time given in the Retry-After header field of
      the response, if any.

   o  "valid": The server has issued the certificate and provisioned its
      URL to the "certificate" field of the order.  Download the
      certificate.

So valid means finalization was done already, why are you finalizing again?

Download the certificate.

@9peppe … that’s the thing … I don’t finalize a second time … it’s returned on the FIRST finalization call … that’s why I’m puzzled as I don’t expect a VALID back with a 403 Status …

Ok, help me navigate your code. Which line is throwing that error?

Hint: https://www.php.net/manual/en/function.debug-print-backtrace.php

it’s thrown in the curl() function - which is called by signedRequest() which again is called by this line …

   $finalizeResponse = $this->signedRequest($finalizeUrl, array('csr' => $csr));

Error thrown here in the curl() Func:

if ($this->lastCode >= 400 && $this->lastCode < 600) {
     throw new RuntimeException($this->lastCode."\n".$body);
}

I don’t know when you see that error.

What’s the output of your order url before that command is started?

can you show us some logs, too?

what puzzles me is that how on earth is the order getting finalized without posting a csr? is it possible your code doesn’t actually get a new order but always reuses the same?

Here is one Log-Dump of such a failed Request - it’s working through all the Challenges - when they are all valid it’s firing the Request to FINALIZE - which itself returns the 403 - Order Status VALID not acceptable …

Logger Cache: 2020-03-18 01:25:01 [info] Getting list of URLs for API
2020-03-18 01:25:02 [info] Requesting new nonce for client communication
2020-03-18 01:25:02 [info] Account already registered. Continuing.
2020-03-18 01:25:02 [info] Sending registration to letsencrypt server
2020-03-18 01:25:02 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/new-acct
2020-03-18 01:25:04 [info] Account: https://acme-v02.api.letsencrypt.org/acme/acct/*****
2020-03-18 01:25:04 [info] Starting certificate generation process for domains
2020-03-18 01:25:04 [info] Requesting challenge for apartments-fieberbrunn.tirol.in.futurecms.at, www.apartments-fieberbrunn.tirol.in.futurecms.at, apartments-fieberbrunn.tirol.ex.futurecms.at, www.apartments-fieberbrunn.tirol.ex.futurecms.at, apartments-fieberbrunn.tirol.ex.ortsinfo.at, www.apartments-fieberbrunn.tirol.ex.ortsinfo.at, apartments-fieberbrunn.tirol.dev.futurecms.at, www.apartments-fieberbrunn.tirol.dev.futurecms.at
2020-03-18 01:25:04 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/new-order
2020-03-18 01:25:05 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921202
2020-03-18 01:25:07 [info] Got challenge token for apartments-fieberbrunn.tirol.dev.futurecms.at
2020-03-18 01:25:07 [info] Token for apartments-fieberbrunn.tirol.dev.futurecms.at saved at /path/to/.well-known/acme-challenge/3ZITFad1qbIFMgVKKoYbSvSlknRoze5SwoX4UCcx53w and should be available at http://apartments-fieberbrunn.tirol.dev.futurecms.at/.well-known/acme-challenge/3ZITFad1qbIFMgVKKoYbSvSlknRoze5SwoX4UCcx53w
2020-03-18 01:25:07 [info] Sending request to challenge
2020-03-18 01:25:07 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921202/wuM2_A
2020-03-18 01:25:08 [info] Verification pending, sleeping 1s
2020-03-18 01:25:09 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921202/wuM2_A
2020-03-18 01:25:12 [info] Verification pending, sleeping 5s
2020-03-18 01:25:17 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921202/wuM2_A
2020-03-18 01:25:19 [info] Verification pending, sleeping 10s
2020-03-18 01:25:29 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921202/wuM2_A
2020-03-18 01:25:30 [info] Verification pending, sleeping 20s
2020-03-18 01:25:50 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921202/wuM2_A
2020-03-18 01:25:51 [info] Verification ended with status: valid
2020-03-18 01:25:51 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921206
2020-03-18 01:25:52 [info] Got challenge token for apartments-fieberbrunn.tirol.ex.futurecms.at
2020-03-18 01:25:52 [info] Token for apartments-fieberbrunn.tirol.ex.futurecms.at saved at /path/to/.well-known/acme-challenge/_qFn9sb3YDA4QVnXB3boPfRGJnwTfvyOKzdgeBI2cC4 and should be available at http://apartments-fieberbrunn.tirol.ex.futurecms.at/.well-known/acme-challenge/_qFn9sb3YDA4QVnXB3boPfRGJnwTfvyOKzdgeBI2cC4
2020-03-18 01:25:52 [info] Sending request to challenge
2020-03-18 01:25:52 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921206/Z4aORg
2020-03-18 01:25:53 [info] Verification pending, sleeping 1s
2020-03-18 01:25:54 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921206/Z4aORg
2020-03-18 01:25:55 [info] Verification pending, sleeping 5s
2020-03-18 01:26:00 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921206/Z4aORg
2020-03-18 01:26:01 [info] Verification pending, sleeping 10s
2020-03-18 01:26:11 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921206/Z4aORg
2020-03-18 01:26:12 [info] Verification pending, sleeping 20s
2020-03-18 01:26:32 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921206/Z4aORg
2020-03-18 01:26:33 [info] Verification ended with status: valid
2020-03-18 01:26:33 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921209
2020-03-18 01:26:34 [info] Got challenge token for apartments-fieberbrunn.tirol.ex.ortsinfo.at
2020-03-18 01:26:34 [info] Token for apartments-fieberbrunn.tirol.ex.ortsinfo.at saved at /path/to/.well-known/acme-challenge/KkDrE9mZrYcOHsN_WpPQa9si5N5puHufE8e0pIAJyIE and should be available at http://apartments-fieberbrunn.tirol.ex.ortsinfo.at/.well-known/acme-challenge/KkDrE9mZrYcOHsN_WpPQa9si5N5puHufE8e0pIAJyIE
2020-03-18 01:26:34 [info] Sending request to challenge
2020-03-18 01:26:34 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921209/NQR76Q
2020-03-18 01:26:35 [info] Verification pending, sleeping 1s
2020-03-18 01:26:36 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921209/NQR76Q
2020-03-18 01:26:37 [info] Verification pending, sleeping 5s
2020-03-18 01:26:42 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921209/NQR76Q
2020-03-18 01:26:42 [info] Verification pending, sleeping 10s
2020-03-18 01:26:53 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921209/NQR76Q
2020-03-18 01:26:53 [info] Verification pending, sleeping 20s
2020-03-18 01:27:13 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921209/NQR76Q
2020-03-18 01:27:14 [info] Verification ended with status: valid
2020-03-18 01:27:14 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921211
2020-03-18 01:27:15 [info] Got challenge token for apartments-fieberbrunn.tirol.in.futurecms.at
2020-03-18 01:27:15 [info] Token for apartments-fieberbrunn.tirol.in.futurecms.at saved at /path/to/.well-known/acme-challenge/-9NvRNz90mqx68_GkIEqW_kBsFAYtPI-7Zl17q5NOI8 and should be available at http://apartments-fieberbrunn.tirol.in.futurecms.at/.well-known/acme-challenge/-9NvRNz90mqx68_GkIEqW_kBsFAYtPI-7Zl17q5NOI8
2020-03-18 01:27:15 [info] Sending request to challenge
2020-03-18 01:27:15 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921211/cAoBnQ
2020-03-18 01:27:16 [info] Verification pending, sleeping 1s
2020-03-18 01:27:17 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921211/cAoBnQ
2020-03-18 01:27:18 [info] Verification pending, sleeping 5s
2020-03-18 01:27:23 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921211/cAoBnQ
2020-03-18 01:27:24 [info] Verification pending, sleeping 10s
2020-03-18 01:27:34 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921211/cAoBnQ
2020-03-18 01:27:35 [info] Verification pending, sleeping 20s
2020-03-18 01:27:55 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921211/cAoBnQ
2020-03-18 01:27:56 [info] Verification ended with status: valid
2020-03-18 01:27:56 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921213
2020-03-18 01:27:56 [info] Got challenge token for www.apartments-fieberbrunn.tirol.dev.futurecms.at
2020-03-18 01:27:56 [info] Token for www.apartments-fieberbrunn.tirol.dev.futurecms.at saved at /path/to/.well-known/acme-challenge/avCoFxkSAvbdHPyEfqCclRAgrxiZBTxeIfl1651_rS0 and should be available at http://www.apartments-fieberbrunn.tirol.dev.futurecms.at/.well-known/acme-challenge/avCoFxkSAvbdHPyEfqCclRAgrxiZBTxeIfl1651_rS0
2020-03-18 01:27:56 [info] Sending request to challenge
2020-03-18 01:27:56 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921213/iX_zgA
2020-03-18 01:27:57 [info] Verification pending, sleeping 1s
2020-03-18 01:27:58 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921213/iX_zgA
2020-03-18 01:27:59 [info] Verification pending, sleeping 5s
2020-03-18 01:28:04 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921213/iX_zgA
2020-03-18 01:28:05 [info] Verification pending, sleeping 10s
2020-03-18 01:28:15 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921213/iX_zgA
2020-03-18 01:28:16 [info] Verification pending, sleeping 20s
2020-03-18 01:28:36 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921213/iX_zgA
2020-03-18 01:28:37 [info] Verification ended with status: valid
2020-03-18 01:28:37 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921216
2020-03-18 01:28:38 [info] Got challenge token for www.apartments-fieberbrunn.tirol.ex.futurecms.at
2020-03-18 01:28:38 [info] Token for www.apartments-fieberbrunn.tirol.ex.futurecms.at saved at /path/to/.well-known/acme-challenge/EbuCl_o5McVwXb0pGFCZmSvYw-MnwLH6WeJgMedRF0U and should be available at http://www.apartments-fieberbrunn.tirol.ex.futurecms.at/.well-known/acme-challenge/EbuCl_o5McVwXb0pGFCZmSvYw-MnwLH6WeJgMedRF0U
2020-03-18 01:28:38 [info] Sending request to challenge
2020-03-18 01:28:38 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921216/YVYh6A
2020-03-18 01:28:39 [info] Verification pending, sleeping 1s
2020-03-18 01:28:40 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921216/YVYh6A
2020-03-18 01:28:41 [info] Verification pending, sleeping 5s
2020-03-18 01:28:46 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921216/YVYh6A
2020-03-18 01:28:47 [info] Verification pending, sleeping 10s
2020-03-18 01:28:57 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921216/YVYh6A
2020-03-18 01:28:57 [info] Verification pending, sleeping 20s
2020-03-18 01:29:17 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921216/YVYh6A
2020-03-18 01:29:18 [info] Verification ended with status: valid
2020-03-18 01:29:18 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921220
2020-03-18 01:29:19 [info] Got challenge token for www.apartments-fieberbrunn.tirol.ex.ortsinfo.at
2020-03-18 01:29:19 [info] Token for www.apartments-fieberbrunn.tirol.ex.ortsinfo.at saved at /path/to/.well-known/acme-challenge/BvoHfTbEkhYyfrZcW-jDxOSvzahX9ScvijGHRkUQbbs and should be available at http://www.apartments-fieberbrunn.tirol.ex.ortsinfo.at/.well-known/acme-challenge/BvoHfTbEkhYyfrZcW-jDxOSvzahX9ScvijGHRkUQbbs
2020-03-18 01:29:19 [info] Sending request to challenge
2020-03-18 01:29:19 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:29:20 [info] Verification pending, sleeping 1s
2020-03-18 01:29:21 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:29:22 [info] Verification pending, sleeping 5s
2020-03-18 01:29:27 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:29:28 [info] Verification pending, sleeping 10s
2020-03-18 01:29:38 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:29:39 [info] Verification pending, sleeping 20s
2020-03-18 01:29:59 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:30:00 [info] Verification ended with status: valid
2020-03-18 01:30:00 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921224
2020-03-18 01:30:00 [info] Got challenge token for www.apartments-fieberbrunn.tirol.in.futurecms.at
2020-03-18 01:30:00 [info] Token for www.apartments-fieberbrunn.tirol.in.futurecms.at saved at /path/to/.well-known/acme-challenge/M7BFni7C6Pv4UwEousPod4djVun4MVKj-ddmpa-1qeE and should be available at http://www.apartments-fieberbrunn.tirol.in.futurecms.at/.well-known/acme-challenge/M7BFni7C6Pv4UwEousPod4djVun4MVKj-ddmpa-1qeE
2020-03-18 01:30:01 [info] Sending request to challenge
2020-03-18 01:30:01 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921224/lN9RnA
2020-03-18 01:30:01 [info] Verification pending, sleeping 1s
2020-03-18 01:30:02 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921224/lN9RnA
2020-03-18 01:30:03 [info] Verification pending, sleeping 5s
2020-03-18 01:30:08 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921224/lN9RnA
2020-03-18 01:30:10 [info] Verification pending, sleeping 10s
2020-03-18 01:30:20 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921224/lN9RnA
2020-03-18 01:30:21 [info] Verification pending, sleeping 20s
2020-03-18 01:30:41 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921224/lN9RnA
2020-03-18 01:30:42 [info] Verification ended with status: valid
2020-03-18 01:30:42 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/finalize/2188868/2691206533

403
{
  "type": "urn:ietf:params:acme:error:orderNotReady",
  "detail": "Order's status (\"valid\") is not acceptable for finalization",
  "status": 403
}

#0 /path/to/includes/lescript/OISSL_ACME2_Lescript.php(583): Analogic\ACME\Client->curl('POST', 'https://acme-v0...', '{"protected":"e...')
#1 /path/to/includes/lescript/OISSL_ACME2_Lescript.php(457): Analogic\ACME\Client->post('https://acme-v0...', '{"protected":"e...')
#2 /path/to/includes/lescript/OISSL_ACME2_Lescript.php(244): Analogic\ACME\OISSL_Lescript->signedRequest('https://acme-v0...', Array)
#3 /path/to/includes/cronjobs/sslManager.php(337): Analogic\ACME\OISSL_Lescript->signDomains(Array)
#4 {main}

It looks like there’s a certificate issued:

https://acme-v02.api.letsencrypt.org/acme/order/2188868/2691206533

yes it’s issued - but the call to https://acme-v02.api.letsencrypt.org/acme/finalize/2188868/2691206533 first returns me the 403 Error which leads to Script Termination which leads to never getting this Cert …
So I try to find out WHY it’s returning the “Order’s status (“valid”) is not acceptable for finalization” Error on first call to finalize Endpoint …

I can and will add checks to the /order/ Endpoint if it’s READY - and only then sent out the finalization Call … but first I want to understand WHY this is happening …

and this puzzles me. what’s boulder signing, if you aren’t sending a csr?

what makes you think it’s not sending the CSR - of course it’s sending the CSR within the call to /finalize/ Endpoint … otherwise it wouldn’t work … :wink:
it’s working fine … on dozens of renews a day there are only 0-2 such Errors … but of course I want to get rid of them …

because that error message tells me “you sent a csr in the past, and I signed it. I am rejecting this newer one.”

is it always the same, or completely random?

mmhhhh - it’s completely random … if I trigger a renew on the same Cert a few seconds later it’s working fine …
I just added some more debug to the Logs … now I’m saving the whole “/order/” Response before sending to the “/finalize/” Endoint … let’s see what it’s returning (well - I guess it will return Status VALID - as the Error tells me … lol)

Of course I could blindly add the Loop to wait for READY … but that’s not helping me understand what excactly is happening … :wink:

as for the CSR:

$reuseCsr = false when Func is called - so no reuse CSR

$csr = $reuseCsr && is_file($domainPath . "/last.csr")?
            $this->getCsrContent($domainPath . "/last.csr") :
            $this->generateCSR($privateDomainKey, $domains);

$finalizeResponse = $this->signedRequest($finalizeUrl, array('csr' => $csr));

I really have no clue, at this point I might try fetching the order object with each action, and check at what point it changes status.

2 Likes

hehe - good i’m not alone with not seeing the Error on this … :rofl:
Will try to narrow it down with some more debug … will report back when the Error is triggered the next time with more Debug Data … thx for your help! :wink:

That log looks curious.

Two rows:

2020-03-18 01:25:04 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/new-order
2020-03-18 01:25:05 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/authz-v3/3418921202

Why isn’t there the result of the order? Looks like you use older authorizations.

Add some debug outputs of your order

https://acme-v02.api.letsencrypt.org/acme/order/2188868/2691206533

Then you see the status and you see, if there is a certificate.

And the code looks buggy.

2020-03-18 01:29:19 [info] Sending request to challenge
2020-03-18 01:29:19 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ
2020-03-18 01:29:20 [info] Verification pending, sleeping 1s
2020-03-18 01:29:21 [info] Sending signed request to https://acme-v02.api.letsencrypt.org/acme/chall-v3/3418921220/VGHXnQ

If you have created the challenges:

  • confirm all challenges
  • then wait 5 seconds.
  • Then a loop checking the first / second / third challenge

Your code:

Loop

  • confirm one challenge
  • wait until checked
  • GoTo next challenge
    EndLoop
1 Like