Can't renew with certbot or Crypt::LE, Timeout during secondary validation (403 resolved)

[MikeMcQ]

@jonadab

I may run a test again to see if that's consistent or variable.

I don't know if that is fruitful. The Let's Encrypt Server gives up once it knows for sure it can't satisfy the cert request. That is, once it learns the primary times out the challenge fails. Or, if more than 1 secondary times out the challenge fails. Or, if it flat out gets wrong data responses rather than timeouts it fails.

So, there may be an element of timing as to how many you see depending on the underlying traffic flows and timeout detections. Emphasis on "may" as I have not studied the LE Boulder code in detail but that is the concept of what happens.

The last one with only 3 Apache log entries had a subset of the one with 4 log entries. I didn't look at the earlier as missing the Primary center is a major failure.

[MikeMcQ]

@jonadab

Update: No, four perspectives is not enough to pass.

It depends which four. The Primary center must pass - always.

@MikeMcQ

But, the one below was legit and we see 4 successful requests. The only one missing is from the Primary Let's Encrypt data center. The Primary must succeed along with at least 3 Secondaries. Again, this is today's behavior subject to change any time.

[jonadab]

@MikeMcQ

It depends which four. The Primary center must pass - always.

I see. Does that mean that's the one (or one of the ones) that's consistently failing? That's interesting, though I'm not sure what the implications are.

[MikeMcQ]

@jonadab

Does that mean that's the one (or one of the ones) that's consistently failing?

It does. I looked at the 4 IP and they were all from AWS data centers which are all Secondary centers. An IP for the Primary center is missing.

The fact we see 4 requests and still fails also means that.

@MikeMcQ

... the one below was legit and we see 4 successful requests. The only one missing is from the Primary Let's Encrypt data center. The Primary must succeed along with at least 3 Secondaries. Again, this is today's behavior subject to change any time.

I'm a little vague on the implications but I believe the primary uses Cloudflare Magic Transit and the center itself is in the USA. The secondary sites are all AWS but the primary is Flexential if I recall correctly. I doubt this helps I'm just giving an outline so you can focus your efforts.

[rg305]

I don't understand...

Previous log entries [failures]:

@jonadab

200 308

Your recent requests [success]:

@jonadab

200 345

I can't reconcile those differences.

[MikeMcQ]

@rg305

I can't reconcile those differences.

Maybe it is a PID (%P) rather than the size of response bytes (%B) ?

This thread has some of the most peculiar combination of oddities.

I don't think the log value is an accurate response bytes. Wouldn't the failure message say "faulty data" rather than timeout if it were?

[rg305]

Then we would need to see the log definition [to be sure].
But I do follow the logic of it is not what we think it is/should be.

[rg305]

I suspect something default, like:
LogFormat "%h %l %u %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\"" combined

[MikeMcQ]

That's likely. And, %O includes headers so maybe there are some unneeded headers

[jonadab]

I've never messed around with changing the log format, so it should be whatever the default is in Devuan. Hang on, lemme look up where it's configured...

Hmm, /etc/apache2/apache2.conf has this:
LogFormat "%v:%p %h %l %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i"" vhost_combined
LogFormat "%h %l %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i"" combined
LogFormat "%h %l %u %t "%r" %>s %O" common
LogFormat "%{Referer}i -> %U" referer
LogFormat "%{User-agent}i" agent

And then sites-enabled/000-default.conf has this:
ErrorLog ${APACHE_LOG_DIR}/error.log
CustomLog ${APACHE_LOG_DIR}/access.log combined

So that suggests this:
"%h %l %u %t "%r" %>s %O "%{Referer}i" "%{User-Agent}i""
So I think the field we're looking at is the %O yes? I think. Unless I am missing something. Again, I have a lot more experience looking at the error log than the access log, and no experience at all with configuring the log formats to anything other than the default. And it's been a rather long time since I've hosted Apache on anything other than Debian (pre-Poettering) and now Devuan, so my notion of the default, is whatever the Debian package maintainer thinks the default should be.

[rg305]

https://httpd.apache.org/docs/2.4/mod/mod_log_config.html#formats

Yes.

I don't understand why the logs shows anything other than 87.
We need to capture one of those replies.

[MikeMcQ]

Wouldn't the reply look like below? I didn't count every byte but it's somewhere in the 300s including headers. The %O says it includes the header bytes.

curl -i http://cgi.galion.lib.oh.us/.well-known/acme-challenge/y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A

