Test blinding

bindings/rust/s2n-tls-tokio/src/lib.rs

@@ -22,7 +22,7 @@ use std::{
 };
 use tokio::{
     io::{AsyncRead, AsyncWrite, ReadBuf},
-    time::{sleep, Duration, Sleep},
+    time::{sleep, Duration, Sleep, Instant},
 };
 
 macro_rules! ready {
@@ -55,7 +55,7 @@ where
         S: AsyncRead + AsyncWrite + Unpin,
     {
         let conn = self.builder.build_connection(Mode::Server)?;
-        TlsStream::open(conn, stream).await
+        TlsStream::open(conn, stream, Mode::Server).await
     }
 }
 
@@ -85,7 +85,7 @@ where
     {
         let mut conn = self.builder.build_connection(Mode::Client)?;
         conn.as_mut().set_server_name(domain)?;
-        TlsStream::open(conn, stream).await
+        TlsStream::open(conn, stream, Mode::Client).await
     }
 }
 
@@ -159,6 +159,7 @@ where
     conn: C,
     stream: S,
     blinding: Option<Pin<Box<BlindingState>>>,
+    mode: Mode,
 }
 
 impl<S, C> TlsStream<S, C>
@@ -176,12 +177,13 @@ where
         &mut self.stream
     }
 
