Created
June 8, 2021 14:59
-
-
Save mdouglass/a4c521167daf8e5e0246bb862b419f36 to your computer and use it in GitHub Desktop.
https://github.com/nodejs/node/issues/38964 repro with tracing on
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| $ export GRPC_TRACE=all | |
| $ export GRPC_VERBOSITY=DEBUG | |
| $ npm run client | |
| > server@1.0.0 client | |
| > node client.js | |
| 2021-06-08T14:57:10.853Z | resolving_load_balancer | dns:127.0.0.1:20000 IDLE -> IDLE | |
| 2021-06-08T14:57:10.854Z | connectivity_state | dns:127.0.0.1:20000 IDLE -> IDLE | |
| 2021-06-08T14:57:10.854Z | dns_resolver | Resolver constructed for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:57:10.855Z | channel | dns:127.0.0.1:20000 createCall [0] method="/EchoService/DuplexEcho", deadline=Infinity | |
| 2021-06-08T14:57:10.856Z | call_stream | [0] Sending metadata | |
| 2021-06-08T14:57:10.856Z | dns_resolver | Resolution update requested for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:57:10.856Z | dns_resolver | Returning IP address for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:57:10.856Z | resolving_load_balancer | dns:127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:57:10.856Z | connectivity_state | dns:127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:57:10.856Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.856Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.856Z | channel | callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0 | |
| 2021-06-08T14:57:10.857Z | call_stream | [0] write() called with message of length 21 | |
| 2021-06-08T14:57:10.857Z | call_stream | [0] deferring writing data chunk of length 26 | |
| 2021-06-08T14:57:10.858Z | pick_first | Connect to address list 127.0.0.1:20000 | |
| 2021-06-08T14:57:10.858Z | subchannel_refcount | 127.0.0.1:20000 refcount 0 -> 1 | |
| 2021-06-08T14:57:10.858Z | subchannel_refcount | 127.0.0.1:20000 refcount 1 -> 2 | |
| 2021-06-08T14:57:10.858Z | pick_first | Start connecting to subchannel with address 127.0.0.1:20000 | |
| 2021-06-08T14:57:10.858Z | pick_first | IDLE -> CONNECTING | |
| 2021-06-08T14:57:10.858Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.858Z | channel | callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0 | |
| 2021-06-08T14:57:10.858Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.858Z | subchannel | 127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:57:10.859Z | pick_first | CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.859Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.859Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:57:10.859Z | channel | Pick result: QUEUE subchannel: undefined status: undefined undefined | |
| 2021-06-08T14:57:10.859Z | channel | callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1 | |
| 2021-06-08T14:57:10.861Z | subchannel | 127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:57:10.861Z | pick_first | Pick subchannel with address 127.0.0.1:20000 | |
| 2021-06-08T14:57:10.861Z | pick_first | CONNECTING -> READY | |
| 2021-06-08T14:57:10.861Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:57:10.861Z | channel | callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0 | |
| 2021-06-08T14:57:10.861Z | channel | Pick result: COMPLETE subchannel: 127.0.0.1:20000 status: undefined undefined | |
| 2021-06-08T14:57:10.861Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:57:10.861Z | subchannel_refcount | 127.0.0.1:20000 refcount 2 -> 3 | |
| 2021-06-08T14:57:10.861Z | subchannel_refcount | 127.0.0.1:20000 refcount 3 -> 2 | |
| 2021-06-08T14:57:10.862Z | call_stream | Starting stream on subchannel 127.0.0.1:20000 with headers | |
| grpc-accept-encoding: identity,deflate,gzip | |
| accept-encoding: identity | |
| :authority: 127.0.0.1:20000 | |
| user-agent: grpc-node-js/1.3.2 | |
| content-type: application/grpc | |
| :method: POST | |
| :path: /EchoService/DuplexEcho | |
| te: trailers | |
| 2021-06-08T14:57:10.862Z | call_stream | [0] attachHttp2Stream from subchannel 127.0.0.1:20000 | |
| 2021-06-08T14:57:10.863Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 0 -> 1 | |
| 2021-06-08T14:57:10.863Z | call_stream | [0] sending data chunk of length 26 (deferred) | |
| 2021-06-08T14:57:10.864Z | call_stream | [0] Received server headers: | |
| :status: 200 | |
| grpc-accept-encoding: identity | |
| grpc-encoding: identity | |
| content-type: application/grpc+proto | |
| date: Tue, 08 Jun 2021 14:57:10 GMT | |
| 2021-06-08T14:57:10.865Z | call_stream | [0] receive HTTP/2 data frame of length 26 | |
| 2021-06-08T14:57:10.865Z | call_stream | [0] parsed message of length 26 | |
| 2021-06-08T14:57:10.865Z | call_stream | [0] filterReceivedMessage of length 26 | |
| 2021-06-08T14:57:10.865Z | call_stream | [0] pushing to reader message of length 21 | |
| duplexEcho response: { message: 'Hello duplex world!' } | |
| 2021-06-08T14:57:10.867Z | channel | dns:127.0.0.1:20000 createCall [1] method="/EchoService/UnaryEcho", deadline=Infinity | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] Sending metadata | |
| 2021-06-08T14:57:10.867Z | channel | Pick result: COMPLETE subchannel: 127.0.0.1:20000 status: undefined undefined | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] write() called with message of length 20 | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] end() called | |
| 2021-06-08T14:57:10.867Z | call_stream | Starting stream on subchannel 127.0.0.1:20000 with headers | |
| grpc-accept-encoding: identity,deflate,gzip | |
| accept-encoding: identity | |
| :authority: 127.0.0.1:20000 | |
| user-agent: grpc-node-js/1.3.2 | |
| content-type: application/grpc | |
| :method: POST | |
| :path: /EchoService/UnaryEcho | |
| te: trailers | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] attachHttp2Stream from subchannel 127.0.0.1:20000 | |
| 2021-06-08T14:57:10.867Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 1 -> 2 | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] sending data chunk of length 25 | |
| 2021-06-08T14:57:10.867Z | call_stream | [1] calling end() on HTTP/2 stream | |
| 2021-06-08T14:57:10.868Z | call_stream | [1] Received server headers: | |
| :status: 200 | |
| grpc-accept-encoding: identity | |
| grpc-encoding: identity | |
| content-type: application/grpc+proto | |
| date: Tue, 08 Jun 2021 14:57:10 GMT | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] receive HTTP/2 data frame of length 25 | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] parsed message of length 25 | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] filterReceivedMessage of length 25 | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] pushing to reader message of length 20 | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] Received server trailers: | |
| grpc-status: 0 | |
| grpc-message: OK | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] received status code 0 from server | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] received status details string "OK" from server | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] ended with status: code=0 details="OK" | |
| 2021-06-08T14:57:10.869Z | call_stream | [1] close http2 stream with code 0 | |
| 2021-06-08T14:57:10.869Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 2 -> 1 | |
| unaryEcho response: { message: 'Hello unary world!' } | |
| 2021-06-08T14:57:10.870Z | call_stream | [1] HTTP/2 stream closed with code 0 | |
| 2021-06-08T14:57:10.870Z | call_stream | [0] cancelWithStatus code: 1 details: "Cancelled on client" | |
| 2021-06-08T14:57:10.870Z | call_stream | [0] ended with status: code=1 details="Cancelled on client" | |
| 2021-06-08T14:57:10.870Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 1 -> 0 | |
| 2021-06-08T14:57:10.870Z | call_stream | [0] close http2 stream with code 8 | |
| duplexEcho error Error: 1 CANCELLED: Cancelled on client | |
| at Object.callErrorFromStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call.js:31:26) | |
| at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client.js:390:49) | |
| at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181) | |
| at /home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78 | |
| at processTicksAndRejections (node:internal/process/task_queues:78:11) | |
| duplexEcho status { | |
| code: 1, | |
| details: 'Cancelled on client', | |
| metadata: Metadata { internalRepr: Map(0) {}, options: {} } | |
| } | |
| free(): double free detected in tcache 2 | |
| $ npm run client | |
| > server@1.0.0 client | |
| > node client.js | |
| 2021-06-08T14:54:35.214Z | resolving_load_balancer | dns:127.0.0.1:20000 IDLE -> IDLE | |
| 2021-06-08T14:54:35.216Z | connectivity_state | dns:127.0.0.1:20000 IDLE -> IDLE | |
| 2021-06-08T14:54:35.216Z | dns_resolver | Resolver constructed for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:54:35.217Z | channel | dns:127.0.0.1:20000 createCall [0] method="/EchoService/DuplexEcho", deadline=Infinity | |
| 2021-06-08T14:54:35.217Z | call_stream | [0] Sending metadata | |
| 2021-06-08T14:54:35.217Z | dns_resolver | Resolution update requested for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:54:35.217Z | dns_resolver | Returning IP address for target dns:127.0.0.1:20000 | |
| 2021-06-08T14:54:35.217Z | resolving_load_balancer | dns:127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:54:35.217Z | connectivity_state | dns:127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:54:35.218Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.218Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.218Z | channel | callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0 | |
| 2021-06-08T14:54:35.218Z | call_stream | [0] write() called with message of length 21 | |
| 2021-06-08T14:54:35.218Z | call_stream | [0] deferring writing data chunk of length 26 | |
| 2021-06-08T14:54:35.219Z | pick_first | Connect to address list 127.0.0.1:20000 | |
| 2021-06-08T14:54:35.220Z | subchannel_refcount | 127.0.0.1:20000 refcount 0 -> 1 | |
| 2021-06-08T14:54:35.220Z | subchannel_refcount | 127.0.0.1:20000 refcount 1 -> 2 | |
| 2021-06-08T14:54:35.220Z | pick_first | Start connecting to subchannel with address 127.0.0.1:20000 | |
| 2021-06-08T14:54:35.220Z | pick_first | IDLE -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | channel | callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0 | |
| 2021-06-08T14:54:35.220Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | subchannel | 127.0.0.1:20000 IDLE -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | pick_first | CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.220Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> CONNECTING | |
| 2021-06-08T14:54:35.221Z | channel | Pick result: QUEUE subchannel: undefined status: undefined undefined | |
| 2021-06-08T14:54:35.221Z | channel | callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1 | |
| 2021-06-08T14:54:35.222Z | subchannel | 127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:54:35.222Z | pick_first | Pick subchannel with address 127.0.0.1:20000 | |
| 2021-06-08T14:54:35.222Z | pick_first | CONNECTING -> READY | |
| 2021-06-08T14:54:35.222Z | resolving_load_balancer | dns:127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:54:35.223Z | channel | callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0 | |
| 2021-06-08T14:54:35.223Z | channel | Pick result: COMPLETE subchannel: 127.0.0.1:20000 status: undefined undefined | |
| 2021-06-08T14:54:35.223Z | connectivity_state | dns:127.0.0.1:20000 CONNECTING -> READY | |
| 2021-06-08T14:54:35.223Z | subchannel_refcount | 127.0.0.1:20000 refcount 2 -> 3 | |
| 2021-06-08T14:54:35.223Z | subchannel_refcount | 127.0.0.1:20000 refcount 3 -> 2 | |
| 2021-06-08T14:54:35.224Z | call_stream | Starting stream on subchannel 127.0.0.1:20000 with headers | |
| grpc-accept-encoding: identity,deflate,gzip | |
| accept-encoding: identity | |
| :authority: 127.0.0.1:20000 | |
| user-agent: grpc-node-js/1.3.2 | |
| content-type: application/grpc | |
| :method: POST | |
| :path: /EchoService/DuplexEcho | |
| te: trailers | |
| 2021-06-08T14:54:35.224Z | call_stream | [0] attachHttp2Stream from subchannel 127.0.0.1:20000 | |
| 2021-06-08T14:54:35.224Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 0 -> 1 | |
| 2021-06-08T14:54:35.224Z | call_stream | [0] sending data chunk of length 26 (deferred) | |
| 2021-06-08T14:54:35.235Z | call_stream | [0] Received server headers: | |
| :status: 200 | |
| grpc-accept-encoding: identity | |
| grpc-encoding: identity | |
| content-type: application/grpc+proto | |
| date: Tue, 08 Jun 2021 14:54:35 GMT | |
| 2021-06-08T14:54:35.235Z | call_stream | [0] receive HTTP/2 data frame of length 26 | |
| 2021-06-08T14:54:35.235Z | call_stream | [0] parsed message of length 26 | |
| 2021-06-08T14:54:35.235Z | call_stream | [0] filterReceivedMessage of length 26 | |
| 2021-06-08T14:54:35.236Z | call_stream | [0] pushing to reader message of length 21 | |
| duplexEcho response: { message: 'Hello duplex world!' } | |
| 2021-06-08T14:54:35.237Z | channel | dns:127.0.0.1:20000 createCall [1] method="/EchoService/UnaryEcho", deadline=Infinity | |
| 2021-06-08T14:54:35.237Z | call_stream | [1] Sending metadata | |
| 2021-06-08T14:54:35.237Z | channel | Pick result: COMPLETE subchannel: 127.0.0.1:20000 status: undefined undefined | |
| 2021-06-08T14:54:35.237Z | call_stream | [1] write() called with message of length 20 | |
| 2021-06-08T14:54:35.238Z | call_stream | [1] end() called | |
| 2021-06-08T14:54:35.238Z | call_stream | Starting stream on subchannel 127.0.0.1:20000 with headers | |
| grpc-accept-encoding: identity,deflate,gzip | |
| accept-encoding: identity | |
| :authority: 127.0.0.1:20000 | |
| user-agent: grpc-node-js/1.3.2 | |
| content-type: application/grpc | |
| :method: POST | |
| :path: /EchoService/UnaryEcho | |
| te: trailers | |
| 2021-06-08T14:54:35.238Z | call_stream | [1] attachHttp2Stream from subchannel 127.0.0.1:20000 | |
| 2021-06-08T14:54:35.238Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 1 -> 2 | |
| 2021-06-08T14:54:35.238Z | call_stream | [1] sending data chunk of length 25 | |
| 2021-06-08T14:54:35.238Z | call_stream | [1] calling end() on HTTP/2 stream | |
| 2021-06-08T14:54:35.240Z | call_stream | [1] Received server headers: | |
| :status: 200 | |
| grpc-accept-encoding: identity | |
| grpc-encoding: identity | |
| content-type: application/grpc+proto | |
| date: Tue, 08 Jun 2021 14:54:35 GMT | |
| 2021-06-08T14:54:35.240Z | call_stream | [1] receive HTTP/2 data frame of length 25 | |
| 2021-06-08T14:54:35.240Z | call_stream | [1] parsed message of length 25 | |
| 2021-06-08T14:54:35.240Z | call_stream | [1] filterReceivedMessage of length 25 | |
| 2021-06-08T14:54:35.240Z | call_stream | [1] pushing to reader message of length 20 | |
| 2021-06-08T14:54:35.242Z | call_stream | [1] Received server trailers: | |
| grpc-status: 0 | |
| grpc-message: OK | |
| 2021-06-08T14:54:35.242Z | call_stream | [1] received status code 0 from server | |
| 2021-06-08T14:54:35.242Z | call_stream | [1] received status details string "OK" from server | |
| 2021-06-08T14:54:35.242Z | call_stream | [1] ended with status: code=0 details="OK" | |
| 2021-06-08T14:54:35.242Z | call_stream | [1] close http2 stream with code 0 | |
| 2021-06-08T14:54:35.242Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 2 -> 1 | |
| unaryEcho response: { message: 'Hello unary world!' } | |
| 2021-06-08T14:54:35.243Z | call_stream | [1] HTTP/2 stream closed with code 0 | |
| 2021-06-08T14:54:35.243Z | call_stream | [0] cancelWithStatus code: 1 details: "Cancelled on client" | |
| 2021-06-08T14:54:35.243Z | call_stream | [0] ended with status: code=1 details="Cancelled on client" | |
| 2021-06-08T14:54:35.243Z | subchannel_refcount | 127.0.0.1:20000 callRefcount 1 -> 0 | |
| 2021-06-08T14:54:35.243Z | call_stream | [0] close http2 stream with code 8 | |
| duplexEcho error Error: 1 CANCELLED: Cancelled on client | |
| at Object.callErrorFromStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call.js:31:26) | |
| at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client.js:390:49) | |
| at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181) | |
| at /home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78 | |
| at processTicksAndRejections (node:internal/process/task_queues:78:11) | |
| duplexEcho status { | |
| code: 1, | |
| details: 'Cancelled on client', | |
| metadata: Metadata { internalRepr: Map(0) {}, options: {} } | |
| } | |
| free(): double free detected in tcache 2 | |
| [1] 1000846 IOT instruction (core dumped) npm run client |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment