Potential interop problem with grpc-node

[jtattermusch]

Got some errors when testing the running the cross-language test suite.

Affected test cases: client_streaming, custom_metadata, empty_unary, large_unary

https://source.cloud.google.com/results/invocations/89f6c1c8-4183-44c3-9dd9-5dba629d4d1e/targets/github%2Fgrpc%2Finterop_test/tests;group=tests;test=cloud_to_cloud:node:aspnetcore_server:client_streaming:tls;row=1

assert.js:607
    throw newErr;
    ^
AssertionError [ERR_ASSERTION]: ifError got unwanted exception: 2 UNKNOWN: Stream removed
    at /var/local/git/grpc-node/test/interop/interop_client.js:128:12
    at Object.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1234:9)
    at Object.exports.createStatusError (/var/local/git/grpc-node/packages/grpc-native-core/src/common.js:91:15)
    at Object.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1233:28)
    at InterceptingListener._callNext (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:618:8)
    at /var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:922:18

events.js:167
      throw er; // Unhandled 'error' event
      ^
Error: 2 UNKNOWN: Stream removed
    at Object.exports.createStatusError (/var/local/git/grpc-node/packages/grpc-native-core/src/common.js:91:15)
    at ClientDuplexStream._emitStatusIfDone (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:233:26)
    at ClientDuplexStream._receiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:211:8)
    at Object.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1306:15)
    at InterceptingListener._callNext (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:618:8)
    at /var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1123:18
Emitted 'error' event at:
    at ClientDuplexStream._emitStatusIfDone (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:234:12)
    at ClientDuplexStream._receiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:211:8)
    [... lines matching original stack trace ...]
    at /var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1123:18

[jtattermusch]

I enabled extra tracing and got this log from grpc-node (native)

I0218 10:14:11.223302131    9729 tcp_custom.cc:136]          READ 0x3b44180 (peer=ipv6:[::1]:50052): 17 03 03 00 25 f0 6a c5 3b 00 e3 a5 b7 07 84 75 7c e0 1f b2 ea 57 db 5a 9b 19 78 a0 cd e4 87 d9 0f 90 a7 64 b5 17 35 b8 dc bf '....%.j.;......u|....W.Z..x........d..5...'
I0218 10:14:11.223343092    9729 chttp2_transport.cc:829]    W:0x3a11000 CLIENT state IDLE -> WRITING [RST_STREAM]
I0218 10:14:11.223414791    9729 chttp2_transport.cc:2590]   ipv6:[::1]:50052: Complete BDP ping err={"created":"@1550484851.223335401","description":"Failed parsing HTTP/2","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2514,"referenced_errors":[{"created":"@1550484851.223323462","description":"invalid window update bytes: -2147418111","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/frame_window_update.cc","file_line":95}]}
I0218 10:14:11.223434384    9729 chttp2_transport.cc:829]    W:0x3a11000 CLIENT state WRITING -> WRITING [begin write in current thread]
I0218 10:14:11.223454109    9729 tcp_custom.cc:233]          WRITE 0x3a96080 (peer=ipv6:[::1]:50052): 17 03 03 00 2e ec 74 5f e7 bb 75 59 74 54 51 87 d7 69 24 9f a8 59 bf 63 2d 77 8e 7f a8 b4 ba ac eb ee 42 cb 57 0e b0 9f 99 f1 f2 25 c9 d3 ff c7 44 cb 52 '......t_..uYtTQ..i$..Y.c-w........B.W......%....D.R'
I0218 10:14:11.223493923    9729 tcp_custom.cc:216]          write complete on 0x3a96080: error="No Error"
I0218 10:14:11.223507878    9729 chttp2_transport.cc:829]    W:0x3a11000 CLIENT state WRITING -> IDLE [finish writing]
I0218 10:14:11.223519968    9729 chttp2_transport.cc:2771]   set connectivity_state=4
I0218 10:14:11.223552792    9729 tcp_custom.cc:285]          TCP 0x3a96080 shutdown why={"created":"@1550484851.223371440","description":"Delayed close due to in-progress write","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":586,"referenced_errors":[{"created":"@1550484851.223335401","description":"Failed parsing HTTP/2","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2514,"grpc_status":14,"referenced_errors":[{"created":"@1550484851.223323462","description":"invalid window update bytes: -2147418111","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/frame_window_update.cc","file_line":95}]}]}
D0218 10:14:11.223602028    9729 dns_resolver.cc:255]        In cooldown from last resolution (from 20 ms ago). Will resolve again in 980 ms
events.js:174
      throw er; // Unhandled 'error' event
      ^

Error: 2 UNKNOWN: Stream removed
    at Object.exports.createStatusError (/var/local/git/grpc-node/packages/grpc-native-core/src/common.js:91:15)
    at ClientDuplexStream._emitStatusIfDone (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:233:26)
    at ClientDuplexStream._receiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client.js:211:8)
    at Object.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1306:15)
    at InterceptingListener._callNext (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:618:8)
    at /var/local/git/grpc-node/packages/grpc-native-core/src/client_interceptors.js:1123:18

[jtattermusch]

Relevant portion of the log seems to be
"description":"invalid window update bytes: -2147418111","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/frame_window_update.cc","file_line":95}
https://github.com/grpc/grpc/blob/master/src/core/ext/transport/chttp2/transport/frame_window_update.cc#L95

which seems related the window update encoding mentioned in grpc/grpc#17840 (which should be fixed on the gRPC core side by now).

[jtattermusch]

I think I now understand what's going on:

1. the rootcause is the same as grpc/grpc#17840
2. the fix on the grpc-core side is not effective because grpc-node uses a fixed version of grpc core from a submodule: https://github.com/grpc/grpc-node/tree/master/packages/grpc-native-core/deps and the version currently used doesn't include the fix Ignore reserved bit in WINDOW_UPDATE frame grpc#17950 yet.
3. the fix on the asp.net core side is not yet available to Grpc.AspNetCore.Server.

The solution is to update the grpc-native-core dependency in https://github.com/grpc/grpc-node/tree/master/packages/grpc-native-core/deps.

FTR, the old version of frame_window_update.cc referenced by grpc-node https://github.com/grpc/grpc/blob/4b7da8ab961e57452b1459ce28e5f68398c62845/src/core/ext/transport/chttp2/transport/frame_window_update.cc#L95

[jtattermusch]

Fixed by bumping grpc-node to the latest version of grpc core (https://github.com/grpc/grpc-node/pull/737/files)