GRPC 传输大文件的时候会block掉其他的调用

[lijiarui]

复现方式

连续给机器人发10个10M以上的文件，机器人通过 message.toFileBox()收文件的时候，会出现 Puppet dogReset() 之后会 Hostie stop()

表现形式

服务端有心跳，客户端没有心跳

客户端日志

• 最后一次收到心跳的时间： 20:34:35
• client 的最后一次操作: 20:34:35 VERB Puppet selfId()
• 下一条就dogRest 了： 20:35:35 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}

20:34:21 SILL Wechaty memoryCheck() free: 218 MB, require: 4 MB
20:34:26 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"manual heartbeat","timeout":60000}"})
20:34:26 SILL Wechaty memoryCheck() free: 214 MB, require: 4 MB
20:34:29 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object]","timeout":60000}"})
20:34:29 SILL Wechaty memoryCheck() free: 225 MB, require: 4 MB
20:34:31 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"manual heartbeat","timeout":60000}"})
20:34:31 SILL Wechaty memoryCheck() free: 210 MB, require: 4 MB
20:34:35 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"1007536"}"})
20:34:35 SILL Wechaty memoryCheck() free: 109 MB, require: 4 MB
20:34:35 VERB Message static load(1007536)
20:34:35 VERB Message constructor(1007536) for class WechatifiedMessage
20:34:35 VERB Message ready()
20:34:35 VERB Puppet messagePayload(1007536)
20:34:35 SILL Puppet messagePayloadCache(1007536) cache MISS
20:34:35 VERB PuppetHostie messageRawPayload(1007536)
20:34:35 SILL Puppet messagePayload(1007536) cache SET
20:34:35 SILL Contact ready() @ Puppet#0<PuppetHostie>() with id="1688850321595920"
20:34:35 SILL Contact ready() isReady() true
20:34:35 SILL Contact constructor(1688850321595921)
20:34:35 SILL Contact ready() @ Puppet#0<PuppetHostie>() with id="1688850321595921"
20:34:35 VERB Message toFileBox()
20:34:35 VERB PuppetHostie messageFile(1007536)
20:34:35 VERB Puppet selfId()
20:35:35 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}
20:35:35 SILL Puppet throttleReset() payload: "{"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}"
20:35:35 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: "onGrpcStreamEvent(EVENT_TYPE_MESSAGE)"
20:35:35 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_MESSAGE))
20:35:35 VERB PuppetHostie stop()

服务端日志

• 在 20:34:35 VERB Puppet selfId() 之后服务端还是在持续发心跳的，但是客户端收不到心跳了：

20:34:35 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007536"})
20:34:36 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:41 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:44 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007539"})
20:34:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:48 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"[object Object]","timeout":60000})
20:34:51 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:54 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007542"})
20:34:56 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:01 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:04 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007545"})
20:35:06 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:11 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:16 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:21 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:23 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"timeout health check","timeout":60000})
20:35:26 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:31 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:34 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007548"})

