apm-agent-nodejs
apm-agent-nodejs copied to clipboard
elastic
spurious `http2.createSecureServer stream respond` test crash/error in GH Actions
A number of times in the past month I have seen the GitHub Actions tests of a PR fail in the http2.createSecureServer stream respond test case.
2021-11-02
https://github.com/elastic/apm-agent-nodejs/runs/4082457680?check_suite_focus=true "test-vers (8)" test matrix element
...
running (cwd: ./): node --require /home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/_promise_rejection.js test/instrumentation/modules/http2.test.js
TAP version 13
...
ok 138 should have expected body
# http2.createSecureServer stream respond
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:133
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
All the earlier ones had crash stacktraces, but not this one.
2021-10-27
https://github.com/elastic/apm-agent-nodejs/runs/4028404599?check_suite_focus=true "test-vers (8)"
# http2.createSecureServer stream respond
node[5627]: ../src/node_http2.cc:1694:void node::http2::Http2Session::ClearOutgoing(int): Assertion `(flags_ & SESSION_STATE_SENDING) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x91530a [node]
4: node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) [node]
5: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
6: node::TLSWrap::InvokeQueued(int, char const*) [node]
7: node::TLSWrap::EncOut() [node]
8: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
9: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
11: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
12: 0x9c5129 [node]
13: 0x9c6358 [node]
14: uv_run [node]
15: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
16: node::Start(int, char**) [node]
17: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
18: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:133
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
2021-10-26
https://github.com/elastic/apm-agent-nodejs/runs/4012831068?check_suite_focus=true "test-vers (8)"
# http2.createSecureServer stream respond
node[6012]: ../src/node_http2.cc:1625:static void node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*): Assertion `(session->flags_ & SESSION_STATE_WRITE_IN_PROGRESS) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x9160bd [node]
4: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
5: node::TLSWrap::InvokeQueued(int, char const*) [node]
6: node::TLSWrap::EncOut() [node]
7: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
8: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
9: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
11: 0x9c5129 [node]
12: 0x9c6358 [node]
13: uv_run [node]
14: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
15: node::Start(int, char**) [node]
16: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
17: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:132
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2021-10-26
https://github.com/elastic/apm-agent-nodejs/runs/4003793067?check_suite_focus=true "test-vers (8)"
# http2.createSecureServer stream respond
node[6014]: ../src/node_http2.cc:1625:static void node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*): Assertion `(session->flags_ & SESSION_STATE_WRITE_IN_PROGRESS) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x9160bd [node]
4: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
5: node::TLSWrap::InvokeQueued(int, char const*) [node]
6: node::TLSWrap::EncOut() [node]
7: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
8: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
9: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
11: 0x9c5129 [node]
12: 0x9c6358 [node]
13: uv_run [node]
14: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
15: node::Start(int, char**) [node]
16: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
17: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:132
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2021-11-09
https://github.com/elastic/apm-agent-nodejs/runs/4159716674?check_suite_focus=true "test-vers (8)"
# http2.createSecureServer stream respond
node[6717]: ../src/node_http2.cc:1694:void node::http2::Http2Session::ClearOutgoing(int): Assertion `(flags_ & SESSION_STATE_SENDING) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x91530a [node]
4: node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) [node]
5: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
6: node::TLSWrap::InvokeQueued(int, char const*) [node]
7: node::TLSWrap::EncOut() [node]
8: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
9: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
11: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
12: 0x9c5129 [node]
13: 0x9c6358 [node]
14: uv_run [node]
15: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
16: node::Start(int, char**) [node]
17: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
18: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:133
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2021-11-17
https://github.com/elastic/apm-agent-nodejs/runs/4246946944?check_suite_focus=true
# http2.createSecureServer stream respond
node[5969]: ../src/node_http2.cc:1694:void node::http2::Http2Session::ClearOutgoing(int): Assertion `(flags_ & SESSION_STATE_SENDING) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x91530a [node]
4: node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) [node]
5: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
6: node::TLSWrap::InvokeQueued(int, char const*) [node]
7: node::TLSWrap::EncOut() [node]
8: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
9: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
11: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
12: 0x9c5129 [node]
13: 0x9c6358 [node]
14: uv_run [node]
15: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
16: node::Start(int, char**) [node]
17: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
18: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:133
if (err) throw err
^
2021-11-29
https://github.com/elastic/apm-agent-nodejs/runs/4357867667?check_suite_focus=true
# http2.createSecureServer stream respond
node[5509]: ../src/node_http2.cc:1625:static void node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*): Assertion `(session->flags_ & SESSION_STATE_WRITE_IN_PROGRESS) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x9160bd [node]
4: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
5: node::TLSWrap::InvokeQueued(int, char const*) [node]
6: node::TLSWrap::EncOut() [node]
7: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
8: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
9: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
11: 0x9c5129 [node]
12: 0x9c6358 [node]
13: uv_run [node]
14: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
15: node::Start(int, char**) [node]
16: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
17: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:133
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:36:19)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
2022-05-06
https://github.com/elastic/apm-agent-nodejs/runs/6327744363?check_suite_focus=true
with test-vers (8)
...
# handling HTTP/1.1 request to http2.createSecureServer with allowHTTP1:true
# NODE_OPTIONS=
node[6023]: ../src/node_http2.cc:1694:void node::http2::Http2Session::ClearOutgoing(int): Assertion `(flags_ & SESSION_STATE_SENDING) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x91530a [node]
4: node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) [node]
5: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
6: node::TLSWrap::InvokeQueued(int, char const*) [node]
7: node::TLSWrap::EncOut() [node]
8: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
9: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
11: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
12: 0x9c5129 [node]
13: 0x9c6358 [node]
14: uv_run [node]
15: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
16: node::Start(int, char**) [node]
17: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
18: 0x89f601 [node]
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:212
if (err) throw err
^
Error: non-zero error code
at ChildProcess.<anonymous> (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:100:21)
at emitTwo (events.js:126:13)
at ChildProcess.emit (events.js:214:7)
at maybeClose (internal/child_process.js:915:16)
at Process.ChildProcess._handle.onexit (internal/child_process.js:209:5)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
This might always be with node v8... which means it'll never get fixed. We can close this as "won't fix" in the next major when we drop node v8 support.
2023-03-02
https://github.com/elastic/apm-agent-nodejs/actions/runs/4318257412/jobs/7536334284
with test-vers (8)
...
# handling HTTP/1.1 request to http2.createSecureServer with allowHTTP1:true
# NODE_OPTIONS=
node[5974]: ../src/node_http2.cc:1694:void node::http2::Http2Session::ClearOutgoing(int): Assertion `(flags_ & SESSION_STATE_SENDING) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x91530a [node]
4: node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) [node]
5: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
6: node::TLSWrap::InvokeQueued(int, char const*) [node]
7: node::TLSWrap::EncOut() [node]
8: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
9: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
11: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
12: 0x9c5129 [node]
13: 0x9c6358 [node]
14: uv_run [node]
15: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
16: node::Start(int, char**) [node]
17: 0x7f4d384a3d90 [/lib/x86_64-linux-gnu/libc.so.6]
18: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
19: 0x89f601 [node]
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2023-03-24
A similar failure (node v8, in the http2 tests), but with a different test step in that file:
https://github.com/elastic/apm-agent-nodejs/actions/runs/4509371700/jobs/7939061181
# http2.request secure
node[5869]: ../src/node_http2.cc:1625:static void node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*): Assertion `(session->flags_ & SESSION_STATE_WRITE_IN_PROGRESS) != (0)' failed.
1: node::Abort() [node]
2: 0x8cd87b [node]
3: 0x9160bd [node]
4: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
5: node::TLSWrap::InvokeQueued(int, char const*) [node]
6: node::TLSWrap::EncOut() [node]
7: node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) [node]
8: node::StreamBase::AfterWrite(node::WriteWrap*, int) [node]
9: node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) [node]
10: node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) [node]
11: 0x9c5129 [node]
12: 0x9c6358 [node]
13: uv_run [node]
14: node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [node]
15: node::Start(int, char**) [node]
16: 0x7f7552faad90 [/lib/x86_64-linux-gnu/libc.so.6]
17: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
18: 0x89f601 [node]
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2023-03-27
https://github.com/elastic/apm-agent-nodejs/actions/runs/4534924028/jobs/7989722549
...
ok 281 span.context.service.target
ok 282 should have expected body
# handling HTTP/1.1 request to http2.createSecureServer with allowHTTP1:true
# NODE_OPTIONS=
/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:218
if (err) throw err
^
Error: non-zero error code
at WriteStream.onClose (/home/runner/work/apm-agent-nodejs/apm-agent-nodejs/test/test.js:86:25)
at Object.onceWrapper (events.js:313:30)
at emitNone (events.js:106:13)
at WriteStream.emit (events.js:208:7)
at fs.close (fs.js:2095:12)
at FSReqWrap.oncomplete (fs.js:135:15)
npm ERR! Test failed. See above for more details.
Error: Process completed with exit code 1.
2023-03-29
On https://github.com/elastic/apm-agent-nodejs/actions/runs/4557559772/jobs/8039354215?pr=3225
# http2.request secure
ok 244 have current transaction
ok 245 should be strictly equal
ok 246 the http2 span should not spill into user code
ok 247 have current transaction
ok 248 should be strictly equal
ok 249 the http2 span should *not* be the currentSpan in user event handlers
ok 250 should be strictly equal
ok 251 should be strictly equal
ok 252 should be truthy
ok 253 should be truthy
ok 254 should be strictly equal
ok 255 should be strictly equal
ok 256 trans.result is "HTTP 2xx"
ok 257 trans.outcome is success
ok 258 should be truthy
ok 259 should be truthy
ok 260 transaction.context.request.socket.remote_address is as expected: ::ffff:127.0.0.1
ok 261 trans.context.request is as expected
ok 262 trans.context.response is as expected
ok 263 should be truthy
ok 264 should be truthy
ok 265 should be strictly equal
ok 266 should be strictly equal
ok 267 trans.result is "HTTP 2xx"
ok 268 trans.outcome is success
ok 269 should be truthy
ok 270 should be truthy
ok 271 transaction.context.request.socket.remote_address is as expected: ::ffff:127.0.0.1
ok 272 trans.context.request is as expected
ok 273 trans.context.response is as expected
ok 274 root transaction should have span
ok 275 should be strictly equal
ok 276 should be strictly equal
ok 277 should be strictly equal
ok 278 should be strictly equal
ok 279 span.context.http
ok 280 span.context.destination
ok 281 span.context.service.target
ok 282 should have expected body
# handling HTTP/1.1 request to http2.createSecureServer with allowHTTP1:true
# NODE_OPTIONS=
Error: Process completed with exit code 1.
This is getting annoying. I propose disabling http2 testing with node 8. Just not worth it. I'd be shocked if there are node 8 and http2 users and more shocked if our instrumentation of it was broken just for node 8 in subsequent changes.