-    async fn open(mut conn: C, stream: S) -> Result<Self, Error> {
+    async fn open(mut conn: C, stream: S, mode: Mode) -> Result<Self, Error> {
         conn.as_mut().set_blinding(Blinding::SelfService)?;
         let mut tls = TlsStream {
             conn,
             stream,
             blinding: None,
+            mode,
         };
         TlsHandshake {
             tls: &mut tls,
@@ -402,11 +404,17 @@ where
     }
 
     fn poll_shutdown(mut self: Pin<&mut Self>, ctx: &mut Context<'_>) -> Poll<io::Result<()>> {
+        let mode = self.mode;
+
+        println!("{:?}{:?} poll_shutdown start", Instant::now(), mode);
         ready!(self.as_mut().poll_blinding(ctx))?;
+        println!("{:?}{:?} blinding complete", Instant::now(), mode);
 
-        let status = ready!(self.as_mut().with_io(ctx, |mut context| {
+        let status = self.as_mut().with_io(ctx, |mut context| {
             context.conn.as_mut().poll_shutdown().map(|r| r.map(|_| ()))
-        }));
+        });
+        println!("{:?}{:?} s2n_shutdown complete: {:?}", Instant::now(), mode, status);
+        let status = ready!(status);
 
         if let Err(e) = status {
             // In case of an error shutting down, make sure you wait for
@@ -416,7 +424,10 @@ where
             unreachable!("should have returned the error we just put in!");
         }
 
-        Pin::new(&mut self.as_mut().stream).poll_shutdown(ctx)
+        println!("{:?}{:?} tcp shutdown start", Instant::now(), mode);
+        let r = Pin::new(&mut self.as_mut().stream).poll_shutdown(ctx);
+        println!("{:?}{:?} tcp shutdown complete: {:?}", Instant::now(), mode, r);
+        r
     }
 }
 

bindings/rust/s2n-tls-tokio/tests/shutdown.rs

@@ -144,6 +144,7 @@ async fn shutdown_after_halfclose_split() -> Result<(), Box<dyn std::error::Erro
 
 #[tokio::test(start_paused = true)]
 async fn shutdown_with_blinding() -> Result<(), Box<dyn std::error::Error>> {
+    for _ in 1..100 {
     let clock = common::TokioTime::default();
     let mut server_config = common::server_config()?;
     server_config.set_monotonic_clock(clock)?;
@@ -170,21 +171,26 @@ async fn shutdown_with_blinding() -> Result<(), Box<dyn std::error::Error>> {
     assert!(result.is_err());
 
     // Shutdown MUST NOT complete faster than minimal blinding time.
+    println!("{:?} Test: first join", time::Instant::now());
     let (timeout, _) = join!(
         time::timeout(common::MIN_BLINDING_SECS, server.shutdown()),
         time::timeout(common::MIN_BLINDING_SECS, read_until_shutdown(&mut client)),
     );
+    println!("{:?} Test: first join done", time::Instant::now());
     assert!(timeout.is_err());
 
     // Shutdown MUST eventually complete after blinding.
     //
     // We check for completion, but not for success. At the moment, the
     // call to s2n_shutdown will fail due to issues in the underlying C library.
+    println!("{:?} Test: second join", time::Instant::now());
     let (timeout, _) = join!(
         time::timeout(common::MAX_BLINDING_SECS, server.shutdown()),
         time::timeout(common::MAX_BLINDING_SECS, read_until_shutdown(&mut client)),
     );
+    println!("{:?} Test: second join done", time::Instant::now());
     assert!(timeout.is_ok());
+    }
 
     Ok(())
 }

tests/unit/s2n_shutdown_test.c

@@ -356,6 +356,61 @@ int main(int argc, char **argv)
         EXPECT_SUCCESS(s2n_shutdown(conn, &blocked));
     };
 
+    /* Test: previous failed partial reads to not affect reading close_notify */
+    {
+        DEFER_CLEANUP(struct s2n_connection *conn = s2n_connection_new(S2N_SERVER),
+                s2n_connection_ptr_free);
+        EXPECT_NOT_NULL(conn);
+        EXPECT_OK(s2n_skip_handshake(conn));
+        EXPECT_SUCCESS(s2n_connection_set_blinding(conn, S2N_SELF_SERVICE_BLINDING));
+
+        /* Set the version so that a record header with the wrong version will
+         * be rejected as invalid.
+         */
+        conn->actual_protocol_version_established = true;
+        conn->actual_protocol_version = S2N_TLS13;
+
+        s2n_blocked_status blocked = S2N_NOT_BLOCKED;
+        DEFER_CLEANUP(struct s2n_stuffer input = { 0 }, s2n_stuffer_free);
+        EXPECT_SUCCESS(s2n_stuffer_growable_alloc(&input, 0));
+        DEFER_CLEANUP(struct s2n_stuffer output = { 0 }, s2n_stuffer_free);
+        EXPECT_SUCCESS(s2n_stuffer_growable_alloc(&output, 0));
+        EXPECT_SUCCESS(s2n_connection_set_io_stuffers(&input, &output, conn));
+
+        /* Receive a malformed record.
+         * We want reading this record to leave our IO in a bad state.
+         */
+        uint8_t header_bytes[] = {
+            /* record type */
+            TLS_HANDSHAKE,
+            /* bad protocol version */
+            0,
+            0,
+            /* zero length */
+            0,
+            0,
+        };
+        EXPECT_SUCCESS(s2n_stuffer_write_bytes(&input, header_bytes, sizeof(header_bytes)));
+        uint8_t recv_buffer[1] = { 0 };
+        EXPECT_FAILURE_WITH_ERRNO(
+                s2n_recv(conn, recv_buffer, sizeof(recv_buffer), &blocked),
+                S2N_ERR_BAD_MESSAGE);
+        EXPECT_TRUE(s2n_stuffer_space_remaining(&conn->header_in) < sizeof(header_bytes));
+
+        /* Clear the blinding delay so that we can call s2n_shutdown */
+        EXPECT_TRUE(conn->delay > 0);
+        conn->delay = 0;
+
+        /* Make the valid close_notify available */
+        EXPECT_SUCCESS(s2n_stuffer_write_bytes(&input, alert_record_header, sizeof(alert_record_header)));
+        EXPECT_SUCCESS(s2n_stuffer_write_bytes(&input, close_notify_alert, sizeof(close_notify_alert)));
+
+        /* Successfully shutdown.
+         * The initial bad call to s2n_recv should not affect shutdown.
+         */
+        EXPECT_SUCCESS(s2n_shutdown(conn, &blocked));
+    };
+
     /* Test: s2n_shutdown with aggressive socket close */
     {
         DEFER_CLEANUP(struct s2n_connection *server_conn = s2n_connection_new(S2N_SERVER),

tls/s2n_shutdown.c

@@ -58,25 +58,32 @@ int s2n_shutdown_send(struct s2n_connection *conn, s2n_blocked_status *blocked)
     POSIX_ENSURE_REF(blocked);
     *blocked = S2N_NOT_BLOCKED;
 
+    const char *mode = (conn->mode == S2N_SERVER) ? "server" : "client";
+    printf("C%s s2n_shutdown_send\n", mode);
+
     /* Treat this call as a no-op if already wiped.
      * This should probably be an error, but wasn't in the past so is left as-is
      * for backwards compatibility.
      */
     if (conn->send == NULL && conn->recv == NULL) {
+        printf("C%s don't send close_notify: already wiped\n", mode);
         return S2N_SUCCESS;
     }
 
     /* Flush any outstanding data */
     s2n_atomic_flag_set(&conn->write_closed);
+    printf("C%s flush\n", mode);
     POSIX_GUARD(s2n_flush(conn, blocked));
 
     /* For a connection closed due to receiving an alert, we don't send anything. */
     if (s2n_atomic_flag_test(&conn->error_alert_received)) {
+        printf("C%s don't send close_notify: alert received\n", mode);
         return S2N_SUCCESS;
     }
 
     /* If we've already sent an alert, don't send another. */
     if (conn->alert_sent) {
+        printf("C%s don't send close_notify: alert sent\n", mode);
         return S2N_SUCCESS;
     }
 
@@ -93,6 +100,7 @@ int s2n_shutdown_send(struct s2n_connection *conn, s2n_blocked_status *blocked)
      *# Each party MUST send a "close_notify" alert before closing its write
      *# side of the connection, unless it has already sent some error alert.
      */
+    printf("C%s write close_notify\n", mode);
     POSIX_GUARD_RESULT(s2n_alerts_write_error_or_close_notify(conn));
     POSIX_GUARD(s2n_flush(conn, blocked));
     return S2N_SUCCESS;
@@ -104,13 +112,17 @@ int s2n_shutdown(struct s2n_connection *conn, s2n_blocked_status *blocked)
     POSIX_ENSURE_REF(blocked);
     *blocked = S2N_NOT_BLOCKED;
 
+    const char *mode = (conn->mode == S2N_SERVER) ? "server" : "client";
+    printf("C%s s2n_shutdown\n", mode);
+
     /* If necessary, send an alert to indicate shutdown. */
     POSIX_GUARD(s2n_shutdown_send(conn, blocked));
 
     /* If we don't expect a close_notify from our peer,
      * just ensure that the connection is marked closed.
      */
     if (!s2n_shutdown_expect_close_notify(conn)) {
+        printf("C%s no close_notify expected: done\n", mode);
         POSIX_GUARD_RESULT(s2n_connection_set_closed(conn));
         *blocked = S2N_NOT_BLOCKED;
         return S2N_SUCCESS;
@@ -121,16 +133,26 @@ int s2n_shutdown(struct s2n_connection *conn, s2n_blocked_status *blocked)
     int isSSLv2 = false;
     *blocked = S2N_BLOCKED_ON_READ;
     while (!s2n_atomic_flag_test(&conn->close_notify_received)) {
-        POSIX_GUARD(s2n_read_full_record(conn, &record_type, &isSSLv2));
+        /* Reset IO. Make sure we do this before attempting to read a record in
+         * case a previous failed read left IO in a bad state.
+         */
+        POSIX_GUARD(s2n_stuffer_wipe(&conn->header_in));
+        POSIX_GUARD(s2n_stuffer_wipe(&conn->in));
+        conn->in_status = ENCRYPTED;
+
+        printf("C%s attempting to read close_notify\n", mode);
+        int r = s2n_read_full_record(conn, &record_type, &isSSLv2);
+        if (r != S2N_SUCCESS) {
+            printf("C%s read failed: %s, %s\n", mode,
+                    s2n_strerror_name(s2n_errno),
+                    s2n_strerror_debug(s2n_errno, NULL));
+        }
+        POSIX_GUARD(r);
         POSIX_ENSURE(!isSSLv2, S2N_ERR_BAD_MESSAGE);
         if (record_type == TLS_ALERT) {
+            printf("C%s alert found\n", mode);
             POSIX_GUARD(s2n_process_alert_fragment(conn));
         }
-
-        /* Wipe and keep trying */
-        POSIX_GUARD(s2n_stuffer_wipe(&conn->header_in));
-        POSIX_GUARD(s2n_stuffer_wipe(&conn->in));
-        conn->in_status = ENCRYPTED;
     }
 
     *blocked = S2N_NOT_BLOCKED;