FazBrowse GitHub Viewer | Trending |
URL:
| Home
Tools: [Download Repo ZIP]   [Original HTTPS Page]

tls: add debugging to native TLS code · nodejs/node@d2666e6 · GitHub

/ node Public

Commit d2666e6

Browse files
addaleax
authored and
BethGriggs
committed
tls: add debugging to native TLS code
Backport-PR-URL: #26951 PR-URL: #26843 Reviewed-By: Sam Roberts <vieuxtech@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Minwoo Jung <minwoo@nodesource.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Tobias Nießen <tniessen@tnie.de> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
1 parent 225417b commit d2666e6

2 files changed

Lines changed: 91 additions & 14 deletions

File tree

‎src/tls_wrap.cc‎

Lines changed: 89 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121

2222
#include "tls_wrap.h"
2323
#include "async_wrap-inl.h"
24+
#include "debug_utils.h"
2425
#include "node_buffer.h" // Buffer
2526
#include "node_crypto.h" // SecureContext
2627
#include "node_crypto_bio.h" // NodeBIO
@@ -72,15 +73,18 @@ TLSWrap::TLSWrap(Environment* env,
7273
stream->PushStreamListener(this);
7374

7475
InitSSL();
76+
Debug(this, "Created new TLSWrap");
7577
}
7678

7779

7880
TLSWrap::~TLSWrap() {
81+
Debug(this, "~TLSWrap()");
7982
sc_ = nullptr;
8083
}
8184

8285

