tls: add debugging to native TLS code

src/tls_wrap.cc

@@ -21,6 +21,7 @@
 
 #include "tls_wrap.h"
 #include "async_wrap-inl.h"
+#include "debug_utils.h"
 #include "node_buffer.h"  // Buffer
 #include "node_crypto.h"  // SecureContext
 #include "node_crypto_bio.h"  // NodeBIO
@@ -72,15 +73,19 @@ TLSWrap::TLSWrap(Environment* env,
   stream->PushStreamListener(this);
 
   InitSSL();
+  Debug(this, "Created new TLSWrap (%s)",
+        kind == kClient ? "client" : "server");
 }
 
 
 TLSWrap::~TLSWrap() {
+  Debug(this, "~TLSWrap()");
   sc_ = nullptr;
 }
 
 
 bool TLSWrap::InvokeQueued(int status, const char* error_str) {
+  Debug(this, "InvokeQueued(%d, %s)", status, error_str);
   if (!write_callback_scheduled_)
     return false;
 
@@ -95,6 +100,7 @@ bool TLSWrap::InvokeQueued(int status, const char* error_str) {
 
 
 void TLSWrap::NewSessionDoneCb() {
+  Debug(this, "NewSessionDoneCb()");
   Cycle();
 }
 
@@ -184,6 +190,7 @@ void TLSWrap::Receive(const FunctionCallbackInfo<Value>& args) {
   CHECK(Buffer::HasInstance(args[0]));
   char* data = Buffer::Data(args[0]);
   size_t len = Buffer::Length(args[0]);
+  Debug(wrap, "Receiving %zu bytes injected from JS", len);
 
   // Copy given buffer entirely or partiall if handle becomes closed
   while (len > 0 && wrap->IsAlive() && !wrap->IsClosing()) {
@@ -230,6 +237,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
   Local<Object> object = c->object();
 
   if (where & SSL_CB_HANDSHAKE_START) {
+    Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_START);");
     // Start is tracked to limit number and frequency of renegotiation attempts,
     // since excessive renegotiation may be an attack.
     Local<Value> callback;
@@ -245,6 +253,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
   // sending HelloRequest in OpenSSL-1.1.1.
   // We need to check whether this is in a renegotiation state or not.
   if (where & SSL_CB_HANDSHAKE_DONE && !SSL_renegotiate_pending(ssl)) {
+    Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);");
     CHECK(!SSL_renegotiate_pending(ssl));
     Local<Value> callback;
 
@@ -259,31 +268,46 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
 
 
 void TLSWrap::EncOut() {
+  Debug(this, "Trying to write encrypted output");
+
   // Ignore cycling data if ClientHello wasn't yet parsed
-  if (!hello_parser_.IsEnded())
+  if (!hello_parser_.IsEnded()) {
+    Debug(this, "Bailing out of EncOut(), hello_parser_ active");
     return;
+  }
 
   // Write in progress
-  if (write_size_ != 0)
+  if (write_size_ != 0) {
+    Debug(this, "Bailing out of EncOut(), write currently in progress");
     return;
+  }
 
   // Wait for `newSession` callback to be invoked
-  if (is_awaiting_new_session())
+  if (is_awaiting_new_session()) {
+    Debug(this, "Bailing out of EncOut(), awaiting new session");
     return;
+  }
 
   // Split-off queue
-  if (established_ && current_write_ != nullptr)
+  if (established_ && current_write_ != nullptr) {
+    Debug(this, "EncOut() setting write_callback_scheduled_");
     write_callback_scheduled_ = true;
+  }
 
-  if (ssl_ == nullptr)
+  if (ssl_ == nullptr) {
+    Debug(this, "Bailing out of EncOut(), ssl_ == nullptr");
     return;
+  }
 
   // No encrypted output ready to write to the underlying stream.
   if (BIO_pending(enc_out_) == 0) {
+    Debug(this, "No pending encrypted output");
     if (pending_cleartext_input_.empty()) {
       if (!in_dowrite_) {
+        Debug(this, "No pending cleartext input, not inside DoWrite()");
         InvokeQueued(0);
       } else {
+        Debug(this, "No pending cleartext input, inside DoWrite()");
         // TODO(@sam-github, @addaleax) If in_dowrite_ is true, appdata was
         // passed to SSL_write().  If we are here, the data was not encrypted to
         // enc_out_ yet.  Calling Done() "works", but since the write is not
@@ -313,13 +337,15 @@ void TLSWrap::EncOut() {
   for (size_t i = 0; i < count; i++)
     buf[i] = uv_buf_init(data[i], size[i]);
 
+  Debug(this, "Writing %zu buffers to the underlying stream", count);
   StreamWriteResult res = underlying_stream()->Write(bufs, count);
   if (res.err != 0) {
     InvokeQueued(res.err);
     return;
   }
 
   if (!res.async) {
+    Debug(this, "Write finished synchronously");
     HandleScope handle_scope(env()->isolate());
 
     // Simulate asynchronous finishing, TLS cannot handle this at the moment.
@@ -331,21 +357,26 @@ void TLSWrap::EncOut() {
 
 
 void TLSWrap::OnStreamAfterWrite(WriteWrap* req_wrap, int status) {
+  Debug(this, "OnStreamAfterWrite(status = %d)", status);
   if (current_empty_write_ != nullptr) {
+    Debug(this, "Had empty write");
     WriteWrap* finishing = current_empty_write_;
     current_empty_write_ = nullptr;
     finishing->Done(status);
     return;
   }
 
-  if (ssl_ == nullptr)
+  if (ssl_ == nullptr) {
+    Debug(this, "ssl_ == nullptr, marking as cancelled");
     status = UV_ECANCELED;
+  }
 
   // Handle error
   if (status) {
-    // Ignore errors after shutdown
-    if (shutdown_)
+    if (shutdown_) {
+      Debug(this, "Ignoring error after shutdown");
       return;
+    }
 
     // Notify about error
     InvokeQueued(status);
@@ -446,23 +477,31 @@ Local<Value> TLSWrap::GetSSLError(int status, int* err, std::string* msg) {
 
 
 void TLSWrap::ClearOut() {
+  Debug(this, "Trying to read cleartext output");
   // Ignore cycling data if ClientHello wasn't yet parsed
-  if (!hello_parser_.IsEnded())
+  if (!hello_parser_.IsEnded()) {
+    Debug(this, "Bailing out of ClearOut(), hello_parser_ active");
     return;
+  }
 
   // No reads after EOF
-  if (eof_)
+  if (eof_) {
+    Debug(this, "Bailing out of ClearOut(), EOF reached");
     return;
+  }
 
-  if (ssl_ == nullptr)
+  if (ssl_ == nullptr) {
+    Debug(this, "Bailing out of ClearOut(), ssl_ == nullptr");
     return;
+  }
 
   crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
 
   char out[kClearOutChunkSize];
   int read;
   for (;;) {
     read = SSL_read(ssl_.get(), out, sizeof(out));
+    Debug(this, "Read %d bytes of cleartext output", read);
 
     if (read <= 0)
       break;
@@ -480,8 +519,10 @@ void TLSWrap::ClearOut() {
       // Caveat emptor: OnRead() calls into JS land which can result in
       // the SSL context object being destroyed.  We have to carefully
       // check that ssl_ != nullptr afterwards.
-      if (ssl_ == nullptr)
+      if (ssl_ == nullptr) {
+        Debug(this, "Bailing out of read loop, ssl_ == nullptr");
         return;
+      }
 
       read -= avail;
       current += avail;
@@ -507,6 +548,7 @@ void TLSWrap::ClearOut() {
       return;
 
     if (!arg.IsEmpty()) {
+      Debug(this, "Got SSL error (%d), calling onerror", err);
       // When TLS Alert are stored in wbio,
       // it should be flushed to socket before destroyed.
       if (BIO_pending(enc_out_) != 0)
@@ -519,12 +561,17 @@ void TLSWrap::ClearOut() {
 
 
 void TLSWrap::ClearIn() {
+  Debug(this, "Trying to write cleartext input");
   // Ignore cycling data if ClientHello wasn't yet parsed
-  if (!hello_parser_.IsEnded())
+  if (!hello_parser_.IsEnded()) {
+    Debug(this, "Bailing out of ClearIn(), hello_parser_ active");
     return;
+  }
 
-  if (ssl_ == nullptr)
+  if (ssl_ == nullptr) {
+    Debug(this, "Bailing out of ClearIn(), ssl_ == nullptr");
     return;
+  }
 
   std::vector<uv_buf_t> buffers;
   buffers.swap(pending_cleartext_input_);
@@ -537,13 +584,15 @@ void TLSWrap::ClearIn() {
     size_t avail = buffers[i].len;
     char* data = buffers[i].base;
     written = SSL_write(ssl_.get(), data, avail);
+    Debug(this, "Writing %zu bytes, written = %d", avail, written);
     CHECK(written == -1 || written == static_cast<int>(avail));
     if (written == -1)
       break;
   }
 
   // All written
   if (i == buffers.size()) {
+    Debug(this, "Successfully wrote all data to SSL");
     // We wrote all the buffers, so no writes failed (written < 0 on failure).
     CHECK_GE(written, 0);
     return;
@@ -557,11 +606,13 @@ void TLSWrap::ClearIn() {
   std::string error_str;
   Local<Value> arg = GetSSLError(written, &err, &error_str);
   if (!arg.IsEmpty()) {
+    Debug(this, "Got SSL error (%d)", err);
     write_callback_scheduled_ = true;
     // TODO(@sam-github) Should forward an error object with
     // .code/.function/.etc, if possible.
     InvokeQueued(UV_EPROTO, error_str.c_str());
   } else {
+    Debug(this, "Pushing back %zu buffers", buffers.size() - i);
     // Push back the not-yet-written pending buffers into their queue.
     // This can be skipped in the error case because no further writes
     // would succeed anyway.
@@ -603,13 +654,15 @@ bool TLSWrap::IsClosing() {
 
 
 int TLSWrap::ReadStart() {
+  Debug(this, "ReadStart()");
   if (stream_ != nullptr)
     return stream_->ReadStart();
   return 0;
 }
 
 
 int TLSWrap::ReadStop() {
+  Debug(this, "ReadStop()");
   if (stream_ != nullptr)
     return stream_->ReadStop();
   return 0;
@@ -633,6 +686,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
                      size_t count,
                      uv_stream_t* send_handle) {
   CHECK_NULL(send_handle);
+  Debug(this, "DoWrite()");
 
   if (ssl_ == nullptr) {
     ClearError();
@@ -660,8 +714,10 @@ int TLSWrap::DoWrite(WriteWrap* w,
   // onto the socket, we just want the side-effects. After, make sure the
   // WriteWrap was accepted by the stream, or that we call Done() on it.
   if (empty) {
+    Debug(this, "Empty write");
     ClearOut();
     if (BIO_pending(enc_out_) == 0) {
+      Debug(this, "No pending encrypted output, writing to underlying stream");
       CHECK_NULL(current_empty_write_);
       current_empty_write_ = w;
       StreamWriteResult res =
@@ -692,6 +748,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
   for (i = 0; i < count; i++) {
     written = SSL_write(ssl_.get(), bufs[i].base, bufs[i].len);
     CHECK(written == -1 || written == static_cast<int>(bufs[i].len));
+    Debug(this, "Writing %zu bytes, written = %d", bufs[i].len, written);
     if (written == -1)
       break;
   }
@@ -702,10 +759,12 @@ int TLSWrap::DoWrite(WriteWrap* w,
 
     // If we stopped writing because of an error, it's fatal, discard the data.
     if (!arg.IsEmpty()) {
+      Debug(this, "Got SSL error (%d), returning UV_EPROTO", err);
       current_write_ = nullptr;
       return UV_EPROTO;
     }
 
+    Debug(this, "Saving %zu buffers for later write", count - i);
     // Otherwise, save unwritten data so it can be written later by ClearIn().
     pending_cleartext_input_.insert(pending_cleartext_input_.end(),
                                     &bufs[i],
@@ -732,6 +791,7 @@ uv_buf_t TLSWrap::OnStreamAlloc(size_t suggested_size) {
 
 
 void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
+  Debug(this, "Read %zd bytes from underlying stream", nread);
   if (nread < 0)  {
     // Error should be emitted only after all data was read
     ClearOut();
@@ -765,6 +825,7 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
     size_t avail = 0;
     uint8_t* data = reinterpret_cast<uint8_t*>(enc_in->Peek(&avail));
     CHECK_IMPLIES(data == nullptr, avail == 0);
+    Debug(this, "Passing %zu bytes to the hello parser", avail);
     return hello_parser_.Parse(data, avail);
   }
 
@@ -779,6 +840,7 @@ ShutdownWrap* TLSWrap::CreateShutdownWrap(Local<Object> req_wrap_object) {
 
 
 int TLSWrap::DoShutdown(ShutdownWrap* req_wrap) {
+  Debug(this, "DoShutdown()");
   crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
 
   if (ssl_ && SSL_shutdown(ssl_.get()) == 0)
@@ -844,6 +906,7 @@ void TLSWrap::EnableSessionCallbacks(
 void TLSWrap::DestroySSL(const FunctionCallbackInfo<Value>& args) {
   TLSWrap* wrap;
   ASSIGN_OR_RETURN_UNWRAP(&wrap, args.Holder());
+  Debug(wrap, "DestroySSL()");
 
   // If there is a write happening, mark it as finished.
   wrap->write_callback_scheduled_ = true;
@@ -858,6 +921,7 @@ void TLSWrap::DestroySSL(const FunctionCallbackInfo<Value>& args) {
 
   if (wrap->stream_ != nullptr)
     wrap->stream_->RemoveStreamListener(wrap);
+  Debug(wrap, "DestroySSL() finished");
 }
 
 
@@ -870,6 +934,7 @@ void TLSWrap::EnableCertCb(const FunctionCallbackInfo<Value>& args) {
 
 void TLSWrap::OnClientHelloParseEnd(void* arg) {
   TLSWrap* c = static_cast<TLSWrap*>(arg);
+  Debug(c, "OnClientHelloParseEnd()");
   c->Cycle();
 }