investigate flaky test-tls-enable-trace-cli

[Trott]

00:06:45 not ok 1842 parallel/test-tls-enable-trace-cli # TODO : Fix flaky test
00:06:45   ---
00:06:45   duration_ms: 0.270
00:06:45   severity: flaky
00:06:45   exitcode: 1
00:06:45   stack: |-
00:06:45     (node:8990) Warning: Enabling --trace-tls can expose sensitive data in the resulting log.
00:06:45     Sent Record
00:06:45     Header:
00:06:45       Version = TLS 1.0 (0x301)
00:06:45       Content Type = Handshake (22)
00:06:45       Length = 340
00:06:45         ClientHello, Length=336
00:06:45           client_version=0x303 (TLS 1.2)
00:06:45           Random:
00:06:45             gmt_unix_time=0x306CB443
00:06:45             random_bytes (len=28): E4125F67C270656192CEF08FFD456C6A103C8B8E3273470B634942AF
00:06:45           session_id (len=32): 0631BBD4779E3397C6B1A74580BC1EF1A37FAF7FAE6618956EF810EEFCDED5B0
00:06:45           cipher_suites (len=118)
00:06:45             {0x13, 0x02} TLS_AES_256_GCM_SHA384
00:06:45             {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
00:06:45             {0x13, 0x01} TLS_AES_128_GCM_SHA256
00:06:45             {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
00:06:45             {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
00:06:45             {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
00:06:45             {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
00:06:45             {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
00:06:45             {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
00:06:45             {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
00:06:45             {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
00:06:45             {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
00:06:45             {0x00, 0xA3} TLS_DHE_DSS_WITH_AES_256_GCM_SHA384
00:06:45             {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
00:06:45             {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
00:06:45             {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
00:06:45             {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
00:06:45             [Error: 140237417195328:error:09072007:PEM routines:PEM_write_bio:BUF lib:../deps/openssl/openssl/crypto/pem/pem_lib.c:658:
00:06:45     140237417195328:error:09072007:PEM routines:PEM_write_bio:BUF lib:../deps/openssl/openssl/crypto/pem/pem_lib.c:658:
00:06:45     ] {
00:06:45       library: 'PEM routines',
00:06:45       function: 'PEM_write_bio',
00:06:45       reason: 'BUF lib',
00:06:45       code: 'ERR_SSL_BUF_LIB'
00:06:45     }
00:06:45     undefined
00:06:45     BUF lib
00:06:45     Sent Record
00:06:45     Header:
00:06:45       Version = TLS 1.2 (0x303)
00:06:45       Content Type = ApplicationData (23)
00:06:45       Length = 19
00:06:45       Inner Content Type = Alert (21)
00:06:45         Level=warning(1), description=close notify(0)
00:06:45     
00:06:45     
00:06:45     (node:8979) internal/test/binding: These APIs are for internal testing only. Do not use them.
00:06:45     assert.js:362
00:06:45         throw err;
00:06:45         ^
00:06:45     
00:06:45     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:06:45     
00:06:45       assert(/Received Record/.test(stderr))
00:06:45     
00:06:45         at ChildProcess.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/parallel/test-tls-enable-trace-cli.js:39:3)
00:06:45         at ChildProcess.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/debian9-64/test/common/index.js:373:15)
00:06:45         at ChildProcess.emit (events.js:196:13)
00:06:45         at maybeClose (internal/child_process.js:1011:16)
00:06:45         at Process.ChildProcess._handle.onexit (internal/child_process.js:268:5)

[Trott]

This happens on Linux frequently, but I can't seem to replicate it on macOS.

[Trott]

/ping @cjihrig (because I'm pretty sure they've looked at this and might have data/info to add?)

[cjihrig]

Not much to add. I also can't replicate it on macOS - I've run it tens of thousands of times at this point 😄

[sam-github]

I'm running it in a loop on my linux laptop to see if I can repro.

[sam-github]

I got a failure within a couple minutes of continuous running, I'll try to fix this, but might not have time until Monday.

[addaleax]

It’s a bit easier to reproduce when running under valgrind (which kinda points to a timing race condition), but that might interfere with debugging. (edit: not the child process, only the test itself)

[addaleax]

Actually, this makes the bug show up pretty reliably for me:

diff --git a/test/parallel/test-tls-enable-trace-cli.js b/test/parallel/test-tls-enable-trace-cli.js
index 5b7189af702d..ace9e6710ba9 100644
--- a/test/parallel/test-tls-enable-trace-cli.js
+++ b/test/parallel/test-tls-enable-trace-cli.js
@@ -40,6 +40,7 @@ child.on('exit', common.mustCall((code) => {
 }));
 
 function test() {
+  process.stderr.write('a'.repeat(1024*1024) + '\n')
   const {
     connect, keys
   } = require(fixtures.path('tls-connect'));

I think the reason might be that stderr refers to a fd that Node has made non-blocking, and which makes OpenSSL’s fwrite() calls fail if the output pipe is already full.

[addaleax]

Yeah, I think we can’t use BIO_new_fp(). (The call also currently leaks memory because we don’t destroy the BIO instance, but that seems like a secondary issue.)

[sam-github]

Thanks for diagnosing this.

I'm OK with messages getting dropped if the pipe is overrun, because in my mind, this kind of logging is "best effort", similar to process._rawDebug's handling of failed fprintfs to stderr, and to Debug().

I think I can fix the leak by storing the bio in the context, and cleaning up in the destructor, and change the test to assert on something that will be seen in the first records logged, so that overflow won't fail the test.

@cjihrig @addaleax Would that be OK, or do you have another suggestion?

[addaleax]

@sam-github I think that is okay, yes.

That being said, I think somebody already requested the ability to print the output to a non-stderr location, so maybe making this more flexible by providing a custom BIO instance would be a good idea anyway?

[cjihrig]

Would that be OK, or do you have another suggestion?

It's not ideal, but I think it's better than not having this functionality. Ideally, this feature is used to diagnose a bad connection, and not turned on in production to log the details of thousands of connections.

[sam-github]

Hopelessly verbose in production. Mostly, I expect it to be used just to debug handshake problems, to answer the question of why node can't agree with its peer on a shared cipher suite.

I didn't see the request for non-stderr location, where was it? If requested location is a specific file, then still wouldn't need a custom BIO, I'd just use a file BIO. Also, a custom BIO would still have the problem of what do when write fails with EAGAIN, what would you suggest? Would you want it to use uv_write, buffering all the written data in memory until it drains, with no backpressure? I'm not sure that's better than dropping.

I have a longer-term idea of making enableTrace take an optional js function as an arg instead of just boolean, so that the message can be delivered to js code and it can do whatever it wants with it, but I think the current impl, while being a bit rigid, satisfies the common use cases.

[addaleax]

@sam-github Not saying I have it all figured out :)

I didn't see the request for non-stderr location, where was it?

I can’t find it rn – it might be mixing it up with something else that unconditionally printed to stderr?

I have a longer-term idea of making enableTrace take an optional js function as an arg instead of just boolean, so that the message can be delivered to js code and it can do whatever it wants with it, but I think the current impl, while being a bit rigid, satisfies the common use cases.

I think this would be best. And if we can use that to replace the current solution by using e.g. process.stderr.write(), I think that’s good, even without backpressure handling.