使用Charles 4.6.2代理Android gRPC调用出现DEADLINE_EXCEEDED错误

故障现象 #

使用Charles 4.6.2对Android应用的gRPC调用进行SSL代理时出现异常：

• 请求始终卡在Received response header. Waiting for response body阶段，最终超时，客户端抛出DEADLINE_EXCEEDED错误码
• Charles内可正常查看完整的请求、响应body内容
• 关闭SSL代理后功能恢复正常，初步推测为Charles响应接收确认环节存在异常

调试日志样例 #

Charles控制台日志 #

22:42:03    FINE     com.xk72.proxy.http.HttpProxyHandler                  Establishing HTTP/2 channel to CONNECT https://server.endpoint
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] CLIENT settings 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] SERVER frame: SETTINGS 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER settings 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] CLIENT frame: SETTINGS 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER settings 0 ack
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] CLIENT frame: SETTINGS 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER window update for 0 268369921
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] CLIENT frame: WINDOW_UPDATE 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] CLIENT headers 3
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Parsed  #307075206 [server.endpoint] CLIENT header 3 'POST https://server.endpoint/server.endpoint/MyRpcCall HTTP/2.0'
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] CLIENT settings 0 ack
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.StreamHandler  #307075206 [server.endpoint] stream 3 starting
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] SERVER frame: SETTINGS 0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http.HttpProxyHandler                  Received request POST /server.endpoint/MyRpcCall HTTP/2.0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] CLIENT data stream: 3 size: 107 END
2021/11/11 22:42:03 FINE     com.xk72.proxy.http.ProxyHttp                         Sending request POST /server.endpoint/MyRpcCall HTTP/2.0 to com.xk72.proxy.http2.v@9e9d902
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] SERVER frame: HEADERS 3
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] SERVER frame: DATA 3 size: 107 END
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER headers 3
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Parsed  #307075206 [server.endpoint] SERVER header 3 'HTTP/2.0 200'
2021/11/11 22:42:03 FINE     com.xk72.proxy.http.ProxyHttp                         Received response HTTP/2.0 200 for request POST /server.endpoint/MyRpcCall HTTP/2.0
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER data stream: 3 size: 229
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Receive #307075206 [server.endpoint] SERVER headers 3 END
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   Parsed  #307075206 [server.endpoint] SERVER header 3 '<empty>'
2021/11/11 22:42:03 FINE     com.xk72.proxy.http2.Frame                            Sending #307075206 [server.endpoint] CLIENT frame: HEADERS 3
2021/11/11 22:42:03 INFO     com.xk72.proxy.http2.Http2ProxyHandler.FrameHandler   #307075206 [server.endpoint] SERVER frame handler runtime error
2021/11/11 22:42:03 java.lang.IllegalStateException
2021/11/11 22:42:03     at com.xk72.proxy.http2.f.a(Unknown Source)
2021/11/11 22:42:03     at com.xk72.proxy.http2.A.a(Unknown Source)
2021/11/11 22:42:03     at com.xk72.proxy.http2.q.run(Unknown Source)
2021/11/11 22:42:03     at com.xk72.util.d.run(Unknown Source)
2021/11/11 22:42:03     at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
2021/11/11 22:42:03     at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
2021/11/11 22:42:03     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
2021/11/11 22:42:03     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
2021/11/11 22:42:03     at java.base/java.lang.Thread.run(Unknown Source)

消息内容日志异常 #

消息内容打印前会出现3条空的next message行，暂推测为gRPC长度前缀解析异常导致，尚未确认：

>--------------------------------next message--------------------------------<
>--------------------------------next message--------------------------------<
>--------------------------------next message--------------------------------<
>--------------------------------next message--------------------------------<
field: "test"

内容的提问来源于stack exchange，提问作者aarnaut