From b800d297e17253f21bb0b2dce95e72e56f68a4b8 Mon Sep 17 00:00:00 2001 From: Sam Roberts Date: Wed, 16 Jan 2019 11:12:30 -0800 Subject: [PATCH 1/4] src: in-source comments and minor TLS cleanups Renamed some internal C++ methods and properties for consistency, and commented SSL I/O. - Rename waiting_new_session_ after is_waiting_new_session(), instead of using reverse naming (new_session_wait_), and change "waiting" to "awaiting". - Make TLSWrap::ClearIn() return void, the value is never used. - Fix a getTicketKeys() cut-n-paste error. Since it doesn't use the arguments, remove them from the js wrapper. - Remove call of setTicketKeys(getTicketKeys()), its a no-op. PR-URL: https://github.com/nodejs/node/pull/25713 Reviewed-By: Anna Henningsen Reviewed-By: Michael Dawson Reviewed-By: Ben Noordhuis --- lib/_tls_wrap.js | 4 +-- src/node_crypto.cc | 5 +-- src/node_crypto.h | 6 ++-- src/node_crypto_bio.h | 11 ++++--- src/node_crypto_clienthello.h | 3 ++ src/stream_wrap.cc | 2 +- src/tls_wrap.cc | 60 +++++++++++++++++++++++++---------- src/tls_wrap.h | 30 ++++++++++++++---- 8 files changed, 84 insertions(+), 37 deletions(-) diff --git a/lib/_tls_wrap.js b/lib/_tls_wrap.js index 7455928dbeba27..bcaf9b48e13db8 100644 --- a/lib/_tls_wrap.js +++ b/lib/_tls_wrap.js @@ -929,8 +929,8 @@ Server.prototype._setServerData = function(data) { }; -Server.prototype.getTicketKeys = function getTicketKeys(keys) { - return this._sharedCreds.context.getTicketKeys(keys); +Server.prototype.getTicketKeys = function getTicketKeys() { + return this._sharedCreds.context.getTicketKeys(); }; diff --git a/src/node_crypto.cc b/src/node_crypto.cc index c5db8377c442e7..1d9214f18dee58 100644 --- a/src/node_crypto.cc +++ b/src/node_crypto.cc @@ -1475,7 +1475,7 @@ int SSLWrap::NewSessionCallback(SSL* s, SSL_SESSION* sess) { reinterpret_cast(session_id), session_id_length).ToLocalChecked(); Local argv[] = { session, buff }; - w->new_session_wait_ = true; + w->awaiting_new_session_ = true; w->MakeCallback(env->onnewsession_string(), arraysize(argv), argv); return 0; @@ -2003,6 +2003,7 @@ void SSLWrap::Renegotiate(const FunctionCallbackInfo& args) { ClearErrorOnReturn clear_error_on_return; + // XXX(sam) Return/throw an error, don't discard the SSL error reason. bool yes = SSL_renegotiate(w->ssl_.get()) == 1; args.GetReturnValue().Set(yes); } @@ -2036,7 +2037,7 @@ template void SSLWrap::NewSessionDone(const FunctionCallbackInfo& args) { Base* w; ASSIGN_OR_RETURN_UNWRAP(&w, args.Holder()); - w->new_session_wait_ = false; + w->awaiting_new_session_ = false; w->NewSessionDoneCb(); } diff --git a/src/node_crypto.h b/src/node_crypto.h index ec784fff88f199..b64a8c249a1303 100644 --- a/src/node_crypto.h +++ b/src/node_crypto.h @@ -218,7 +218,7 @@ class SSLWrap { kind_(kind), next_sess_(nullptr), session_callbacks_(false), - new_session_wait_(false), + awaiting_new_session_(false), cert_cb_(nullptr), cert_cb_arg_(nullptr), cert_cb_running_(false) { @@ -234,7 +234,7 @@ class SSLWrap { inline void enable_session_callbacks() { session_callbacks_ = true; } inline bool is_server() const { return kind_ == kServer; } inline bool is_client() const { return kind_ == kClient; } - inline bool is_waiting_new_session() const { return new_session_wait_; } + inline bool is_awaiting_new_session() const { return awaiting_new_session_; } inline bool is_waiting_cert_cb() const { return cert_cb_ != nullptr; } protected: @@ -324,7 +324,7 @@ class SSLWrap { SSLSessionPointer next_sess_; SSLPointer ssl_; bool session_callbacks_; - bool new_session_wait_; + bool awaiting_new_session_; // SSL_set_cert_cb CertCb cert_cb_; diff --git a/src/node_crypto_bio.h b/src/node_crypto_bio.h index 1c62fbbd359405..b7f1d4f169edfe 100644 --- a/src/node_crypto_bio.h +++ b/src/node_crypto_bio.h @@ -34,8 +34,8 @@ namespace node { namespace crypto { // This class represents buffers for OpenSSL I/O, implemented as a singly-linked -// list of chunks. It can be used both for writing data from Node to OpenSSL -// and back, but only one direction per instance. +// list of chunks. It can be used either for writing data from Node to OpenSSL, +// or for reading data back, but not both. // The structure is only accessed, and owned by, the OpenSSL BIOPointer // (a.k.a. std::unique_ptr). class NodeBIO : public MemoryRetainer { @@ -80,11 +80,12 @@ class NodeBIO : public MemoryRetainer { // Put `len` bytes from `data` into buffer void Write(const char* data, size_t size); - // Return pointer to internal data and amount of - // contiguous data available for future writes + // Return pointer to contiguous block of reserved data and the size available + // for future writes. Call Commit() once the write is complete. char* PeekWritable(size_t* size); - // Commit reserved data + // Specify how much data was written into the block returned by + // PeekWritable(). void Commit(size_t size); diff --git a/src/node_crypto_clienthello.h b/src/node_crypto_clienthello.h index 687e9589b6d932..3a834c85c20b65 100644 --- a/src/node_crypto_clienthello.h +++ b/src/node_crypto_clienthello.h @@ -30,6 +30,9 @@ namespace node { namespace crypto { +// Parse the client hello so we can do async session resumption. OpenSSL's +// session resumption uses synchronous callbacks, see SSL_CTX_sess_set_get_cb +// and get_session_cb. class ClientHelloParser { public: inline ClientHelloParser(); diff --git a/src/stream_wrap.cc b/src/stream_wrap.cc index ea3c98591b7409..10444fea4ab5bf 100644 --- a/src/stream_wrap.cc +++ b/src/stream_wrap.cc @@ -222,7 +222,7 @@ void LibuvStreamWrap::OnUvRead(ssize_t nread, const uv_buf_t* buf) { type = uv_pipe_pending_type(reinterpret_cast(stream())); } - // We should not be getting this callback if someone as already called + // We should not be getting this callback if someone has already called // uv_close() on the handle. CHECK_EQ(persistent().IsEmpty(), false); diff --git a/src/tls_wrap.cc b/src/tls_wrap.cc index f510b20488b1bd..1c7c32fb8f979a 100644 --- a/src/tls_wrap.cc +++ b/src/tls_wrap.cc @@ -116,6 +116,11 @@ void TLSWrap::InitSSL() { #endif // SSL_MODE_RELEASE_BUFFERS SSL_set_app_data(ssl_.get(), this); + // Using InfoCallback isn't how we are supposed to check handshake progress: + // https://github.com/openssl/openssl/issues/7199#issuecomment-420915993 + // + // Note on when this gets called on various openssl versions: + // https://github.com/openssl/openssl/issues/7199#issuecomment-420670544 SSL_set_info_callback(ssl_.get(), SSLInfoCallback); if (is_server()) { @@ -194,6 +199,9 @@ void TLSWrap::Start(const FunctionCallbackInfo& args) { // Send ClientHello handshake CHECK(wrap->is_client()); + // Seems odd to read when when we want to send, but SSL_read() triggers a + // handshake if a session isn't established, and handshake will cause + // encrypted data to become available for output. wrap->ClearOut(); wrap->EncOut(); } @@ -243,7 +251,7 @@ void TLSWrap::EncOut() { return; // Wait for `newSession` callback to be invoked - if (is_waiting_new_session()) + if (is_awaiting_new_session()) return; // Split-off queue @@ -253,7 +261,7 @@ void TLSWrap::EncOut() { if (ssl_ == nullptr) return; - // No data to write + // No encrypted output ready to write to the underlying stream. if (BIO_pending(enc_out_) == 0) { if (pending_cleartext_input_.empty()) InvokeQueued(0); @@ -442,13 +450,13 @@ void TLSWrap::ClearOut() { } -bool TLSWrap::ClearIn() { +void TLSWrap::ClearIn() { // Ignore cycling data if ClientHello wasn't yet parsed if (!hello_parser_.IsEnded()) - return false; + return; if (ssl_ == nullptr) - return false; + return; std::vector buffers; buffers.swap(pending_cleartext_input_); @@ -468,8 +476,9 @@ bool TLSWrap::ClearIn() { // All written if (i == buffers.size()) { + // We wrote all the buffers, so no writes failed (written < 0 on failure). CHECK_GE(written, 0); - return true; + return; } // Error or partial write @@ -481,6 +490,8 @@ bool TLSWrap::ClearIn() { Local arg = GetSSLError(written, &err, &error_str); if (!arg.IsEmpty()) { write_callback_scheduled_ = true; + // XXX(sam) Should forward an error object with .code/.function/.etc, if + // possible. InvokeQueued(UV_EPROTO, error_str.c_str()); } else { // Push back the not-yet-written pending buffers into their queue. @@ -491,7 +502,7 @@ bool TLSWrap::ClearIn() { buffers.end()); } - return false; + return; } @@ -547,6 +558,7 @@ void TLSWrap::ClearError() { } +// Called by StreamBase::Write() to request async write of clear text into SSL. int TLSWrap::DoWrite(WriteWrap* w, uv_buf_t* bufs, size_t count, @@ -560,18 +572,26 @@ int TLSWrap::DoWrite(WriteWrap* w, } bool empty = true; - - // Empty writes should not go through encryption process size_t i; - for (i = 0; i < count; i++) + for (i = 0; i < count; i++) { if (bufs[i].len > 0) { empty = false; break; } + } + + // We want to trigger a Write() on the underlying stream to drive the stream + // system, but don't want to encrypt empty buffers into a TLS frame, so see + // if we can find something to Write(). + // First, call ClearOut(). It does an SSL_read(), which might cause handshake + // or other internal messages to be encrypted. If it does, write them later + // with EncOut(). + // If there is still no encrypted output, call Write(bufs) on the underlying + // stream. Since the bufs are empty, it won't actually write non-TLS data + // 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) { ClearOut(); - // However, if there is any data that should be written to the socket, - // the callback should not be invoked immediately if (BIO_pending(enc_out_) == 0) { CHECK_NULL(current_empty_write_); current_empty_write_ = w; @@ -591,7 +611,7 @@ int TLSWrap::DoWrite(WriteWrap* w, CHECK_NULL(current_write_); current_write_ = w; - // Write queued data + // Write encrypted data to underlying stream and call Done(). if (empty) { EncOut(); return 0; @@ -610,17 +630,20 @@ int TLSWrap::DoWrite(WriteWrap* w, if (i != count) { int err; Local arg = GetSSLError(written, &err, &error_); + + // If we stopped writing because of an error, it's fatal, discard the data. if (!arg.IsEmpty()) { current_write_ = nullptr; return UV_EPROTO; } + // Otherwise, save unwritten data so it can be written later by ClearIn(). pending_cleartext_input_.insert(pending_cleartext_input_.end(), &bufs[i], &bufs[count]); } - // Try writing data immediately + // Write any encrypted/handshake output that may be ready. EncOut(); return 0; @@ -652,17 +675,20 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) { return; } - // Only client connections can receive data if (ssl_ == nullptr) { EmitRead(UV_EPROTO); return; } - // Commit read data + // Commit the amount of data actually read into the peeked/allocated buffer + // from the underlying stream. crypto::NodeBIO* enc_in = crypto::NodeBIO::FromBIO(enc_in_); enc_in->Commit(nread); - // Parse ClientHello first + // Parse ClientHello first, if we need to. It's only parsed if session event + // listeners are used on the server side. "ended" is the initial state, so + // can mean parsing was never started, or that parsing is finished. Either + // way, ended means we can give the buffered data to SSL. if (!hello_parser_.IsEnded()) { size_t avail = 0; uint8_t* data = reinterpret_cast(enc_in->Peek(&avail)); diff --git a/src/tls_wrap.h b/src/tls_wrap.h index 4c47cd81197189..527c11bf33b7a6 100644 --- a/src/tls_wrap.h +++ b/src/tls_wrap.h @@ -71,7 +71,9 @@ class TLSWrap : public AsyncWrap, uv_buf_t* bufs, size_t count, uv_stream_t* send_handle) override; + // Return error_ string or nullptr if it's empty. const char* Error() const override; + // Reset error_ string to empty. Not related to "clear text". void ClearError() override; void NewSessionDoneCb(); @@ -104,11 +106,22 @@ class TLSWrap : public AsyncWrap, static void SSLInfoCallback(const SSL* ssl_, int where, int ret); void InitSSL(); - void EncOut(); - bool ClearIn(); - void ClearOut(); + // SSL has a "clear" text (unencrypted) side (to/from the node API) and + // encrypted ("enc") text side (to/from the underlying socket/stream). + // On each side data flows "in" or "out" of SSL context. + // + // EncIn() doesn't exist. Encrypted data is pushed from underlying stream into + // enc_in_ via the stream listener's OnStreamAlloc()/OnStreamRead() interface. + void EncOut(); // Write encrypted data from enc_out_ to underlying stream. + void ClearIn(); // SSL_write() clear data "in" to SSL. + void ClearOut(); // SSL_read() clear text "out" from SSL. + + // Call Done() on outstanding WriteWrap request. bool InvokeQueued(int status, const char* error_str = nullptr); + // Drive the SSL state machine by attempting to SSL_read() and SSL_write() to + // it. Transparent handshakes mean SSL_read() might trigger I/O on the + // underlying stream even if there is no clear text to read or write. inline void Cycle() { // Prevent recursion if (++cycle_depth_ > 1) @@ -117,6 +130,7 @@ class TLSWrap : public AsyncWrap, for (; cycle_depth_ > 0; cycle_depth_--) { ClearIn(); ClearOut(); + // EncIn() doesn't exist, it happens via stream listener callbacks. EncOut(); } } @@ -138,16 +152,18 @@ class TLSWrap : public AsyncWrap, static void SetVerifyMode(const v8::FunctionCallbackInfo& args); static void EnableSessionCallbacks( const v8::FunctionCallbackInfo& args); - static void EnableCertCb( - const v8::FunctionCallbackInfo& args); + static void EnableTrace(const v8::FunctionCallbackInfo& args); + static void EnableCertCb(const v8::FunctionCallbackInfo& args); static void DestroySSL(const v8::FunctionCallbackInfo& args); static void GetServername(const v8::FunctionCallbackInfo& args); static void SetServername(const v8::FunctionCallbackInfo& args); static int SelectSNIContextCallback(SSL* s, int* ad, void* arg); crypto::SecureContext* sc_; - BIO* enc_in_ = nullptr; - BIO* enc_out_ = nullptr; + // BIO buffers hold encrypted data. + BIO* enc_in_ = nullptr; // StreamListener fills this for SSL_read(). + BIO* enc_out_ = nullptr; // SSL_write()/handshake fills this for EncOut(). + // Waiting for ClearIn() to pass to SSL_write(). std::vector pending_cleartext_input_; size_t write_size_ = 0; WriteWrap* current_write_ = nullptr; From 6bcc06e80adb229322b3f1da696fa5863c64eac9 Mon Sep 17 00:00:00 2001 From: cjihrig Date: Sat, 3 Nov 2018 11:24:50 -0400 Subject: [PATCH 2/4] src: fix Get() usage in tls_wrap.cc PR-URL: https://github.com/nodejs/node/pull/24060 Reviewed-By: Daniel Bevenius Reviewed-By: Anna Henningsen Reviewed-By: Joyee Cheung --- src/tls_wrap.cc | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/src/tls_wrap.cc b/src/tls_wrap.cc index 1c7c32fb8f979a..7dcf9d5f8a063e 100644 --- a/src/tls_wrap.cc +++ b/src/tls_wrap.cc @@ -221,8 +221,10 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) { Local object = c->object(); if (where & SSL_CB_HANDSHAKE_START) { - Local callback = object->Get(env->onhandshakestart_string()); - if (callback->IsFunction()) { + Local callback; + + if (object->Get(env->context(), env->onhandshakestart_string()) + .ToLocal(&callback) && callback->IsFunction()) { Local argv[] = { env->GetNow() }; c->MakeCallback(callback.As(), arraysize(argv), argv); } @@ -232,9 +234,12 @@ 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)) { + Local callback; + c->established_ = true; - Local callback = object->Get(env->onhandshakedone_string()); - if (callback->IsFunction()) { + + if (object->Get(env->context(), env->onhandshakedone_string()) + .ToLocal(&callback) && callback->IsFunction()) { c->MakeCallback(callback.As(), 0, nullptr); } } @@ -845,7 +850,10 @@ int TLSWrap::SelectSNIContextCallback(SSL* s, int* ad, void* arg) { // Call the SNI callback and use its return value as context Local object = p->object(); - Local ctx = object->Get(env->sni_context_string()); + Local ctx; + + if (!object->Get(env->context(), env->sni_context_string()).ToLocal(&ctx)) + return SSL_TLSEXT_ERR_NOACK; // Not an object, probably undefined or null if (!ctx->IsObject()) From 7b3277e828e6bbc35c493e9eafefd266e3735149 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Thu, 21 Mar 2019 16:45:44 +0100 Subject: [PATCH 3/4] tls: add CHECK for impossible condition MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/tls_wrap.cc b/src/tls_wrap.cc index 7dcf9d5f8a063e..6e827d3dc2e047 100644 --- a/src/tls_wrap.cc +++ b/src/tls_wrap.cc @@ -680,10 +680,10 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) { return; } - if (ssl_ == nullptr) { - EmitRead(UV_EPROTO); - return; - } + // DestroySSL() is the only thing that un-sets ssl_, but that also removes + // this TLSWrap as a stream listener, so we should not receive OnStreamRead() + // calls anymore. + CHECK(ssl_); // Commit the amount of data actually read into the peeked/allocated buffer // from the underlying stream. From b043cc149bdfe0855509032b06c72acd21b48e96 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Thu, 21 Mar 2019 17:01:12 +0100 Subject: [PATCH 4/4] tls: add debugging to native TLS code MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 6e827d3dc2e047..e3daf9b650e318 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 @@ -74,15 +75,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; @@ -97,6 +101,7 @@ bool TLSWrap::InvokeQueued(int status, const char* error_str) { void TLSWrap::NewSessionDoneCb() { + Debug(this, "NewSessionDoneCb()"); Cycle(); } @@ -174,6 +179,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()) { @@ -221,6 +227,9 @@ 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; if (object->Get(env->context(), env->onhandshakestart_string()) @@ -234,6 +243,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);"); Local callback; c->established_ = true; @@ -247,27 +257,40 @@ 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()) InvokeQueued(0); return; @@ -286,6 +309,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); @@ -295,6 +319,7 @@ void TLSWrap::EncOut() { NODE_COUNT_NET_BYTES_SENT(write_size_); if (!res.async) { + Debug(this, "Write finished synchronously"); HandleScope handle_scope(env()->isolate()); // Simulate asynchronous finishing, TLS cannot handle this at the moment. @@ -306,21 +331,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); @@ -383,16 +413,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; @@ -400,6 +437,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; @@ -417,8 +455,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; @@ -444,6 +484,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) @@ -456,12 +497,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_); @@ -474,6 +520,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; @@ -481,6 +528,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; @@ -494,11 +542,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; // XXX(sam) 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. @@ -511,6 +561,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); } @@ -540,6 +601,7 @@ bool TLSWrap::IsClosing() { int TLSWrap::ReadStart() { + Debug(this, "ReadStart()"); if (stream_ != nullptr) return stream_->ReadStart(); return 0; @@ -547,6 +609,7 @@ int TLSWrap::ReadStart() { int TLSWrap::ReadStop() { + Debug(this, "ReadStop()"); if (stream_ != nullptr) return stream_->ReadStop(); return 0; @@ -569,6 +632,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(); @@ -596,8 +660,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 = @@ -628,6 +694,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; } @@ -638,10 +705,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], @@ -665,6 +734,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(); @@ -698,6 +768,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); } @@ -712,6 +783,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) @@ -770,6 +842,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; @@ -784,6 +857,7 @@ void TLSWrap::DestroySSL(const FunctionCallbackInfo& args) { if (wrap->stream_ != nullptr) wrap->stream_->RemoveStreamListener(wrap); + Debug(wrap, "DestroySSL() finished"); } @@ -796,6 +870,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 527c11bf33b7a6..9c349cf37720c7 100644 --- a/src/tls_wrap.h +++ b/src/tls_wrap.h @@ -83,6 +83,8 @@ class TLSWrap : public AsyncWrap, SET_MEMORY_INFO_NAME(TLSWrap) SET_SELF_SIZE(TLSWrap) + std::string diagnostic_name() const override; + protected: inline StreamBase* underlying_stream() { return static_cast(stream_);