Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reusing TLS sessions causes to socket.servername being false #28985

Closed
szmarczak opened this issue Aug 5, 2019 · 53 comments
Closed

Reusing TLS sessions causes to socket.servername being false #28985

szmarczak opened this issue Aug 5, 2019 · 53 comments
Labels
blocked PRs that are blocked by other issues or PRs. http2 Issues or PRs related to the http2 subsystem. openssl Issues and PRs related to the OpenSSL dependency. tls Issues and PRs related to the tls subsystem.

Comments

@szmarczak
Copy link
Member

szmarczak commented Aug 5, 2019

  • Version: v12.6.0
  • Platform: Linux solus 5.1.14-121.current deps: update openssl to 1.0.1j #1 SMP PREEMPT Sun Jun 23 13:57:07 UTC 2019 x86_64 GNU/Linux
  • Subsystem: tls, http2

https://runkit.com/szmarczak/5d48640bd3cab4001399357c

The issue happens randomly. Sometimes socket.servername is set to false, sometimes it's a string. I tracked the source down to this C++ code:

node/src/tls_wrap.cc

Lines 991 to 1006 in 0481a7f

void TLSWrap::GetServername(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
TLSWrap* wrap;
ASSIGN_OR_RETURN_UNWRAP(&wrap, args.Holder());
CHECK_NOT_NULL(wrap->ssl_);
const char* servername = SSL_get_servername(wrap->ssl_.get(),
TLSEXT_NAMETYPE_host_name);
if (servername != nullptr) {
args.GetReturnValue().Set(OneByteString(env->isolate(), servername));
} else {
args.GetReturnValue().Set(false);
}
}

servername sometimes is a null pointer. This causes http2session.originSet to look like:

[ 'https://false:35575' ]
@mscdex
Copy link
Contributor

mscdex commented Aug 5, 2019

I can't reproduce this with node master, v12.7.0, or v8.x. I can only reproduce it with node v10.x. Also, the runkit link is using node v10.16.0.

@szmarczak
Copy link
Member Author

On my machine the example shows false. I'll try to think of another example.

@szmarczak
Copy link
Member Author

Do:

git clone https://github.com/szmarczak/http2-wrapper
cd http2-wrapper
git checkout bug
npm install
ava test/agent.js -v

Here's what I get every time:

[ 'https://false:36827' ]

@szmarczak
Copy link
Member Author

The issue still occurs on v12.7.0.

@szmarczak
Copy link
Member Author

szmarczak commented Aug 5, 2019

const http2 = require('http2');

const session = http2.connect('https://google.com', {servername: 'google.com'});
session.socket.once('secureConnect', () => {
    const tlsSession = session.socket.getSession();
    
    session.close();
    session.once('close', () => {
        const secondSession = http2.connect('https://google.com', {servername: 'google.com', session: tlsSession});
        secondSession.socket.once('secureConnect', () => {
            console.log(secondSession.socket.servername);
        });
        secondSession.once('localSettings', () => {
            console.log(secondSession.originSet);
        });
    });
});

Very rarely shows [ 'https://false' ].

@bnoordhuis bnoordhuis added the tls Issues and PRs related to the tls subsystem. label Aug 6, 2019
@szmarczak
Copy link
Member Author

Any news on this?

@szmarczak
Copy link
Member Author

szmarczak commented Sep 7, 2019

Hello? Anybody there? It's been a month since the creation of this issue.

The bug breaks the whole originSet functionality.

@mscdex
Copy link
Contributor

mscdex commented Sep 7, 2019

/cc @nodejs/crypto

@bnoordhuis
Copy link
Member

I suspect it's this line that's at fault:

