tls: allow enabling the TLS debug trace

Enable the same trace output that the OpenSSL s_client and s_server
support with their `-trace` option. This is invaluable when debugging
reports of TLS bugs as well as when debugging the internal TLS
implementation.

See:
- #25383
- #17936
- postmanlabs/postman-app-support#5918 (comment)

PR-URL: #27376
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
Reviewed-By: Richard Lau <riclau@uk.ibm.com>

doc/api/tls.md

@@ -725,6 +725,19 @@ added: v8.4.0
 Disables TLS renegotiation for this `TLSSocket` instance. Once called, attempts
 to renegotiate will trigger an `'error'` event on the `TLSSocket`.
 
+### tlsSocket.enableTrace()
+<!-- YAML
+added: REPLACEME
+-->
+
+When enabled, TLS packet trace information is written to `stderr`. This can be
+used to debug TLS connection problems.
+
+Note: The format of the output is identical to the output of `openssl s_client
+-trace` or `openssl s_server -trace`. While it is produced by OpenSSL's
+`SSL_trace()` function, the format is undocumented, can change without notice,
+and should not be relied on.
+
 ### tlsSocket.encrypted
 <!-- YAML
 added: v0.11.4
@@ -1438,6 +1451,10 @@ changes:
     `['hello', 'world']`. (Protocols should be ordered by their priority.)
   * `clientCertEngine` {string} Name of an OpenSSL engine which can provide the
     client certificate.
+  * `enableTrace` {boolean} If `true`, [`tls.TLSSocket.enableTrace()`][] will be
+    called on new connections. Tracing can be enabled after the secure
+    connection is established, but this option must be used to trace the secure
+    connection setup. **Default:** `false`.
   * `handshakeTimeout` {number} Abort the connection if the SSL/TLS handshake
     does not finish in the specified number of milliseconds.
     A `'tlsClientError'` is emitted on the `tls.Server` object whenever
@@ -1693,6 +1710,7 @@ where `secureSocket` has the same API as `pair.cleartext`.
 [`tls.DEFAULT_MAX_VERSION`]: #tls_tls_default_max_version
 [`tls.DEFAULT_MIN_VERSION`]: #tls_tls_default_min_version
 [`tls.Server`]: #tls_class_tls_server
+[`tls.TLSSocket.enableTrace()`]: #tls_tlssocket_enabletrace
 [`tls.TLSSocket.getPeerCertificate()`]: #tls_tlssocket_getpeercertificate_detailed
 [`tls.TLSSocket.getSession()`]: #tls_tlssocket_getsession
 [`tls.TLSSocket.getTLSTicket()`]: #tls_tlssocket_gettlsticket

lib/_tls_wrap.js

@@ -63,6 +63,7 @@ const kErrorEmitted = Symbol('error-emitted');
 const kHandshakeTimeout = Symbol('handshake-timeout');
 const kRes = Symbol('res');
 const kSNICallback = Symbol('snicallback');
+const kEnableTrace = Symbol('enableTrace');
 
 const noop = () => {};
 
@@ -811,6 +812,7 @@ function makeSocketMethodProxy(name) {
   'getSession',
   'getTLSTicket',
   'isSessionReused',
+  'enableTrace',
 ].forEach((method) => {
   TLSSocket.prototype[method] = makeSocketMethodProxy(method);
 });
@@ -872,6 +874,8 @@ function tlsConnectionListener(rawSocket) {
     ALPNProtocols: this.ALPNProtocols,
     SNICallback: this[kSNICallback] || SNICallback
   });
+  if (this[kEnableTrace] && socket._handle)
+    socket._handle.enableTrace();
 
   socket.on('secure', onServerSocketSecure);
 
@@ -992,6 +996,15 @@ function Server(options, listener) {
   if (listener) {
     this.on('secureConnection', listener);
   }
+
+  const enableTrace = options.enableTrace;
+  if (enableTrace === true)
+    this[kEnableTrace] = true;
+  else if (enableTrace === false || enableTrace == null)
+    ;  // Tracing explicitly disabled, or defaulting to disabled.
+  else
+    throw new ERR_INVALID_ARG_TYPE(
+      'options.enableTrace', 'boolean', enableTrace);
 }
 
 Object.setPrototypeOf(Server.prototype, net.Server.prototype);

src/tls_wrap.cc

@@ -912,6 +912,29 @@ void TLSWrap::EnableSessionCallbacks(
                             wrap);
 }
 
