Bug 64437

Created attachment 37243 [details]
network dump when accessing directly to s_server with firefox

Created attachment 37244 [details]
network dump when accessing s_server via mod_proxy

Ok, here some more information...

The error message "SSL Proxy connect failed" is produced here 
https://github.com/apache/httpd/blob/2.4.43/modules/ssl/ssl_engine_io.c#L1244

By tracking down the code path starting from SSL_connect() one finishes in OpenSSL's ssl3_read_bytes(), more precisely at this position

https://github.com/openssl/openssl/blob/OpenSSL_1_1_1g/ssl/record/rec_layer_s3.c#L1727

The comment in the code  "At this point, we were expecting handshake data, but have application data." exactly reflects the dump of attachment 3744.

Anyway, I still not get it what what's going wrong. As already mentioned, doing the same without mod_proxy works fine.

So, any hint in the right direction is highly appreciated!

I think it has to do with Post Handshake Authentication (PHA) with TLS 1.3, which is not handled by mod_proxy. Switching to OpenSSL 1.1.1 enables TLS 1.3.

Does "SSLProxyProtocol All -TLSv1.3" help?

(In reply to Yann Ylavic from comment #4)
> I think it has to do with Post Handshake Authentication (PHA) with TLS 1.3,
> which is not handled by mod_proxy. Switching to OpenSSL 1.1.1 enables TLS
> 1.3.
> 
> Does "SSLProxyProtocol All -TLSv1.3" help?

Please note that when reproducing it on CentOS we ran s_server with the -tls1_2 option. So it seems not to be related to TLS 1.3/PHA only.

Created attachment 37291 [details]
Use buffered data upon proxy renegotiation

Could you please try this patch on top of 2.4.43 (or 2.4.x)?

I applied the patch to 2.4.43. Now, I get status 200 and there is no error in the error_log.

However, the network dumps still look different when requesting the URI directly or when mod_proxy is involved. I don't attach new dumps as the look the same as the ones already attached.

That there is still a difference in behavior can be shown by staring s_server with the -msg option, e.g. like following

openssl s_server -port 10016 -www -tls1_2 -cert sserver.pem -msg | grep -E "TLS 1.|reneg"

The output when requesting the URI /reneg directly from s_server looks following

<<< TLS 1.3, Handshake [length 0200], ClientHello
>>> TLS 1.2, Handshake [length 0041], ServerHello
>>> TLS 1.2, Handshake [length 0412], Certificate
>>> TLS 1.2, Handshake [length 012c], ServerKeyExchange
>>> TLS 1.2, Handshake [length 0004], ServerHelloDone
<<< TLS 1.2, Handshake [length 0025], ClientKeyExchange
<<< TLS 1.2, Handshake [length 0010], Finished
>>> TLS 1.2, Handshake [length 00aa], NewSessionTicket
>>> TLS 1.2, ChangeCipherSpec [length 0001]
>>> TLS 1.2, Handshake [length 0010], Finished
SSL_renegotiate -> 1
>>> TLS 1.2, Handshake [length 0004], HelloRequest
<<< TLS 1.3, Handshake [length 0200], ClientHello
>>> TLS 1.2, Handshake [length 0041], ServerHello
>>> TLS 1.2, Handshake [length 0412], Certificate
>>> TLS 1.2, Handshake [length 012c], ServerKeyExchange
>>> TLS 1.2, Handshake [length 0004], ServerHelloDone
<<< TLS 1.2, Handshake [length 0025], ClientKeyExchange
<<< TLS 1.2, Handshake [length 0010], Finished
>>> TLS 1.2, Handshake [length 00aa], NewSessionTicket
>>> TLS 1.2, ChangeCipherSpec [length 0001]
>>> TLS 1.2, Handshake [length 0010], Finished

When mod_proxy is involved, the output of s_server looks following

<<< TLS 1.3, Handshake [length 0200], ClientHello
>>> TLS 1.2, Handshake [length 0041], ServerHello
>>> TLS 1.2, Handshake [length 0412], Certificate
>>> TLS 1.2, Handshake [length 012c], ServerKeyExchange
>>> TLS 1.2, Handshake [length 0004], ServerHelloDone
<<< TLS 1.2, Handshake [length 0025], ClientKeyExchange
<<< TLS 1.2, Handshake [length 0010], Finished
>>> TLS 1.2, Handshake [length 00aa], NewSessionTicket
>>> TLS 1.2, ChangeCipherSpec [length 0001]
>>> TLS 1.2, Handshake [length 0010], Finished
SSL_renegotiate -> 1
>>> TLS 1.2, Handshake [length 0004], HelloRequest

In the later case it looks like as renegotiation is not finished correctly.

I filled a PR for openssl 2 days ago (see [1]).

openssl s_server with "/reneg" does not behave correctly (IMHO), it assumes that the request is a single line, which is never true for HTTP/1.x requests for instance.
So long as the request is a single line (like an HTTP/0.9 "GET /\r\n"), there is nothing buffered by s_server (which it can BIO_gets() immediately), thus the handshake completes.
But otherwise, s_server will send its HelloRequest to start the renegotiation, read the *buffered* second line (which does not trigger the handshake), and go straight to the HTTP response (application data).

On the mod_proxy side (as SSL client), after sending the request to the backend and while reading the response header (line by line), it first gets the HelloRequest and then sends its ClientHello to satisfy the renegotitation, and then by reading the next step of the handshake it gets the application data directly (full response header + body, which it buffers).
Now thanks to [2] (as you noted in comment 3), application data are "kind of valid" when the client is in ClientHello state, so the first response line is read successfully and returned. But the connection somehow is still in ClientHello state (hence PR [1] to ask for clarification), so mod_proxy still thinks it is in the middle of a handshake (per SSL_is_init_finished() returning 0), thus when reading the second response line it thinks it should start/continue the handshake, which fails because the connection has been closed by s_server already.

So what my patch does is that it always tries to read from the buffered data before asking for complete handshake to the openssl layer, and let openssl handle renegotiations on its own (if any), thus the reponse which was already fully buffered is returned and mod_proxy can proceed with the response to the client. The connection closed is not an error anymore (that's the end of the body for a response without Content-Length), and everything seems to work, but still the SSL client connection state remains in an exit/error path all that long.

So I'm not sure it's the correct fix, unless the openssl team clarifies this ClientHello => application data non-transition but no-failure either case.
What is a SSL client supposed to do while !SSL_is_init_finished(), handshake or read? I'm a bit nervous about the patch's SSL_total_renegotiations() != 0 workaround / bypass...


[1] https://github.com/openssl/openssl/pull/12081
[2] https://github.com/openssl/openssl/blob/OpenSSL_1_1_1g/ssl/record/rec_layer_s3.c#L1727

Created attachment 37302 [details]
37291: Use buffered data upon proxy renegotiation (v2)

This v2 should be more acceptable.

The check for SSL_is_init_finished() is replaced by !SSL_in_defore() which concerns the first handshake only (we shouldn't enter ssl_io_filter_handshake() for any other case anyway).

Also it fixes the EOF error condition (SSL_ERROR_ZERO_RETURN) in ssl_io_input_read(), otherwise the final close-notify can still break the response completeness and lead to 502.

I've applied your new patch (v2) to 2.4.43 and did the test with s_server. The renegotiation works IF s_server is patched with your proposed change. Otherwise the behavior is still the same as mentioned in comment #7.

I've tested the v2 patch also against our "proprietary" server software. The observation there is that renegotiation sometimes works... but most often not. 

As the behavior looks to me like a timing-issue (handshake data sometimes delay, sometimes not) I've changed the server by repeatably calling SSL_do_handshake() as long as SSL_renegotiate_pending() is true, additionally by peeking for data. Before the change SSL_do_handshake() was called again only on SSL_ERROR_WANT_READ or SSL_ERROR_WANT_WRITE.

Note that the server uses non-blocking sockets.


SSL_renegotiate(ssl);

while (goahead) {
  SSL_do_handshake(ssl);

  if (SSL_renegotiate_pending(ssl)) {
    char peekbuf[1];
    SSL_peek(ssl, peekbuf, 0); 
    goahead = 1;
  }
  
  // also repeat on SSL_ERROR_WANT_READ/SSL_ERROR_WANT_WRITE
  ...

  // otherwise we are finished with renegotiation
  ...
}

Doing so the renegotiation always works.

Whether the workaround is right or not remains to be seen, but in my opinion it clearly shows what the problem is about.