From d2666e6ded3ab77a222c784eda8662a3d9f321f8 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Thu, 21 Mar 2019 17:01:12 +0100 Subject: [PATCH] tls: add debugging to native TLS code MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Backport-PR-URL: https://github.com/nodejs/node/pull/26951 PR-URL: https://github.com/nodejs/node/pull/26843 Reviewed-By: Sam Roberts Reviewed-By: Colin Ihrig Reviewed-By: Minwoo Jung Reviewed-By: Ben Noordhuis Reviewed-By: James M Snell Reviewed-By: Tobias Nießen Reviewed-By: Ruben Bridgewater --- src/tls_wrap.cc | 103 +++++++++++++++++++++++++++++++++++++++++------- src/tls_wrap.h | 2 + 2 files changed, 91 insertions(+), 14 deletions(-) diff --git a/src/tls_wrap.cc b/src/tls_wrap.cc index 17f9ccacf1b379..59400d8f3a4a72 100644 --- a/src/tls_wrap.cc +++ b/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,18 @@ TLSWrap::TLSWrap(Environment* env, stream->PushStreamListener(this); InitSSL(); + Debug(this, "Created new TLSWrap"); } 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 +99,7 @@ bool TLSWrap::InvokeQueued(int status, const char* error_str) { void TLSWrap::NewSessionDoneCb() { + Debug(this, "NewSessionDoneCb()"); Cycle(); } @@ -184,6 +189,7 @@ void TLSWrap::Receive(const FunctionCallbackInfo& 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 +236,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) { Local 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 callback; @@ -245,6 +252,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 callback; @@ -259,31 +267,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, "Returning from EncOut(), hello_parser_ active"); return; + } // Write in progress - if (write_size_ != 0) + if (write_size_ != 0) { + Debug(this, "Returning from 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, "Returning from 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, "Returning from 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,6 +336,7 @@ 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); @@ -320,6 +344,7 @@ void TLSWrap::EncOut() { } 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 +356,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,16 +476,23 @@ Local 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, "Returning from ClearOut(), hello_parser_ active"); return; + } // No reads after EOF - if (eof_) + if (eof_) { + Debug(this, "Returning from ClearOut(), EOF reached"); return; + } - if (ssl_ == nullptr) + if (ssl_ == nullptr) { + Debug(this, "Returning from ClearOut(), ssl_ == nullptr"); return; + } crypto::MarkPopErrorOnReturn mark_pop_error_on_return; @@ -463,6 +500,7 @@ void TLSWrap::ClearOut() { 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 +518,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, "Returning from read loop, ssl_ == nullptr"); return; + } read -= avail; current += avail; @@ -507,6 +547,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 +560,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, "Returning from ClearIn(), hello_parser_ active"); return; + } - if (ssl_ == nullptr) + if (ssl_ == nullptr) { + Debug(this, "Returning from ClearIn(), ssl_ == nullptr"); return; + } std::vector buffers; buffers.swap(pending_cleartext_input_); @@ -537,6 +583,7 @@ 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(avail)); if (written == -1) break; @@ -544,6 +591,7 @@ void TLSWrap::ClearIn() { // 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 +605,13 @@ void TLSWrap::ClearIn() { std::string error_str; Local 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. @@ -574,6 +624,17 @@ void TLSWrap::ClearIn() { } +std::string TLSWrap::diagnostic_name() const { + std::string name = "TLSWrap "; + if (is_server()) + name += "server ("; + else + name += "client ("; + name += std::to_string(static_cast(get_async_id())) + ")"; + return name; +} + + AsyncWrap* TLSWrap::GetAsyncWrap() { return static_cast(this); } @@ -603,6 +664,7 @@ bool TLSWrap::IsClosing() { int TLSWrap::ReadStart() { + Debug(this, "ReadStart()"); if (stream_ != nullptr) return stream_->ReadStart(); return 0; @@ -610,6 +672,7 @@ int TLSWrap::ReadStart() { int TLSWrap::ReadStop() { + Debug(this, "ReadStop()"); if (stream_ != nullptr) return stream_->ReadStop(); return 0; @@ -633,6 +696,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 +724,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 +758,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(bufs[i].len)); + Debug(this, "Writing %zu bytes, written = %d", bufs[i].len, written); if (written == -1) break; } @@ -702,10 +769,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 +801,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 +835,7 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) { size_t avail = 0; uint8_t* data = reinterpret_cast(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 +850,7 @@ ShutdownWrap* TLSWrap::CreateShutdownWrap(Local 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 +916,7 @@ void TLSWrap::EnableSessionCallbacks( void TLSWrap::DestroySSL(const FunctionCallbackInfo& 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 +931,7 @@ void TLSWrap::DestroySSL(const FunctionCallbackInfo& args) { if (wrap->stream_ != nullptr) wrap->stream_->RemoveStreamListener(wrap); + Debug(wrap, "DestroySSL() finished"); } @@ -870,6 +944,7 @@ void TLSWrap::EnableCertCb(const FunctionCallbackInfo& args) { void TLSWrap::OnClientHelloParseEnd(void* arg) { TLSWrap* c = static_cast(arg); + Debug(c, "OnClientHelloParseEnd()"); c->Cycle(); } diff --git a/src/tls_wrap.h b/src/tls_wrap.h index 84abd55c164b8d..85a53f236df5c9 100644 --- a/src/tls_wrap.h +++ b/src/tls_wrap.h @@ -88,6 +88,8 @@ class TLSWrap : public AsyncWrap, SET_MEMORY_INFO_NAME(TLSWrap) SET_SELF_SIZE(TLSWrap) + std::string diagnostic_name() const override; + protected: // Alternative to StreamListener::stream(), that returns a StreamBase instead // of a StreamResource.