When enabling DEBUG mode, the logs for the acme.sh are still sent to /dev/null

luilegeant commented 2 years ago

Trying to figure out why Let's Encrypt (LE) was refusing to give me a new certificate, I wanted to enable logging & using LE stagging environment.

Bug description

When adding the env var DEBUG=1 to the container being proxied, some extra logging is provided by the acme-companion container. BUT, this still doesn't enable logging for the acme.sh errors. See: letsencrypt-service L134 On line 135, it does enable extra logging for the acme-companion's code...

acme-companion image version

image pulled from hub.docker.com: nginxproxy/acme-companion:2.1.2

nginx-proxy's Docker configuration

My reverse proxy is composed of:

nginx:1.20.2-alpine
helder/docker-gen:latest
nginxproxy/acme-companion:2.1.2

rendered nginx configuration

Not important for this report.

Containers logs

That's the issue, it says read the extra logging by acme.sh at /dev/null :zany_face:

My workaround

In the acme-companion container, I edited the app/letsencrypt_service file at line 134 with an amazing log file path; then i retrigered the generation of config & certificate request and got some extra log information.

Wished change

That the log path if DEBUG is true to be set a bit like it is at line 180 of letsencrypt-service.

Last but not least

Thank you for this amazing project !

buchdag commented 2 years ago

Hi. Do you have a sample of the extra log information that goes to the --log file ?

The fact that the log file and the stdin / stderr log contains different information would be very awkward.

logantracyo commented 2 years ago

@buchdag, I can help with that extra log info, thanks to a related issue: Initial startup of a new Tomcat container fails, but docker logs only shows a seductive but ultimately unsatisfying error message. I'll provide detailed info on how to show that extra log info (and may add a follow-up comment with what I found using that additional info).

I'll use our nginx-letsencrypt container for this writeup (its image is: nginxproxy/acme-companion:latest), and will demonstrate the current state using docker logs nginx-letsencrypt 2>&1 | grep -B9 "Please check log file for more details:":

Using CA: https://acme-v02.api.letsencrypt.org/directory
Creating domain key
The domain key is here: /etc/acme.sh/user@example.com/new-site.example.com/new-site.example.com.key
Single domain='new-site.example.com'
Getting domain auth token for each domain
Getting webroot for domain='new-site.example.com'
Verifying: new-site.example.com
new-site.example.com:Verify error:123.123.123.123: Invalid response from http://new-site.example.com/.well-known/acme-challenge/seLW0jILWVInNDOE8ii4h5h-wPO_-k8NEK-Ec-OPsos: 503
**Please check log file for more details: /dev/null**

We see this every time we add a new site -- but haven't yet found a solution other than brute-force (regenerating all certs just to get things working). Therefore, I've taken @luilegeant's above suggestion to change /dev/null to a real log-file path (documented here in detail in the hope of helping others needing a workaround to see what acme.sh is logging):

Log into our container: docker-login nginx-letsencrypt

Use sed to replace that specific instance of /dev/null with something we can view, using the existing /log/ folder and a good log-file name, saving the original with a .bak extension (and using _ as the separator to avoid escaping the usual / separators since we're working with a file path). sed -i.bak 's_--log /dev/null_--log /var/log/letsencrypt.log_' /app/letsencrypt_service

Confirm the change & backup with ls -al /app:

-rwxr-xr-x 1 root root  18820 Sep 23 16:20 letsencrypt_service
-rwxr-xr-x 1 root root  18805 Sep 22 21:12 letsencrypt_service.bak

Show the actual change with diff /app/letsencrypt_service.bak /app/letsencrypt_service:

     local -a params_base_arr
-    params_base_arr+=(--log /dev/null)
+    params_base_arr+=(--log /var/log/letsencrypt.log)
     [[ "$DEBUG" == 1 ]] && params_base_arr+=(--debug 2)

Activate the change by exiting the container, then stopping & starting it as usual.

Trigger the error again (creating a new site / TC container in our case).

Confirm that the new log-file is used with docker logs nginx-letsencrypt 2>&1 | grep "Please check log file for more details:"; should now show: Please check log file for more details: /var/log/letsencrypt.log

Log back into the container, then view that new log file with cat /var/log/letsencrypt.log; the logging of our error contains a lot of potentially-sensitive info, so I am posting only the normal (slightly-obfuscated) extended output:

Lets find script dir.
_SCRIPT_='/app/acme.sh'
_script='/app/acme.sh'
_script_home='/app'
Using default home:/root/.acme.sh
Using config home:/etc/acme.sh/user@example.com
Running cmd: issue
_main_domain='new-site.example.com'
_alt_domains='no'
Using config home:/etc/acme.sh/user@example.com
ACME_DIRECTORY='https://acme-v02.api.letsencrypt.org/directory'
DOMAIN_PATH='/etc/acme.sh/user@example.com/new-site.example.com'
Using ACME_DIRECTORY: https://acme-v02.api.letsencrypt.org/directory
_init api for server: https://acme-v02.api.letsencrypt.org/directory
GET
url='https://acme-v02.api.letsencrypt.org/directory'
timeout=
_CURL='curl --silent --dump-header /etc/acme.sh/user@example.com/http.header  -L '
ret='0'
ACME_KEY_CHANGE='https://acme-v02.api.letsencrypt.org/acme/key-change'
ACME_NEW_AUTHZ
ACME_NEW_ORDER='https://acme-v02.api.letsencrypt.org/acme/new-order'
ACME_NEW_ACCOUNT='https://acme-v02.api.letsencrypt.org/acme/new-acct'
ACME_REVOKE_CERT='https://acme-v02.api.letsencrypt.org/acme/revoke-cert'
ACME_AGREEMENT='https://letsencrypt.org/documents/LE-SA-v1.3-September-21-2022.pdf'
ACME_NEW_NONCE='https://acme-v02.api.letsencrypt.org/acme/new-nonce'
Le_NextRenewTime='1668456222'
_saved_domain='new-site.example.com'
_saved_alt='no'
Domains not changed.
Skip, Next renewal time is: Tue Nov 15 20:03:42 UTC 2022
Add '--force' to force to renew.

NOW UNDO THIS LOGGING CHANGE! This is very important, so you don't fill up the limited disk space available -- either remove and recreate the container, or log back into the container, and overwrite the modified file with the backup with mv /app/letsencrypt_service.bak /app/letsencrypt_service, then logout and stop/start the container as usual.

This logging is clearly far more output than would be sensible to write to the container normally, so it makes lots of sense to send it to /dev/null -- but during debugging, just writing it to that file instead would save folks from having to take these steps to be able to see the actual problem (note that the actual log output for our error is very promising; I'll add another comment with that if it seems useful as I dig further into it).

And I agree with @luilegeant that logging that extra output from acme.sh where docker logs can show it when DEBUG == 1 would be a tasty solution -- and hope that this info helps inspire that change, if you agree it makes sense.

Many thanks for this great tool!

brian-maher commented 3 months ago

Sorry to bump, but could this potentially be reconsidered please?

This log info is rather more critical when using DNS-01 challenges, as without it users will have no idea why their DNS challenges are failing.

nginx-proxy / acme-companion