search

letsencrypt / pebble

A miniature version of Boulder, Pebble is a small RFC 8555 ACME test server not suited for a production certificate authority.
Mozilla Public License 2.0
640 stars 155 forks source link

How to see the verbose log of pebble? #214

Closed Neilpang closed 5 years ago

Neilpang commented 5 years ago

Is there an option to turn on verbose log of pebble ?

cpu commented 5 years ago

Hi @Neilpang - Pebble doesn't have any logging controls right now. It always logs the same level of detail. Is there something in particular you were hoping to see logged that isn't?

Neilpang commented 5 years ago

@cpu Yes, I was fixing the compatibility of acme.sh to pebble.

The standalone mode is not working for me.

my standalone server is using socat: https://github.com/Neilpang/acme.sh/blob/peb/acme.sh#L2099

I always got the following error:

[Sat Feb 23 07:19:02 UTC 2019] original='{
   "type": "http-01",
   "url": "https://xxxxxxx.xxxxxxx.com:14000/chalZ/2ryOVarTFeMBlF73XxCdqMVoOh9ZZ8wT7uFvst6ksGE",
   "token": "yQR6WtUpep2yyX4-cu2w9bI0IPSb6w8EraZ_21dkAcE",
   "status": "invalid",
   "validated": "2019-02-23T07:18:59Z",
   "error": {
      "type": "urn:ietf:params:acme:error:unauthorized",
      "detail": "The key authorization file from the server did not match this challenge \"yQR6WtUpep2yyX4-cu2w9bI0IPSb6w8EraZ_21dkAcE.9DasZ6FPiK1slzWr5toPX_VWkXBgDcmpFH55vuo30jM\" != \"\"",
      "status": 403
   }
}'

It seems that the pebble server got an empty http body, but I don't know why. I debugged a lot without any luck.

If you have a few minutes, I would appreciate if you can give me some help.

Install acme.sh branch peb

curl https://get.acme.sh | sh
source ~/.bashrc
acme.sh --upgrade -b peb

Test with pebble server;

acme.sh  --server http://xxxxxxxxxx.com:14000/dir  \
    --issue -d  mydomain.com  --standalone \
    --debug 2  --insecure

Uninstall and remove acme.sh


acme.sh --uninstall
rm -rf ~/.acme.sh
Neilpang commented 5 years ago

Hi @cpu

Do you happen to know if there is a public pebble server I can use to test ?

Thanks.

cpu commented 5 years ago

It seems that the pebble server got an empty http body, but I don't know why. I debugged a lot without any luck.

Pebble performs multiple validations with a random sleep between them, is it possible socat is returning the key authorization only once?

If you have a few minutes, I would appreciate if you can give me some help.

Very curious! I'll try and take a look this week.

Do you happen to know if there is a public pebble server I can use to test ?

Sorry, there isn't a public instance of Pebble. You should be able to get one running quickly without needing a Go environment using the latest pebble docker image.

Neilpang commented 5 years ago

is it possible socat is returning the key authorization only once?

I don't think so. socat can return multiple times. It's working well for the production Letsencrypt server.

You should be able to get one running quickly without needing

That was what I did. I'm still try debugging.

Thanks a lot.

cpu commented 5 years ago

I don't think so. socat can return multiple times. It's working well for the production Letsencrypt server.

The production Let's Encrypt servers only make one validation request. The staging Let's Encrypt servers make multiple but they are not spaced apart by random sleeps.

Thanks a lot.

Np! I think between the two of us we can figure it out :-)

Neilpang commented 5 years ago

@cpu

The staging Let's Encrypt servers make multiple but they are not spaced apart by random sleeps.

When I first test socat with the staging server, I'm sure it can return multiple times. :)

cpu commented 5 years ago

Hi @Neilpang,

So far I'm not able to reproduce the error you describe. I'm seeing a different error closer to https://github.com/Neilpang/acme.sh/issues/2074

I installed acme.sh per your instructions for the peb branch. I'm running Pebble unmodified with no special configuration, just an /etc/hosts entry to direct a test domain name to 127.0.0.1.

I'm testing on a throw-away x86_64 Ubuntu 16.04 server with BASH 4.3.48 and curl 7.47.0.

When I run:

acme.sh --server https://127.0.0.1:14000/dir --issue -d test.domain.com --standalone --debug 2 --insecure

It halts before completing account registration with the output:

