chore: add logs to help debugging tls issues in prod

util/tls/tls_socket.cc

@@ -13,6 +13,11 @@
 #include "util/fibers/proactor_base.h"
 #include "util/tls/tls_engine.h"
 
+#define VSOCK(verbosity)                                                      \
+  VLOG(verbosity) << "sock[" << native_handle() << "], state " << int(state_) \
+                  << ", write_total:" << upstream_write_ << " " << " pending output: " \
+                  << engine_->OutputPending() << " "
+
 namespace util {
 namespace tls {
 
@@ -52,8 +57,9 @@ error_condition error_category::default_error_condition(int ev) const noexcept {
 
 error_category tls_category;
 
-inline error_code SSL2Error(unsigned long err) {
+inline error_code SSL2Error(unsigned lineno, unsigned long err) {
   CHECK_LT(err, unsigned(INT_MAX));
+  VLOG(1) << "SSL2Error at line " << lineno << ": " << error_category{}.message(int(err));
 
   return error_code{int(err), tls_category};
 }
@@ -128,12 +134,13 @@ auto TlsSocket::Accept() -> AcceptResult {
     // it is important to send output (protocol errors) before we return from this function.
     error_code ec = MaybeSendOutput();
     if (ec) {
+      VSOCK(1) << "MaybeSendOutput failed " << ec;
       return make_unexpected(ec);
     }
 
     // now check the result of the handshake.
     if (!op_result) {
-      return make_unexpected(SSL2Error(op_result.error()));
+      return make_unexpected(SSL2Error(__LINE__, op_result.error()));
     }
 
     int op_val = *op_result;
@@ -243,7 +250,7 @@ io::Result<size_t> TlsSocket::RecvMsg(const msghdr& msg, int flags) {
 
     Engine::OpResult op_result = engine_->Read(dest.data(), read_len);
     if (!op_result) {
-      return make_unexpected(SSL2Error(op_result.error()));
+      return make_unexpected(SSL2Error(__LINE__, op_result.error()));
     }
 
     int op_val = *op_result;
@@ -340,7 +347,7 @@ io::Result<size_t> TlsSocket::SendBuffer(Engine::Buffer buf) {
   while (true) {
     Engine::OpResult op_result = engine_->Write(buf);
     if (!op_result) {
-      return make_unexpected(SSL2Error(op_result.error()));
+      return make_unexpected(SSL2Error(__LINE__, op_result.error()));
     }
 
     int op_val = *op_result;
@@ -411,16 +418,17 @@ auto TlsSocket::MaybeSendOutput() -> error_code {
     return error_code{};
   }
 
-  return HandleSocketWrite();
+  return HandleUpstreamWrite();
 }
 
-auto TlsSocket::HandleSocketRead() -> error_code {
+auto TlsSocket::HandleUpstreamRead() -> error_code {
   RETURN_ON_ERROR(MaybeSendOutput());
 
   if (state_ & READ_IN_PROGRESS) {
     // We need to Yield because otherwise we might end up in an infinite loop.
     // See also comments in MaybeSendOutput.
     ThisFiber::Yield();
+    VSOCK(1) << "HandleUpstreamRead: Yielded";
     return error_code{};
   }
 
@@ -429,24 +437,28 @@ auto TlsSocket::HandleSocketRead() -> error_code {
   io::Result<size_t> esz = next_sock_->Recv(mut_buf, 0);
   state_ &= ~READ_IN_PROGRESS;
   if (!esz) {
+    // log any errors as well as situations where we have unflushed output.
+    if (esz.error() != errc::connection_aborted || engine_->OutputPending() > 0) {
+      VSOCK(1) << "HandleUpstreamRead failed " << esz.error();
+    }
     return esz.error();
   }
 
-  DVLOG(1) << "TlsSocket:Read " << *esz << " bytes";
+  DVLOG(1) << "HandleUpstreamRead " << *esz << " bytes";
 
   engine_->CommitInput(*esz);
 
   return error_code{};
 }
 
-error_code TlsSocket::HandleSocketWrite() {
+error_code TlsSocket::HandleUpstreamWrite() {
   Engine::Buffer buffer = engine_->PeekOutputBuf();
   DCHECK(!buffer.empty());
 
   if (buffer.empty())
     return {};
 
-  DVLOG(2) << "HandleSocketWrite " << buffer.size();
+  DVLOG(2) << "HandleUpstreamWrite " << buffer.size();
   // we do not allow concurrent writes from multiple fibers.
   state_ |= WRITE_IN_PROGRESS;
   while (!buffer.empty()) {
@@ -456,13 +468,23 @@ error_code TlsSocket::HandleSocketWrite() {
     if (!write_result) {
       state_ &= ~WRITE_IN_PROGRESS;
 
+      // broken_pipe - happens when the other side closes the connection. do not log this.
+      if (write_result.error() != errc::broken_pipe) {
+        VSOCK(1) << "HandleUpstreamWrite failed " << write_result.error();
+      }
+
       return write_result.error();
     }
     CHECK_GT(*write_result, 0u);
+    upstream_write_ += *write_result;
     engine_->ConsumeOutputBuf(*write_result);
     buffer.remove_prefix(*write_result);
   }
-  DCHECK_EQ(engine_->OutputPending(), 0u);
+
+  if (engine_->OutputPending() > 0) {
+    LOG(INFO) << "ssl buffer is not empty with " << engine_->OutputPending()
+              << " bytes. short write detected";
+  }
 
   state_ &= ~WRITE_IN_PROGRESS;
 
@@ -472,9 +494,10 @@ error_code TlsSocket::HandleSocketWrite() {
 error_code TlsSocket::HandleOp(int op_val) {
   switch (op_val) {
     case Engine::EOF_STREAM:
+      VLOG(1) << "EOF_STREAM received " << next_sock_->native_handle();
       return make_error_code(errc::connection_reset);
     case Engine::NEED_READ_AND_MAYBE_WRITE:
-      return HandleSocketRead();
+      return HandleUpstreamRead();
     case Engine::NEED_WRITE:
       return MaybeSendOutput();
     default:

util/tls/tls_socket.h

@@ -95,13 +95,14 @@ class TlsSocket final : public FiberSocketBase {
   error_code MaybeSendOutput();
 
   /// Read encrypted data from the network socket and feed it into the TLS engine.
-  error_code HandleSocketRead();
+  error_code HandleUpstreamRead();
 
-  error_code HandleSocketWrite();
+  error_code HandleUpstreamWrite();
   error_code HandleOp(int op);
 
   std::unique_ptr<FiberSocketBase> next_sock_;
   std::unique_ptr<Engine> engine_;
+  size_t upstream_write_ = 0;
 
   enum { WRITE_IN_PROGRESS = 1, READ_IN_PROGRESS = 2, SHUTDOWN_IN_PROGRESS = 4, SHUTDOWN_DONE = 8 };
   uint8_t state_{0};