if (socket.servername != null) {

It should probably be something like if (typeof socket.servername === 'string') {

I'm changing the labels because it's not a tls bug: the servername doesn't need to be present, it's optionally sent by the client as an extension in the ClientHello. The http2 code should handle that.

@bnoordhuis bnoordhuis added http2 Issues or PRs related to the http2 subsystem. and removed tls Issues and PRs related to the tls subsystem. labels Sep 8, 2019
@szmarczak
Copy link
Member Author

@bnoordhuis That would case to originSet being empty. It cannot be empty. There needs to be at least one origin.

@szmarczak
Copy link
Member Author

@bnoordhuis I think if it hasn't received the servername yet, it should show the requested authority in the originSet.

@szmarczak
Copy link
Member Author

Any updates on this? It's been over two months already.

@bnoordhuis
Copy link
Member

@nodejs/http2

@mcollina
Copy link
Member

I don’t understand what is the problem here, and what it is causing to the end user. There are some mentioning of tls, and then http2.

Can you please explain what is the problem here?

(As a side note, you seems to have investigated this problem in great detail.. so you might be best equipped to send a PR to fix it).

@szmarczak
Copy link
Member Author

@mscdex @mcollina

Okay, I can reproduce it every time now (v12.10.0). On v11.15.0 it works as expected tho:

https://runkit.com/szmarczak/5d7e73e9896e0f001a92c20d

Can you please explain what is the problem here?

The problem here is an invalid originSet caused by socket.servername to be false.

As a side note, you seems to have investigated this problem in great detail.. so you might be best equipped to send a PR to fix it

Almost. I have got to the source of it, but haven't figured anything out to fix it yet. (maybe it's a regression? haven't checked that)

@szmarczak
Copy link
Member Author

It's definitely a regression (? or maybe it's the correct behavior now):

const sleep = ms => new Promise(resolve => setTimeout(resolve, ms));

const session = http2.connect('https://google.com', options);
session.socket.once('secureConnect', async () => {
	await sleep(1000);
	console.log(session.originSet);

	session.destroy();
});

after a second:

[ 'https://false' ]

@addaleax addaleax added the tls Issues and PRs related to the tls subsystem. label Sep 16, 2019
@addaleax
Copy link
Member

@szmarczak This seems to reproduce on RunKit for me every time, but never locally… do you have any idea why? I wouldn’t really know how to start debugging there, unfortunately…

@bnoordhuis
Copy link
Member

If I had to venture a guess it's because runkit.com does some kind of reverse-proxying over HTTPS and doesn't forward the servername extension.

@szmarczak
Copy link
Member Author

If I had to venture a guess it's because runkit.com does some kind of reverse-proxying over HTTPS and doesn't forward the servername extension.

Nah. The same code if I run locally also gives me https://false. Note that I'm running a Linux.

This seems to reproduce on RunKit for me every time, but never locally… do you have any idea why? I wouldn’t really know how to start debugging there, unfortunately…

@addaleax Are you running Node v12.10.0? I'll debug it today and let you know anyway.

@addaleax
Copy link
Member

@szmarczak Yes, I’m on x64 Linux too, and all of Node v12.10.0, v11.15.0 and master give the same result, with and without timeout. :/

@addaleax
Copy link
Member

@szmarczak Can you run the failing code locally with NODE_DEBUG_NATIVE=tls NODE_DEBUG=tls set? I wouldn’t expect the output to be too helpful here, but it might be an easy starting point in case there’s obvious differences between your and my setup…

@addaleax
Copy link
Member

Also, just curious, does pinning the TLS version via node --tls-max-v1.3 --tls-min-v1.3 or node --tls-max-v1.2 --tls-min-v1.2 make a difference?

@szmarczak
Copy link
Member Author

szmarczak commented Sep 16, 2019

szm@solus ~/Desktop/http2-wrapper $ node bug.js 
[ 'https://false' ]
szm@solus ~/Desktop/http2-wrapper $ node --tls-max-v1.3 --tls-min-v1.3 bug.js
[ 'https://false' ]
szm@solus ~/Desktop/http2-wrapper $ node --tls-max-v1.2 --tls-min-v1.2 bug.js
[ 'https://google.com' ]

Can you run the failing code locally with NODE_DEBUG_NATIVE=tls NODE_DEBUG=tls set? I wouldn’t expect the output to be too helpful here, but it might be an easy starting point in case there’s obvious differences between your and my setup…

It doesn't output anything new. forgot about export NODE_...=tls

Also, just curious, does pinning the TLS version via node --tls-max-v1.3 --tls-min-v1.3 or node --tls-max-v1.2 --tls-min-v1.2 make a difference?

Yes, actually it works as expected with TLS 1.2. I guess the problem is not in Node itself but in TLS 1.3 or something has changed with TLS 1.3 and Node hasn't updated that yet.

@szmarczak

This comment has been minimized.

@szmarczak
Copy link
Member Author

I do use NVM. NVM uses the binaries from the official Node website.

I think there is a chance that this is a bug in OpenSSL, too.

👍

are you using your operating system’s copy of OpenSSL?

How do I check that?

@sindresorhus
Copy link

I ran https://runkit.com/szmarczak/5d7e73e9896e0f001a92c20d locally and here's the results:

~/Downloads
❯ node --version
v12.10.0

~/Downloads
❯ node --tls-max-v1.3 --tls-min-v1.3 bug.js
[ 'https://false' ]

~/Downloads
❯ node --tls-max-v1.2 --tls-min-v1.2 bug.js
[ 'https://google.com' ]

macOS 10.14.6

@sam-github
Copy link
Contributor

I'm watching this, but haven't had time to try to debug it. Is it possible that TLS 1.3 servername messages come across with different timing than TLS1.2, that http/2 depends on the TLS1.2 timing?

@szmarczak
Copy link
Member Author

szm@solus ~/Desktop/http2-wrapper $ node --tls-max-v1.3 --tls-min-v1.3 bug.js
TLSWrap client (3) Created new TLSWrap
TLS 6163: client _init handle? true
TLS 6163: client initRead handle? true buffered? false
TLS 6163: client _start handle? true connecting? false requestOCSP? false
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) SSLInfoCallback(SSL_CB_HANDSHAKE_START);
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) Writing 1 buffers to the underlying stream
TLSWrap client (3) Write finished synchronously
TLSWrap client (3) ReadStart()
TLSWrap client (3) OnStreamAfterWrite(status = 0)
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) Read 228 bytes from underlying stream
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);
TLS 6163: client onhandshakedone
TLS 6163: client _finishInit handle? true alpn h2 servername false
TLS 6163: client emit secureConnect. authorized: true
[ 'https://false' ]
TLSWrap client (3) ReadStop()
TLSWrap client (3) DoWrite()
TLSWrap client (3) Writing 56 bytes, written = 56
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) EncOut() setting write_callback_scheduled_
TLSWrap client (3) Writing 1 buffers to the underlying stream
TLSWrap client (3) Write finished synchronously
TLSWrap client (3) ReadStop()
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) Returning from EncOut(), write currently in progress
TLSWrap client (3) OnStreamAfterWrite(status = 0)
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) EncOut() setting write_callback_scheduled_
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) DestroySSL()
TLSWrap client (3) InvokeQueued(-125, Canceled because of SSL destruction)
TLSWrap client (3) DestroySSL() finished
TLSWrap client (3) ~TLSWrap()
szm@solus ~/Desktop/http2-wrapper $ node --tls-max-v1.2 --tls-min-v1.2 bug.js
TLSWrap client (3) Created new TLSWrap
TLS 6256: client _init handle? true
TLS 6256: client initRead handle? true buffered? false
TLS 6256: client _start handle? true connecting? false requestOCSP? false
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) SSLInfoCallback(SSL_CB_HANDSHAKE_START);
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) Writing 1 buffers to the underlying stream
TLSWrap client (3) Write finished synchronously
TLSWrap client (3) ReadStart()
TLSWrap client (3) OnStreamAfterWrite(status = 0)
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) Read 1418 bytes from underlying stream
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) Read 1418 bytes from underlying stream
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) Read 867 bytes from underlying stream
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) Writing 1 buffers to the underlying stream
TLSWrap client (3) Write finished synchronously
TLSWrap client (3) OnStreamAfterWrite(status = 0)
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) Read 284 bytes from underlying stream
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to read cleartext output
TLSWrap client (3) SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);
TLS 6256: client onhandshakedone
TLS 6256: client _finishInit handle? true alpn h2 servername google.com
TLS 6256: client emit secureConnect. authorized: true
[ 'https://google.com' ]
TLSWrap client (3) ReadStop()
TLSWrap client (3) DoWrite()
TLSWrap client (3) Writing 56 bytes, written = 56
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) EncOut() setting write_callback_scheduled_
TLSWrap client (3) Writing 1 buffers to the underlying stream
TLSWrap client (3) Write finished synchronously
TLSWrap client (3) ReadStop()
TLSWrap client (3) Read -1 bytes of cleartext output
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) Returning from EncOut(), write currently in progress
TLSWrap client (3) OnStreamAfterWrite(status = 0)
TLSWrap client (3) Trying to write cleartext input
TLSWrap client (3) Returning from ClearIn(), no pending data
TLSWrap client (3) Trying to write encrypted output
TLSWrap client (3) EncOut() setting write_callback_scheduled_
TLSWrap client (3) No pending encrypted output
TLSWrap client (3) No pending cleartext input, not inside DoWrite()
TLSWrap client (3) InvokeQueued(0, (null))
TLSWrap client (3) DestroySSL()
TLSWrap client (3) InvokeQueued(-125, Canceled because of SSL destruction)
TLSWrap client (3) DestroySSL() finished
TLSWrap client (3) ~TLSWrap()

Diff: https://www.diffchecker.com/DeyYrmsv

@szmarczak

This comment has been minimized.

@szmarczak

This comment has been minimized.

@szmarczak
Copy link
Member Author

Synchronised (NODE_DEBUG + --trace-tls):

