From b3b91a854a1e30f00f861bb6dec3ff6118d7c574 Mon Sep 17 00:00:00 2001 From: Lindsay Stewart Date: Wed, 10 Jan 2024 13:48:40 -0800 Subject: [PATCH] logging --- bindings/rust/s2n-tls-tokio/src/lib.rs | 23 ++++++++++++++----- bindings/rust/s2n-tls-tokio/tests/shutdown.rs | 4 ++++ tls/s2n_shutdown.c | 22 +++++++++++++++++- 3 files changed, 42 insertions(+), 7 deletions(-) diff --git a/bindings/rust/s2n-tls-tokio/src/lib.rs b/bindings/rust/s2n-tls-tokio/src/lib.rs index 52f31daaa69..fa64e37cce3 100644 --- a/bindings/rust/s2n-tls-tokio/src/lib.rs +++ b/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>>, + mode: Mode, } impl TlsStream @@ -176,12 +177,13 @@ where &mut self.stream } - async fn open(mut conn: C, stream: S) -> Result { + async fn open(mut conn: C, stream: S, mode: Mode) -> Result { 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> { + 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 } } diff --git a/bindings/rust/s2n-tls-tokio/tests/shutdown.rs b/bindings/rust/s2n-tls-tokio/tests/shutdown.rs index d5e59fc5f52..2ffcfeccb65 100644 --- a/bindings/rust/s2n-tls-tokio/tests/shutdown.rs +++ b/bindings/rust/s2n-tls-tokio/tests/shutdown.rs @@ -144,6 +144,7 @@ async fn shutdown_after_halfclose_split() -> Result<(), Box Result<(), Box> { + 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> { 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> { // // 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(()) } diff --git a/tls/s2n_shutdown.c b/tls/s2n_shutdown.c index 3ad818d6c00..1337d9290fd 100644 --- a/tls/s2n_shutdown.c +++ b/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,6 +112,9 @@ 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)); @@ -111,6 +122,7 @@ int s2n_shutdown(struct s2n_connection *conn, s2n_blocked_status *blocked) * 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)); } }