logging

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

@@ -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", mode);
         ready!(self.as_mut().poll_blinding(ctx))?;
+        println!("{:?} blinding complete", 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: {:?}", 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", mode);
+        let r = Pin::new(&mut self.as_mut().stream).poll_shutdown(ctx);
+        println!("{:?} tcp shutdown complete: {:?}", 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,6 +171,7 @@ 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");
     let (timeout, _) = join!(
         time::timeout(common::MIN_BLINDING_SECS, server.shutdown()),
         time::timeout(common::MIN_BLINDING_SECS, read_until_shutdown(&mut client)),
@@ -180,11 +182,13 @@ async fn shutdown_with_blinding() -> Result<(), Box<dyn std::error::Error>> {
     //
     // 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");
     let (timeout, _) = join!(
         time::timeout(common::MAX_BLINDING_SECS, server.shutdown()),
         time::timeout(common::MAX_BLINDING_SECS, read_until_shutdown(&mut client)),
     );
     assert!(timeout.is_ok());
+    }
 
     Ok(())
 }

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;
@@ -128,9 +140,17 @@ int s2n_shutdown(struct s2n_connection *conn, s2n_blocked_status *blocked)
         POSIX_GUARD(s2n_stuffer_wipe(&conn->in));
         conn->in_status = ENCRYPTED;
 
-        POSIX_GUARD(s2n_read_full_record(conn, &record_type, &isSSLv2));
+        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));
         }
     }