C:\Users\Szymon Marczak\Desktop>node --tls-max-v1.3 --tls-min-v1.3 --trace-tls bug.js
TLSWrap client (4) Created new TLSWrap
TLS 16492: client _init handle? true
(node:16492) Warning: Enabling --trace-tls can expose sensitive data in the resulting log.
TLS 16492: client initRead handle? true buffered? false
TLS 16492: client _start handle? true connecting? false requestOCSP? false
TLSWrap client (4) Trying to read cleartext output
TLSWrap client (4) SSLInfoCallback(SSL_CB_HANDSHAKE_START);
Sent Record
Header:
  Version = TLS 1.0 (0x301)
  Content Type = Handshake (22)
  Length = 535
    ClientHello, Length=531
      client_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0xC88DDC94
        random_bytes (len=28): B07EF6FA3953664F0EDCF752DEF8B63C9B01E673E054B18A7807FC5E
      session_id (len=32): 3B77725C332B8584BF501BFAB7D393C732C3E0CD99CADE5A6678E165C17B0139
      cipher_suites (len=8)
        {0x13, 0x02} TLS_AES_256_GCM_SHA384
        {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
        {0x13, 0x01} TLS_AES_128_GCM_SHA256
        {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
      compression_methods (len=1)
        No Compression (0x00)
      extensions, length = 450
        extension_type=server_name(0), length=15
          0000 - 00 0d 00 00 0a 67 6f 6f-67 6c 65 2e 63 6f 6d   .....google.com
        extension_type=ec_point_formats(11), length=4
          uncompressed (0)
          ansiX962_compressed_prime (1)
          ansiX962_compressed_char2 (2)
        extension_type=supported_groups(10), length=12
          ecdh_x25519 (29)
          secp256r1 (P-256) (23)
          ecdh_x448 (30)
          secp521r1 (P-521) (25)
          secp384r1 (P-384) (24)
        extension_type=session_ticket(35), length=0
        extension_type=application_layer_protocol_negotiation(16), length=5
          h2
        extension_type=encrypt_then_mac(22), length=0
        extension_type=extended_master_secret(23), length=0
        extension_type=signature_algorithms(13), length=30
          ecdsa_secp256r1_sha256 (0x0403)
          ecdsa_secp384r1_sha384 (0x0503)
          ecdsa_secp521r1_sha512 (0x0603)
          ed25519 (0x0807)
          ed448 (0x0808)
          rsa_pss_pss_sha256 (0x0809)
          rsa_pss_pss_sha384 (0x080a)
          rsa_pss_pss_sha512 (0x080b)
          rsa_pss_rsae_sha256 (0x0804)
          rsa_pss_rsae_sha384 (0x0805)
          rsa_pss_rsae_sha512 (0x0806)
          rsa_pkcs1_sha256 (0x0401)
          rsa_pkcs1_sha384 (0x0501)
          rsa_pkcs1_sha512 (0x0601)
        extension_type=supported_versions(43), length=3
          TLS 1.3 (772)
        extension_type=psk_key_exchange_modes(45), length=2
          psk_dhe_ke (1)
        extension_type=key_share(51), length=38
            NamedGroup: ecdh_x25519 (29)
            key_exchange:  (len=32): 79F38BD0A662B28643ECD70D9384D623DCA03E9309D74EFFB74A7A232BD5CF34
        extension_type=psk(41), length=293
          0000 - 00 f0 00 ea 00 71 80 1c-cc b0 cf ff 19 58 b7   .....q.......X.
          000f - b3 6e 0b 61 5d d3 8d 2b-27 95 19 e7 e6 6f d4   .n.a]..+'....o.
          001e - 31 d1 48 e4 90 ee a3 4d-8e 01 04 66 7e bf ab   1.H....M...f~..
          002d - 8b e7 47 4e e9 36 1b 00-c2 67 53 30 b1 d2 30   ..GN.6...gS0..0
          003c - 4c 88 d4 9c bd ca 67 6b-d3 06 72 b0 74 2d 31   L.....gk..r.t-1
          004b - 66 32 d7 16 a1 6c 0e 1c-f7 f1 11 2e 70 c4 d6   f2...l......p..
          005a - 94 7e ee bf ca c8 70 bd-dd 18 45 54 1e ef 11   .~....p...ET...
          0069 - cc 81 33 1d cb d7 8b 5f-7c ae fc 3f 29 b7 04   ..3...._|..?)..
          0078 - 6a ef f6 0c fe 51 42 9b-ad e9 35 e1 71 b8 b8   j....QB...5.q..
          0087 - a4 2e 1d a1 00 5c 3d fe-1c eb e7 ea 3c 44 b4   .....\=.....<D.
          0096 - c1 b2 3b aa 37 24 44 c5-8f e2 23 53 84 d7 6b   ..;.7$D...#S..k
          00a5 - 60 ea 68 61 68 df f3 84-50 f2 dd 31 4a cc 3d   `.hah...P..1J.=
          00b4 - 4c 2e 64 31 b0 da 3b 6f-8a 60 df c9 f6 b1 96   L.d1..;o.`.....
          00c3 - da 11 b1 81 0f f2 0f 5b-75 a5 59 c0 74 b8 af   .......[u.Y.t..
          00d2 - e5 e9 ce 6f 1c f5 55 08-6e 46 a1 3f f4 ce 3f   ...o..U.nF.?..?
          00e1 - a0 be f8 a6 61 bc 4a 90-b4 92 7c dd 29 52 db   ....a.J...|.)R.
          00f0 - 13 05 00 31 30 36 d8 1f-3c c3 17 08 97 b1 0b   ...106..<......
          00ff - 28 5e 49 75 b7 05 49 ea-1d d4 47 99 eb 1f 8a   (^Iu..I...G....
          010e - a0 6c 75 dd 74 c7 7d 41-6c 3b ab 87 8a 75 1f   .lu.t.}Al;...u.
          011d - 6e 30 bd 46 df 74 45 f7-                       n0.F.tE.

TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) Writing 1 buffers to the underlying stream
TLSWrap client (4) Write finished synchronously
TLSWrap client (4) ReadStart()
TLSWrap client (4) OnStreamAfterWrite(status = 0)
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) Read 228 bytes from underlying stream
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to read cleartext output
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 128
    ServerHello, Length=124
      server_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x9709BECF
        random_bytes (len=28): A1C526D883F4F2D66474CD9CFA9AA53A5223E5AC7EE6AC121163F7A3
      session_id (len=32): 3B77725C332B8584BF501BFAB7D393C732C3E0CD99CADE5A6678E165C17B0139
      cipher_suite {0x13, 0x02} TLS_AES_256_GCM_SHA384
      compression_method: No Compression (0x00)
      extensions, length = 52
        extension_type=psk(41), length=2
          0000 - 00 00                                          ..
        extension_type=key_share(51), length=36
            NamedGroup: ecdh_x25519 (29)
            key_exchange:  (len=32): 35FD81FC6A74C424EFD6FB1A000B7CD01DC60B10DCE718166A9CDCD61B289E7A
        extension_type=supported_versions(43), length=2
            TLS 1.3 (772)

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ApplicationData (23)
  Length = 84
  Inner Content Type = Handshake (22)
    EncryptedExtensions, Length=11
      extensions, length = 9
        extension_type=application_layer_protocol_negotiation(16), length=5
          h2

    Finished, Length=48
      verify_data (len=48): 79DAD621E638867D8AD140FE4AC1A4EA3F9EE9932F92FA6944E3917F141ADE7FB181E7F5BD34DC63C20B14E029E91F6A

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
    change_cipher_spec (1)

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ApplicationData (23)
  Length = 69
  Inner Content Type = Handshake (22)
    Finished, Length=48
      verify_data (len=48): 00B0AB26130FBB61BDBD0DD1348AFD4ACE83D9C93061507D3122E16E5169B82303DBC4BD85649AF5A48AA41121D49C9B

TLSWrap client (4) SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);
TLS 16492: client onhandshakedone
TLS 16492: client _finishInit handle? true alpn h2 servername false
TLS 16492: client emit secureConnect. authorized: true
[ 'https://false' ]
TLSWrap client (4) ReadStop()
TLSWrap client (4) DoWrite()
Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ApplicationData (23)
  Length = 73
  Inner Content Type = ApplicationData (23)