[Mon Feb 25 14:18:40 UTC 2019] Registering account
[Mon Feb 25 14:18:40 UTC 2019] url='https://127.0.0.1:14000/sign-me-up'
[Mon Feb 25 14:18:40 UTC 2019] payload='{"termsOfServiceAgreed": true}'
[Mon Feb 25 14:18:40 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/127.0.0.1/account.key
[Mon Feb 25 14:18:40 UTC 2019] Get nonce with HEAD. ACME_NEW_NONCE='https://127.0.0.1:14000/nonce-plz'
[Mon Feb 25 14:18:40 UTC 2019] HEAD
[Mon Feb 25 14:18:40 UTC 2019] _post_url='https://127.0.0.1:14000/nonce-plz'
[Mon Feb 25 14:18:40 UTC 2019] body
[Mon Feb 25 14:18:40 UTC 2019] _postContentType='application/jose+json'
[Mon Feb 25 14:18:40 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.HqyhEHgS8H  -g  --insecure  '

On the Pebble side two requests were received and replied to: one GET for /dir and one HEAD for /nonce-plz. Looking at /tmp/tmp.HqyhEHgS8H while acme.sh is hung shows what seems to be a complete response to the HEAD request, but the connection appears unclosed:

== Info:   Trying 127.0.0.1...
== Info: Connected to 127.0.0.1 (127.0.0.1) port 14000 (#0)
== Info: found 148 certificates in /etc/ssl/certs/ca-certificates.crt
== Info: found 592 certificates in /etc/ssl/certs
== Info: ALPN, offering http/1.1
== Info: SSL connection using TLS1.2 / ECDHE_RSA_AES_128_GCM_SHA256
== Info:     server certificate verification SKIPPED
== Info:     server certificate status verification SKIPPED
== Info:     common name: localhost (matched)
== Info:     server certificate expiration date OK
== Info:     server certificate activation date OK
== Info:     certificate public key: RSA
== Info:     certificate version: #3
== Info:     subject: CN=localhost
== Info:     start date: Wed, 06 Dec 2017 19:42:10 GMT
== Info:     expire date: Tue, 06 Dec 2107 19:42:10 GMT
== Info:     issuer: CN=minica root ca 24e2db
== Info:     compression: NULL
== Info: ALPN, server accepted to use http/1.1
=> Send header, 185 bytes (0xb9)
0000: HEAD /nonce-plz HTTP/1.1
001a: Host: 127.0.0.1:14000
0031: User-Agent: acme.sh/2.8.1 (https://github.com/Neilpang/acme.sh)
0072: Accept: */*
007f: Content-Type: application/jose+json
00a4: Content-Length: 0
00b7: 
<= Recv header, 17 bytes (0x11)
0000: HTTP/1.1 200 OK
<= Recv header, 44 bytes (0x2c)
0000: Cache-Control: public, max-age=0, no-cache
<= Recv header, 49 bytes (0x31)
0000: Link: <https://127.0.0.1:14000/dir>;rel="index"
<= Recv header, 38 bytes (0x26)
0000: Replay-Nonce: YISn30RCQByh2GF2yohfXA
<= Recv header, 37 bytes (0x25)
0000: Date: Mon, 25 Feb 2019 14:18:40 GMT
== Info: no chunk, no close, no size. Assume close to signal end
<= Recv header, 2 bytes (0x2)
0000:

Looking at the /root/.acme.sh/http.header file while acme.sh is hung shows what seems like normal response headers for the HEAD request as well:

HTTP/1.1 200 OK
Cache-Control: public, max-age=0, no-cache
Link: <https://127.0.0.1:14000/dir>;rel="index"
Replay-Nonce: YISn30RCQByh2GF2yohfXA
Date: Mon, 25 Feb 2019 14:18:40 GMT

Do you have any ideas why curl might be hanging on its HEAD to the pebble server? I quickly skimmed the arguments in use and compared them to the curl manpage and didn't spot anything obvious.

Is it possible your client doesn't handle HTTP/2 well? The staging/prod APIs are behind a CDN and aren't using HTTP/2 but Pebble's WFE will.

If I kill the Pebble server while acme.sh is hung it immediately unhangs, spews a curl dump log, and then starts retrying to get the directory and nonce.

Neilpang commented 5 years ago

@cpu

I think it's not really hanging.

yes, I saw this http2 HEAD specific error for curl against pebble. (When I use wget instead, it has no such problem, so I think it's compatible problem with curl, I will check it later)

but don't worry, acme.sh tries HEAD first, if it fails it will try again with GET to obtain a nonce.

It should not be hanging, it just retrying. can you try again?

cpu commented 5 years ago

It should not be hanging, it just retrying. can you try again?

I'm confident its hanging. I also ran a tshark -i any -Y "tcp.port==14000" alongside the acme.sh issuance attempt and while its hung there are no packets being sent that would indicate requests being retried. There's also nothing on the server-side indicating any additional requests are received after the HEAD that is replied to.

There is however periodic TCP keep-alive and TCP keep-alive ACK's being sent while acme.sh is hung. I think that's indicative of what I'm seeing: the http/2 connection between acme.sh and Pebble is kept alive by acme.sh but not used for any further requests.

Neilpang commented 5 years ago

@cpu

can you please paste all the output log here ?

Thanks.

cpu commented 5 years ago

~/go/bin/pebble | tee /tmp/pebble.log.txt: https://gist.github.com/cpu/0bd87f713cd9caba7d06f8445447b150

acme.sh --server https://127.0.0.1:14000/dir --issue -d test.domain.com --standalone --debug 2 --insecure &> /tmp/acme.sh.log.txt - https://gist.github.com/cpu/f89fc67e781dc1b507df33c3ab55bc8f

/root/.acme.sh/http.header and /tmp/tmp.qLCyqrEfJD (mentioned in the end of acme.sh.log.txt): https://gist.github.com/cpu/bd1c4e5bc53a25d71e6b43e23ede6a91

I have to switch back to other tasks for a little while but I'll try and keep an eye on this thread. Thanks!

Neilpang commented 5 years ago

@cpu
Thanks.

I will test more and update this thread later.

Thanks.

Neilpang commented 5 years ago

@cpu

I just used tshark on my pebble server: tshark -i any -Y "tcp.port==80"

it seems that it never emitted a outgoing http request to the client side to validate the domain(http-01).

Do you have any idea why it could be possible ?

I used the default docker-compose file from pebble.

cpu commented 5 years ago

@Neilpang At a high level I think we're still chasing different problems. My attempts to reproduce this problem with acme.sh fail before an account is created and never make it to challenge validation.

I just used tshark on my pebble server: tshark -i any -Y "tcp.port==80" it seems that it never emitted a outgoing http request to the client side to validate the domain(http-01).

For the problem you're investigating I think 80 is the wrong port to be using with tshark if you're also using the default docker-compose/config file. It sets a non-standard httpPort/tlsPort to make testing against an unprivileged ACME client/webserver that can't bind low ports easier: https://github.com/letsencrypt/pebble/blob/074a53b40cb464152f9a57ffb92ef90c66344c22/test/config/pebble-config.json#L6-L7

You would either want to change httpPort to 80 and restart the Pebble container or change the webserver that acme.sh is configuring to bind to port 5002 and update your tshark to use a display filter of tcp.port == 5002.

I think the Pebble README could use a touch-up to make that information more accessible. I'll do that shortly.

Neilpang commented 5 years ago

I just edited pebble-config.json

{
  "pebble": {
    "listenAddress": "0.0.0.0:14000",
    "certificate": "test/certs/localhost/cert.pem",
    "privateKey": "test/certs/localhost/key.pem",
    "httpPort": 80,
    "tlsPort": 5001
  }
}

stopped and removed all the docker containers, and run docker-compose up -d again.

but it seems pebble server is still using 5002 port.

On my pebble server, it shows outgoing connection to 5002 port:

/usr/share/wireshark/init.lua:32: dofile has been disabled due to running Wireshark as superuser. See https://wiki.wireshark.org/CaptureSetup/CapturePrivileges for help in running Wireshark as an unprivileged user.
Capturing on 'any'
  122 2.119742091   10.30.50.2 → 10.30.50.3   TCP 76 53726 → 5002 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=247734894 TSecr=0 WS=64
  123 2.119756160   10.30.50.2 → 10.30.50.3   TCP 76 [TCP Out-Of-Order] 53726 → 5002 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=247734894 TSecr=0 WS=64
  124 2.119783548   10.30.50.3 → 10.30.50.2   TCP 76 5002 → 53726 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2753769627 TSecr=247734894 WS=64

But on my client side it never got any incoming connection on 5002 port. It's a little wired. :) still trying more.

cpu commented 5 years ago

I just edited pebble-config.json stopped and removed all the docker containers, and run docker-compose up -d again but it seems pebble server is still using 5002 port.

I've noticed this before too. It's really hard to convince docker-compose to get rid of all of its state and the config file is baked into the actual pebble image. I suspect the most likely explanation is that you didn't remove the last trace of an old image that had the old config file.

Try this:

docker-compose stop
docker-compose rm
for id in $(docker images pebble_pebble -q); do docker rmi $id; done

After that if you run docker-compose up again you should immediately see the build output for the new Pebble image being created:

Building pebble
Step 1/11 : FROM golang:1.11-alpine as builder
 ---> 57915f96905a
Step 2/11 : RUN apk --update upgrade && apk --no-cache --no-progress add git bash curl && rm -rf /var/cache/apk/*
 ---> Using cache
 ---> 82c5575997f3
....

If you still see request going to port 5002 after verifying the above I'll take another look.

Thanks @Neilpang !

Neilpang commented 5 years ago

@cpu

Good. I just made a small fix to make the container use the configs outside of the image: https://github.com/Neilpang/pebble/commit/91577830f1038630b7c932bcb883401bca33404c

I can make a PR if you like.

After this fix, I saw another issue. The --dnsserver is not working for me.

In the docker-compose file:

command: pebble -config /test/config/pebble-config.json -strict -dnsserver 10.30.50.3:8053

It uses a internal server, on my pebble server, it can not resolve my client domain, I'm not sure why. However, my question is : why not use 8.8.8.8 or 1.1.1.1 as default ?

It doesn't do any harm, but makes testing easier. what do you think ?

Neilpang commented 5 years ago

@cpu

BTW, I changed the dns server to:

command: pebble -config /test/config/pebble-config.json -dnsserver 1.1.1.1:53

it's working for me.

cpu commented 5 years ago

It uses a internal server, on my pebble server, it can not resolve my client domain, I'm not sure why. However, my question is : why not use 8.8.8.8 or 1.1.1.1 as default ?

The default docker-compose.yml starts up a pebble-challtestsrv process on the internal IP you mention in a separate container: https://github.com/letsencrypt/pebble/blob/074a53b40cb464152f9a57ffb92ef90c66344c22/docker-compose.yml#L14-L24

The intent is that you can add mock DNS entries to the pebble-challtestrsv docker container that point to anywhere else.

I don't think its appropriate to use a public recursive resolver for the default because that would require test domains fully resolve in the public internet and makes it harder to use Pebble in an isolated test environment with mock DNS.

Neilpang commented 5 years ago

@cpu

I come to the last finalize order step. First I got a processing status:

[Tue Feb 26 15:27:57 UTC 2019] original='{
   "status": "processing",
   "expires": "2019-02-27T15:27:47Z",
   "identifiers": [
      {
         "type": "dns",
         "value": "mydomina.com"
      }
   ],
   "finalize": "https://myserver.com:14000/finalize-order/HTRWVsSlmjuH6vRxY1nbzDwRHlXg9R7DRgMc-CMTlrI",
   "authorizations": [
      "https://myserver.com:14000/authZ/mLtpsI55dVZTvpuXuG4yPWhojPwGPuBaBDlC9qlCcrI"
   ]
}'

So I just wait a few seconds and retry. Then I got a wrong status error:

[Tue Feb 26 15:28:04 UTC 2019] Sign error, wrong status
[Tue Feb 26 15:28:04 UTC 2019] {
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}

It seems the order status is valid now, but not ready.

It's from this line: https://github.com/letsencrypt/pebble/blob/074a53b40cb464152f9a57ffb92ef90c66344c22/wfe/wfe.go#L1453

From the RFC: https://ietf-wg-acme.github.io/acme/draft-ietf-acme-acme.html#rfc.section.7.1.6


    pending --------------+
       |                  |
       | All authz        |
       | "valid"          |
       V                  |
     ready ---------------+
       |                  |
       | Receive          |
       | finalize         |
       | request          |
       V                  |
   processing ------------+
       |                  |
       | Certificate      | Error or
       | issued           | Authorization failure
       V                  V
     valid             invalid

I'm confused: why pebble requires ready status after already processing status ?

cpu commented 5 years ago

I'm confused: why pebble requires ready status after already processing status ?

I think this is the wrong conclusion from the output. Can you share full logs from the server and client side?

It seems the order status is valid now, but not ready.

I can't tell without logs but I'd guess the order was "pending", then you completed the relevant authorizations, then the order was "ready", then you finalized it, and as you note it was "processing". You said you "retry" at this point but there isn't anything to retry - you just need to wait for the server to issue the certificate and make the order valid. In this case it looks like you retried finalizing and it failed because the order already finished processing and "valid" != "ready". That all matches up with the RFC. You can't transition from "processing" with a client side action. It either becomes valid or invalid based on the server's handling of the finalization.

Neilpang commented 5 years ago

@cpu

Here is the log from the pebble side:

Attaching to pebble_pebble_1, pebble_challtestsrv_1
pebble_1        | Pebble 2019/02/26 15:53:35 Starting Pebble ACME server
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Creating HTTP-01 challenge server on :5002
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Creating HTTPS HTTP-01 challenge server on :5003
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Creating TCP and UDP DNS-01 challenge server on :8053
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Creating TLS-ALPN-01 challenge server on :5001
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Answering A queries with 10.30.50.3 by default
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Starting challenge servers
challtestsrv_1  | pebble-challtestsrv - 2019/02/26 15:53:36 Starting management server on :8055
pebble_1        | Pebble 2019/02/26 15:53:36 Generated new root issuer with serial 56227ae3f55b0835
pebble_1        | Pebble 2019/02/26 15:53:36 Generated new intermediate issuer with serial 74e81ab9c088e09f
pebble_1        | Pebble 2019/02/26 15:53:36 Configured to reject 5% of good nonces
pebble_1        | Pebble 2019/02/26 15:53:36 Listening on: 0.0.0.0:14000
pebble_1        | Pebble 2019/02/26 15:53:36 ACME directory available at: https://0.0.0.0:14000/dir
pebble_1        | Pebble 2019/02/26 15:53:36 Root CA certificate available at: https://0.0.0.0:14000/root
pebble_1        | Pebble 2019/02/26 15:53:53 GET /dir -> calling handler()
pebble_1        | Pebble 2019/02/26 15:53:55 HEAD /dir -> calling handler()
pebble_1        | Pebble 2019/02/26 15:53:56 HEAD /nonce-plz -> calling handler()
pebble_1        | Pebble 2019/02/26 15:53:56 POST /order-plz -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:09 GET /dir -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:11 HEAD /dir -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:12 HEAD /nonce-plz -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:12 POST /sign-me-up -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:12 There are now 1 accounts in memory
pebble_1        | Pebble 2019/02/26 15:54:13 POST /order-plz -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:13 There are now 1 authorizations in the db
pebble_1        | Pebble 2019/02/26 15:54:13 Added order "r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA" to the db
pebble_1        | Pebble 2019/02/26 15:54:13 There are now 1 orders in the db
pebble_1        | Pebble 2019/02/26 15:54:14 POST /authZ/Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:16 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:16 Pulled a task from the Tasks queue: &va.vaTask{Identifier:"mydomain.com", Challenge:(*core.Challenge)(0xc0002aae60), Account:(*core.Account)(0xc000282190)}
pebble_1        | Pebble 2019/02/26 15:54:16 Starting 3 validations.
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 0s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 1s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 0s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc
pebble_1        | Pebble 2019/02/26 15:54:17 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc
pebble_1        | Pebble 2019/02/26 15:54:19 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:22 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:22 authz Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE set VALID by completed challenge 7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE
pebble_1        | Pebble 2019/02/26 15:54:24 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:25 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:25 Order r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA is fully authorized. Processing finalization
pebble_1        | Pebble 2019/02/26 15:54:25 Issued certificate serial 037e5c3b1c2497a9 for order r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA
pebble_1        | Pebble 2019/02/26 15:54:32 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:39 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()

Here is the last part of the log from the client side:

[Tue Feb 26 15:54:16 UTC 2019] responseHeaders='HTTP/2 200 
cache-control: public, max-age=0, no-cache
content-type: application/json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
link: <https://myserver.com:14000/authZ/Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE>;rel="up"
replay-nonce: CUUZ4HJu61I1ABWjnGmrUQ
content-length: 200
date: Tue, 26 Feb 2019 15:54:16 GMT
'
[Tue Feb 26 15:54:16 UTC 2019] code='200'
[Tue Feb 26 15:54:16 UTC 2019] original='{
   "type": "http-01",
   "url": "https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE",
   "token": "C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc",
   "status": "pending"
}'
[Tue Feb 26 15:54:16 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending"}'
[Tue Feb 26 15:54:16 UTC 2019] trigger validation code: 200
[Tue Feb 26 15:54:16 UTC 2019] sleep 2 secs to verify
[Tue Feb 26 15:54:18 UTC 2019] checking
[Tue Feb 26 15:54:18 UTC 2019] url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:18 UTC 2019] payload
[Tue Feb 26 15:54:18 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:18 UTC 2019] Use _CACHED_NONCE='CUUZ4HJu61I1ABWjnGmrUQ'
[Tue Feb 26 15:54:18 UTC 2019] nonce='CUUZ4HJu61I1ABWjnGmrUQ'
[Tue Feb 26 15:54:18 UTC 2019] POST
[Tue Feb 26 15:54:18 UTC 2019] _post_url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:18 UTC 2019] body='{"protected": "eyJub25jZSI6ICJDVVVaNEhKdTYxSTFBQldqbkdtclVRIiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9jaGFsWi83WXhzWFNMTTRJOFh5U3ZIZUxWNHRoa2ZBaFN3RVdPTUhrb0haSVZMTkZFIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "", "signature": "2LGIpyNakiSsjDrWyVbHx4Gr7SVjsPGnJNZvTcuuQ98Mw1q1tYXfSMSxkF1e1T1hXm9Sc6sOP_jbr1hv8Cla46yBg9v-b8J6Hhu8wUFIeSEoYkXVyuHW0iEgO1-RDjAqGaj3OcpCjBndaE8FUwJ80lFcBs37onKC-HoN40s51bE951zmVCLDmIM_erhAh74G20QitpuqTLG80aSLmue9SUkPFcdnVFXlnLqPwb-frv_mPBjws3__5Wu0wh2NkXvYsn0Uj-bC6g7ucrmV6iNFu1O6Uhd7vgHb86jM3CDZTlEfCDHGUmdBUdRcEQQ9ENlunZQiBKAGOePaK0xSnskKyA"}'
[Tue Feb 26 15:54:18 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:18 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:18 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
[Tue Feb 26 15:54:19 UTC 2019] _ret='0'
[Tue Feb 26 15:54:19 UTC 2019] responseHeaders='HTTP/2 200 
cache-control: public, max-age=0, no-cache
content-type: application/json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
replay-nonce: E94I24AQNu7yR7I-FeUhzg
content-length: 240
date: Tue, 26 Feb 2019 15:54:19 GMT
'
[Tue Feb 26 15:54:19 UTC 2019] code='200'
[Tue Feb 26 15:54:19 UTC 2019] original='{
   "type": "http-01",
   "url": "https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE",
   "token": "C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc",
   "status": "pending",
   "validated": "2019-02-26T15:54:16Z"
}'
[Tue Feb 26 15:54:19 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:19 UTC 2019] original='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:19 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:19 UTC 2019] Pending
[Tue Feb 26 15:54:19 UTC 2019] sleep 2 secs to verify
[Tue Feb 26 15:54:21 UTC 2019] checking
[Tue Feb 26 15:54:21 UTC 2019] url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:21 UTC 2019] payload
[Tue Feb 26 15:54:21 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:21 UTC 2019] Use _CACHED_NONCE='E94I24AQNu7yR7I-FeUhzg'
[Tue Feb 26 15:54:21 UTC 2019] nonce='E94I24AQNu7yR7I-FeUhzg'
[Tue Feb 26 15:54:21 UTC 2019] POST
[Tue Feb 26 15:54:21 UTC 2019] _post_url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:21 UTC 2019] body='{"protected": "eyJub25jZSI6ICJFOTRJMjRBUU51N3lSN0ktRmVVaHpnIiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9jaGFsWi83WXhzWFNMTTRJOFh5U3ZIZUxWNHRoa2ZBaFN3RVdPTUhrb0haSVZMTkZFIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "", "signature": "kc41RraSdvRUStdRQ20hR7_xHVHQLWAM5JMEmpgFfuXWy7azL0onlMKCFzdJJk-4PRzLSJhzjTya24Kw5D9r-otXNeO-gpkJE2Ine4Kr68Japf3FL8myEhhCtNp39yL9iKhnU82bywz9VvMzR_eVSj1zh-lKrF0Hw0MA5uvbNe_bNF78nFBdKxSiMSY89GcjxuT_0OBRCL5HZ5jiVySakB1_w2sbODQZBkdTsBAAw9MHEaUZgKFeFT6Q_AsbqTzHON6cT_H6S3Csr2t-4pNRp5aB2LMFa2sIkgnvJs0zMhA6I9WSAYC21Rq5NdDbNx_UgL6gGDDvatRUwg2Ti8-Pbw"}'
[Tue Feb 26 15:54:21 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:21 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:21 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
2019/02/26 15:54:21 socat[19853] N accepting connection from AF=2 192.3.51.58:42634 on AF=2 10.170.0.2:80
2019/02/26 15:54:21 socat[19853] N forked off child process 20176
2019/02/26 15:54:21 socat[19853] N listening on AF=2 0.0.0.0:80
2019/02/26 15:54:21 socat[19853] N accepting connection from AF=2 192.3.51.58:42632 on AF=2 10.170.0.2:80
2019/02/26 15:54:21 socat[19853] N forked off child process 20177
2019/02/26 15:54:21 socat[19853] N listening on AF=2 0.0.0.0:80
2019/02/26 15:54:21 socat[19853] N accepting connection from AF=2 192.3.51.58:42630 on AF=2 10.170.0.2:80
2019/02/26 15:54:21 socat[19853] N forked off child process 20178
2019/02/26 15:54:21 socat[19853] N listening on AF=2 0.0.0.0:80
2019/02/26 15:54:21 socat[20178] N forking off child, using socket for reading and writing
2019/02/26 15:54:21 socat[20178] N forked off child process 20179
2019/02/26 15:54:21 socat[20178] N forked off child process 20179
2019/02/26 15:54:21 socat[20178] N starting data transfer loop with FDs [6,6] and [5,5]
> 2019/02/26 15:54:21.793719  length=212 from=0 to=211
GET /.well-known/acme-challenge/C_Mn2019/02/26 15:54:21 socat[20177] N forking off child, using socket for reading and writing
zUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc HTTP/1.1
Host: 2019/02/26 15:54:21 socat[20177] N forked off child process 20180
mydomain.com:80
User-Agent: LetsEncrypt-Pebble-VA (linux; am2019/02/26 15:54:21 socat[20177] N forked off child process 20180
d642019/02/26 15:54:21 socat[20177] N starting data transfer loop with FDs [6,6] and [5,5]
)
Accept: *> 2019/02/26 15:54:21.797367  length=212 from=0 to=211
/*
Accept-EncGoEdTi n/g.:w eglzli-pk
nCoonnectiownn:/ acclmoes-ec
h
allenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc HTTP/1.1
Host: mydomain.com:80
User-Agent: LetsEncrypt-Pebble-VA (linux; amd64)
Accept: */*
Accept-Encoding: gzip
Connection: close

2019/02/26 15:54:21 socat[20176] N forking off child, using socket for reading and writing
2019/02/26 15:54:21 socat[20176] N forked off child process 20181
2019/02/26 15:54:21 socat[20176] N forked off child process 20181
2019/02/26 15:54:21 socat[20176] N starting data transfer loop with FDs [6,6] and [5,5]
> 2019/02/26 15:54:21.800434  length=212 from=0 to=211
GET /.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc HTTP/1.1
Host: mydomain.com:80
User-Agent: LetsEncrypt-Pebble-VA (linux; amd64)
Accept: */*
Accept-Encoding: gzip
Connection: close

[Tue Feb 26 15:54:22 UTC 2019] _ret='0'
[Tue Feb 26 15:54:22 UTC 2019] responseHeaders='HTTP/2 200 
cache-control: public, max-age=0, no-cache
content-type: application/json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
replay-nonce: gZliDYbFtDCcY0BKwpoXwQ
content-length: 240
date: Tue, 26 Feb 2019 15:54:22 GMT
'
[Tue Feb 26 15:54:22 UTC 2019] code='200'
[Tue Feb 26 15:54:22 UTC 2019] original='{
   "type": "http-01",
   "url": "https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE",
   "token": "C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc",
   "status": "pending",
   "validated": "2019-02-26T15:54:16Z"
}'
[Tue Feb 26 15:54:22 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:22 UTC 2019] original='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:22 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"pending","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:22 UTC 2019] Pending
[Tue Feb 26 15:54:22 UTC 2019] sleep 2 secs to verify
2019/02/26 15:54:22 socat[20178] N childdied(): handling signal 17
2019/02/26 15:54:22 socat[20177] N childdied(): handling signal 17
< 2019/02/26 15:54:22.805939  length=126 from=0 to=125
HTTP/1< 2019/02/26 15:54:22.805993  length=126 from=0 to=125
.0 200 OK\r
CoHn2019/02/26 15:54:22 socat[20176] N childdied(): handling signal 17
< 2019/02/26 15:54:22.806592  length=126 from=0 to=125
HTTP/1.0 200 OK\r
Content-Length: 8tT7\reT
Pn\r/t
1-C.L0e n2g0t0_h :MO nK8z\r7U
\raC
uo\r-n
dtCye_NnM4tnm-z3LUKeapnu-g-Htd4hyv:N- 4k8mo7Z\rB
3u\rKY
pTC-T_HcM4Nnv7z-hUkyao8uZ2-BBduVYyRTNKT4NcmcN3.7KYhpry-G8He24PBvwV-GRkeKocNZWcBd.umYYxTr3TG1ceBNPz7w2hGFyeG8cH2W0BdSVm3xr3qT1ZBRDzK12N7F9cGR.HcY0HrSPG3perGPbwFGqPeTccZEWD2019/02/26 15:54:22 socat[20176] W read(5, 0x55d741445220, 8192): Connection reset by peer
d1m7x31Bz92FRGcHH0PSp3GrbqFT2019/02/26 15:54:22 socat[20176] N socket 2 to socket 1 is in error
PZcDE12019/02/26 15:54:22 socat[20176] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20177] W read(5, 0x55d741445220, 8192): Connection reset by peer
79RcHPpGb2019/02/26 15:54:22 socat[20177] N socket 2 to socket 1 is in error
FPcE2019/02/26 15:54:22 socat[20177] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20178] W read(5, 0x55d741445220, 8192): Connection reset by peer
2019/02/26 15:54:22 socat[20178] N socket 2 to socket 1 is in error
2019/02/26 15:54:22 socat[20178] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20176] N socket 1 (fd 6) is at EOF
2019/02/26 15:54:22 socat[20177] N socket 1 (fd 6) is at EOF
2019/02/26 15:54:22 socat[20177] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20177] N exiting with status 0
2019/02/26 15:54:22 socat[20176] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20176] N exiting with status 0
2019/02/26 15:54:22 socat[19853] N childdied(): handling signal 17
2019/02/26 15:54:22 socat[20178] N socket 1 (fd 6) is at EOF
2019/02/26 15:54:22 socat[20178] N socket 2 (fd 5) is at EOF
2019/02/26 15:54:22 socat[20178] N exiting with status 0
2019/02/26 15:54:22 socat[19853] N childdied(): handling signal 17
2019/02/26 15:54:22 socat[19853] N childdied(): handling signal 17
[Tue Feb 26 15:54:24 UTC 2019] checking
[Tue Feb 26 15:54:24 UTC 2019] url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:24 UTC 2019] payload
[Tue Feb 26 15:54:24 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:24 UTC 2019] Use _CACHED_NONCE='gZliDYbFtDCcY0BKwpoXwQ'
[Tue Feb 26 15:54:24 UTC 2019] nonce='gZliDYbFtDCcY0BKwpoXwQ'
[Tue Feb 26 15:54:24 UTC 2019] POST
[Tue Feb 26 15:54:24 UTC 2019] _post_url='https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE'
[Tue Feb 26 15:54:24 UTC 2019] body='{"protected": "eyJub25jZSI6ICJnWmxpRFliRnREQ2NZMEJLd3BvWHdRIiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9jaGFsWi83WXhzWFNMTTRJOFh5U3ZIZUxWNHRoa2ZBaFN3RVdPTUhrb0haSVZMTkZFIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "", "signature": "FTBGR9BOwtzTvoMXE9SlvVVv1ZFugwctySqMvKFF94TZsUFF5MvAfG9jcxJFDzYLzWJb8K5uEWjpZbzQ8-QivrJfjxuvg7CILh7BeEOihuTWZRXYsUPZZV9uPgKX7Bme6oys-HyuBV2ag9r1njZaj1nV1Zf1tcCU1UZl7SoHaslrKjzy9kPaA9wwrgsbZRxzEBryRyzNEno6PwOzrBEXwPLRlwGGmB6QJmW6LE_CUdkM_e4TtbJImPl39B7Y25G3F3n96bTTXXceFqNimvdat4dFcngpb2tER3Jl0VzfbNcFCbq0cCu0YCPS7ydt2tDVvDhhdH9-bMt7XQv9B2c_qg"}'
[Tue Feb 26 15:54:24 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:24 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:24 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
[Tue Feb 26 15:54:25 UTC 2019] _ret='0'
[Tue Feb 26 15:54:25 UTC 2019] responseHeaders='HTTP/2 200 
cache-control: public, max-age=0, no-cache
content-type: application/json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
replay-nonce: zhIq3yg84NCcG7njegd7_w
content-length: 238
date: Tue, 26 Feb 2019 15:54:24 GMT
'
[Tue Feb 26 15:54:25 UTC 2019] code='200'
[Tue Feb 26 15:54:25 UTC 2019] original='{
   "type": "http-01",
   "url": "https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE",
   "token": "C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc",
   "status": "valid",
   "validated": "2019-02-26T15:54:16Z"
}'
[Tue Feb 26 15:54:25 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"valid","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:25 UTC 2019] original='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"valid","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:25 UTC 2019] response='{"type":"http-01","url":"https://myserver.com:14000/chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE","token":"C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc","status":"valid","validated":"2019-02-26T15:54:16Z"}'
[Tue Feb 26 15:54:25 UTC 2019] Success
[Tue Feb 26 15:54:25 UTC 2019] pid='19853'
2019/02/26 15:54:25 socat[19853] N socat_signal(): handling signal 15
2019/02/26 15:54:25 socat[19853] W exiting on signal 15
2019/02/26 15:54:25 socat[19853] N socat_signal(): finishing signal 15
2019/02/26 15:54:25 socat[19853] N exit(143)
[Tue Feb 26 15:54:25 UTC 2019] Skip for removelevel:
[Tue Feb 26 15:54:25 UTC 2019] pid
[Tue Feb 26 15:54:25 UTC 2019] No need to restore nginx, skip.
[Tue Feb 26 15:54:25 UTC 2019] _clearupdns
[Tue Feb 26 15:54:25 UTC 2019] dns_entries
[Tue Feb 26 15:54:25 UTC 2019] skip dns.
[Tue Feb 26 15:54:25 UTC 2019] Verify finished, start to sign.
[Tue Feb 26 15:54:25 UTC 2019] i='2'
[Tue Feb 26 15:54:25 UTC 2019] j='15'
[Tue Feb 26 15:54:25 UTC 2019] url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:25 UTC 2019] payload='{"csr": "MIICmTCCAYECAQAwGjEYMBYGA1UEAwwPZ2NwLnBhbmdsb25nLm1lMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAqR8zwDgmULfZEHNrt3Rwo5ZXyUuSUKrL3GQaney7lMPgtMygH7QWkNgtXcVdXulMi3bGyXnDT3__0bkR_yvrkzk8Wul5o92wWbGLLxNKveWCZyjBMMa6pfouuSTAaOm8lpo6fxyHRhp4w4nUiHTNE6IeilI5S9eGlD-79jdOeHIjWSfF7ZQ2zxf2IJtzHgZEVkdYd7x1GFu8qV_-zeIUrQjyY2jhgmB6RebPp46D06PgTVZvXoyAl9ECRysOEcqxIk8M9EHR4eyCafn-mAlIUkz0lQzo2aWiSmvqWjV56bodSIlicoGPYywaUehkIhS5I4FrJJI_rn7UNxH-2a6Q-wIDAQABoDowOAYJKoZIhvcNAQkOMSswKTALBgNVHQ8EBAMCBeAwGgYDVR0RBBMwEYIPZ2NwLnBhbmdsb25nLm1lMA0GCSqGSIb3DQEBCwUAA4IBAQAcxo16pmB0VRVGsJKIrlwBybc3wVoclgZLVLyTDw2Vi6Impsl6TCARh2ZqupgBBfDdgfkYE5RKg_bL-8AdCebJoY-wGLH2IxPF6d5qDMWDqAnqfq98U4NZRXTMvd8RkON-42baaR_3gQMpfEE3RPRML3p2p24Kmr04VwV_TQn6KqVnoHEyJDcdsUbRgHM5q4Mp4ipT7uWko6nRjY51tmSyUdiE6EpOsRzQImlS0KCJSrVSk3MFw2y97Jq27Zp1pLmF3h8Mv4Yw4MkxZfnNFPz8ErV_jVxX46AnVIwgXzA3RKpjFZSAtsKmbcGFbyoiOedE-MctGTXAhWrC0nAna8CM"}'
[Tue Feb 26 15:54:25 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:25 UTC 2019] Use _CACHED_NONCE='zhIq3yg84NCcG7njegd7_w'
[Tue Feb 26 15:54:25 UTC 2019] nonce='zhIq3yg84NCcG7njegd7_w'
[Tue Feb 26 15:54:25 UTC 2019] POST
[Tue Feb 26 15:54:25 UTC 2019] _post_url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:25 UTC 2019] body='{"protected": "eyJub25jZSI6ICJ6aElxM3lnODROQ2NHN25qZWdkN193IiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9maW5hbGl6ZS1vcmRlci9yLUhPQUVTNHhWbm51Y2dvaWtCZWd0Y1VrRWZyYl9ydjlBZnpDSXl1aHZBIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "eyJjc3IiOiAiTUlJQ21UQ0NBWUVDQVFBd0dqRVlNQllHQTFVRUF3d1BaMk53TG5CaGJtZHNiMjVuTG0xbE1JSUJJakFOQmdrcWhraUc5dzBCQVFFRkFBT0NBUThBTUlJQkNnS0NBUUVBcVI4endEZ21VTGZaRUhOcnQzUndvNVpYeVV1U1VLckwzR1FhbmV5N2xNUGd0TXlnSDdRV2tOZ3RYY1ZkWHVsTWkzYkd5WG5EVDNfXzBia1JfeXZya3prOFd1bDVvOTJ3V2JHTEx4Tkt2ZVdDWnlqQk1NYTZwZm91dVNUQWFPbThscG82Znh5SFJocDR3NG5VaUhUTkU2SWVpbEk1UzllR2xELTc5amRPZUhJaldTZkY3WlEyenhmMklKdHpIZ1pFVmtkWWQ3eDFHRnU4cVZfLXplSVVyUWp5WTJqaGdtQjZSZWJQcDQ2RDA2UGdUVlp2WG95QWw5RUNSeXNPRWNxeElrOE05RUhSNGV5Q2Fmbi1tQWxJVWt6MGxRem8yYVdpU212cVdqVjU2Ym9kU0lsaWNvR1BZeXdhVWVoa0loUzVJNEZySkpJX3JuN1VOeEgtMmE2US13SURBUUFCb0Rvd09BWUpLb1pJaHZjTkFRa09NU3N3S1RBTEJnTlZIUThFQkFNQ0JlQXdHZ1lEVlIwUkJCTXdFWUlQWjJOd0xuQmhibWRzYjI1bkxtMWxNQTBHQ1NxR1NJYjNEUUVCQ3dVQUE0SUJBUUFjeG8xNnBtQjBWUlZHc0pLSXJsd0J5YmMzd1ZvY2xnWkxWTHlURHcyVmk2SW1wc2w2VENBUmgyWnF1cGdCQmZEZGdma1lFNVJLZ19iTC04QWRDZWJKb1ktd0dMSDJJeFBGNmQ1cURNV0RxQW5xZnE5OFU0TlpSWFRNdmQ4UmtPTi00MmJhYVJfM2dRTXBmRUUzUlBSTUwzcDJwMjRLbXIwNFZ3Vl9UUW42S3FWbm9IRXlKRGNkc1ViUmdITTVxNE1wNGlwVDd1V2tvNm5Salk1MXRtU3lVZGlFNkVwT3NSelFJbWxTMEtDSlNyVlNrM01GdzJ5OTdKcTI3WnAxcExtRjNoOE12NFl3NE1reFpmbk5GUHo4RXJWX2pWeFg0NkFuVkl3Z1h6QTNSS3BqRlpTQXRzS21iY0dGYnlvaU9lZEUtTWN0R1RYQWhXckMwbkFuYThDTSJ9", "signature": "uVpHkIirDF-cm4MqLvqtJFVQ3bNCurBTh-PnFcEpIsmEAOAfBh5WQZVQbMFxRqE2tAJtDtvI3O7hCcZ3v62m_LpXt3UhcNTYWEtrCECtH4thjvOoaBl53rT-HA1nTUUzCK4jYQwVELLXyGmhvm3s19qzoRnbcru1sx9uSHlkHId1hsToPl9-J4z5aMicOKQVWZkApj8ZDkvNS1Tj8q9b-Zlkw7CCjlH1s3mf7urTFskC7XdYeR1job9yVOwWZdnBHyCdzcXI2wW6yvwMKaLOX8Y7x2PKxxPHDFDt3pQvWAJJw3Oc-bdTxSnajb8ar1krkCB3AHv8pwW7mQa-Nq5Ghw"}'
[Tue Feb 26 15:54:25 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:25 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:25 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
[Tue Feb 26 15:54:25 UTC 2019] _ret='0'
[Tue Feb 26 15:54:25 UTC 2019] responseHeaders='HTTP/2 200 
cache-control: public, max-age=0, no-cache
content-type: application/json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
location: https://myserver.com:14000/my-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA
replay-nonce: W1orO1LyZ7EV_AcmZKB6Gg
content-length: 393
date: Tue, 26 Feb 2019 15:54:25 GMT
'
[Tue Feb 26 15:54:25 UTC 2019] code='200'
[Tue Feb 26 15:54:25 UTC 2019] original='{
   "status": "processing",
   "expires": "2019-02-27T15:54:13Z",
   "identifiers": [
      {
         "type": "dns",
         "value": "mydomain.com"
      }
   ],
   "finalize": "https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA",
   "authorizations": [
      "https://myserver.com:14000/authZ/Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE"
   ]
}'
[Tue Feb 26 15:54:25 UTC 2019] response='{"status":"processing","expires":"2019-02-27T15:54:13Z","identifiers":[{"type":"dns","value":"mydomain.com"}],"finalize":"https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA","authorizations":["https://myserver.com:14000/authZ/Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE"]}'
[Tue Feb 26 15:54:25 UTC 2019] Le_LinkCert
[Tue Feb 26 15:54:31 UTC 2019] url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:31 UTC 2019] payload='{"csr": "MIICmTCCAYECAQAwGjEYMBYGA1UEAwwPZ2NwLnBhbmdsb25nLm1lMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAqR8zwDgmULfZEHNrt3Rwo5ZXyUuSUKrL3GQaney7lMPgtMygH7QWkNgtXcVdXulMi3bGyXnDT3__0bkR_yvrkzk8Wul5o92wWbGLLxNKveWCZyjBMMa6pfouuSTAaOm8lpo6fxyHRhp4w4nUiHTNE6IeilI5S9eGlD-79jdOeHIjWSfF7ZQ2zxf2IJtzHgZEVkdYd7x1GFu8qV_-zeIUrQjyY2jhgmB6RebPp46D06PgTVZvXoyAl9ECRysOEcqxIk8M9EHR4eyCafn-mAlIUkz0lQzo2aWiSmvqWjV56bodSIlicoGPYywaUehkIhS5I4FrJJI_rn7UNxH-2a6Q-wIDAQABoDowOAYJKoZIhvcNAQkOMSswKTALBgNVHQ8EBAMCBeAwGgYDVR0RBBMwEYIPZ2NwLnBhbmdsb25nLm1lMA0GCSqGSIb3DQEBCwUAA4IBAQAcxo16pmB0VRVGsJKIrlwBybc3wVoclgZLVLyTDw2Vi6Impsl6TCARh2ZqupgBBfDdgfkYE5RKg_bL-8AdCebJoY-wGLH2IxPF6d5qDMWDqAnqfq98U4NZRXTMvd8RkON-42baaR_3gQMpfEE3RPRML3p2p24Kmr04VwV_TQn6KqVnoHEyJDcdsUbRgHM5q4Mp4ipT7uWko6nRjY51tmSyUdiE6EpOsRzQImlS0KCJSrVSk3MFw2y97Jq27Zp1pLmF3h8Mv4Yw4MkxZfnNFPz8ErV_jVxX46AnVIwgXzA3RKpjFZSAtsKmbcGFbyoiOedE-MctGTXAhWrC0nAna8CM"}'
[Tue Feb 26 15:54:31 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:31 UTC 2019] Use _CACHED_NONCE='W1orO1LyZ7EV_AcmZKB6Gg'
[Tue Feb 26 15:54:31 UTC 2019] nonce='W1orO1LyZ7EV_AcmZKB6Gg'
[Tue Feb 26 15:54:31 UTC 2019] POST
[Tue Feb 26 15:54:31 UTC 2019] _post_url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:31 UTC 2019] body='{"protected": "eyJub25jZSI6ICJXMW9yTzFMeVo3RVZfQWNtWktCNkdnIiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9maW5hbGl6ZS1vcmRlci9yLUhPQUVTNHhWbm51Y2dvaWtCZWd0Y1VrRWZyYl9ydjlBZnpDSXl1aHZBIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "eyJjc3IiOiAiTUlJQ21UQ0NBWUVDQVFBd0dqRVlNQllHQTFVRUF3d1BaMk53TG5CaGJtZHNiMjVuTG0xbE1JSUJJakFOQmdrcWhraUc5dzBCQVFFRkFBT0NBUThBTUlJQkNnS0NBUUVBcVI4endEZ21VTGZaRUhOcnQzUndvNVpYeVV1U1VLckwzR1FhbmV5N2xNUGd0TXlnSDdRV2tOZ3RYY1ZkWHVsTWkzYkd5WG5EVDNfXzBia1JfeXZya3prOFd1bDVvOTJ3V2JHTEx4Tkt2ZVdDWnlqQk1NYTZwZm91dVNUQWFPbThscG82Znh5SFJocDR3NG5VaUhUTkU2SWVpbEk1UzllR2xELTc5amRPZUhJaldTZkY3WlEyenhmMklKdHpIZ1pFVmtkWWQ3eDFHRnU4cVZfLXplSVVyUWp5WTJqaGdtQjZSZWJQcDQ2RDA2UGdUVlp2WG95QWw5RUNSeXNPRWNxeElrOE05RUhSNGV5Q2Fmbi1tQWxJVWt6MGxRem8yYVdpU212cVdqVjU2Ym9kU0lsaWNvR1BZeXdhVWVoa0loUzVJNEZySkpJX3JuN1VOeEgtMmE2US13SURBUUFCb0Rvd09BWUpLb1pJaHZjTkFRa09NU3N3S1RBTEJnTlZIUThFQkFNQ0JlQXdHZ1lEVlIwUkJCTXdFWUlQWjJOd0xuQmhibWRzYjI1bkxtMWxNQTBHQ1NxR1NJYjNEUUVCQ3dVQUE0SUJBUUFjeG8xNnBtQjBWUlZHc0pLSXJsd0J5YmMzd1ZvY2xnWkxWTHlURHcyVmk2SW1wc2w2VENBUmgyWnF1cGdCQmZEZGdma1lFNVJLZ19iTC04QWRDZWJKb1ktd0dMSDJJeFBGNmQ1cURNV0RxQW5xZnE5OFU0TlpSWFRNdmQ4UmtPTi00MmJhYVJfM2dRTXBmRUUzUlBSTUwzcDJwMjRLbXIwNFZ3Vl9UUW42S3FWbm9IRXlKRGNkc1ViUmdITTVxNE1wNGlwVDd1V2tvNm5Salk1MXRtU3lVZGlFNkVwT3NSelFJbWxTMEtDSlNyVlNrM01GdzJ5OTdKcTI3WnAxcExtRjNoOE12NFl3NE1reFpmbk5GUHo4RXJWX2pWeFg0NkFuVkl3Z1h6QTNSS3BqRlpTQXRzS21iY0dGYnlvaU9lZEUtTWN0R1RYQWhXckMwbkFuYThDTSJ9", "signature": "ssgu-L1cZ4G_Jheezab6rggYwXh_C69DsddPOvr0KHzEFGSKQ37B3qB5lXPYQ1ZcHqb7NhtlUPQXzgey36wM_oCZ0d4snTCu5QroMYiLkmC6hzE317j7kBB031uVYn29IqxwHnlK4rvYGwyPrRRy-po_CA2wLgezCwQqZjD4tK6vDNpnAdmRXrakfWvxUfGVUswDVH_EZThZpi71L2ZPqwX7hmFjbOjrItFKKkhnPP7zFhDYiZp9ESn4VIIDV2Zjyu2A_dpaTAzxodUDMUmcTxNjMrFe4wKlUc9pazrE7sAHfGy04FTeOaeOXxHwFZU33mq5NcPV2XdodyFX0FLb5w"}'
[Tue Feb 26 15:54:31 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:31 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:32 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
[Tue Feb 26 15:54:32 UTC 2019] _ret='0'
[Tue Feb 26 15:54:32 UTC 2019] responseHeaders='HTTP/2 403 
cache-control: public, max-age=0, no-cache
content-type: application/problem+json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
replay-nonce: ckRdussaUeA-4_sX7V1STw
content-length: 132
date: Tue, 26 Feb 2019 15:54:32 GMT
'
[Tue Feb 26 15:54:32 UTC 2019] code='403'
[Tue Feb 26 15:54:32 UTC 2019] original='{
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}'
[Tue Feb 26 15:54:32 UTC 2019] response='{
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}'
[Tue Feb 26 15:54:32 UTC 2019] Le_LinkCert
[Tue Feb 26 15:54:32 UTC 2019] Sign error, wrong status
[Tue Feb 26 15:54:32 UTC 2019] {
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}
[Tue Feb 26 15:54:38 UTC 2019] url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:38 UTC 2019] payload='{"csr": "MIICmTCCAYECAQAwGjEYMBYGA1UEAwwPZ2NwLnBhbmdsb25nLm1lMIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAqR8zwDgmULfZEHNrt3Rwo5ZXyUuSUKrL3GQaney7lMPgtMygH7QWkNgtXcVdXulMi3bGyXnDT3__0bkR_yvrkzk8Wul5o92wWbGLLxNKveWCZyjBMMa6pfouuSTAaOm8lpo6fxyHRhp4w4nUiHTNE6IeilI5S9eGlD-79jdOeHIjWSfF7ZQ2zxf2IJtzHgZEVkdYd7x1GFu8qV_-zeIUrQjyY2jhgmB6RebPp46D06PgTVZvXoyAl9ECRysOEcqxIk8M9EHR4eyCafn-mAlIUkz0lQzo2aWiSmvqWjV56bodSIlicoGPYywaUehkIhS5I4FrJJI_rn7UNxH-2a6Q-wIDAQABoDowOAYJKoZIhvcNAQkOMSswKTALBgNVHQ8EBAMCBeAwGgYDVR0RBBMwEYIPZ2NwLnBhbmdsb25nLm1lMA0GCSqGSIb3DQEBCwUAA4IBAQAcxo16pmB0VRVGsJKIrlwBybc3wVoclgZLVLyTDw2Vi6Impsl6TCARh2ZqupgBBfDdgfkYE5RKg_bL-8AdCebJoY-wGLH2IxPF6d5qDMWDqAnqfq98U4NZRXTMvd8RkON-42baaR_3gQMpfEE3RPRML3p2p24Kmr04VwV_TQn6KqVnoHEyJDcdsUbRgHM5q4Mp4ipT7uWko6nRjY51tmSyUdiE6EpOsRzQImlS0KCJSrVSk3MFw2y97Jq27Zp1pLmF3h8Mv4Yw4MkxZfnNFPz8ErV_jVxX46AnVIwgXzA3RKpjFZSAtsKmbcGFbyoiOedE-MctGTXAhWrC0nAna8CM"}'
[Tue Feb 26 15:54:38 UTC 2019] Use cached jwk for file: /root/.acme.sh/ca/myserver.com/account.key
[Tue Feb 26 15:54:38 UTC 2019] Use _CACHED_NONCE='ckRdussaUeA-4_sX7V1STw'
[Tue Feb 26 15:54:38 UTC 2019] nonce='ckRdussaUeA-4_sX7V1STw'
[Tue Feb 26 15:54:38 UTC 2019] POST
[Tue Feb 26 15:54:38 UTC 2019] _post_url='https://myserver.com:14000/finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA'
[Tue Feb 26 15:54:38 UTC 2019] body='{"protected": "eyJub25jZSI6ICJja1JkdXNzYVVlQS00X3NYN1YxU1R3IiwgInVybCI6ICJodHRwczovL3ZtNC5maXJzdHZtLm5ldDoxNDAwMC9maW5hbGl6ZS1vcmRlci9yLUhPQUVTNHhWbm51Y2dvaWtCZWd0Y1VrRWZyYl9ydjlBZnpDSXl1aHZBIiwgImFsZyI6ICJSUzI1NiIsICJraWQiOiAiaHR0cHM6Ly92bTQuZmlyc3R2bS5uZXQ6MTQwMDAvbXktYWNjb3VudC8xIn0", "payload": "eyJjc3IiOiAiTUlJQ21UQ0NBWUVDQVFBd0dqRVlNQllHQTFVRUF3d1BaMk53TG5CaGJtZHNiMjVuTG0xbE1JSUJJakFOQmdrcWhraUc5dzBCQVFFRkFBT0NBUThBTUlJQkNnS0NBUUVBcVI4endEZ21VTGZaRUhOcnQzUndvNVpYeVV1U1VLckwzR1FhbmV5N2xNUGd0TXlnSDdRV2tOZ3RYY1ZkWHVsTWkzYkd5WG5EVDNfXzBia1JfeXZya3prOFd1bDVvOTJ3V2JHTEx4Tkt2ZVdDWnlqQk1NYTZwZm91dVNUQWFPbThscG82Znh5SFJocDR3NG5VaUhUTkU2SWVpbEk1UzllR2xELTc5amRPZUhJaldTZkY3WlEyenhmMklKdHpIZ1pFVmtkWWQ3eDFHRnU4cVZfLXplSVVyUWp5WTJqaGdtQjZSZWJQcDQ2RDA2UGdUVlp2WG95QWw5RUNSeXNPRWNxeElrOE05RUhSNGV5Q2Fmbi1tQWxJVWt6MGxRem8yYVdpU212cVdqVjU2Ym9kU0lsaWNvR1BZeXdhVWVoa0loUzVJNEZySkpJX3JuN1VOeEgtMmE2US13SURBUUFCb0Rvd09BWUpLb1pJaHZjTkFRa09NU3N3S1RBTEJnTlZIUThFQkFNQ0JlQXdHZ1lEVlIwUkJCTXdFWUlQWjJOd0xuQmhibWRzYjI1bkxtMWxNQTBHQ1NxR1NJYjNEUUVCQ3dVQUE0SUJBUUFjeG8xNnBtQjBWUlZHc0pLSXJsd0J5YmMzd1ZvY2xnWkxWTHlURHcyVmk2SW1wc2w2VENBUmgyWnF1cGdCQmZEZGdma1lFNVJLZ19iTC04QWRDZWJKb1ktd0dMSDJJeFBGNmQ1cURNV0RxQW5xZnE5OFU0TlpSWFRNdmQ4UmtPTi00MmJhYVJfM2dRTXBmRUUzUlBSTUwzcDJwMjRLbXIwNFZ3Vl9UUW42S3FWbm9IRXlKRGNkc1ViUmdITTVxNE1wNGlwVDd1V2tvNm5Salk1MXRtU3lVZGlFNkVwT3NSelFJbWxTMEtDSlNyVlNrM01GdzJ5OTdKcTI3WnAxcExtRjNoOE12NFl3NE1reFpmbk5GUHo4RXJWX2pWeFg0NkFuVkl3Z1h6QTNSS3BqRlpTQXRzS21iY0dGYnlvaU9lZEUtTWN0R1RYQWhXckMwbkFuYThDTSJ9", "signature": "13-a7vAUnBffHrd-_rCJjgi7Xfr_6bR3wQBjBfM9cVRNvqq5fTqB4bBuXgBSS5tGEcKWTX3F8C1Tfvo24mYbW31jzHSXiynpFBLjGNGkLBloxE7qkFsr0uVHnc6fKC4UCoVKKZoVGmgJzSEeqRq2_11ie76JXaJsiSRigd6ggXVXFIkUMGIbYabnTeYLjCVv3X9VKapdh7CJnTue2BlwNEs1zC7zTP8TJLh544N_X-Co_EKtBRKHkri9tzhpW4H5hHCgUvAdbAl2snTw835-5XlCcMGVr5ng_CLBUKSnyQEhJ3-2YpxGhxX4nE335KOsNYWV0J1BeD-k_xBkM1cpzg"}'
[Tue Feb 26 15:54:38 UTC 2019] _postContentType='application/jose+json'
[Tue Feb 26 15:54:38 UTC 2019] Http already initialized.
[Tue Feb 26 15:54:38 UTC 2019] _CURL='curl -L --silent --dump-header /root/.acme.sh/http.header  --trace-ascii /tmp/tmp.mtgIAe8dIo  -g  --insecure  '
[Tue Feb 26 15:54:39 UTC 2019] _ret='0'
[Tue Feb 26 15:54:39 UTC 2019] responseHeaders='HTTP/2 403 
cache-control: public, max-age=0, no-cache
content-type: application/problem+json; charset=utf-8
link: <https://myserver.com:14000/dir>;rel="index"
replay-nonce: atrTTQfP-ffV1Rd2ziEOCA
content-length: 132
date: Tue, 26 Feb 2019 15:54:39 GMT
'
[Tue Feb 26 15:54:39 UTC 2019] code='403'
[Tue Feb 26 15:54:39 UTC 2019] original='{
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}'
[Tue Feb 26 15:54:39 UTC 2019] response='{
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}'
[Tue Feb 26 15:54:39 UTC 2019] Le_LinkCert
[Tue Feb 26 15:54:39 UTC 2019] Sign error, wrong status
[Tue Feb 26 15:54:39 UTC 2019] {
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}
jsha commented 5 years ago

docker-compose stop docker-compose rm for id in $(docker images pebble_pebble -q); do docker rmi $id; done

BTW, a quicker version of this is:

docker-compose down (which also gets rid of networks)

OR

docker-compose down --rmi all (which gets rid of networks and images.

https://docs.docker.com/compose/reference/down/

cpu commented 5 years ago

Here is the log from the pebble side:

@Neilpang Thanks, that confirms what I said earlier: acme.sh is behaving incorrectly and POSTing finalize multiple times. Here's an annotated version of the pebble log you shared to emphasize this:

<snipped>
# acme.sh POSTs the order's authz's HTTP-01 challenge:
pebble_1        | Pebble 2019/02/26 15:54:16 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()

# Pebble pulls the task from the queue to start the validations.
pebble_1        | Pebble 2019/02/26 15:54:16 Pulled a task from the Tasks queue: &va.vaTask{Identifier:"mydomain.com", Challenge:(*core.Challenge)(0xc0002aae60), Account:(*core.Account)(0xc000282190)}
pebble_1        | Pebble 2019/02/26 15:54:16 Starting 3 validations.
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 0s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 1s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Sleeping for 0s seconds before validating
pebble_1        | Pebble 2019/02/26 15:54:16 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc
pebble_1        | Pebble 2019/02/26 15:54:17 Attempting to validate w/ HTTP: http://mydomain.com:80/.well-known/acme-challenge/C_MnzUau-dyN4m3Kp-H4v-koZBuYTTcN7hy82BVRKNc

# At this point it looks like `acme.sh` is impatient and POSTs the challenge that is currently being validated by Pebble twice more. It should instead be polling the authorization to see if its valid or invalid.
pebble_1        | Pebble 2019/02/26 15:54:19 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:22 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()

# Pebble has completed the HTTP-01 validation and so the authz is now valid. Since the associated order has only 1 identifier it is now "ready".
pebble_1        | Pebble 2019/02/26 15:54:22 authz Gngyz0u3VkVZ-4ce8eeEkBTMIZbOPe2G_v4xbEyGnLE set VALID by completed challenge 7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE

# Acme.sh is _still_ POSTing the authz however. Maybe POST-as-GET polling?
pebble_1        | Pebble 2019/02/26 15:54:24 POST /chalZ/7YxsXSLM4I8XySvHeLV4thkfAhSwEWOMHkoHZIVLNFE -> calling handler()

# Acme.sh POSTs the "ready" order. It is now "processing".
pebble_1        | Pebble 2019/02/26 15:54:25 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()

# Pebble agrees the order is fully authorized and processes the finalized order
pebble_1        | Pebble 2019/02/26 15:54:25 Order r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA is fully authorized. Processing finalization

# Pebble issues a certificate - the order is now "valid"
pebble_1        | Pebble 2019/02/26 15:54:25 Issued certificate serial 037e5c3b1c2497a9 for order r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA

# Acme.sh is still trying to finalize the order even though its already fully valid and has an associated certificate!
# This will error because the order is "valid" not "ready"
pebble_1        | Pebble 2019/02/26 15:54:32 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()
pebble_1        | Pebble 2019/02/26 15:54:39 POST /finalize-order/r-HOAES4xVnnucgoikBegtcUkEfrb_rv9AfzCIyuhvA -> calling handler()

I hope that explains the errors you're seeing from finalizing orders in the wrong state.

Neilpang commented 5 years ago

@cpu

Thanks a lot for your help. it was a bug of acme.sh processing the async finalize-order.

acme.sh is compatible with Pebble strict mode now.

https://github.com/Neilpang/acme.sh/pull/2126

Really appreciate your time :) .

cpu commented 5 years ago

@Neilpang I'm very glad to hear you figured out the problem! :rocket: That's great news :-)

Neilpang commented 5 years ago

@cpu

your help makes it happen. :)

cpu commented 5 years ago

I think the Pebble README could use a touch-up to make that information more accessible. I'll do that shortly.

Here's my promised PR to update the README to mention the non-standard default challenge ports: https://github.com/letsencrypt/pebble/pull/219

aral commented 4 years ago 
[Tue Feb 26 15:28:04 UTC 2019] Sign error, wrong status
[Tue Feb 26 15:28:04 UTC 2019] {
   "type": "urn:ietf:params:acme:error:orderNotReady",
   "detail": "Order's status (\"valid\") was not ready",
   "status": 403
}

I’m getting the same error (and yes, I was also trying to call the finalise url again. I’m confused. In the RFC § 7.4, it says:

"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.

But which URL do we send the POST-as-GET request to?

Thanks in advance for your help. Looking forward to getting the tests for my Node.js client working with Pebble :)

aral commented 4 years ago

Ah, I see, in the paragraph above it mentions that in response to a 403, you should post to the order resource. Assuming that’s what’s returned in the Location field of a new order creation response. Going to try that:

 HTTP/1.1 201 Created
   Replay-Nonce: MYAuvOpaoIiywTezizk5vw
   Link: <https://example.com/acme/directory>;rel="index"
   Location: https://example.com/acme/order/TOlocE8rfgo
aral commented 4 years ago

Yep, that was it; it’s working now :)