20:34:21 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:22 VERB Bridge onEvent() type: 11087(MT_HEARTBEAT), data: {"data":{},"type":11087}
20:34:24 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f6604444e45574944315f3233316663343531306334643937376235663831616134665f36336564303165662d613265312d343864372d386263362d6163356133643762306233360201000204009a65400410241b45e59f8cfc8fe422d4309fbe18710201010201000400","file_size":10118454,"is_pc":0,"local_id":"2256","receiver":"1688850321595921","send_time":"1602333264","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007545"},"type":11042}
20:34:24 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:26 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:29 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f8004444e45574944315f3233316663343531306334643937376235663831616135335f33313734663238652d393763312d343034612d613164612d6161313061376533373132350201000204009f7780041015ded860437d4832556351cbca16e0370201010201000400","file_size":10450808,"is_pc":0,"local_id":"2257","receiver":"1688850321595921","send_time":"1602333269","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007548"},"type":11042}
20:34:29 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"[object Object]","timeout":60000})
20:34:29 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:31 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:32 VERB Bridge onEvent() type: 11087(MT_HEARTBEAT), data: {"data":{},"type":11087}
20:34:34 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f8004444e45574944315f3233316663343531306334643937376235663831616135385f33313734663238652d393763312d343034612d613164612d6161313061376533373132350201000204009f7780041015ded860437d4832556351cbca16e0370201010201000400","file_size":10450808,"is_pc":0,"local_id":"2258","receiver":"1688850321595921","send_time":"1602333274","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007551"},"type":11042}
20:34:34 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:35 VERB PuppetWork onMessage({"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f6604444e45574944315f3233316663343531306334643937376235663831616134325f36336564303165662d613265312d343864372d386263362d6163356133643762306233360201000204009a65400410241b45e59f8cfc8fe422d4309fbe18710201010201000400","file_size":10118454,"is_pc":0,"local_id":"2253","receiver":"1688850321595921","send_time":"1602333252","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007536","type":11042,"file_path":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921\\Cache\\Image\\2020-10\\67830c15-c500-49cf-91ab-085b68f82f88.png","file_name":"67830c15-c500-49cf-91ab-085b68f82f88.png"})
20:34:35 VERB Message static load(1007536)
20:34:35 VERB Message constructor(1007536) for class WechatifiedMessage
20:34:35 VERB Message ready()
20:34:35 VERB Puppet messagePayload(1007536)
20:34:35 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007536"})
20:34:35 VERB IoClient onMessage(Message#Image[�Contact<Rui芮>])
20:34:35 VERB Puppet selfId()
20:34:35 VERB PuppetServiceImpl messagePayload()
20:34:35 VERB Puppet messagePayload(1007536)
20:34:35 VERB PuppetServiceImpl messageFile()
20:34:35 VERB PuppetWork messageFile(1007536)
20:34:36 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:39 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f8004444e45574944315f3233316663343531306334643937376235663831616135635f33313734663238652d393763312d343034612d613164612d6161313061376533373132350201000204009f7780041015ded860437d4832556351cbca16e0370201010201000400","file_size":10450808,"is_pc":0,"local_id":"2259","receiver":"1688850321595921","send_time":"1602333279","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007554"},"type":11042}
20:34:39 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:41 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:42 VERB Bridge onEvent() type: 11087(MT_HEARTBEAT), data: {"data":{},"type":11087}
20:34:44 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f8004444e45574944315f3233316663343531306334643937376235663831616136315f33313734663238652d393763312d343034612d613164612d6161313061376533373132350201000204009f7780041015ded860437d4832556351cbca16e0370201010201000400","file_size":10450808,"is_pc":0,"local_id":"2260","receiver":"1688850321595921","send_time":"1602333283","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007557"},"type":11042}
20:34:44 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:44 VERB PuppetWork onMessage({"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f6604444e45574944315f3233316663343531306334643937376235663831616134365f36336564303165662d613265312d343864372d386263362d6163356133643762306233360201000204009a65400410241b45e59f8cfc8fe422d4309fbe18710201010201000400","file_size":10118454,"is_pc":0,"local_id":"2254","receiver":"1688850321595921","send_time":"1602333256","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007539","type":11042,"file_path":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921\\Cache\\Image\\2020-10\\b1bd6d28-cde0-4058-ab1f-088f142e3363.png","file_name":"b1bd6d28-cde0-4058-ab1f-088f142e3363.png"})
20:34:44 VERB Message static load(1007539)
20:34:44 VERB Message constructor(1007539) for class WechatifiedMessage
20:34:44 VERB Message ready()
20:34:44 VERB Puppet messagePayload(1007539)
20:34:44 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007539"})
20:34:44 VERB IoClient onMessage(Message#Image[�Contact<Rui芮>])
20:34:44 VERB Puppet selfId()
20:34:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:48 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f9904444e45574944315f3233316663343531306334643937376235663831616136365f64393165666239392d316139622d343866332d616530652d6137646235343837386666300201000204009a73900410e171e3bdcefbfb93cbac84f60370d1e30201010201000400","file_size":10122122,"is_pc":0,"local_id":"2261","receiver":"1688850321595921","send_time":"1602333288","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007560"},"type":11042}
20:34:48 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"[object Object]","timeout":60000})
20:34:48 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:51 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:52 VERB Bridge onEvent() type: 11087(MT_HEARTBEAT), data: {"data":{},"type":11087}
20:34:53 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f9904444e45574944315f3233316663343531306334643937376235663831616136625f64393165666239392d316139622d343866332d616530652d6137646235343837386666300201000204009a73900410e171e3bdcefbfb93cbac84f60370d1e30201010201000400","file_size":10122122,"is_pc":0,"local_id":"2262","receiver":"1688850321595921","send_time":"1602333293","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007563"},"type":11042}
20:34:53 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:34:54 VERB PuppetWork onMessage({"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f6604444e45574944315f3233316663343531306334643937376235663831616134615f36336564303165662d613265312d343864372d386263362d6163356133643762306233360201000204009a65400410241b45e59f8cfc8fe422d4309fbe18710201010201000400","file_size":10118454,"is_pc":0,"local_id":"2255","receiver":"1688850321595921","send_time":"1602333260","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007542","type":11042,"file_path":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921\\Cache\\Image\\2020-10\\fe0d0604-475c-4f81-bca7-9bac868ff410.png","file_name":"fe0d0604-475c-4f81-bca7-9bac868ff410.png"})
20:34:54 VERB Message static load(1007542)
20:34:54 VERB Message constructor(1007542) for class WechatifiedMessage
20:34:54 VERB Message ready()
20:34:54 VERB Puppet messagePayload(1007542)
20:34:54 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007542"})
20:34:54 VERB IoClient onMessage(Message#Image[�Contact<Rui芮>])
20:34:54 VERB Puppet selfId()
20:34:56 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:34:58 VERB Bridge onEvent() type: 11042(MT_RECV_IMG_MSG), data: {"data":{"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f9904444e45574944315f3233316663343531306334643937376235663831616136665f64393165666239392d316139622d343866332d616530652d6137646235343837386666300201000204009a73900410e171e3bdcefbfb93cbac84f60370d1e30201010201000400","file_size":10122122,"is_pc":0,"local_id":"2263","receiver":"1688850321595921","send_time":"1602333297","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007566"},"type":11042}
20:34:58 VERB DataManager _processMessage(MT_RECV_IMG_MSG, {"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:01 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:04 VERB PuppetWork onMessage({"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f6604444e45574944315f3233316663343531306334643937376235663831616134665f36336564303165662d613265312d343864372d386263362d6163356133643762306233360201000204009a65400410241b45e59f8cfc8fe422d4309fbe18710201010201000400","file_size":10118454,"is_pc":0,"local_id":"2256","receiver":"1688850321595921","send_time":"1602333264","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007545","type":11042,"file_path":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921\\Cache\\Image\\2020-10\\b073b4ae-eb38-4fbc-aa3a-08732f592681.png","file_name":"b073b4ae-eb38-4fbc-aa3a-08732f592681.png"})
20:35:04 VERB Message static load(1007545)
20:35:04 VERB Message constructor(1007545) for class WechatifiedMessage
20:35:04 VERB Message ready()
20:35:04 VERB Puppet messagePayload(1007545)
20:35:04 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007545"})
20:35:04 VERB IoClient onMessage(Message#Image[�Contact<Rui芮>])
20:35:04 VERB Puppet selfId()
20:35:06 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:11 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:13 VERB BaseRequest request() apiType: MT_GET_OWNER_INFO_MSG
20:35:13 VERB Work(ffi-adapter) SendWxWorkData(1,{"data":{},"type":11035})
20:35:13 VERB ffi-adapter Backend.lib(0: "Z:\juzi\node_modules\@juzibot\wechaty-puppet-wxwork\dist\dlls\WxWorkLoaderJs.dll")
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:16 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:21 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:23 VERB Manager onRequestTimeout(1)
20:35:23 ERR health check failed, maybe some requests blocked it, times: 1!
20:35:23 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"timeout health check","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:26 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:31 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"manual heartbeat","timeout":60000})
20:35:34 VERB PuppetWork onMessage({"content_type":14,"conversation_id":"S:1688850321595920_1688850321595921","file_key":"30818c0201020481843081810201000204231fc45102030f55c902040c4d977b02045f7e0f8004444e45574944315f3233316663343531306334643937376235663831616135335f33313734663238652d393763312d343034612d613164612d6161313061376533373132350201000204009f7780041015ded860437d4832556351cbca16e0370201010201000400","file_size":10450808,"is_pc":0,"local_id":"2257","receiver":"1688850321595921","send_time":"1602333269","sender":"1688850321595920","sender_name":"Rui芮","server_id":"1007548","type":11042,"file_path":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921\\Cache\\Image\\2020-10\\5a9c1676-8f64-4c9b-9d5c-830c1b1bd8cf.jpg","file_name":"5a9c1676-8f64-4c9b-9d5c-830c1b1bd8cf.jpg"})
20:35:34 VERB Message static load(1007548)
20:35:34 VERB Message constructor(1007548) for class WechatifiedMessage
20:35:34 VERB Message ready()
20:35:34 VERB Puppet messagePayload(1007548)
20:35:34 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"1007548"})
20:35:34 VERB IoClient onMessage(Message#Image[�Contact<Rui芮>])
20:35:34 VERB Puppet selfId()
20:35:35 VERB PuppetServiceImpl stop()
20:35:35 VERB EventStreamManager stop()
20:35:35 VERB PuppetWork stop()
20:35:35 VERB StateSwitch <PuppetWork> off(pending) <- (false)
20:35:35 VERB PuppetWork stopManager()
20:35:35 VERB Manager stop()
20:35:35 VERB Manager releaseQueue()
20:35:35 VERB BaseData release()
20:35:35 VERB CacheManager release()
20:35:35 VERB CacheManager releaseCache()
20:35:35 VERB WxWorkCache release()
20:35:35 VERB WxWorkCache constructor() cacheMapping db closed!
20:35:35 VERB Manager clearLaunchTimer()
20:35:35 VERB Bridge stop()
20:35:35 VERB Work(ffi-adapter) DestroyWxWork()
20:35:35 VERB ffi-adapter Backend.lib(0: "Z:\juzi\node_modules\@juzibot\wechaty-puppet-wxwork\dist\dlls\WxWorkLoaderJs.dll")
20:35:35 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:35 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
0067:fixme:thread:NtQueryInformationThread Cannot get kerneltime or usertime of other threads
20:35:36 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:36 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
20:35:36 VERB Bridge stop() destroyWxWorkResult: true
20:35:36 VERB Manager stop() stopped
20:35:36 VERB StateSwitch <PuppetWork> off(true) <- (pending)
20:35:36 VERB PuppetWork stop() stopped
20:35:36 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:36 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
20:35:36 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:36 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
20:35:36 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:36 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:36 VERB WxWorkCache getFilePathWithKey() skip getting file path since the state is [object Object]
20:35:36 ERR Bridge onEvent() rejection: CacheManager getMessageCache() has no cache
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:46 VERB EventStreamManager this.onStreamingCallEnd() this.eventStream.on(finish) fired
20:35:46 VERB EventStreamManager connectPuppetEventToStreamingCall() disconnect() 14 callbacks
20:35:46 WARN EventStreamManager this.onStreamingCallEnd() this.eventStream.on(finish) eventStream is undefined
20:35:48 INFO Io on(jsonrpc): [object Object]
20:35:48 VERB Io on(jsonrpc) send({"id":-9007199254740682,"jsonrpc":"2.0","result":19012})
20:35:49 VERB PuppetServiceImpl start()
20:35:49 VERB PuppetWork start()
20:35:49 VERB StateSwitch <PuppetWork> on(pending) <- (false)
20:35:49 VERB PuppetWork startManager()
20:35:49 VERB Bridge start()
20:35:49 VERB Work(ffi-adapter) InjectWxWork(Z:\juzi\node_modules\@juzibot\wechaty-puppet-wxwork\dist\dlls\WxWorkHelper_3.0.27.2701_1008.dll,C:\Program Files (x86)\WXWork\WXWork.exe)
20:35:49 VERB ffi-adapter Backend.lib(0: "Z:\juzi\node_modules\@juzibot\wechaty-puppet-wxwork\dist\dlls\WxWorkLoaderJs.dll")
20:35:49 VERB Bridge start() WxWork injected, clientId: 112
20:35:49 VERB Manager initQueue()
20:35:49 VERB Manager initLaunchTimer()
20:35:49 INFO Guard launchMonitorLoop() WxWork Launched
20:35:49 INFO Manager start() started
20:35:49 VERB StateSwitch <PuppetWork> on(true) <- (pending)
20:35:49 VERB PuppetWork start() started
20:35:49 VERB PuppetServiceImpl event()
20:35:49 VERB EventStreamManager start(stream)
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() for Puppet#0<PuppetWork>(puppet_wxwork_816924ac3fff1797)
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(friendship) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(login) (listenerCount:2) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(logout) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(message) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-invite) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-join) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-leave) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-topic) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(scan) (listenerCount:2) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(dirty) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(dong) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(error) (listenerCount:1) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(heartbeat) (listenerCount:5) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(ready) (listenerCount:2) registering...
20:35:49 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(reset) (listenerCount:4) registering...
20:35:49 VERB EventStreamManager onStreamingCallEnd(callback)
20:35:49 INFO Io on(jsonrpc): [object Object]
20:35:49 VERB Io on(jsonrpc) send({"id":-9007199254740681,"jsonrpc":"2.0","result":19012})
20:35:49 INFO Io on(jsonrpc): [object Object]
20:35:49 VERB Io on(jsonrpc) send({"id":-9007199254740680,"jsonrpc":"2.0","result":19012})
017e:fixme:ver:GetCurrentPackageId (0x710ff2c (nil)): stub
20:35:50 VERB Bridge onEvent() type: 11024(MT_APP_READY_MSG), data: {"data":{"pid":112},"type":11024}
20:35:50 VERB EventStreamManager grpcEmit(EVENT_TYPE_HEARTBEAT[1], {"data":"[object Object]","timeout":60000})
20:35:50 VERB Manager all api are ready.
20:35:51 VERB Bridge onEvent() type: 11026(MT_USER_LOGIN), data: {"data":{"account":"zidonghua@juzi.bot","acctid":"ZiDongHua","avatar":"http://wework.qpic.cn/bizmail/aib5Kbav9c2B5uzwvemfJKFvdnQgGDbxdGrQDAlX92YsAoFXL8aicmZw/0","corp_id":"1970324972075112","corp_name":"","document_root":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921","email":"","job_name":"","mobile":"13811254048","nickname":"","pid":112,"position":"","sex":1,"user_id":"1688850321595921","username":"自动化"},"type":11026}
20:35:51 VERB Manager processEvent() receive login event: {"account":"zidonghua@juzi.bot","acctid":"ZiDongHua","avatar":"http://wework.qpic.cn/bizmail/aib5Kbav9c2B5uzwvemfJKFvdnQgGDbxdGrQDAlX92YsAoFXL8aicmZw/0","corp_id":"1970324972075112","corp_name":"","document_root":"C:\\users\\user\\My Documents\\WXWork\\1688850321595921","email":"","job_name":"","mobile":"13811254048","nickname":"","pid":112,"position":"","sex":1,"user_id":"1688850321595921","username":"自动化"}
20:35:51 VERB Manager clearLaunchTimer()
20:35:51 VERB Manager clearScanLoginTimer()
20:35:51 VERB BaseData login(1688850321595921, 自动化)
20:35:51 VERB BaseData initCache()
20:35:51 VERB CacheManager init()
20:35:51 VERB CacheManager initCache(1688850321595921)
0071:fixme:win:FlashWindowEx 0xcfc74d4 - semi-stub
20:35:51 VERB CacheManager initCache() inited Contacts: 54, Rooms: 29, RoomMembers: 29 Messages: 47, Friendship: 0, SearchFriend: 0, ContactMoreInfo: 2, cacheDir="C:\users\user\.wechaty\puppet-work-cache\flash-store-v0.12\1688850321595921"
20:35:51 VERB BaseData initStorage()
20:35:51 VERB StorageManager init()
20:35:51 VERB StorageManager init() StorageManager has been initialized, no need to initialize again.
20:35:51 VERB BaseData initWxWorkCache(C:\users\user\My Documents\WXWork\1688850321595921)
20:35:51 INFO WxWorkCache constructor() connected to cacheManager db.
20:35:51 VERB WxWorkCache constructor() cacheMapping db opened!
20:35:51 VERB BaseData syncData()
20:35:51 VERB BaseData getBotInfo(1688850321595921)
20:35:51 VERB BaseData setBotInfo(1688850321595921)
20:35:51 INFO PuppetWork onLogin(1688850321595921)
20:35:51 VERB EVENT_LOG LOGIN, 1688850321595921
20:35:51 VERB Puppet selfId()
20:35:51 VERB EventStreamManager grpcEmit(EVENT_TYPE_LOGIN[25], {"contactId":"1688850321595921"})
20:35:51 VERB ContactSelf name()
20:35:51 INFO IoClient 自动化 logged in
0071:fixme:win:RegisterTouchWindow (0x10124 00000000): stub

[windmemory]

Created a repo to get a minimal reproduce code for this problem:
https://github.com/windmemory/repro-grpc-bug

Seems like this is caused by single connection between server and client, the connection can be only used to hold one request each time, and all the other requests are in the queue waiting to be transferred.