HTTP: Cannot read property 'Symbol(asyncId)' of null

[tutman96]

• Version: 8.0.0 - latest
• Platform: Darwin 16.6.0 Darwin Kernel Version 16.6.0: Fri Apr 14 16:21:16 PDT 2017; root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64
• Subsystem: http

It appears like the addition of async_hooks API into the http module (commit 4a7233c) causes an edge case to occur with 'write after end'. Here is a stack trace:

TypeError: Cannot read property 'Symbol(asyncId)' of null
    at write_ (_http_outgoing.js:636:24)
    at ServerResponse.write (_http_outgoing.js:630:10)
    at Immediate.setImmediate [as _onImmediate] (/test.js:10:7)
    at runCallback (timers.js:800:20)
    at tryOnImmediate (timers.js:762:5)
    at processImmediate [as _immediateCallback] (timers.js:733:5)

This is an unhandled exception, thrown all the way up to OutgoingMessage.prototype.write, causing crashes when used with streams in some cases. It appears like msg.socket[async_id_symbol] is causing the error due to msg.socket being null. I have slimmed down the code into as bare as I could. Here is my code:

var http = require('http');

// This code crashes the process
http.createServer((req, res) => {
    res.on("error", (err) => console.error("res had error:", err));
    
    res.write('hello');
    res.end();
    setImmediate(() => {
        res.write('world')
    })
}).listen(9000);

// This code works as expected
http.createServer((req, res) => {
    res.on("error", (err) => console.error("res had error:", err));
    
    res.write('hello');
    res.end();
    res.write('world')
}).listen(9001);

The second block works as intended (emits the error event). It appears like this bug occurs in all versions after v8.0.0.

[mscdex]

/cc @nodejs/async_hooks

[AndreasMadsen]

Thanks for the issue report. This appears to be already have been fixed (at least when I try). Can you try the nightly build and confirm?

[tutman96]

Sure, just tried it. Here is the log output (called http://localhost:9001 and then http://localhost:9000):

res had error: Error: write after end
    at write_ (_http_outgoing.js:644:15)
    at ServerResponse.write (_http_outgoing.js:639:10)
    at Server.http.createServer (/test.js:18:6)
    at emitTwo (events.js:125:13)
    at Server.emit (events.js:213:7)
    at parserOnIncoming (_http_server.js:603:12)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:116:23)
_http_outgoing.js:645
    nextTick(msg.socket[async_id_symbol],
                        ^

TypeError: Cannot read property 'Symbol(asyncId)' of null
    at write_ (_http_outgoing.js:645:25)
    at ServerResponse.write (_http_outgoing.js:639:10)
    at Immediate.setImmediate [as _onImmediate] (/test.js:9:7)
    at runCallback (timers.js:781:20)
    at tryOnImmediate (timers.js:743:5)
    at processImmediate [as _immediateCallback] (timers.js:714:5)

(node -v = v9.0.0-nightly20170718f406a7ebae)

[AndreasMadsen]

Ah, okay. I can reproduce this, thanks :)

[AndreasMadsen]

@refack I'm not going to have time to debug/fix this, could you look at it.

I think msg.socket === null ? null : msg.socket[async_id_symbol] is a resonable solution. That being said, having msg.socket[async_id_symbol] after the trigger is destroyed is kinda odd to me, so there might be more to it.

[refack]

@refack I'm not going to have time to debug/fix this, could you look at it.

Will do

[mcollina]

@refack do you have a PR for this?

[mcollina]

I've included a fix for this in #14387.

[refack]

@refack do you have a PR for this?

I was still fighting with reproducing, so 👍 on #14387