Attempt to get length of local 'certs' (a nil value) about lua-resty-auto-ssl HOT 8 CLOSED

I think i'm experiencing a similar error to this. Here are my logs:

{"log":"2017/03/23 10:20:16 [notice] 56#56: *1071875 [lua] ssl_certificate.lua:85: issue_cert(): auto-ssl: issuing new certificate for example.com, context: ssl_certificate_by_lua*, client: 172.31.2.109, server: 0.0.0.0:443\n","stream":"stderr","time":"2017-03-23T10:20:16.473051893Z"}
{"log":"2017/03/23 10:20:16 [error] 56#56: *1071875 lua entry thread aborted: runtime error: ...re/lua/5.1/resty/auto-ssl/ssl_providers/lets_encrypt.lua:21: attempt to concatenate a nil value\n","stream":"stderr","time":"2017-03-23T10:20:16.473057068Z"}
{"log":"stack traceback:\n","stream":"stderr","time":"2017-03-23T10:20:16.473060427Z"}
{"log":"coroutine 0:\n","stream":"stderr","time":"2017-03-23T10:20:16.473064263Z"}
{"log":"\u0009...re/lua/5.1/resty/auto-ssl/ssl_providers/lets_encrypt.lua: in function 'issue_cert'\n","stream":"stderr","time":"2017-03-23T10:20:16.473067343Z"}
{"log":"\u0009.../luajit/share/lua/5.1/resty/auto-ssl/ssl_certificate.lua:86: in function 'issue_cert'\n","stream":"stderr","time":"2017-03-23T10:20:16.473070704Z"}
{"log":"\u0009.../luajit/share/lua/5.1/resty/auto-ssl/ssl_certificate.lua:112: in function 'get_cert'\n","stream":"stderr","time":"2017-03-23T10:20:16.47307377Z"}
{"log":"\u0009.../luajit/share/lua/5.1/resty/auto-ssl/ssl_certificate.lua:245: in function 'ssl_certificate'\n","stream":"stderr","time":"2017-03-23T10:20:16.47307742Z"}
{"log":"\u0009.../local/openresty/luajit/share/lua/5.1/resty/auto-ssl.lua:70: in function 'ssl_certificate'\n","stream":"stderr","time":"2017-03-23T10:20:16.473080429Z"}
{"log":"\u0009ssl_certificate_by_lua:2: in function \u003cssl_certificate_by_lua:1\u003e, context: ssl_certificate_by_lua*, client: 172.31.2.109, server: 0.0.0.0:443\n","stream":"stderr","time":"2017-03-23T10:20:16.473083802Z"}
{"log":"2017/03/23 10:20:16 [error] 56#56: *1071875 lua entry thread aborted: runtime error: ...re/lua/5.1/resty/auto-ssl/ssl_providers/lets_encrypt.lua:21: attempt to concatenate a nil value\n","stream":"stderr","time":"2017-03-23T10:20:16.47308708Z"}
{"log":"2017/03/23 10:20:16 [crit] 56#56: *1071874 SSL_do_handshake() failed (SSL: error:1408A179:SSL routines:ssl3_get_client_hello:cert cb error) while SSL handshaking, client: 172.31.2.109, server: 0.0.0.0:443\n","stream":"stderr","time":"2017-03-23T10:20:16.473152026Z"}

About 2 minutes after this happens, the docker container becomes totally unresponsive and only a restart fixes it. I'm on v0.10.3-1 of this plugin.

from lua-resty-auto-ssl.

So in tracing through the code, I think this should have only been possible if OpenResty's built in ssl.cert_pem_to_der or ssl.priv_key_pem_to_der functions failed for some reason. If those failed, then lua-resty-auto-ssl wasn't properly returning an error, so it would try to proceed with OCSP stapling, which leads to this nil value error.

I've fixed lua-resty-auto-ssl so that it will log and return a proper error when those builtin functions fail (035dcba), and that update is published in the v0.10.4 release. I've also included some fixes in v0.10.4 which should hopefully handle unexpected errors like this more gracefully (so you might not have to fully restart things if an unexpected error like this crops up).

