_stream_wrap: prevent use after free in TLS by indutny · Pull Request #1910 · nodejs/node

indutny · 2015-06-06T22:39:23Z

Queued write requests should be invoked on handle close, otherwise the
"consumer" might be already destroyed when the write callbacks of the
"consumed" handle will be invoked.

Fix: #1696

cc @EricTheOne

indutny · 2015-06-06T22:40:41Z

CI: https://jenkins-iojs.nodesource.com/job/iojs+any-pr+multi/776/

indutny · 2015-06-06T22:43:42Z

cc @nodejs/crypto

indutny · 2015-06-09T15:25:34Z

@bnoordhuis : let's review it anyway, even without @EricTheOne's feedback the fix that it does is still relevant

indutny · 2015-06-09T15:25:38Z

cc @EricTheOne

thefourtheye · 2015-06-10T05:56:53Z

Totally a noob question. Why are we not implementing this with an array instead of this complex enqueue and dequeue logic?

Is queue supposed to be accessed directly from outside of the class?
Should it be prefixed or not?

@thefourtheye because I'd like to avoid lookup cost when removing elements from it
@ChALkeR Should be prefixed, thanks.

@indutny I am trying to understand this better. Theoretically, there will be no lookup in a queue, the first-in will be dequeued, right? If we are going to arbitrarily remove, then why not a Map?

@thefourtheye there is no promise of FIFO here, and I like linked lists pretty much :)

@ChALkeR fixed

indutny · 2015-06-11T16:33:05Z

cc @trevnorris @shigeki @bnoordhuis @chrisdickinson maybe? Let's land this thing!

EricTheOne · 2015-06-11T17:16:01Z

@indutny this really seems to fix the original issue - no more segfaults and no more runaway memory allocations, thank you very much!

I've been running my server for a while, and found a few errors which I haven't seen before:

TypeError: Cannot read property 'start' of null
at TLSSocket._start (_tls_wrap.js:550:15)
at TLSSocket.<anonymous> (_tls_wrap.js:542:12)
at TLSSocket.g (events.js:260:16)
at emitNone (events.js:72:20)
at TLSSocket.emit (events.js:166:7)
at Socket.<anonymous> (_tls_wrap.js:432:12)
at Socket.g (events.js:260:16)
at emitNone (events.js:67:13)
at Socket.emit (events.js:166:7)
at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1029:10)
TypeError: Cannot read property 'start' of null
at TLSSocket._start (_tls_wrap.js:550:15)
at TLSSocket.<anonymous> (_tls_wrap.js:542:12)
at TLSSocket.g (events.js:260:16)
at emitNone (events.js:72:20)

TypeError: immediate._onImmediate is not a function
at processImmediate (timers.js:371:17)
at doNTCallback0 (node.js:408:9)
at process._tickCallback (node.js:337:13)
at Socket.<anonymous> (_stream_wrap.js:41:20)
at emitOne (events.js:77:13)
at Socket.emit (events.js:169:7)
at readableAddChunk (_stream_readable.js:145:16)
at Socket.Readable.push (_stream_readable.js:109:10)
at TCP.onread (net.js:519:20)
TypeError: immediate._onImmediate is not a function
at processImmediate (timers.js:371:17)
at doNTCallback0 (node.js:408:9)
at process._tickCallback (node.js:337:13)

Error: read EINVAL
at exports._errnoException (util.js:838:11)
at StreamWrap.Socket._read (net.js:391:21)
at StreamWrap.Readable.read (_stream_readable.js:324:10)
at StreamWrap.Socket.read (net.js:280:43)
at StreamWrap.Socket (net.js:166:12)
at new StreamWrap (_stream_wrap.js:51:10)
at new TLSSocket (_tls_wrap.js:233:12)
at Object.exports.connect (_tls_wrap.js:913:16)

Maybe it's in my code, but I don't see it in the stack traces. The patch was applied over master (0f68377)

thefourtheye · 2015-06-11T17:37:10Z

Can we const these, as we don't reassign anything to them?

trevnorris · 2015-06-11T18:18:33Z

Patch looks good. I'd have to give it a closer look, but don't let that hold up merging it if more devs sign off before then.

indutny · 2015-06-16T16:49:18Z

Fixed the first problem, please take a look @EricTheOne

EricTheOne · 2015-06-17T20:27:39Z

@indutny thanks, the original onImmediate issue seemed to be due to my code (passed a function() instead of function in to setImmediate).
I'm now testing this pull request over v2.3.0, and have found an issue:

TypeError: Cannot read property 'finishShutdown' of null
at Immediate._onImmediate (_stream_wrap.js:86:19)
at processImmediate [as _immediateCallback] (timers.js:371:17)