8386
bool TLSWrap::InvokeQueued(int status, const char* error_str) {
87+
Debug(this, "InvokeQueued(%d, %s)", status, error_str);
8488
if (!write_callback_scheduled_)
8589
return false;
8690

@@ -95,6 +99,7 @@ bool TLSWrap::InvokeQueued(int status, const char* error_str) {
9599

96100

97101
void TLSWrap::NewSessionDoneCb() {
102+
Debug(this, "NewSessionDoneCb()");
98103
Cycle();
99104
}
100105

@@ -184,6 +189,7 @@ void TLSWrap::Receive(const FunctionCallbackInfo<Value>& args) {
184189
CHECK(Buffer::HasInstance(args[0]));
185190
char* data = Buffer::Data(args[0]);
186191
size_t len = Buffer::Length(args[0]);
192+
Debug(wrap, "Receiving %zu bytes injected from JS", len);
187193

188194
// Copy given buffer entirely or partiall if handle becomes closed
189195
while (len > 0 && wrap->IsAlive() && !wrap->IsClosing()) {
@@ -230,6 +236,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
230236
Local<Object> object = c->object();
231237

232238
if (where & SSL_CB_HANDSHAKE_START) {
239+
Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_START);");
233240
// Start is tracked to limit number and frequency of renegotiation attempts,
234241
// since excessive renegotiation may be an attack.
235242
Local<Value> callback;
@@ -245,6 +252,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
245252
// sending HelloRequest in OpenSSL-1.1.1.
246253
// We need to check whether this is in a renegotiation state or not.
247254
if (where & SSL_CB_HANDSHAKE_DONE && !SSL_renegotiate_pending(ssl)) {
255+
Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);");
248256
CHECK(!SSL_renegotiate_pending(ssl));
249257
Local<Value> callback;
250258

@@ -259,31 +267,46 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
259267

260268

261269
void TLSWrap::EncOut() {
270+
Debug(this, "Trying to write encrypted output");
271+
262272
// Ignore cycling data if ClientHello wasn't yet parsed
263-
if (!hello_parser_.IsEnded())
273+
if (!hello_parser_.IsEnded()) {
274+
Debug(this, "Returning from EncOut(), hello_parser_ active");
264275
return;
276+
}
265277

266278
// Write in progress
267-
if (write_size_ != 0)
279+
if (write_size_ != 0) {
280+
Debug(this, "Returning from EncOut(), write currently in progress");
268281
return;
282+
}
269283

270284
// Wait for `newSession` callback to be invoked
271-
if (is_awaiting_new_session())
285+
if (is_awaiting_new_session()) {
286+
Debug(this, "Returning from EncOut(), awaiting new session");
272287
return;
288+
}
273289

274290
// Split-off queue
275-
if (established_ && current_write_ != nullptr)
291+
if (established_ && current_write_ != nullptr) {
292+
Debug(this, "EncOut() setting write_callback_scheduled_");
276293
write_callback_scheduled_ = true;
294+
}
277295

278-
if (ssl_ == nullptr)
296+
if (ssl_ == nullptr) {
297+
Debug(this, "Returning from EncOut(), ssl_ == nullptr");
279298
return;
299+
}
280300

281301
// No encrypted output ready to write to the underlying stream.
282302
if (BIO_pending(enc_out_) == 0) {
303+
Debug(this, "No pending encrypted output");
283304
if (pending_cleartext_input_.empty()) {
284305
if (!in_dowrite_) {
306+
Debug(this, "No pending cleartext input, not inside DoWrite()");
285307
InvokeQueued(0);
286308
} else {
309+
Debug(this, "No pending cleartext input, inside DoWrite()");
287310
// TODO(@sam-github, @addaleax) If in_dowrite_ is true, appdata was
288311
// passed to SSL_write(). If we are here, the data was not encrypted to
289312
// enc_out_ yet. Calling Done() "works", but since the write is not
@@ -313,13 +336,15 @@ void TLSWrap::EncOut() {
313336
for (size_t i = 0; i < count; i++)
314337
buf[i] = uv_buf_init(data[i], size[i]);
315338

339+
Debug(this, "Writing %zu buffers to the underlying stream", count);
316340
StreamWriteResult res = underlying_stream()->Write(bufs, count);
317341
if (res.err != 0) {
318342
InvokeQueued(res.err);
319343
return;
320344
}
321345

322346
if (!res.async) {
347+
Debug(this, "Write finished synchronously");
323348
HandleScope handle_scope(env()->isolate());
324349

325350
// Simulate asynchronous finishing, TLS cannot handle this at the moment.
@@ -331,21 +356,26 @@ void TLSWrap::EncOut() {
331356

332357

333358
void TLSWrap::OnStreamAfterWrite(WriteWrap* req_wrap, int status) {
359+
Debug(this, "OnStreamAfterWrite(status = %d)", status);
334360
if (current_empty_write_ != nullptr) {
361+
Debug(this, "Had empty write");
335362
WriteWrap* finishing = current_empty_write_;
336363
current_empty_write_ = nullptr;
337364
finishing->Done(status);
338365
return;
339366
}
340367

341-
if (ssl_ == nullptr)
368+
if (ssl_ == nullptr) {
369+
Debug(this, "ssl_ == nullptr, marking as cancelled");
342370
status = UV_ECANCELED;
371+
}
343372

344373
// Handle error
345374
if (status) {
346-
// Ignore errors after shutdown
347-
if (shutdown_)
375+
if (shutdown_) {
376+
Debug(this, "Ignoring error after shutdown");
348377
return;
378+
}
349379

350380
// Notify about error
351381
InvokeQueued(status);
@@ -446,23 +476,31 @@ Local<Value> TLSWrap::GetSSLError(int status, int* err, std::string* msg) {
446476

447477

448478
void TLSWrap::ClearOut() {
479+
Debug(this, "Trying to read cleartext output");
449480
// Ignore cycling data if ClientHello wasn't yet parsed
450-
if (!hello_parser_.IsEnded())
481+
if (!hello_parser_.IsEnded()) {
482+
Debug(this, "Returning from ClearOut(), hello_parser_ active");
451483
return;
484+
}
452485

453486
// No reads after EOF
454-
if (eof_)
487+
if (eof_) {
488+
Debug(this, "Returning from ClearOut(), EOF reached");
455489
return;
490+
}
456491

457-
if (ssl_ == nullptr)
492+
if (ssl_ == nullptr) {
493+
Debug(this, "Returning from ClearOut(), ssl_ == nullptr");
458494
return;
495+
}
459496

460497
crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
461498

462499
char out[kClearOutChunkSize];
463500
int read;
464501
for (;;) {
465502
read = SSL_read(ssl_.get(), out, sizeof(out));
503+
Debug(this, "Read %d bytes of cleartext output", read);
466504

467505
if (read <= 0)
468506
break;
@@ -480,8 +518,10 @@ void TLSWrap::ClearOut() {
480518
// Caveat emptor: OnRead() calls into JS land which can result in
481519
// the SSL context object being destroyed. We have to carefully
482520
// check that ssl_ != nullptr afterwards.
483-
if (ssl_ == nullptr)
521+
if (ssl_ == nullptr) {
522+
Debug(this, "Returning from read loop, ssl_ == nullptr");
484523
return;
524+
}
485525

486526
read -= avail;
487527
current += avail;
@@ -507,6 +547,7 @@ void TLSWrap::ClearOut() {
507547
return;
508548

509549
if (!arg.IsEmpty()) {
550+
Debug(this, "Got SSL error (%d), calling onerror", err);
510551
// When TLS Alert are stored in wbio,
511552
// it should be flushed to socket before destroyed.
512553
if (BIO_pending(enc_out_) != 0)
@@ -519,12 +560,17 @@ void TLSWrap::ClearOut() {
519560

520561

521562
void TLSWrap::ClearIn() {
563+
Debug(this, "Trying to write cleartext input");
522564
// Ignore cycling data if ClientHello wasn't yet parsed
523-
if (!hello_parser_.IsEnded())
565+
if (!hello_parser_.IsEnded()) {
566+
Debug(this, "Returning from ClearIn(), hello_parser_ active");
524567
return;
568+
}
525569

526-
if (ssl_ == nullptr)
570+
if (ssl_ == nullptr) {
571+
Debug(this, "Returning from ClearIn(), ssl_ == nullptr");
527572
return;
573+
}
528574

529575
std::vector<uv_buf_t> buffers;
530576
buffers.swap(pending_cleartext_input_);
@@ -537,13 +583,15 @@ void TLSWrap::ClearIn() {
537583
size_t avail = buffers[i].len;
538584
char* data = buffers[i].base;
539585
written = SSL_write(ssl_.get(), data, avail);
586+
Debug(this, "Writing %zu bytes, written = %d", avail, written);
540587
CHECK(written == -1 || written == static_cast<int>(avail));
541588
if (written == -1)
542589
break;
543590
}
544591

545592
// All written
546593
if (i == buffers.size()) {
594+
Debug(this, "Successfully wrote all data to SSL");
547595
// We wrote all the buffers, so no writes failed (written < 0 on failure).
548596
CHECK_GE(written, 0);
549597
return;
@@ -557,11 +605,13 @@ void TLSWrap::ClearIn() {
557605
std::string error_str;
558606
Local<Value> arg = GetSSLError(written, &err, &error_str);
559607
if (!arg.IsEmpty()) {
608+
Debug(this, "Got SSL error (%d)", err);
560609
write_callback_scheduled_ = true;
561610
// TODO(@sam-github) Should forward an error object with
562611
// .code/.function/.etc, if possible.
563612
InvokeQueued(UV_EPROTO, error_str.c_str());
564613
} else {
614+
Debug(this, "Pushing back %zu buffers", buffers.size() - i);
565615
// Push back the not-yet-written pending buffers into their queue.
566616
// This can be skipped in the error case because no further writes
567617
// would succeed anyway.
@@ -574,6 +624,17 @@ void TLSWrap::ClearIn() {
574624
}
575625

576626

627+
std::string TLSWrap::diagnostic_name() const {
628+
std::string name = "TLSWrap ";
629+
if (is_server())
630+
name += "server (";
631+
else
632+
name += "client (";
633+
name += std::to_string(static_cast<int64_t>(get_async_id())) + ")";
634+
return name;
635+
}
636+
637+
577638
AsyncWrap* TLSWrap::GetAsyncWrap() {
578639
return static_cast<AsyncWrap*>(this);
579640
}
@@ -603,13 +664,15 @@ bool TLSWrap::IsClosing() {
603664

604665

605666
int TLSWrap::ReadStart() {
667+
Debug(this, "ReadStart()");
606668
if (stream_ != nullptr)
607669
return stream_->ReadStart();
608670
return 0;
609671
}
610672

611673

612674
int TLSWrap::ReadStop() {
675+
Debug(this, "ReadStop()");
613676
if (stream_ != nullptr)
614677
return stream_->ReadStop();
615678
return 0;
@@ -633,6 +696,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
633696
size_t count,
634697
uv_stream_t* send_handle) {
635698
CHECK_NULL(send_handle);
699+
Debug(this, "DoWrite()");
636700

637701
if (ssl_ == nullptr) {
638702
ClearError();
@@ -660,8 +724,10 @@ int TLSWrap::DoWrite(WriteWrap* w,
660724
// onto the socket, we just want the side-effects. After, make sure the
661725
// WriteWrap was accepted by the stream, or that we call Done() on it.
662726
if (empty) {
727+
Debug(this, "Empty write");
663728
ClearOut();
664729
if (BIO_pending(enc_out_) == 0) {
730+
Debug(this, "No pending encrypted output, writing to underlying stream");
665731
CHECK_NULL(current_empty_write_);
666732
current_empty_write_ = w;
667733
StreamWriteResult res =
@@ -692,6 +758,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
692758
for (i = 0; i < count; i++) {
693759
written = SSL_write(ssl_.get(), bufs[i].base, bufs[i].len);
694760
CHECK(written == -1 || written == static_cast<int>(bufs[i].len));
761+
Debug(this, "Writing %zu bytes, written = %d", bufs[i].len, written);
695762
if (written == -1)
696763
break;
697764
}
@@ -702,10 +769,12 @@ int TLSWrap::DoWrite(WriteWrap* w,
702769

703770
// If we stopped writing because of an error, it's fatal, discard the data.
704771
if (!arg.IsEmpty()) {
772+
Debug(this, "Got SSL error (%d), returning UV_EPROTO", err);
705773
current_write_ = nullptr;
706774
return UV_EPROTO;
707775
}
708776

777+
Debug(this, "Saving %zu buffers for later write", count - i);
709778
// Otherwise, save unwritten data so it can be written later by ClearIn().
710779
pending_cleartext_input_.insert(pending_cleartext_input_.end(),
711780
&bufs[i],
@@ -732,6 +801,7 @@ uv_buf_t TLSWrap::OnStreamAlloc(size_t suggested_size) {
732801

733802

734803
void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
804+
Debug(this, "Read %zd bytes from underlying stream", nread);
735805
if (nread < 0) {
736806
// Error should be emitted only after all data was read
737807
ClearOut();
@@ -765,6 +835,7 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
765835
size_t avail = 0;
766836
uint8_t* data = reinterpret_cast<uint8_t*>(enc_in->Peek(&avail));
767837
CHECK_IMPLIES(data == nullptr, avail == 0);
838+
Debug(this, "Passing %zu bytes to the hello parser", avail);
768839
return hello_parser_.Parse(data, avail);
769840
}
770841

@@ -779,6 +850,7 @@ ShutdownWrap* TLSWrap::CreateShutdownWrap(Local<Object> req_wrap_object) {
779850

780851

781852
int TLSWrap::DoShutdown(ShutdownWrap* req_wrap) {
853+
Debug(this, "DoShutdown()");
782854
crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
783855

784856
if (ssl_ && SSL_shutdown(ssl_.get()) == 0)
@@ -844,6 +916,7 @@ void TLSWrap::EnableSessionCallbacks(
844916
void TLSWrap::DestroySSL(const FunctionCallbackInfo<Value>& args) {
845917
TLSWrap* wrap;
846918
ASSIGN_OR_RETURN_UNWRAP(&wrap, args.Holder());
919+
Debug(wrap, "DestroySSL()");
847920

848921
// If there is a write happening, mark it as finished.
849922
wrap->write_callback_scheduled_ = true;
@@ -858,6 +931,7 @@ void TLSWrap::DestroySSL(const FunctionCallbackInfo<Value>& args) {
858931

859932
if (wrap->stream_ != nullptr)
860933
wrap->stream_->RemoveStreamListener(wrap);
934+
Debug(wrap, "DestroySSL() finished");
861935
}
862936

863937

@@ -870,6 +944,7 @@ void TLSWrap::EnableCertCb(const FunctionCallbackInfo<Value>& args) {
870944

871945
void TLSWrap::OnClientHelloParseEnd(void* arg) {
872946
TLSWrap* c = static_cast<TLSWrap*>(arg);
947+
Debug(c, "OnClientHelloParseEnd()");
873948
c->Cycle();
874949
}
875950

‎src/tls_wrap.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -88,6 +88,8 @@ class TLSWrap : public AsyncWrap,
8888
SET_MEMORY_INFO_NAME(TLSWrap)
8989
SET_SELF_SIZE(TLSWrap)
9090

91+
std::string diagnostic_name() const override;
92+
9193
protected:
9294
// Alternative to StreamListener::stream(), that returns a StreamBase instead
9395
// of a StreamResource.

0 commit comments

Comments
 (0)
Back | FazBrowse Home | New Git URL