500 warnings / badNonce

[devth]

When kube-lego starts up and tries to obtain the cert, I see 3 repetitions of these logs (domain masked):

time="2016-06-06T12:54:05Z" level=debug msg="testing reachablity of http://foo.com/.well-known/acme-challenge/_selftest" context=acme host=foo.com
time="2016-06-06T12:54:05Z" level=warning msg="wrong status code '503'" context=acme host=foo.com

This results in:

time="2016-06-06T12:54:06Z" level=info msg="initialize lego acme connection" context=acme
2016/06/06 12:54:06 [INFO][foo.com] acme: Obtaining bundled SAN certificate
t
Error 400 - urn:acme:error:badNonce - JWS has invalid anti-replay nonce tlGC7MNn-udU86kjs_DOK1pTWynV5P3kYjNmDuVIruo]" context=acme

Are those related? I saw many others with similar JWS errors and read possible solutions (retry ~6 times, change email address) but still no luck.

[devth]

I fixed the JWS issue so ignore that part (I had to delete the kube-lego-account secret when switching between staging and prod). Still a heads up about the 500s: apparently they are benign?

[simonswine]

The 503 could come from multiple sources.

Please provide a bit more context:

• Which cloud you are running in?
• Can you reach nginx in general "http://foo.com/" should so the service from ingress?
• Can you verify the k8s services have endpoints assinged?

[devth]

• GKE
• Yes, and SSL is configured and working
• Yes, nginx service has an external IP

[simonswine]

I think it's normal that you see a couple of 503s before nginx actually routes the traffic to kube-lego. Can you provide a more detailed log?

[devth]

Here's the log from startup up until it actually obtains the cert:

time="2016-06-06T13:07:44Z" level=info msg="kube-lego 0.0.2-4c1dd2c0 starting" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="connected to kubernetes api v1.2.4" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="start event watcher" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="server listening on http://:8080/" context=acme
time="2016-06-06T13:07:44Z" level=info msg="CREATE default/foo" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="Worker: begin processing true" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="ignoring as has no annotiation 'kubernetes.io/tls-acme'" context=ingress name=kube-lego namespace=default
time="2016-06-06T13:07:44Z" level=info msg="update challenge endpoint ingress, if needed" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="challenge endpoints don't need an update" context=ingress name=kube-lego namespace=default
time="2016-06-06T13:07:44Z" level=info msg="process certificates requests for ingresses" context=kubelego
time="2016-06-06T13:07:44Z" level=info msg="creating new secret" context=secret name=foo-tls namespace=default
time="2016-06-06T13:07:44Z" level=info msg="no cert associated with ingress" context="ingress_tls" name=foo namespace=default
time="2016-06-06T13:07:44Z" level=info msg="requesting certificate for foo.com" context="ingress_tls" name=foo namespace=default
time="2016-06-06T13:07:44Z" level=debug msg="testing reachablity of http://foo.com/.well-known/acme-challenge/_selftest" context=acme host=foo.com
time="2016-06-06T13:07:44Z" level=warning msg="wrong status code '503'" context=acme host=foo.com
time="2016-06-06T13:07:45Z" level=debug msg="testing reachablity of http://foo.com/.well-known/acme-challenge/_selftest" context=acme host=foo.com
time="2016-06-06T13:07:45Z" level=warning msg="wrong status code '503'" context=acme host=foo.com
time="2016-06-06T13:07:46Z" level=debug msg="testing reachablity of http://foo.com/.well-known/acme-challenge/_selftest" context=acme host=foo.com
time="2016-06-06T13:07:46Z" level=info msg="initialize lego acme connection" context=acme
time="2016-06-06T13:07:46Z" level=info msg="creating new secret" context=secret name=kube-lego-account namespace=default
2016/06/06 13:07:46 [INFO] acme: Registering account for devth@foo.com
time="2016-06-06T13:07:47Z" level=info msg="creating new secret" context=secret name=kube-lego-account namespace=default
2016/06/06 13:07:47 [INFO][foo.com] acme: Obtaining bundled SAN certificate
2016/06/06 13:07:47 [INFO][foo.com] acme: Trying to solve HTTP-01
time="2016-06-06T13:07:47Z" level=info msg="responding to challenge request" basePath="/.well-known/acme-challenge" context=acme host=foo.com token="fehKLcN4MKvX-2fgkCOmss9qzcq805wvXHws_shI8_Y"
2016/06/06 13:07:48 [INFO][foo.com] The server validated our request
2016/06/06 13:07:48 [INFO][foo.com] acme: Validations succeeded; requesting certificates
2016/06/06 13:07:49 [INFO] acme: Requesting issuer cert from https://acme-v01.api.letsencrypt.org/acme/issuer-cert
2016/06/06 13:07:49 [INFO][foo.com] Server responded with a certificate.

[simonswine]

That's a completely normal output, I have just have to move the 503 output from level warn to debug/info.

The first self-test requests fail, because nginx reconfiguration takes some time. kube-lego is just retrying with an exponential back-off...

[devth]

👍