tls: add debugging to native TLS code · nodejs/node@2d5387e (original) (raw)
`@@ -21,6 +21,7 @@
`
21
21
``
22
22
`#include "tls_wrap.h"
`
23
23
`#include "async_wrap-inl.h"
`
``
24
`+
#include "debug_utils.h"
`
24
25
`#include "node_buffer.h" // Buffer
`
25
26
`#include "node_crypto.h" // SecureContext
`
26
27
`#include "node_crypto_bio.h" // NodeBIO
`
`@@ -72,15 +73,18 @@ TLSWrap::TLSWrap(Environment* env,
`
72
73
` stream->PushStreamListener(this);
`
73
74
``
74
75
`InitSSL();
`
``
76
`+
Debug(this, "Created new TLSWrap");
`
75
77
`}
`
76
78
``
77
79
``
78
80
`TLSWrap::~TLSWrap() {
`
``
81
`+
Debug(this, "~TLSWrap()");
`
79
82
` sc_ = nullptr;
`
80
83
`}
`
81
84
``
82
85
``
83
86
`bool TLSWrap::InvokeQueued(int status, const char* error_str) {
`
``
87
`+
Debug(this, "InvokeQueued(%d, %s)", status, error_str);
`
84
88
`if (!write_callback_scheduled_)
`
85
89
`return false;
`
86
90
``
`@@ -95,6 +99,7 @@ bool TLSWrap::InvokeQueued(int status, const char* error_str) {
`
95
99
``
96
100
``
97
101
`void TLSWrap::NewSessionDoneCb() {
`
``
102
`+
Debug(this, "NewSessionDoneCb()");
`
98
103
`Cycle();
`
99
104
`}
`
100
105
``
`@@ -184,6 +189,7 @@ void TLSWrap::Receive(const FunctionCallbackInfo& args) {
`
184
189
`CHECK(Buffer::HasInstance(args[0]));
`
185
190
`char* data = Buffer::Data(args[0]);
`
186
191
`size_t len = Buffer::Length(args[0]);
`
``
192
`+
Debug(wrap, "Receiving %zu bytes injected from JS", len);
`
187
193
``
188
194
`// Copy given buffer entirely or partiall if handle becomes closed
`
189
195
`while (len > 0 && wrap->IsAlive() && !wrap->IsClosing()) {
`
`@@ -230,6 +236,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
`
230
236
` Local object = c->object();
`
231
237
``
232
238
`if (where & SSL_CB_HANDSHAKE_START) {
`
``
239
`+
Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_START);");
`
233
240
`// Start is tracked to limit number and frequency of renegotiation attempts,
`
234
241
`// since excessive renegotiation may be an attack.
`
235
242
` Local callback;
`
`@@ -245,6 +252,7 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
`
245
252
`// sending HelloRequest in OpenSSL-1.1.1.
`
246
253
`// We need to check whether this is in a renegotiation state or not.
`
247
254
`if (where & SSL_CB_HANDSHAKE_DONE && !SSL_renegotiate_pending(ssl)) {
`
``
255
`+
Debug(c, "SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);");
`
248
256
`CHECK(!SSL_renegotiate_pending(ssl));
`
249
257
` Local callback;
`
250
258
``
`@@ -259,31 +267,46 @@ void TLSWrap::SSLInfoCallback(const SSL* ssl_, int where, int ret) {
`
259
267
``
260
268
``
261
269
`void TLSWrap::EncOut() {
`
``
270
`+
Debug(this, "Trying to write encrypted output");
`
``
271
+
262
272
`// 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");
`
264
275
`return;
`
``
276
`+
}
`
265
277
``
266
278
`// Write in progress
`
267
``
`-
if (write_size_ != 0)
`
``
279
`+
if (write_size_ != 0) {
`
``
280
`+
Debug(this, "Returning from EncOut(), write currently in progress");
`
268
281
`return;
`
``
282
`+
}
`
269
283
``
270
284
`` // 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");
`
272
287
`return;
`
``
288
`+
}
`
273
289
``
274
290
`// Split-off queue
`
275
``
`-
if (established_ && current_write_ != nullptr)
`
``
291
`+
if (established_ && current_write_ != nullptr) {
`
``
292
`+
Debug(this, "EncOut() setting write_callback_scheduled_");
`
276
293
` write_callback_scheduled_ = true;
`
``
294
`+
}
`
277
295
``
278
``
`-
if (ssl_ == nullptr)
`
``
296
`+
if (ssl_ == nullptr) {
`
``
297
`+
Debug(this, "Returning from EncOut(), ssl_ == nullptr");
`
279
298
`return;
`
``
299
`+
}
`
280
300
``
281
301
`// No encrypted output ready to write to the underlying stream.
`
282
302
`if (BIO_pending(enc_out_) == 0) {
`
``
303
`+
Debug(this, "No pending encrypted output");
`
283
304
`if (pending_cleartext_input_.empty()) {
`
284
305
`if (!in_dowrite_) {
`
``
306
`+
Debug(this, "No pending cleartext input, not inside DoWrite()");
`
285
307
`InvokeQueued(0);
`
286
308
` } else {
`
``
309
`+
Debug(this, "No pending cleartext input, inside DoWrite()");
`
287
310
`// TODO(@sam-github, @addaleax) If in_dowrite_ is true, appdata was
`
288
311
`// passed to SSL_write(). If we are here, the data was not encrypted to
`
289
312
`// enc_out_ yet. Calling Done() "works", but since the write is not
`
`@@ -313,13 +336,15 @@ void TLSWrap::EncOut() {
`
313
336
`for (size_t i = 0; i < count; i++)
`
314
337
` buf[i] = uv_buf_init(data[i], size[i]);
`
315
338
``
``
339
`+
Debug(this, "Writing %zu buffers to the underlying stream", count);
`
316
340
` StreamWriteResult res = underlying_stream()->Write(bufs, count);
`
317
341
`if (res.err != 0) {
`
318
342
`InvokeQueued(res.err);
`
319
343
`return;
`
320
344
` }
`
321
345
``
322
346
`if (!res.async) {
`
``
347
`+
Debug(this, "Write finished synchronously");
`
323
348
` HandleScope handle_scope(env()->isolate());
`
324
349
``
325
350
`// Simulate asynchronous finishing, TLS cannot handle this at the moment.
`
`@@ -331,21 +356,26 @@ void TLSWrap::EncOut() {
`
331
356
``
332
357
``
333
358
`void TLSWrap::OnStreamAfterWrite(WriteWrap* req_wrap, int status) {
`
``
359
`+
Debug(this, "OnStreamAfterWrite(status = %d)", status);
`
334
360
`if (current_empty_write_ != nullptr) {
`
``
361
`+
Debug(this, "Had empty write");
`
335
362
` WriteWrap* finishing = current_empty_write_;
`
336
363
` current_empty_write_ = nullptr;
`
337
364
` finishing->Done(status);
`
338
365
`return;
`
339
366
` }
`
340
367
``
341
``
`-
if (ssl_ == nullptr)
`
``
368
`+
if (ssl_ == nullptr) {
`
``
369
`+
Debug(this, "ssl_ == nullptr, marking as cancelled");
`
342
370
` status = UV_ECANCELED;
`
``
371
`+
}
`
343
372
``
344
373
`// Handle error
`
345
374
`if (status) {
`
346
``
`-
// Ignore errors after shutdown
`
347
``
`-
if (shutdown_)
`
``
375
`+
if (shutdown_) {
`
``
376
`+
Debug(this, "Ignoring error after shutdown");
`
348
377
`return;
`
``
378
`+
}
`
349
379
``
350
380
`// Notify about error
`
351
381
`InvokeQueued(status);
`
`@@ -446,23 +476,31 @@ Local TLSWrap::GetSSLError(int status, int* err, std::string* msg) {
`
446
476
``
447
477
``
448
478
`void TLSWrap::ClearOut() {
`
``
479
`+
Debug(this, "Trying to read cleartext output");
`
449
480
`// 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");
`
451
483
`return;
`
``
484
`+
}
`
452
485
``
453
486
`// No reads after EOF
`
454
``
`-
if (eof_)
`
``
487
`+
if (eof_) {
`
``
488
`+
Debug(this, "Returning from ClearOut(), EOF reached");
`
455
489
`return;
`
``
490
`+
}
`
456
491
``
457
``
`-
if (ssl_ == nullptr)
`
``
492
`+
if (ssl_ == nullptr) {
`
``
493
`+
Debug(this, "Returning from ClearOut(), ssl_ == nullptr");
`
458
494
`return;
`
``
495
`+
}
`
459
496
``
460
497
` crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
`
461
498
``
462
499
`char out[kClearOutChunkSize];
`
463
500
`int read;
`
464
501
`for (;;) {
`
465
502
`read = SSL_read(ssl_.get(), out, sizeof(out));
`
``
503
`+
Debug(this, "Read %d bytes of cleartext output", read);
`
466
504
``
467
505
`if (read <= 0)
`
468
506
`break;
`
`@@ -480,8 +518,10 @@ void TLSWrap::ClearOut() {
`
480
518
`// Caveat emptor: OnRead() calls into JS land which can result in
`
481
519
`// the SSL context object being destroyed. We have to carefully
`
482
520
`// check that ssl_ != nullptr afterwards.
`
483
``
`-
if (ssl_ == nullptr)
`
``
521
`+
if (ssl_ == nullptr) {
`
``
522
`+
Debug(this, "Returning from read loop, ssl_ == nullptr");
`
484
523
`return;
`
``
524
`+
}
`
485
525
``
486
526
`read -= avail;
`
487
527
` current += avail;
`
`@@ -507,6 +547,7 @@ void TLSWrap::ClearOut() {
`
507
547
`return;
`
508
548
``
509
549
`if (!arg.IsEmpty()) {
`
``
550
`+
Debug(this, "Got SSL error (%d), calling onerror", err);
`
510
551
`// When TLS Alert are stored in wbio,
`
511
552
`// it should be flushed to socket before destroyed.
`
512
553
`if (BIO_pending(enc_out_) != 0)
`
`@@ -519,12 +560,17 @@ void TLSWrap::ClearOut() {
`
519
560
``
520
561
``
521
562
`void TLSWrap::ClearIn() {
`
``
563
`+
Debug(this, "Trying to write cleartext input");
`
522
564
`// 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");
`
524
567
`return;
`
``
568
`+
}
`
525
569
``
526
``
`-
if (ssl_ == nullptr)
`
``
570
`+
if (ssl_ == nullptr) {
`
``
571
`+
Debug(this, "Returning from ClearIn(), ssl_ == nullptr");
`
527
572
`return;
`
``
573
`+
}
`
528
574
``
529
575
` std::vector buffers;
`
530
576
` buffers.swap(pending_cleartext_input_);
`
`@@ -537,13 +583,15 @@ void TLSWrap::ClearIn() {
`
537
583
`size_t avail = buffers[i].len;
`
538
584
`char* data = buffers[i].base;
`
539
585
` written = SSL_write(ssl_.get(), data, avail);
`
``
586
`+
Debug(this, "Writing %zu bytes, written = %d", avail, written);
`
540
587
`CHECK(written == -1 || written == static_cast(avail));
`
541
588
`if (written == -1)
`
542
589
`break;
`
543
590
` }
`
544
591
``
545
592
`// All written
`
546
593
`if (i == buffers.size()) {
`
``
594
`+
Debug(this, "Successfully wrote all data to SSL");
`
547
595
`// We wrote all the buffers, so no writes failed (written < 0 on failure).
`
548
596
`CHECK_GE(written, 0);
`
549
597
`return;
`
`@@ -557,11 +605,13 @@ void TLSWrap::ClearIn() {
`
557
605
` std::string error_str;
`
558
606
` Local arg = GetSSLError(written, &err, &error_str);
`
559
607
`if (!arg.IsEmpty()) {
`
``
608
`+
Debug(this, "Got SSL error (%d)", err);
`
560
609
` write_callback_scheduled_ = true;
`
561
610
`// TODO(@sam-github) Should forward an error object with
`
562
611
`// .code/.function/.etc, if possible.
`
563
612
`InvokeQueued(UV_EPROTO, error_str.c_str());
`
564
613
` } else {
`
``
614
`+
Debug(this, "Pushing back %zu buffers", buffers.size() - i);
`
565
615
`// Push back the not-yet-written pending buffers into their queue.
`
566
616
`// This can be skipped in the error case because no further writes
`
567
617
`// would succeed anyway.
`
`@@ -574,6 +624,17 @@ void TLSWrap::ClearIn() {
`
574
624
`}
`
575
625
``
576
626
``
``
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(get_async_id())) + ")";
`
``
634
`+
return name;
`
``
635
`+
}
`
``
636
+
``
637
+
577
638
`AsyncWrap* TLSWrap::GetAsyncWrap() {
`
578
639
`return static_cast<AsyncWrap*>(this);
`
579
640
`}
`
`@@ -603,13 +664,15 @@ bool TLSWrap::IsClosing() {
`
603
664
``
604
665
``
605
666
`int TLSWrap::ReadStart() {
`
``
667
`+
Debug(this, "ReadStart()");
`
606
668
`if (stream_ != nullptr)
`
607
669
`return stream_->ReadStart();
`
608
670
`return 0;
`
609
671
`}
`
610
672
``
611
673
``
612
674
`int TLSWrap::ReadStop() {
`
``
675
`+
Debug(this, "ReadStop()");
`
613
676
`if (stream_ != nullptr)
`
614
677
`return stream_->ReadStop();
`
615
678
`return 0;
`
`@@ -633,6 +696,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
`
633
696
`size_t count,
`
634
697
`uv_stream_t* send_handle) {
`
635
698
`CHECK_NULL(send_handle);
`
``
699
`+
Debug(this, "DoWrite()");
`
636
700
``
637
701
`if (ssl_ == nullptr) {
`
638
702
`ClearError();
`
`@@ -660,8 +724,10 @@ int TLSWrap::DoWrite(WriteWrap* w,
`
660
724
`// onto the socket, we just want the side-effects. After, make sure the
`
661
725
`// WriteWrap was accepted by the stream, or that we call Done() on it.
`
662
726
`if (empty) {
`
``
727
`+
Debug(this, "Empty write");
`
663
728
`ClearOut();
`
664
729
`if (BIO_pending(enc_out_) == 0) {
`
``
730
`+
Debug(this, "No pending encrypted output, writing to underlying stream");
`
665
731
`CHECK_NULL(current_empty_write_);
`
666
732
` current_empty_write_ = w;
`
667
733
` StreamWriteResult res =
`
`@@ -692,6 +758,7 @@ int TLSWrap::DoWrite(WriteWrap* w,
`
692
758
`for (i = 0; i < count; i++) {
`
693
759
` written = SSL_write(ssl_.get(), bufs[i].base, bufs[i].len);
`
694
760
`CHECK(written == -1 || written == static_cast(bufs[i].len));
`
``
761
`+
Debug(this, "Writing %zu bytes, written = %d", bufs[i].len, written);
`
695
762
`if (written == -1)
`
696
763
`break;
`
697
764
` }
`
`@@ -702,10 +769,12 @@ int TLSWrap::DoWrite(WriteWrap* w,
`
702
769
``
703
770
`// If we stopped writing because of an error, it's fatal, discard the data.
`
704
771
`if (!arg.IsEmpty()) {
`
``
772
`+
Debug(this, "Got SSL error (%d), returning UV_EPROTO", err);
`
705
773
` current_write_ = nullptr;
`
706
774
`return UV_EPROTO;
`
707
775
` }
`
708
776
``
``
777
`+
Debug(this, "Saving %zu buffers for later write", count - i);
`
709
778
`// Otherwise, save unwritten data so it can be written later by ClearIn().
`
710
779
` pending_cleartext_input_.insert(pending_cleartext_input_.end(),
`
711
780
` &bufs[i],
`
`@@ -732,6 +801,7 @@ uv_buf_t TLSWrap::OnStreamAlloc(size_t suggested_size) {
`
732
801
``
733
802
``
734
803
`void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
`
``
804
`+
Debug(this, "Read %zd bytes from underlying stream", nread);
`
735
805
`if (nread < 0) {
`
736
806
`// Error should be emitted only after all data was read
`
737
807
`ClearOut();
`
`@@ -765,6 +835,7 @@ void TLSWrap::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
`
765
835
`size_t avail = 0;
`
766
836
`uint8_t* data = reinterpret_cast<uint8_t*>(enc_in->Peek(&avail));
`
767
837
`CHECK_IMPLIES(data == nullptr, avail == 0);
`
``
838
`+
Debug(this, "Passing %zu bytes to the hello parser", avail);
`
768
839
`return hello_parser_.Parse(data, avail);
`
769
840
` }
`
770
841
``
`@@ -779,6 +850,7 @@ ShutdownWrap* TLSWrap::CreateShutdownWrap(Local req_wrap_object) {
`
779
850
``
780
851
``
781
852
`int TLSWrap::DoShutdown(ShutdownWrap* req_wrap) {
`
``
853
`+
Debug(this, "DoShutdown()");
`
782
854
` crypto::MarkPopErrorOnReturn mark_pop_error_on_return;
`
783
855
``
784
856
`if (ssl_ && SSL_shutdown(ssl_.get()) == 0)
`
`@@ -844,6 +916,7 @@ void TLSWrap::EnableSessionCallbacks(
`
844
916
`void TLSWrap::DestroySSL(const FunctionCallbackInfo& args) {
`
845
917
` TLSWrap* wrap;
`
846
918
`ASSIGN_OR_RETURN_UNWRAP(&wrap, args.Holder());
`
``
919
`+
Debug(wrap, "DestroySSL()");
`
847
920
``
848
921
`// If there is a write happening, mark it as finished.
`
849
922
` wrap->write_callback_scheduled_ = true;
`
`@@ -858,6 +931,7 @@ void TLSWrap::DestroySSL(const FunctionCallbackInfo& args) {
`
858
931
``
859
932
`if (wrap->stream_ != nullptr)
`
860
933
` wrap->stream_->RemoveStreamListener(wrap);
`
``
934
`+
Debug(wrap, "DestroySSL() finished");
`
861
935
`}
`
862
936
``
863
937
``
`@@ -870,6 +944,7 @@ void TLSWrap::EnableCertCb(const FunctionCallbackInfo& args) {
`
870
944
``
871
945
`void TLSWrap::OnClientHelloParseEnd(void* arg) {
`
872
946
` TLSWrap* c = static_cast<TLSWrap*>(arg);
`
``
947
`+
Debug(c, "OnClientHelloParseEnd()");
`
873
948
` c->Cycle();
`
874
949
`}
`
875
950
``