+// Check required capabilities were not excluded from the OpenSSL build:
+// - OPENSSL_NO_SSL_TRACE excludes SSL_trace()
+// - OPENSSL_NO_STDIO excludes BIO_new_fp()
+// HAVE_SSL_TRACE is available on the internal tcp_wrap binding for the tests.
+#if defined(OPENSSL_NO_SSL_TRACE) || defined(OPENSSL_NO_STDIO)
+# define HAVE_SSL_TRACE 0
+#else
+# define HAVE_SSL_TRACE 1
+#endif
+
+void TLSWrap::EnableTrace(
+    const FunctionCallbackInfo<Value>& args) {
+  TLSWrap* wrap;
+  ASSIGN_OR_RETURN_UNWRAP(&wrap, args.Holder());
+
+#if HAVE_SSL_TRACE
+  if (wrap->ssl_) {
+    BIO* b = BIO_new_fp(stderr,  BIO_NOCLOSE | BIO_FP_TEXT);
+    SSL_set_msg_callback(wrap->ssl_.get(), SSL_trace);
+    SSL_set_msg_callback_arg(wrap->ssl_.get(), b);
+  }
+#endif
+}
 
 void TLSWrap::DestroySSL(const FunctionCallbackInfo<Value>& args) {
   TLSWrap* wrap;
@@ -1057,6 +1080,8 @@ void TLSWrap::Initialize(Local<Object> target,
 
   env->SetMethod(target, "wrap", TLSWrap::Wrap);
 
+  NODE_DEFINE_CONSTANT(target, HAVE_SSL_TRACE);
+
   Local<FunctionTemplate> t = BaseObject::MakeLazilyInitializedJSTemplate(env);
   Local<String> tlsWrapString =
       FIXED_ONE_BYTE_STRING(env->isolate(), "TLSWrap");
@@ -1080,6 +1105,7 @@ void TLSWrap::Initialize(Local<Object> target,
   env->SetProtoMethod(t, "start", Start);
   env->SetProtoMethod(t, "setVerifyMode", SetVerifyMode);
   env->SetProtoMethod(t, "enableSessionCallbacks", EnableSessionCallbacks);
+  env->SetProtoMethod(t, "enableTrace", EnableTrace);
   env->SetProtoMethod(t, "destroySSL", DestroySSL);
   env->SetProtoMethod(t, "enableCertCb", EnableCertCb);
 

src/tls_wrap.h

@@ -160,6 +160,7 @@ class TLSWrap : public AsyncWrap,
   static void SetVerifyMode(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void EnableSessionCallbacks(
       const v8::FunctionCallbackInfo<v8::Value>& args);
+  static void EnableTrace(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void EnableCertCb(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void DestroySSL(const v8::FunctionCallbackInfo<v8::Value>& args);
   static void GetServername(const v8::FunctionCallbackInfo<v8::Value>& args);

test/parallel/test-tls-enable-trace.js

@@ -0,0 +1,58 @@
+// Flags: --expose-internals
+'use strict';
+const common = require('../common');
+if (!common.hasCrypto) common.skip('missing crypto');
+const fixtures = require('../common/fixtures');
+
+// Test enableTrace: option for TLS.
+
+const assert = require('assert');
+const { fork } = require('child_process');
+
+if (process.argv[2] === 'test')
+  return test();
+
+const binding = require('internal/test/binding').internalBinding;
+
+if (!binding('tls_wrap').HAVE_SSL_TRACE)
+  return common.skip('no SSL_trace() compiled into openssl');
+
+const child = fork(__filename, ['test'], { silent: true });
+
+let stderr = '';
+child.stderr.setEncoding('utf8');
+child.stderr.on('data', (data) => stderr += data);
+child.on('close', common.mustCall(() => {
+  assert(/Received Record/.test(stderr));
+  assert(/ClientHello/.test(stderr));
+}));
+
+// For debugging and observation of actual trace output.
+child.stderr.pipe(process.stderr);
+child.stdout.pipe(process.stdout);
+
+child.on('exit', common.mustCall((code) => {
+  assert.strictEqual(code, 0);
+}));
+
+function test() {
+  const {
+    connect, keys
+  } = require(fixtures.path('tls-connect'));
+
+  connect({
+    client: {
+      checkServerIdentity: (servername, cert) => { },
+      ca: `${keys.agent1.cert}\n${keys.agent6.ca}`,
+    },
+    server: {
+      cert: keys.agent6.cert,
+      key: keys.agent6.key,
+      enableTrace: true,
+    },
+  }, common.mustCall((err, pair, cleanup) => {
+    pair.client.conn.enableTrace();
+
+    return cleanup();
+  }));
+}