Seems to be due to _handle being null in _stream_wrap.js:

StreamWrap.prototype.shutdown = function shutdown(req) {
const self = this;
this.stream.end(function() {
// Ensure that write was dispatched
setImmediate(function() {
self._handle.finishShutdown(req, 0);
});
});
return 0;
};

EricTheOne · 2015-06-18T08:43:21Z

@indutny thanks for a4c5489 and 4cbf799, I ran the server with them but "TypeError: Cannot read property 'finishShutdown' of null" still happens.

EricTheOne · 2015-06-18T11:00:33Z

@indutny two more issues found, in addition to finishShutdown error:

../deps/uv/src/unix/stream.c:1489: uv_read_start: Assertion `((stream)->io_watcher.fd) >= 0' failed.

Error: read EINVAL
at exports._errnoException (util.js:839:11)
at StreamWrap.Socket._read (net.js:392:21)
at StreamWrap.Readable.read (_stream_readable.js:325:10)
at StreamWrap.Socket.read (net.js:281:43)
at StreamWrap.Socket (net.js:167:12)
at new StreamWrap (_stream_wrap.js:52:10)
at new TLSSocket (_tls_wrap.js:234:12)
at Object.exports.connect (_tls_wrap.js:938:16)
...

By far the most frequent is the finishShutdown error, second to it is EINVAL, and last is the assertion.

EricTheOne · 2015-06-22T18:46:35Z

@indutny is there any more info I can extract to help with the above three issues?

indutny · 2015-06-28T22:00:23Z

Fixed finishShutdown error, looking at the rest.

indutny · 2015-06-29T01:47:59Z

@EricTheOne hopefully fixed the last ones two, thank you for reporting them! Please give it a try ;)

EricTheOne · 2015-06-29T07:26:41Z

@indutny this is excellent news! I applied the pull request over v2.3.1 and ran the server twice. The first thing to notice is that the server behaves much better:

Memory and CPU are far more stable
finishShutdown error is gone

We're very close to resolving this, however two issues still appear:

read EINVAL and write EINVAL
../deps/uv/src/unix/stream.c:1489: uv_read_start: Assertion `((stream)->io_watcher.fd) >= 0' failed.

They happen at roughly the same time (less than 20 seconds apart) and then the server crashes. I use multiple processes so the errors may come from different child processes.

I may have a clue - visually inspecting the logs, it seems that the two errors and a memory leak appear on reconnects. Especially I notice a lot of reconnects due to timeouts. I generally dispose of the sockets and create new ones. There is no kernel socket leak.

indutny · 2015-06-29T18:42:40Z

@EricTheOne may I ask you to provide a fresh stack trace for EINVAL? (Maybe both of read/write?)

indutny · 2015-06-29T23:36:12Z

@EricTheOne pushed one more fix, hope it helps

EricTheOne · 2015-06-30T10:12:51Z

@indutny with some more testing I found another issue (causing a crash). Not related to the latest commit (cb4a005):

