Race condition in server TlsHandler when negotiating client certificate

[mindlink]

We are seeing an issue in our Dotnetty server when negotiating TLS -- the TlsHandler which we add to our pipeline sometimes fails to propagate data through the pipeline once the TLS handshake completes successfully.

This occurs sporadically with the following configuration:

• The TlsHandler is configured with ServerTlsSettings specifying the server certificate and negotiateClientCertificate set to true.
• The TlsHandler's sslStreamFactory specifies a custom certificate validation callback to apply domain-specific validation logic to the client certificate.

The issue does not occur when negotiateClientCertificate is set to false.

There seems to be an issue with how data is propagated in the case that the client accepts the server's certificate, completes TLS negotiation and immediately sends some data, but the server receives this data before it has finished validating the client certificate. This race would explain the inconsistent nature of the issue, as well as the fact that it does not occur when not negotiating the client certificate.

To illustrate the issue, we have added LoggingHandlers to our pipeline both before and after the TlsHandler, logging for contexts [SRV-ENC] and [SRV-CONN], respectively. The sslStreamFactory also wraps the SslStream's inner stream in a logging wrapper, logging for context [LoggingStream].

These are the logs for the successful case:

[Debug] 2022-11-23T14:59:45.064Z  [StartTlsHandler] TLS validation callback triggered...
[Debug] 2022-11-23T14:59:45.064Z  [CertificateValidator] Attempting to validate certificate with subject 'X'.
[Debug] 2022-11-23T14:59:45.064Z  [CertificateValidator] Determining certificate with subject 'X' to be valid as there were no SSL policy errors.
[Debug] 2022-11-23T14:59:45.064Z  [StartTlsHandler] Setting inbound connection state to '"Secure"' as remote certificate was valid.
[Debug] 2022-11-23T14:59:45.064Z  [SRV-CONN] [id: 0x35c59e55, [::ffff:192.168.1.120]:64521 => [::ffff:192.168.1.120]:5369] USER_EVENT: TlsHandshakeCompletionEvent(SUCCESS)
[Debug] 2022-11-23T14:59:45.068Z  [SRV-ENC] [id: 0x35c59e55, [::ffff:192.168.1.120]:64521 => [::ffff:192.168.1.120]:5369] RECEIVED: 229B

<encrypted bytes>

[Debug] 2022-11-23T14:59:45.070Z  [LoggingStream] Asynchronously reading from stream. buffer='... (32768 bytes)', offset=0, count=32768, cancellation token='System.Threading.CancellationToken'.
[Debug] 2022-11-23T14:59:45.071Z  [LoggingStream] Asynchronously reading from stream. buffer='... (32768 bytes)', offset=0, count=32768, cancellation token='System.Threading.CancellationToken'.
[Debug] 2022-11-23T14:59:45.074Z  [SRV-CONN] [id: 0x35c59e55, [::ffff:192.168.1.120]:64521 => [::ffff:192.168.1.120]:5369] RECEIVED: 173B

<decrypted bytes>

These are the logs when the issue occurs:

[Debug] 2022-11-23T14:58:19.807Z  [StartTlsHandler] TLS validation callback triggered...
[Debug] 2022-11-23T14:58:19.809Z  [CertificateValidator] Attempting to validate certificate with subject 'X'.
[Debug] 2022-11-23T14:58:19.809Z  [CertificateValidator] Determining certificate with subject 'X' to be valid as there were no SSL policy errors.
[Debug] 2022-11-23T14:58:19.809Z  [StartTlsHandler] Setting inbound connection state to '"Secure"' as remote certificate was valid.
[Debug] 2022-11-23T14:58:19.839Z  [SRV-ENC] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] RECEIVED: 229B

<encrypted bytes>

[Debug] 2022-11-23T14:58:19.840Z  [SRV-ENC] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] RECEIVED_COMPLETE
[Debug] 2022-11-23T14:58:19.840Z  [SRV-CONN] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] RECEIVED_COMPLETE
[Debug] 2022-11-23T14:58:19.840Z  [SRV-CONN] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] READ
[Debug] 2022-11-23T14:58:19.840Z  [SRV-ENC] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] READ
[Debug] 2022-11-23T14:58:19.841Z  [SRV-CONN] [id: 0x6286a09c, [::ffff:192.168.1.120]:64411 => [::ffff:192.168.1.120]:5369] USER_EVENT: TlsHandshakeCompletionEvent(SUCCESS)

Nothing more is logged in the failure case. The SslStream's inner stream is never invoked, and the decrypted bytes are never propagated through the pipeline.

[ailn]

Just to clarify I assume you use latest version of dotnetty (0.7.5), correct? What's the environment: is it .net6?