HTTP/1.1 200 OK
Date: Thu, 25 Apr 2024 13:20:42 GMT
Server: Apache/2.4.59 (Debian)
Last-Modified: Wed, 24 Apr 2024 17:58:02 GMT
ETag: "57-616db69675ce0"
Accept-Ranges: bytes
Content-Length: 87

y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A.AT5JajgpWjv1ULtDGDL25oQO0YEHg-QklIW6-jtJrVA

[rg305]

For curl -I requests, yes.
But why would LE make such a request?

[MikeMcQ]

The lower case i does a GET and has curl show the headers and data.

Omitting that lower case i would still do a GET but only show the response data.

Their Apache would be sending headers and data for any request. And thus its length would be reflected in its own log.

[rg305]

I suppose
you may be right...
[I may be crazy]

[MikeMcQ]

@rg305

I suppose
you may be right...

I'm sure you have a spare Apache laying around. Setup a log format that includes %O and %B. Make sure your Apache sends some headers with every response. Then send a curl with and without a lower case i and see if those log values change. They shouldn't. The O entry will include the length of the headers and the B just the data.

[rg305]

That would take time... [away from my ]
And it wouldn't explain why sometimes it was 308 and other times 345.

But it is a red herring none-the-less.

[MikeMcQ]

@rg305

And it wouldn't explain why sometimes it was 308 and other times 345.

But it is a red herring none-the-less.

Yes, a diversion. The 345 length log entries were from their wget tests. The response headers were longer for those as they included some "keep-alive" info. wget probably sets different request headers compared to curl (and LE) resulting in slightly different response headers.

Why the LE Primary data center cannot reach their server is still a mystery.

[jonadab]

Showing the entire reply including headers is what wget -S does:

jonadab@hippo:~$ wget -S http://cgi.galion.lib.oh.us/.well-known/acme-challenge/y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A
--2024-04-25 11:08:23-- http://cgi.galion.lib.oh.us/.well-known/acme-challenge/y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A
Resolving cgi.galion.lib.oh.us (cgi.galion.lib.oh.us)... 66.213.116.5
Connecting to cgi.galion.lib.oh.us (cgi.galion.lib.oh.us)|66.213.116.5|:80... connected.
HTTP request sent, awaiting response...
HTTP/1.1 200 OK
Date: Thu, 25 Apr 2024 15:08:23 GMT
Server: Apache/2.4.59 (Debian)
Last-Modified: Wed, 24 Apr 2024 17:58:02 GMT
ETag: "57-616db69675ce0"
Accept-Ranges: bytes
Content-Length: 87
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Length: 87
Saving to: ‘y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A.2’

y13yBugLjpX9LrHjJA7AwI3RHxPgi 100%[=================================================>] 87 --.-KB/s in 0s

2024-04-25 11:08:23 (10.4 MB/s) - ‘y13yBugLjpX9LrHjJA7AwI3RHxPgiUOhMeNpgAxUw0A.2’ saved [87/87]

You have new mail in /var/mail/jonadab
jonadab@hippo:~$

So yeah, the headers are somewhere in the 300-byte range, but it would vary depending on stuff like what headers the client sent, because the server responds to those. That's all a normal part of http, as I understand it. In principle the headers can even have cookies in them, although in this case they wouldn't, because the files being served are static (and I haven't set up any site-wide cookie apparatus).

[jonadab]

For the sake of completeness:

Wed_2024-May-01_15:00
jonadab@ostrich:~$ telnet www.galionlibrary.org 80
Trying 66.213.116.5...
Connected to www.galionlibrary.org.
Escape character is '^]'.
GET http://www.galionlibrary.org/.well-known/acme-challenge/06Zqq3xKoJl0b5n-sWip_F-uHiGfxjYf_Dv_E0P3q0s HTTP/1.1
Host: www.galionlibrary.org

HTTP/1.1 200 OK
Date: Wed, 01 May 2024 19:00:45 GMT
Server: Apache/2.4.59 (Debian)
Last-Modified: Wed, 24 Apr 2024 19:31:46 GMT
ETag: "57-616dcb8a557d7"
Accept-Ranges: bytes
Content-Length: 87

06Zqq3xKoJl0b5n-sWip_F-uHiGfxjYf_Dv_E0P3q0s.AT5JajgpWjv1ULtDGDL25oQO0YEHg-QklIW6-jtJrVAConnection closed by foreign host.

Wed_2024-May-01_15:01
jonadab@ostrich:~$

But yes, this is a rabbit trail. The size of the http headers is unlikely to be related to the problem.