../src/node_crypto.cc:2283: node::crypto::CheckResult node::crypto::CheckWhitelistedServerCert(X509_STORE_CTX*): Assertion `(root_cert) != (nullptr)' failed.

shigeki · 2015-06-30T10:21:24Z

@EricTheOne Could you try the latest HEAD of master? I bleave it was fixed in #2064.

EricTheOne · 2015-06-30T10:57:19Z

@shigeki thanks, checking now, so far seems stable

EricTheOne · 2015-06-30T14:16:27Z

@shigeki @indutny #2064 indeed fixes the assertion, thanks.

@indutny I have reduced the rate of reconnects on the server, and neither of the two errors happen even without cb4a005. It seems like cause was either a race condition or incorrect handling of edge cases.
I've since run the server with cb4a005 too (the entire pull request was applied over 05a73c0 (master)), and it looks fine, no new issues.

From my point of view this work solves the original issues and does not introduce new ones, hence I'd like to see it merged.

indutny · 2015-06-30T18:16:08Z

cc @trevnorris please do one more pass over it. @shigeki may I ask you to take a look too?

Queued write requests should be invoked on handle close, otherwise the "consumer" might be already destroyed when the write callbacks of the "consumed" handle will be invoked. Fix: nodejs#1696

indutny · 2015-06-30T18:17:54Z

CI: https://jenkins-iojs.nodesource.com/job/iojs+any-pr+multi/95/

trevnorris · 2015-06-30T19:16:34Z

nit: throw in a comment on why the setImmediate() is necessary. future proofing for new devs. :)

Actually, let's drop it out, and revert it back only in case of any troubles. I no longer think that it might be reasonable. (@EricTheOne: I hope you don't mind)

@indutny I don't understand the code enough to comment on the code level, but I'll retest the final version and let you know if anything new comes up.
btw just to further my understanding, why would setImmediate be resolving possible troubles there?

trevnorris · 2015-06-30T19:24:07Z

Left comments about cosmetic stuff, but LGTM.

Queued write requests should be invoked on handle close, otherwise the "consumer" might be already destroyed when the write callbacks of the "consumed" handle will be invoked. Same applies to the shutdown requests. Make sure to "move" away socket from server to not break the `connections` counter in `net.js`. Otherwise it might not call `close` callback, or call it too early. Fix: #1696 PR-URL: #1910 Reviewed-By: Trevor Norris <trev.norris@gmail.com>

indutny · 2015-07-01T03:10:15Z

Landed in 9180140, thank you! (Decided to squash everything into one commit, because I forgot what this hotfixes belonged too)

EricTheOne · 2015-07-01T08:00:25Z

@indutny thanks, I'll retest with master as soon as possible.

Queued write requests should be invoked on handle close, otherwise the "consumer" might be already destroyed when the write callbacks of the "consumed" handle will be invoked. Same applies to the shutdown requests. Make sure to "move" away socket from server to not break the `connections` counter in `net.js`. Otherwise it might not call `close` callback, or call it too early. Fix: nodejs#1696 PR-URL: nodejs#1910 Reviewed-By: Trevor Norris <trev.norris@gmail.com>

This was referenced Jun 6, 2015
segfault in TLS #1696
Closed
Segfault node v0.11.14 related to TLS nodejs/node-v0.x-archive#8780
Closed

brendanashworth added the tls Issues and PRs related to the tls subsystem. label Jun 6, 2015

thefourtheye reviewed Jun 10, 2015
View reviewed changes

thefourtheye reviewed Jun 11, 2015
View reviewed changes

rvagg force-pushed the master branch from 9d21135 to 628a3abCompare June 25, 2015 09:18

indutny added 12 commits June 30, 2015 11:17

_stream_wrap: prevent use after free in TLS
c2aea93
Queued write requests should be invoked on handle close, otherwise the "consumer" might be already destroyed when the write callbacks of the "consumed" handle will be invoked. Fix: nodejs#1696

_stream_wrap: internalize queue
8d46c7b

fix
b349032

fix
b27ff94

fix assertion when destroying parent socket
94c12fe

tls: migrate server, fix StreamWrap close
6cdda31

tls: comment about moving server
8375f78

improvementswq
29b3713

fix
95bc05a

stream_wrap: fix finishShutdown error
aff1b5f

stream_wrap: fix initialization order
b6444ee

...
3d3709b

indutny force-pushed the fix/tls-crashes branch from cb4a005 to 3d3709bCompare June 30, 2015 18:17

trevnorris reviewed Jun 30, 2015
View reviewed changes

indutny closed this Jul 1, 2015

indutny deleted the fix/tls-crashes branch July 1, 2015 03:10

rvagg mentioned this pull request Jul 2, 2015
Release proposal: v2.3.2 #2083
Closed

Uh oh!

Uh oh!

Conversation

indutny commented Jun 6, 2015

Uh oh!

indutny commented Jun 6, 2015

Uh oh!

indutny commented Jun 6, 2015

Uh oh!

indutny commented Jun 9, 2015

Uh oh!

indutny commented Jun 9, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

indutny commented Jun 11, 2015

Uh oh!

EricTheOne commented Jun 11, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

trevnorris commented Jun 11, 2015

Uh oh!

indutny commented Jun 16, 2015

Uh oh!

EricTheOne commented Jun 17, 2015

Uh oh!

EricTheOne commented Jun 18, 2015

Uh oh!

EricTheOne commented Jun 18, 2015

Uh oh!

EricTheOne commented Jun 22, 2015

Uh oh!

indutny commented Jun 28, 2015

Uh oh!

indutny commented Jun 29, 2015

Uh oh!

EricTheOne commented Jun 29, 2015

Uh oh!

indutny commented Jun 29, 2015

Uh oh!

indutny commented Jun 29, 2015

Uh oh!

EricTheOne commented Jun 30, 2015

Uh oh!

shigeki commented Jun 30, 2015

Uh oh!

EricTheOne commented Jun 30, 2015

Uh oh!

EricTheOne commented Jun 30, 2015

Uh oh!

indutny commented Jun 30, 2015

Uh oh!

indutny commented Jun 30, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

trevnorris commented Jun 30, 2015

Uh oh!

indutny commented Jul 1, 2015

Uh oh!

EricTheOne commented Jul 1, 2015