Azure / Azure/DotNetty

Race condition in server TlsHandler when negotiating client certificate

Open
#602 1 comment 0 reactions 0 assignees View on GitHub
Dominant language
C#
Stars
4.3k
Forks
1k
PR merge metrics
No merged PRs in 30d

Description

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

[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

```

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

[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.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.