That being said, I'm still not exactly sure why ssl.cert_pem_to_der or ssl.priv_key_pem_to_der would fail (I've never seen that before). So while v0.10.4 should hopefully help debug the real underlying issue (with better error logging), I'm not sure it will solve the real issue. For those built in functions to even be called, there has to be certificate data returned from storage (or a newly issued certificate with data), but then those DER functions fail for some reason. The fact that it works again after restarting nginx is curious, since that would seem to indicate the data stored in Redis is valid. So unless Redis is sometimes returning a partial or corrupted response, this is all a bit odd.

So could you try updating to v0.10.4 and then we can see what the logs say when those built-in functions fail? Sorry for the trouble and hassle, but hopefully with v0.10.4's logging we can get to the bottom of this. If you get better error logs from v0.10.4, could you also provide which version of OpenResty and OpenSSL you're running, and whether this seems to be happening for existing certs, or just when certs are renewed? Thanks!

from lua-resty-auto-ssl.

Hey,

I've upgraded to the latest version and now i get the following error in my logs:

*23036 [lua] ssl_certificate.lua:265: ssl_certificate(): auto-ssl: failed to run do_ssl: ...re/lua/5.1/resty/auto-ssl/ssl_providers/lets_encrypt.lua:15: attempt to concatenate a nil value, context: ssl_certificate_by_lua*

This seems to be around time when new certificates are generated.

Edit this appears to be coming from this file: https://github.com/GUI/lua-resty-auto-ssl/blob/f7fe3e62c081d77c7d021fcc10371ebb26c97bc0/lib/resty/auto-ssl/ssl_providers/lets_encrypt.lua#L15 maybe hook_port is nil somehow? I can't see how that would be the case as the asserts above should be covering for this: https://github.com/GUI/lua-resty-auto-ssl/blob/f7fe3e62c081d77c7d021fcc10371ebb26c97bc0/lib/resty/auto-ssl/ssl_providers/lets_encrypt.lua#L10-L11

Edit 2 I'm also not overriding the hook_server_port so this should be always set to be the default https://github.com/GUI/lua-resty-auto-ssl/blob/e994c8cc5d00100401dbd0138180bd368b80d34c/lib/resty/auto-ssl.lua#L43-L45

from lua-resty-auto-ssl.

@domharrington: Thanks for reporting this and for the details! I think I was able to track down what was happening. The line number on the error backtrace was a bit off for some reason, but the culprit was hook_secret being nil. The only way I think this could happen is if the shdict used for caching certs data in memory ran out of space. I think this in turn could lead to things becoming unresponsive if new certificates were being registered (because without the secret, the internal communication becomes rather broken).

So if this theory is correct, you might need to increase the configured size of lua_shared_dict auto_ssl in your nginx config. I estimated that for each 1MB, you can store 100 certificates, but that estimate might be off. But does this seem like it could be the issue in your setup, or do you not have that many certificates for this to make sense?

In any case, I've released v0.10.6, which I'm hoping should fix this in a couple different ways:

• The hook secret is stored in a different way, so it shouldn't ever be subject to getting evicted from the cache, like it was before.
• If the lua_shared_dict used for caching data begins to run out of memory, more explicit errors are logged to nginx's error log, suggesting that you raise the configured amount (but the server should still be operational when this happens due to the first change--just less efficient).

I'm hoping those updates in v0.10.6 should make things less fatal and easier to track down if your configured amount of memory is too low. This might also explain some other unresponsive issues a couple other people reported, but we were never able to get to the bottom of, so thanks again for the report.

Caveat: I'm not entirely certain this error is related to the original issue @gjongenelen reported.

from lua-resty-auto-ssl.

Hey @GUI thank you very much for investigating this and coming up with a potential solution.

We do currently have lua_shared_dict set to 1m, and we a few hundred certs. I will try bumping this limit now and hopefully that will solve the problem!

Thank you very much again for taking the time to look into this. I will upgrade to 0.10.6 now.

Dom

from lua-resty-auto-ssl.

@domharrington did you experience any more issues after bumping the limit and upgrading to the latest version?

from lua-resty-auto-ssl.

@luto nope. It's been very stable since deploying the latest update.

from lua-resty-auto-ssl.

Great, thank you for confirming! Going to go ahead and close this then.

from lua-resty-auto-ssl.