node_http2.cc fatal error

[armoreal]

• Version: v12.16.2
• Platform: Linux JS_EU 4.15.0-96-generic #97-Ubuntu SMP Wed Apr 1 03:25:46 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem:

What steps will reproduce the bug?

I use simple http2 server for my site. It worked fine for about 1 week and today I got fatal exeption. Seems problem in Http2Session module.

const https = require('http2');
const server = https.createSecureServer(secureContextOptions,
    async function (req, res) {
})
server.on('session', (session, socket) => {
    session.on('remoteSettings', (settings) => {
            console.log(settings)
});
});

How often does it reproduce? Is there a required condition?

What is the expected behavior?

What do you see instead?

node[24676]: ../src/node_http2.cc:1545:void node::http2::Http2Session::MaybeScheduleWrite(): Assertion `(flags_ & SESSION_STATE_WRITE_SCHEDULED) == (0)' failed.
 1: 0xa02f90 node::Abort() [node]
 2: 0xa0300e  [node]
 3: 0xa34802 node::http2::Http2Session::MaybeScheduleWrite() [node]
 4: 0xa3cf08 node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [node]
 5: 0xb35eeb node::TLSWrap::ClearOut() [node]
 6: 0xb38618 node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [node]
 7: 0xac5726 node::LibuvStreamWrap::OnUvRead(long, uv_buf_t const*) [node]
 8: 0x1332c19  [node]
 9: 0x1333240  [node]
10: 0x1339398  [node]
11: 0x13273fb uv_run [node]
12: 0xa458f3 node::NodeMainInstance::Run() [node]
13: 0x9d4e18 node::Start(int, char**) [node]
14: 0x7f50c32b8b97 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
15: 0x96ec55  [node]
Aborted (core dumped)

Additional information

[jasnell]

I've actually been investigating this one and I think I'm close to a fix on it.

[rahbari]

I got this in node 14.12, Centos 7

/home/App[26840]: ../src/node_http2.cc:1471:void node::http2::Http2Session::MaybeScheduleWrite(): Assertion `!is_write_scheduled()' failed.
1: 0xa0a660 node::Abort() [/home/App]
2: 0xa0a6de  [/home/App]
3: 0xa2e672  [/home/App]
4: 0xa38945 node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [/home/App]
5: 0xb66a22 node::TLSWrap::ClearOut() [/home/App]
6: 0xb680a0 node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [/home/App]
7: 0xaebadc  [/home/App]
8: 0x1414413  [/home/App]
9: 0x1414978  [/home/App]
10: 0x141b215  [/home/App]
11: 0x14088ea uv_run [/home/App]
12: 0xa4cb7d node::NodeMainInstance::Run() [/home/App]
13: 0x9d6da1 node::Start(int, char**) [/home/App]
14: 0x7f1627036555 __libc_start_main [/lib64/libc.so.6]
15: 0x971b5c  [/home/App]

[rahbari]

We used node 12.4 for so long because of https://github.com/nodejs/node/pull/33875, Now we upgraded to 14.12 and after two days, this exception has happened more than 4 times and caused so many problems, for example all pending DB updates gone. I wonder why an error in one of the http2 streams should kill the whole process and can't even be catched in uncaughtException.

@jasnell Anyway as it seems there is no interest in resolving this issue, I just want to know if it's ok to replace this assertion with a normal if check in the source code so node continues to work?

[SimonWoolf]

I've actually been investigating this one and I think I'm close to a fix on it.

@jasnell As that was April not sure if you're still working on this. If not, would you mind sharing your conclusions/analysis and/or your half-finished fix attempt, so others could try to progress this if you no longer have the time? Many thanks 🙂

[davedoesdev]

Seeing this too but only on Node 12:

grunt[1151]: ../src/node_http2.cc:1549:void node::http2::Http2Session::MaybeScheduleWrite(): Assertion `(flags_ & SESSION_STATE_WRITE_SCHEDULED) == (0)' failed.
 1: 0xa17c40 node::Abort() [grunt]
 2: 0xa17cbe  [grunt]
 3: 0xa49c32 node::http2::Http2Session::MaybeScheduleWrite() [grunt]
 4: 0xa52138 node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [grunt]
 5: 0xb65bd1 node::TLSWrap::ClearOut() [grunt]
 6: 0xb6723b node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [grunt]
 7: 0xaf1681  [grunt]
 8: 0x137b239  [grunt]
 9: 0x137b860  [grunt]
10: 0x1382165  [grunt]
11: 0x136f8ef uv_run [grunt]
12: 0xa5aac6 node::NodeMainInstance::Run() [grunt]
13: 0x9e85cc node::Start(int, char**) [grunt]
14: 0x7ffaac5f20b3 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
15: 0x9819b5  [grunt]

[davedoesdev]

Fix and test here: https://github.com/nodejs/node/compare/v12.19.1...davedoesdev:issue-33156-http2-close-while-writing?expand=1

I can't seem to PR against 12.19.1

It's fixed on Node 15 due to

https://github.com/nodejs/node/commit/91ca22106c8d20dd4b09741c59c2f24f3a287277?branch=91ca22106c8d20dd4b09741c59c2f24f3a287277&diff=unified#diff-33f026e43570112875cf4c8eab6743496f3aa014329611128e348ec23d6f771cR84

(However, making that change doesn't make Node 12 pass, doesn't seem quite to follow the same path/timings)

[davedoesdev]

Wouldn't harm to make the equivalent fix on Node 15 and then backport. There might be a case where it triggers but I couldn't get a test that did so.

[davedoesdev]

@Trott Thanks for merging the fix to master. Do I need to do anything to get the fix to Node 12 merged?
https://github.com/nodejs/node/compare/v12.19.1...davedoesdev:issue-33156-http2-close-while-writing?expand=1

[Trott]

@Trott Thanks for merging the fix to master. Do I need to do anything to get the fix to Node 12 merged?
https://github.com/nodejs/node/compare/v12.19.1...davedoesdev:issue-33156-http2-close-while-writing?expand=1

Unfortunately, 83166fb doesn't currently cherry-pick cleanly over to the v12.x-staging branch. Unless something else lands first to make it cherry-pick cleanly there, it will need a backport PR. If you don't mind doing the work to put that together, the instructions are at https://github.com/nodejs/node/blob/1ed72f67f5ea82b36b8589e447619e98c004fa12/doc/guides/backporting-to-release-lines.md.

[davedoesdev]

Thanks, I'll look at doing it soon.