TLSWrap client (4) Writing 56 bytes, written = 56
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) EncOut() setting write_callback_scheduled_
TLSWrap client (4) Writing 1 buffers to the underlying stream
TLSWrap client (4) Write finished synchronously
TLSWrap client (4) ReadStop()
TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) Returning from EncOut(), write currently in progress
TLSWrap client (4) OnStreamAfterWrite(status = 0)
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) EncOut() setting write_callback_scheduled_
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) DestroySSL()
TLSWrap client (4) InvokeQueued(-4081, Canceled because of SSL destruction)
TLSWrap client (4) DestroySSL() finished
TLSWrap client (4) ~TLSWrap()
C:\Users\Szymon Marczak\Desktop>node --tls-max-v1.2 --tls-min-v1.2 --trace-tls bug.js
TLSWrap client (4) Created new TLSWrap
TLS 16648: client _init handle? true
(node:16648) Warning: Enabling --trace-tls can expose sensitive data in the resulting log.
TLS 16648: client initRead handle? true buffered? false
TLS 16648: client _start handle? true connecting? false requestOCSP? false
TLSWrap client (4) Trying to read cleartext output
TLSWrap client (4) SSLInfoCallback(SSL_CB_HANDSHAKE_START);
Sent Record
Header:
  Version = TLS 1.0 (0x301)
  Content Type = Handshake (22)
  Length = 273
    ClientHello, Length=269
      client_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x301D28F1
        random_bytes (len=28): F037BCC3F6BF8391CF6C89A46387901A9CBB9B55985A5916BB1CC096
      session_id (len=0):
      cipher_suites (len=112)
        {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
        {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
        {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
        {0x00, 0xA3} TLS_DHE_DSS_WITH_AES_256_GCM_SHA384
        {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
        {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xC0, 0xAF} TLS_ECDHE_ECDSA_WITH_AES_256_CCM_8
        {0xC0, 0xAD} TLS_ECDHE_ECDSA_WITH_AES_256_CCM
        {0xC0, 0xA3} TLS_DHE_RSA_WITH_AES_256_CCM_8
        {0xC0, 0x9F} TLS_DHE_RSA_WITH_AES_256_CCM
        {0xC0, 0x5D} TLS_ECDHE_ECDSA_WITH_ARIA_256_GCM_SHA384
        {0xC0, 0x61} TLS_ECDHE_RSA_WITH_ARIA_256_GCM_SHA384
        {0xC0, 0x57} TLS_DHE_DSS_WITH_ARIA_256_GCM_SHA384
        {0xC0, 0x53} TLS_DHE_RSA_WITH_ARIA_256_GCM_SHA384
        {0x00, 0xA2} TLS_DHE_DSS_WITH_AES_128_GCM_SHA256
        {0xC0, 0xAE} TLS_ECDHE_ECDSA_WITH_AES_128_CCM_8
        {0xC0, 0xAC} TLS_ECDHE_ECDSA_WITH_AES_128_CCM
        {0xC0, 0xA2} TLS_DHE_RSA_WITH_AES_128_CCM_8
        {0xC0, 0x9E} TLS_DHE_RSA_WITH_AES_128_CCM
        {0xC0, 0x5C} TLS_ECDHE_ECDSA_WITH_ARIA_128_GCM_SHA256
        {0xC0, 0x60} TLS_ECDHE_RSA_WITH_ARIA_128_GCM_SHA256
        {0xC0, 0x56} TLS_DHE_DSS_WITH_ARIA_128_GCM_SHA256
        {0xC0, 0x52} TLS_DHE_RSA_WITH_ARIA_128_GCM_SHA256
        {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
        {0x00, 0x6A} TLS_DHE_DSS_WITH_AES_256_CBC_SHA256
        {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x40} TLS_DHE_DSS_WITH_AES_128_CBC_SHA256
        {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x38} TLS_DHE_DSS_WITH_AES_256_CBC_SHA
        {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
        {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x32} TLS_DHE_DSS_WITH_AES_128_CBC_SHA
        {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
        {0xC0, 0xA1} TLS_RSA_WITH_AES_256_CCM_8
        {0xC0, 0x9D} TLS_RSA_WITH_AES_256_CCM
        {0xC0, 0x51} TLS_RSA_WITH_ARIA_256_GCM_SHA384
        {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0xA0} TLS_RSA_WITH_AES_128_CCM_8
        {0xC0, 0x9C} TLS_RSA_WITH_AES_128_CCM
        {0xC0, 0x50} TLS_RSA_WITH_ARIA_128_GCM_SHA256
        {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
        {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
      compression_methods (len=1)
        No Compression (0x00)
      extensions, length = 116
        extension_type=server_name(0), length=15
          0000 - 00 0d 00 00 0a 67 6f 6f-67 6c 65 2e 63 6f 6d   .....google.com
        extension_type=ec_point_formats(11), length=4
          uncompressed (0)
          ansiX962_compressed_prime (1)
          ansiX962_compressed_char2 (2)
        extension_type=supported_groups(10), length=12
          ecdh_x25519 (29)
          secp256r1 (P-256) (23)
          ecdh_x448 (30)
          secp521r1 (P-521) (25)
          secp384r1 (P-384) (24)
        extension_type=session_ticket(35), length=0
        extension_type=application_layer_protocol_negotiation(16), length=5
          h2
        extension_type=encrypt_then_mac(22), length=0
        extension_type=extended_master_secret(23), length=0
        extension_type=signature_algorithms(13), length=48
          ecdsa_secp256r1_sha256 (0x0403)
          ecdsa_secp384r1_sha384 (0x0503)
          ecdsa_secp521r1_sha512 (0x0603)
          ed25519 (0x0807)
          ed448 (0x0808)
          rsa_pss_pss_sha256 (0x0809)
          rsa_pss_pss_sha384 (0x080a)
          rsa_pss_pss_sha512 (0x080b)
          rsa_pss_rsae_sha256 (0x0804)
          rsa_pss_rsae_sha384 (0x0805)
          rsa_pss_rsae_sha512 (0x0806)
          rsa_pkcs1_sha256 (0x0401)
          rsa_pkcs1_sha384 (0x0501)
          rsa_pkcs1_sha512 (0x0601)
          ecdsa_sha224 (0x0303)
          ecdsa_sha1 (0x0203)
          rsa_pkcs1_sha224 (0x0301)
          rsa_pkcs1_sha1 (0x0201)
          dsa_sha224 (0x0302)
          dsa_sha1 (0x0202)
          dsa_sha256 (0x0402)
          dsa_sha384 (0x0502)
          dsa_sha512 (0x0602)

TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) Writing 1 buffers to the underlying stream
TLSWrap client (4) Write finished synchronously
TLSWrap client (4) ReadStart()
TLSWrap client (4) OnStreamAfterWrite(status = 0)
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) Read 1430 bytes from underlying stream
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to read cleartext output
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 72
    ServerHello, Length=68
      server_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x5D827090
        random_bytes (len=28): 0DAC58CDF8592FFA8992923251B19E51A0923131444F574E47524401
      session_id (len=0):
      cipher_suite {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
      compression_method: No Compression (0x00)
      extensions, length = 28
        extension_type=extended_master_secret(23), length=0
        extension_type=renegotiate(65281), length=1
            <EMPTY>
        extension_type=ec_point_formats(11), length=2
          uncompressed (0)
        extension_type=session_ticket(35), length=0
        extension_type=application_layer_protocol_negotiation(16), length=5
          h2

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 3491
TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) Read 2272 bytes from underlying stream
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to read cleartext output
    Certificate, Length=3487
      certificate_list, length=3484
        ASN.1Cert, length=2376
------details-----
Certificate:
    Data:
        Version: 3 (0x2)
        Serial Number:
            bc:f1:1c:16:a5:25:b4:f2:08:00:00:00:00:13:17:a2
        Signature Algorithm: sha256WithRSAEncryption
        Issuer: C = US, O = Google Trust Services, CN = GTS CA 1O1
        Validity
            Not Before: Sep  5 20:21:47 2019 GMT
            Not After : Nov 28 20:21:47 2019 GMT
        Subject: C = US, ST = California, L = Mountain View, O = Google LLC, CN = *.google.com
        Subject Public Key Info:
            Public Key Algorithm: id-ecPublicKey
                Public-Key: (256 bit)
                pub:
                    04:7b:9d:61:14:06:1f:78:ed:98:d9:a6:2e:3d:a2:
                    1e:d2:86:32:b6:10:5f:14:b9:ad:7b:79:33:45:85:
                    8a:0c:e4:0e:5e:56:77:6b:b5:43:12:57:80:6a:64:
                    8b:4b:0a:a0:bb:65:a8:5d:71:10:22:7d:7b:19:fd:
                    b1:a3:f3:bf:77
                ASN1 OID: prime256v1
                NIST CURVE: P-256
        X509v3 extensions:
            X509v3 Key Usage: critical
                Digital Signature
            X509v3 Extended Key Usage:
                TLS Web Server Authentication
            X509v3 Basic Constraints: critical
                CA:FALSE
            X509v3 Subject Key Identifier:
                FB:9F:BB:CF:37:2E:14:10:35:7C:7B:58:97:2A:BF:D9:8D:39:0E:7C
            X509v3 Authority Key Identifier:
                keyid:98:D1:F8:6E:10:EB:CF:9B:EC:60:9F:18:90:1B:A0:EB:7D:09:FD:2B

            Authority Information Access:
                OCSP - URI:http://ocsp.pki.goog/gts1o1
                CA Issuers - URI:http://pki.goog/gsr2/GTS1O1.crt

            X509v3 Subject Alternative Name:
                DNS:*.google.com, DNS:*.android.com, DNS:*.appengine.google.com, DNS:*.cloud.google.com, DNS:*.crowdsource.google.com, DNS:*.g.co, DNS:*.gcp.gvt2.com, DNS:*.gcpcdn.gvt1.com, DNS:*.ggpht.cn, DNS:*.gkecnapps.cn, DNS:*.google-analytics.com, DNS:*.google.ca, DNS:*.google.cl, DNS:*.google.co.in, DNS:*.google.co.jp, DNS:*.google.co.uk, DNS:*.google.com.ar, DNS:*.google.com.au, DNS:*.google.com.br, DNS:*.google.com.co, DNS:*.google.com.mx, DNS:*.google.com.tr, DNS:*.google.com.vn, DNS:*.google.de, DNS:*.google.es, DNS:*.google.fr, DNS:*.google.hu, DNS:*.google.it, DNS:*.google.nl, DNS:*.google.pl, DNS:*.google.pt, DNS:*.googleadapis.com, DNS:*.googleapis.cn, DNS:*.googlecnapps.cn, DNS:*.googlecommerce.com, DNS:*.googlevideo.com, DNS:*.gstatic.cn, DNS:*.gstatic.com, DNS:*.gstaticcnapps.cn, DNS:*.gvt1.com, DNS:*.gvt2.com, DNS:*.metric.gstatic.com, DNS:*.urchin.com, DNS:*.url.google.com, DNS:*.wear.gkecnapps.cn, DNS:*.youtube-nocookie.com, DNS:*.youtube.com, DNS:*.youtubeeducation.com, DNS:*.youtubekids.com, DNS:*.yt.be, DNS:*.ytimg.com, DNS:android.clients.google.com, DNS:android.com, DNS:developer.android.google.cn, DNS:developers.android.google.cn, DNS:g.co, DNS:ggpht.cn, DNS:gkecnapps.cn, DNS:goo.gl, DNS:google-analytics.com, DNS:google.com, DNS:googlecnapps.cn, DNS:googlecommerce.com, DNS:source.android.google.cn, DNS:urchin.com, DNS:www.goo.gl, DNS:youtu.be, DNS:youtube.com, DNS:youtubeeducation.com, DNS:youtubekids.com, DNS:yt.be
            X509v3 Certificate Policies:
                Policy: 2.23.140.1.2.2
                Policy: 1.3.6.1.4.1.11129.2.5.3

            X509v3 CRL Distribution Points:

                Full Name:
                  URI:http://crl.pki.goog/GTS1O1.crl

            CT Precertificate SCTs:
                Signed Certificate Timestamp:
                    Version   : v1 (0x0)
                    Log ID    : 63:F2:DB:CD:E8:3B:CC:2C:CF:0B:72:84:27:57:6B:33:
                                A4:8D:61:77:8F:BD:75:A6:38:B1:C7:68:54:4B:D8:8D
                    Timestamp : Sep  5 21:21:51.086 2019 GMT
                    Extensions: none
                    Signature : ecdsa-with-SHA256
                                30:45:02:21:00:BE:BA:0F:05:A2:CD:31:43:27:95:BC:
                                65:C3:52:2E:E4:28:16:A7:08:83:A6:EA:B0:03:6F:B4:
                                60:CF:1D:9E:63:02:20:19:95:E2:27:9F:58:11:65:9C:
                                1C:CE:D4:F4:5A:CD:B3:B6:AF:3E:3E:ED:C2:6E:C8:47:
                                29:92:A4:F6:0B:A9:B6
                Signed Certificate Timestamp:
                    Version   : v1 (0x0)
                    Log ID    : 74:7E:DA:83:31:AD:33:10:91:21:9C:CE:25:4F:42:70:
                                C2:BF:FD:5E:42:20:08:C6:37:35:79:E6:10:7B:CC:56
                    Timestamp : Sep  5 21:21:51.116 2019 GMT
                    Extensions: none
                    Signature : ecdsa-with-SHA256
                                30:45:02:20:35:1C:0B:C9:0C:4D:92:37:90:DC:2B:F7:
                                AF:F6:B2:FB:3A:4A:1E:53:60:51:87:AC:1F:3E:21:EF:
                                34:44:8A:FD:02:21:00:F2:5E:B3:4B:04:01:4D:79:BB:
                                53:85:52:FD:C3:28:09:51:92:CE:5F:7B:22:1A:30:48:
                                D2:EF:3D:CC:F0:31:A9
    Signature Algorithm: sha256WithRSAEncryption
         75:0d:c8:01:d9:25:c2:31:d9:ad:06:14:9e:cd:bf:55:67:e1:
         40:ae:21:cb:79:87:8e:10:6a:ff:bd:15:1e:77:72:93:9f:21:
         c2:13:87:9f:04:aa:6b:16:c6:02:de:7e:4d:5b:90:0a:36:4b:
         30:05:da:84:9f:c9:02:3c:ad:7d:1b:95:f5:29:35:53:56:3a:
         b5:b2:d8:4d:ec:0e:8a:44:c2:1e:14:d8:73:15:e0:31:a4:52:
         3b:94:f7:ad:37:94:40:ef:a2:7d:33:69:1f:b6:1b:95:8a:73:
         2e:9c:ef:26:ab:05:19:30:2b:ad:d9:03:6f:0d:e6:1c:ad:88:
         9f:9e:fa:ca:c5:65:53:02:25:21:8a:59:e8:61:10:65:b5:36:
         c6:25:2d:c3:fc:36:72:a2:25:3c:f4:14:0c:cf:8c:a7:9e:04:
         a6:aa:37:18:d3:9a:f4:88:0c:42:98:8b:86:db:30:eb:2a:52:
         fb:94:3b:2f:25:f4:35:09:38:2f:be:1f:56:f6:a5:7a:7a:5e:
         7f:cf:6e:a8:8f:ca:f3:4c:3e:1a:b8:b2:3e:52:63:77:93:e3:
         f1:4f:4e:e2:ca:da:ef:58:40:e0:e3:93:2e:02:6b:13:a4:2a:
         29:c4:55:72:7f:0a:5f:67:e6:2a:83:f4:83:52:fd:77:e2:a3:
         70:f0:6d:ff
-----BEGIN CERTIFICATE-----
MIIJRDCCCCygAwIBAgIRALzxHBalJbTyCAAAAAATF6IwDQYJKoZIhvcNAQELBQAw
QjELMAkGA1UEBhMCVVMxHjAcBgNVBAoTFUdvb2dsZSBUcnVzdCBTZXJ2aWNlczET
MBEGA1UEAxMKR1RTIENBIDFPMTAeFw0xOTA5MDUyMDIxNDdaFw0xOTExMjgyMDIx
NDdaMGYxCzAJBgNVBAYTAlVTMRMwEQYDVQQIEwpDYWxpZm9ybmlhMRYwFAYDVQQH
Ew1Nb3VudGFpbiBWaWV3MRMwEQYDVQQKEwpHb29nbGUgTExDMRUwEwYDVQQDDAwq
Lmdvb2dsZS5jb20wWTATBgcqhkjOPQIBBggqhkjOPQMBBwNCAAR7nWEUBh947ZjZ
pi49oh7ShjK2EF8Uua17eTNFhYoM5A5eVndrtUMSV4BqZItLCqC7ZahdcRAifXsZ
/bGj8793o4IG2jCCBtYwDgYDVR0PAQH/BAQDAgeAMBMGA1UdJQQMMAoGCCsGAQUF
BwMBMAwGA1UdEwEB/wQCMAAwHQYDVR0OBBYEFPufu883LhQQNXx7WJcqv9mNOQ58
MB8GA1UdIwQYMBaAFJjR+G4Q68+b7GCfGJAboOt9Cf0rMGQGCCsGAQUFBwEBBFgw
VjAnBggrBgEFBQcwAYYbaHR0cDovL29jc3AucGtpLmdvb2cvZ3RzMW8xMCsGCCsG
AQUFBzAChh9odHRwOi8vcGtpLmdvb2cvZ3NyMi9HVFMxTzEuY3J0MIIEnQYDVR0R
BIIElDCCBJCCDCouZ29vZ2xlLmNvbYINKi5hbmRyb2lkLmNvbYIWKi5hcHBlbmdp
bmUuZ29vZ2xlLmNvbYISKi5jbG91ZC5nb29nbGUuY29tghgqLmNyb3dkc291cmNl
Lmdvb2dsZS5jb22CBiouZy5jb4IOKi5nY3AuZ3Z0Mi5jb22CESouZ2NwY2RuLmd2
dDEuY29tggoqLmdncGh0LmNugg4qLmdrZWNuYXBwcy5jboIWKi5nb29nbGUtYW5h
bHl0aWNzLmNvbYILKi5nb29nbGUuY2GCCyouZ29vZ2xlLmNsgg4qLmdvb2dsZS5j
by5pboIOKi5nb29nbGUuY28uanCCDiouZ29vZ2xlLmNvLnVrgg8qLmdvb2dsZS5j
b20uYXKCDyouZ29vZ2xlLmNvbS5hdYIPKi5nb29nbGUuY29tLmJygg8qLmdvb2ds
ZS5jb20uY2+CDyouZ29vZ2xlLmNvbS5teIIPKi5nb29nbGUuY29tLnRygg8qLmdv
b2dsZS5jb20udm6CCyouZ29vZ2xlLmRlggsqLmdvb2dsZS5lc4ILKi5nb29nbGUu
ZnKCCyouZ29vZ2xlLmh1ggsqLmdvb2dsZS5pdIILKi5nb29nbGUubmyCCyouZ29v
Z2xlLnBsggsqLmdvb2dsZS5wdIISKi5nb29nbGVhZGFwaXMuY29tgg8qLmdvb2ds
ZWFwaXMuY26CESouZ29vZ2xlY25hcHBzLmNughQqLmdvb2dsZWNvbW1lcmNlLmNv
bYIRKi5nb29nbGV2aWRlby5jb22CDCouZ3N0YXRpYy5jboINKi5nc3RhdGljLmNv
bYISKi5nc3RhdGljY25hcHBzLmNuggoqLmd2dDEuY29tggoqLmd2dDIuY29tghQq
Lm1ldHJpYy5nc3RhdGljLmNvbYIMKi51cmNoaW4uY29tghAqLnVybC5nb29nbGUu
Y29tghMqLndlYXIuZ2tlY25hcHBzLmNughYqLnlvdXR1YmUtbm9jb29raWUuY29t
gg0qLnlvdXR1YmUuY29tghYqLnlvdXR1YmVlZHVjYXRpb24uY29tghEqLnlvdXR1
YmVraWRzLmNvbYIHKi55dC5iZYILKi55dGltZy5jb22CGmFuZHJvaWQuY2xpZW50
cy5nb29nbGUuY29tggthbmRyb2lkLmNvbYIbZGV2ZWxvcGVyLmFuZHJvaWQuZ29v
Z2xlLmNughxkZXZlbG9wZXJzLmFuZHJvaWQuZ29vZ2xlLmNuggRnLmNvgghnZ3Bo
dC5jboIMZ2tlY25hcHBzLmNuggZnb28uZ2yCFGdvb2dsZS1hbmFseXRpY3MuY29t
ggpnb29nbGUuY29tgg9nb29nbGVjbmFwcHMuY26CEmdvb2dsZWNvbW1lcmNlLmNv
bYIYc291cmNlLmFuZHJvaWQuZ29vZ2xlLmNuggp1cmNoaW4uY29tggp3d3cuZ29v
Lmdsggh5b3V0dS5iZYILeW91dHViZS5jb22CFHlvdXR1YmVlZHVjYXRpb24uY29t
gg95b3V0dWJla2lkcy5jb22CBXl0LmJlMCEGA1UdIAQaMBgwCAYGZ4EMAQICMAwG
CisGAQQB1nkCBQMwLwYDVR0fBCgwJjAkoCKgIIYeaHR0cDovL2NybC5wa2kuZ29v
Zy9HVFMxTzEuY3JsMIIBBAYKKwYBBAHWeQIEAgSB9QSB8gDwAHYAY/Lbzeg7zCzP
C3KEJ1drM6SNYXePvXWmOLHHaFRL2I0AAAFtA04R7gAABAMARzBFAiEAvroPBaLN
MUMnlbxlw1Iu5CgWpwiDpuqwA2+0YM8dnmMCIBmV4iefWBFlnBzO1PRazbO2rz4+
7cJuyEcpkqT2C6m2AHYAdH7agzGtMxCRIZzOJU9CcMK//V5CIAjGNzV55hB7zFYA
AAFtA04SDAAABAMARzBFAiA1HAvJDE2SN5DcK/ev9rL7OkoeU2BRh6wfPiHvNESK
/QIhAPJes0sEAU15u1OFUv3DKAlRks5feyIaMEjS7z3M8DGpMA0GCSqGSIb3DQEB
CwUAA4IBAQB1DcgB2SXCMdmtBhSezb9VZ+FAriHLeYeOEGr/vRUed3KTnyHCE4ef
BKprFsYC3n5NW5AKNkswBdqEn8kCPK19G5X1KTVTVjq1sthN7A6KRMIeFNhzFeAx
pFI7lPetN5RA76J9M2kfthuVinMunO8mqwUZMCut2QNvDeYcrYifnvrKxWVTAiUh
ilnoYRBltTbGJS3D/DZyoiU89BQMz4ynngSmqjcY05r0iAxCmIuG2zDrKlL7lDsv
JfQ1CTgvvh9W9qV6el5/z26oj8rzTD4auLI+UmN3k+PxT07iytrvWEDg45MuAmsT
pCopxFVyfwpfZ+Yqg/SDUv134qNw8G3/
-----END CERTIFICATE-----
------------------
        extensions, length = 4
extensions, extype = 20016, extlen = 33284
          0000 - 4e 30 82 04                                    N0..
Message length parse error!

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 115
    ServerKeyExchange, Length=111
      KeyExchangeAlgorithm=ECDHE
        named_curve: ecdh_x25519 (29)
        point (len=32): 3C0B8D3C26673014C9A3BB1FE67DE9FCD066258343B7647492206705FC3DB37D
      Signature Algorithm: ecdsa_secp256r1_sha256 (0x0403)
      Signature (len=71): 304502207C7B959447B55E4BB810388672A5D5EC3808C110A69AE6DB6646695CBB64B3D8022100D9E60B3D03B3C4FCE570FDDF53CE8475E0A2F7A3EA9A70A85837627C1189D26F

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 4
    ServerHelloDone, Length=0

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 37
    ClientKeyExchange, Length=33
      KeyExchangeAlgorithm=ECDHE
        ecdh_Yc (len=32): 3A4734CF0765FCF1E22B011D260DF2D38A1726B1D9138BBDB91A1DE510047F12

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
    change_cipher_spec (1)

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 40
    Finished, Length=12
      verify_data (len=12): ACDF04244EB90F9472AFCE3A

TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) Writing 1 buffers to the underlying stream
TLSWrap client (4) Write finished synchronously
TLSWrap client (4) OnStreamAfterWrite(status = 0)
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) Read 353 bytes from underlying stream
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to read cleartext output
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 228
    NewSessionTicket, Length=224
        ticket_lifetime_hint=100800
        ticket (len=218): 0071801CCCB0CFFF1958B7B36E0B615DDA0D333324DFEEBA2B2A0428C275A0E11A487ED34D451C3FECC8B0BAE9CCF7416EC48397BBC2816956FC4DFB45909334603E08011DE6CF034266BD0C20F78ADB2D60A7210749F40FB6E85B3686D3423E9A127733AEB74453357791F8E8941560D2B48E73B2308DDBD34BC5F53D978BAEE09B524D0179B56CD2527B4848D9EA303EE423ED063234C06DD1714E29521FF1FE27831DE4E6C86820F0DD3D76F341AE83669919A742411AE51EF5993E5FB0D11B88D23B8B612559161649E7175B006AA922E0B23DAF6658829D

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 40
    Finished, Length=12
      verify_data (len=12): 049167241D2469C487E2EB75

TLSWrap client (4) SSLInfoCallback(SSL_CB_HANDSHAKE_DONE);
TLS 16648: client onhandshakedone
TLS 16648: client _finishInit handle? true alpn h2 servername google.com
TLS 16648: client emit secureConnect. authorized: true
[ 'https://google.com' ]
TLSWrap client (4) ReadStop()
TLSWrap client (4) DoWrite()
Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ApplicationData (23)
  Length = 80
TLSWrap client (4) Writing 56 bytes, written = 56
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) EncOut() setting write_callback_scheduled_
TLSWrap client (4) Writing 1 buffers to the underlying stream
TLSWrap client (4) Write finished synchronously
TLSWrap client (4) ReadStop()
Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ApplicationData (23)
  Length = 64
TLSWrap client (4) Read 40 bytes of cleartext output
TLSWrap client (4) Read -1 bytes of cleartext output
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) Returning from EncOut(), write currently in progress
TLSWrap client (4) OnStreamAfterWrite(status = 0)
TLSWrap client (4) Trying to write cleartext input
TLSWrap client (4) Returning from ClearIn(), no pending data
TLSWrap client (4) Trying to write encrypted output
TLSWrap client (4) EncOut() setting write_callback_scheduled_
TLSWrap client (4) No pending encrypted output
TLSWrap client (4) No pending cleartext input, not inside DoWrite()
TLSWrap client (4) InvokeQueued(0, (null))
TLSWrap client (4) DestroySSL()
TLSWrap client (4) InvokeQueued(-4081, Canceled because of SSL destruction)
TLSWrap client (4) DestroySSL() finished
TLSWrap client (4) ~TLSWrap()

@szmarczak
Copy link
Member Author

So I tested it on Node 11 with TLS 1.3, and the issue still exists.

@szmarczak
Copy link
Member Author

checkServerIdentity is not called: https://runkit.com/szmarczak/5d83cc42172c06001a256cfa (expected "google.com" outputted twice)

@szmarczak
Copy link
Member Author

I have analyzed the source code and I figured out that's not possible to fail. So I went through openssl issues and found this:

openssl/openssl#8822

Yeah, you were right, it's an openssl issue.

@addaleax
Copy link
Member

@szmarczak Okay, thanks for doing all the digging here. I’ll take a deeper look at the openssl source.

@addaleax
Copy link
Member

From what I can tell, SSL_get_servername() returns nullptr because s->hit is set on the SSL* object, which happens here:

Stack trace
#0  tls_parse_stoc_psk (s=0x55b088abc1f0, pkt=0x55b088ac0518, context=512, x=0x0, chainidx=0) at ../deps/openssl/openssl/ssl/statem/extensions_clnt.c:1968
#1  0x000055b085f23e79 in tls_parse_extension (s=0x55b088abc1f0, idx=TLSEXT_IDX_psk, context=512, exts=0x55b088ac0130, x=0x0, chainidx=0) at ../deps/openssl/openssl/ssl/statem/extensions.c:715
#2  0x000055b085f36c1f in tls_process_server_hello (s=0x55b088abc1f0, pkt=0x7ffdce89f080) at ../deps/openssl/openssl/ssl/statem/statem_clnt.c:1549
#3  0x000055b085f3599f in ossl_statem_client_process_message (s=0x55b088abc1f0, pkt=0x7ffdce89f080) at ../deps/openssl/openssl/ssl/statem/statem_clnt.c:1039
#4  0x000055b085f32f40 in read_state_machine (s=0x55b088abc1f0) at ../deps/openssl/openssl/ssl/statem/statem.c:636
#5  0x000055b085f329ce in state_machine (s=0x55b088abc1f0, server=0) at ../deps/openssl/openssl/ssl/statem/statem.c:434
#6  0x000055b085f324d4 in ossl_statem_connect (s=0x55b088abc1f0) at ../deps/openssl/openssl/ssl/statem/statem.c:250
#7  0x000055b085ef907e in ssl3_read_bytes (s=0x55b088abc1f0, type=23, recvd_type=0x0, buf=0x7ffdce89f450 "", len=16384, peek=0, readbytes=0x7ffdce89f360) at ../deps/openssl/openssl/ssl/record/rec_layer_s3.c:1270
#8  0x000055b085f061ec in ssl3_read_internal (s=0x55b088abc1f0, buf=0x7ffdce89f450, len=16384, peek=0, readbytes=0x7ffdce89f360) at ../deps/openssl/openssl/ssl/s3_lib.c:4473
#9  0x000055b085f062c3 in ssl3_read (s=0x55b088abc1f0, buf=0x7ffdce89f450, len=16384, readbytes=0x7ffdce89f360) at ../deps/openssl/openssl/ssl/s3_lib.c:4497
#10 0x000055b085f145aa in ssl_read_internal (s=0x55b088abc1f0, buf=0x7ffdce89f450, num=16384, readbytes=0x7ffdce89f360) at ../deps/openssl/openssl/ssl/ssl_lib.c:1752
#11 0x000055b085f1462a in SSL_read (s=0x55b088abc1f0, buf=0x7ffdce89f450, num=16384) at ../deps/openssl/openssl/ssl/ssl_lib.c:1766
#12 0x000055b084e33575 in node::TLSWrap::ClearOut (this=0x55b088aba210) at ../src/tls_wrap.cc:503

hit is described in the source code as “reusing a previous session”, so I think this is intentional on OpenSSL’s side, I just don’t understand why.

@addaleax
Copy link
Member

@szmarczak It looks like the tlsext_hostname key is missing from the Buffer instances in your runkit examples. If it were present, OpenSSL would use that. This also seems to happen in the issue you linked, but then again maybe the OpenSSL CLI utility doesn’t set the hostname explicitly like we do.

How did you generate those Buffers? That might be useful to know.

Generally, I can see a few ways that this goes forward:

  1. This turns out to be a bug in OpenSSL not storing the hostname in the serialized session data when it should.
  2. OpenSSL should fall back to providing the hostname stored on the SSL object if the re-used session did not provide one.
  3. We decide to cache the hostname on our side when we set it, and if SSL_get_servername() happens returns nullptr, we use that cached hostname.

I don’t really know how TLS v1.3 comes into play here. The SSL version stored in your Buffers is TLS v1.3, so it’s not some kind of incompatibility thing, I’d say.

@szmarczak
Copy link
Member Author

How did you generate those Buffers? That might be useful to know.

@addaleax I just simply connect, save the session buffer, close the connection and reconnect: https://runkit.com/szmarczak/5d851a78b56e55001a047b7d

This turns out to be a bug in OpenSSL not storing the hostname in the serialized session data when it should.

👍

OpenSSL should fall back to providing the hostname stored on the SSL object if the re-used session did not provide one.

👍

We decide to cache the hostname on our side when we set it, and if SSL_get_servername() happens returns nullptr, we use that cached hostname.

👍

I don’t really know how TLS v1.3 comes into play here. The SSL version stored in your Buffers is TLS v1.3, so it’s not some kind of incompatibility thing, I’d say.

And it started to also not work even if using TLS v1.2. It's getting weirder and weirder.

@addaleax
Copy link
Member

I have come to the conclusion that this involves some kind of witchcraft – the same test file that would reproduce the issue consistently for me yesterday does not do that today. (My best guess would be that behaviour varies depending on what remote host exactly is being reached.)

That being said, @szmarczak, could you try to apply this diff to Node.js master and verify that it doesn’t work before and works after, since you seem to be the person who has the easiest time reproducing this consistently?

diff --git a/deps/openssl/openssl/ssl/ssl_lib.c b/deps/openssl/openssl/ssl/ssl_lib.c
index f559bc10eff4..0aa4ceb954f2 100644
--- a/deps/openssl/openssl/ssl/ssl_lib.c
+++ b/deps/openssl/openssl/ssl/ssl_lib.c
@@ -2630,7 +2630,7 @@ const char *SSL_get_servername(const SSL *s, const int type)
      * call the relevant callbacks for such resumption flows, and callbacks
      * might error out if there is not a SNI value available.
      */
-    if (s->hit)
+    if (s->hit && s->session->ext.hostname != NULL)
         return s->session->ext.hostname;
     return s->ext.hostname;
 }

@szmarczak
Copy link
Member Author

@addaleax

szm@solus ~/Desktop $ node -v
v12.10.0
szm@solus ~/Desktop $ ./node -v
v13.0.0-pre
szm@solus ~/Desktop $ node bug.js
false
szm@solus ~/Desktop $ ./node bug.js
google.com

I confirm your patch fixes the bug. 😃

addaleax added a commit to addaleax/openssl that referenced this issue Sep 21, 2019
In `SSL_get_servername()`, fall back to returning the hostname
set earlier via `SSL_set_tlsext_host_name()` when the resumed
session data does not include a host name field.

Refs: openssl#8822
Fixes: nodejs/node#28985

CLA: Trivial
@addaleax
Copy link
Member

I’ve opened a PR against OpenSSL, let’s see where that leads us. Even if it doesn’t land we can easily work around that in Node.js, but I’m not sure if the approach is okay as-is.

@mattcaswell
Copy link

It is interesting to note in all of the problematic traces given above the server_name extension that exists in the ClientHello is not acknowledged by the server in the ServerHello/EncryptedExtensions which concurs with my expectations from my comments in openssl/openssl#9964

@o2genum
Copy link

o2genum commented Dec 1, 2019

@addaleax @szmarczak Could you please explain a bit how badly this impairs HTTP/2 support?

Does this ruin the HTTP/2 benefits of parallel requests? Does this break HTTP/2 completely?

@szmarczak
Copy link
Member Author

@o2genum It breaks the originSet functionality only when using a custom TLS session.
If you don't use it, then you have nothing to worry about.
I'm working on an Agent for HTTP2, I cache TLS session for faster handshake.

@addaleax addaleax added blocked PRs that are blocked by other issues or PRs. openssl Issues and PRs related to the OpenSSL dependency. labels Dec 11, 2019
@addaleax
Copy link
Member

Marking this as blocked until openssl/openssl#10018 is merged

@mattcaswell
Copy link

openssl/openssl#10018 is now merged.

@szmarczak
Copy link
Member Author

@addaleax You may want to remove the blocked label since the upstream issue has been fixed two weeks ago :)

@addaleax
Copy link
Member

@szmarczak So … maybe you have been more active in following the OpenSSL discussion than I have, but our primary options are either a) waiting for the next OpenSSL release and picking those changes up, b) cherry-picking the relevant commit(s) and hoping that that doesn’t work out too badly for downstream vendors (e.g. Linux distros that make Node.js use the system OpenSSL) or c) implementing a temporary fix in our TLS code that make the code work as expected.

I think we’re unlikely to do b), and I don’t know what would be involved in c) – if you do know what we’d need to do (or are able to open a PR yourself), great, but otherwise only a) really remains and in that case we’re still blocked on upstream OpenSSL…

@szmarczak
Copy link
Member Author

Closing since Node.js upgraded OpenSSL for v10 and v12 which means this error is indeed fixed. I cannot reproduce it anymore. Thanks everyone for involving!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
blocked PRs that are blocked by other issues or PRs. http2 Issues or PRs related to the http2 subsystem. openssl Issues and PRs related to the OpenSSL dependency. tls Issues and PRs related to the tls subsystem.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants