search

wechaty / puppet-supports

Wechaty Puppet Services (WPS)
https://wechaty.js.org/docs/puppet-services/
Apache License 2.0
32 stars 4 forks source link

wechaty connection padlocal gateway is always disconnected and reconnected #85

Closed Jesn closed 3 years ago

Jesn commented 3 years ago 
15:21:08 VERB Puppet selfId()
15:22:07 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}
15:22:07 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_MESSAGE))
15:22:07 VERB PuppetHostie stop()
15:22:07 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:22:07 VERB PuppetHostie stopGrpcStream()
15:22:07 VERB PuppetHostie stopGrpcClient()
15:22:07 VERB Puppet selfId()
15:22:07 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:22:07 INFO StarterBot Contact<MacWeChat> logout
15:22:07 VERB PuppetHostie start()
15:22:07 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:22:07 VERB PuppetHostie startGrpcClient()
15:22:07 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:22:08 VERB PuppetHostie startGrpcStream()
15:22:10 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:22:11 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:22:11 INFO StarterBot Contact<MacWeChat> login
15:22:11 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:22:11 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:22:16 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:22:16 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:23:16 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:23:16 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:23:16 VERB PuppetHostie stop()
15:23:16 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:23:16 VERB PuppetHostie stopGrpcStream()
15:23:16 VERB PuppetHostie stopGrpcClient()
15:23:16 VERB Puppet selfId()
15:23:16 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:23:16 INFO StarterBot Contact<MacWeChat> logout
15:23:16 VERB PuppetHostie start()
15:23:16 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:23:16 VERB PuppetHostie startGrpcClient()
15:23:16 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:23:17 VERB PuppetHostie startGrpcStream()
15:23:17 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:23:18 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:23:18 INFO StarterBot Contact<MacWeChat> login
15:23:18 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"9049040460844034225"}"})
15:23:18 VERB Message static load(9049040460844034225)
15:23:18 VERB Message constructor(9049040460844034225) for class WechatifiedMessage
15:23:18 VERB Message ready()
15:23:18 VERB Puppet messagePayload(9049040460844034225)
15:23:18 VERB PuppetHostie messageRawPayload(9049040460844034225)
15:23:18 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"3345666082938147455"}"})
15:23:18 VERB Message static load(3345666082938147455)
15:23:18 VERB Message constructor(3345666082938147455) for class WechatifiedMessage
15:23:18 VERB Message ready()
15:23:18 VERB Puppet messagePayload(3345666082938147455)
15:23:18 VERB PuppetHostie messageRawPayload(3345666082938147455)
15:23:19 VERB Room ready()
15:23:19 INFO StarterBot Message#Text[🗣Contact<线报员>@👥Room<京东活动线报群⑤>]    好价回归  
先领199-40券
https://mmbizurl.cn/s/fI1tw50Ah
【 JD自营】蜀道香 香辣/麻辣 牛肉干 
15:23:19 INFO 好价回归  
先领199-40券
https://mmbizurl.cn/s/fI1tw50Ah
【 JD自营】蜀道香 香辣/麻辣 牛肉干 200g/袋
https://u.jd.com/wKXE2zz
https://u.jd.com/wJXPdBd
（麻辣味需取消Plus会员价）
 任选4件再减100元，实付59.2元+运费
*折合14.8元/袋，又便宜又好吃 
15:23:19 INFO StarterBot Message#Unknown[🗣Contact<MacWeChat>]   <msg>
<op id='11'>
<name>HandOffMaster</name>
<arg><handofflist opcode
15:23:19 INFO <msg>
<op id='11'>
<name>HandOffMaster</name>
<arg><handofflist opcode="4" seq="1544" deviceid="A1ce85b51b227c93" networkstatus="wifi">

        </handofflist></arg>
</op>
</msg> 
15:23:19 VERB Puppet selfId()
15:23:19 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:23:19 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:23:23 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:23:23 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:24:23 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:24:23 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:24:23 VERB PuppetHostie stop()
15:24:23 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:24:23 VERB PuppetHostie stopGrpcStream()
15:24:23 VERB PuppetHostie stopGrpcClient()
15:24:23 VERB Puppet selfId()
15:24:23 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:24:23 INFO StarterBot Contact<MacWeChat> logout
15:24:23 VERB PuppetHostie start()
15:24:23 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:24:23 VERB PuppetHostie startGrpcClient()
15:24:23 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:24:24 VERB PuppetHostie startGrpcStream()
15:24:25 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:24:25 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:24:25 INFO StarterBot Contact<MacWeChat> login
15:24:26 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:24:26 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:24:31 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:24:31 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:25:31 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:25:31 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:25:31 VERB PuppetHostie stop()
15:25:31 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:25:31 VERB PuppetHostie stopGrpcStream()
15:25:31 VERB PuppetHostie stopGrpcClient()
15:25:31 VERB Puppet selfId()
15:25:31 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:25:31 INFO StarterBot Contact<MacWeChat> logout
15:25:31 VERB PuppetHostie start()
15:25:31 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:25:31 VERB PuppetHostie startGrpcClient()
15:25:31 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:25:32 VERB PuppetHostie startGrpcStream()
15:25:32 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:25:33 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:25:33 INFO StarterBot Contact<MacWeChat> login
15:25:34 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:25:34 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:25:38 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:25:38 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:26:38 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:26:38 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:26:38 VERB PuppetHostie stop()
15:26:38 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:26:38 VERB PuppetHostie stopGrpcStream()
15:26:38 VERB PuppetHostie stopGrpcClient()
15:26:38 VERB Puppet selfId()
15:26:38 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:26:38 INFO StarterBot Contact<MacWeChat> logout
15:26:38 VERB PuppetHostie start()
15:26:38 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:26:38 VERB PuppetHostie startGrpcClient()
15:26:38 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:26:39 VERB PuppetHostie startGrpcStream()
15:26:40 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:26:40 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:26:40 INFO StarterBot Contact<MacWeChat> login
15:26:40 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"7135407267584892821"}"})
15:26:40 VERB Message static load(7135407267584892821)
15:26:40 VERB Message constructor(7135407267584892821) for class WechatifiedMessage
15:26:40 VERB Message ready()
15:26:40 VERB Puppet messagePayload(7135407267584892821)
15:26:40 VERB PuppetHostie messageRawPayload(7135407267584892821)
15:26:40 VERB Room ready()
15:26:40 INFO StarterBot Message#Text[🗣Contact<线报员>@👥Room<京东活动线报群⑤>]    上面安慕希酸奶是下3件啊- -！打错了。。囧
【29元】圣美伦 浪漫女士缘香水30ml/瓶
https://u.jd.com/wPXNlAv
15:26:40 INFO 上面安慕希酸奶是下3件啊- -！打错了。。囧
【29元】圣美伦 浪漫女士缘香水30ml/瓶
https://u.jd.com/wPXNlAv
情人节快到了，你懂的！
旗舰店，放心买，送两支小样！ 
15:26:41 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:26:41 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:26:45 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:26:45 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:27:45 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:27:45 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:27:45 VERB PuppetHostie stop()
15:27:45 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:27:45 VERB PuppetHostie stopGrpcStream()
15:27:45 VERB PuppetHostie stopGrpcClient()
15:27:45 VERB Puppet selfId()
15:27:45 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:27:45 INFO StarterBot Contact<MacWeChat> logout
15:27:45 VERB PuppetHostie start()
15:27:45 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:27:45 VERB PuppetHostie startGrpcClient()
15:27:45 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:27:46 VERB PuppetHostie startGrpcStream()
15:27:47 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:27:48 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:27:48 INFO StarterBot Contact<MacWeChat> login
15:27:48 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"413346624058173795"}"})
15:27:48 VERB Message static load(413346624058173795)
15:27:48 VERB Message constructor(413346624058173795) for class WechatifiedMessage
15:27:48 VERB Message ready()
15:27:48 VERB Puppet messagePayload(413346624058173795)
15:27:48 VERB PuppetHostie messageRawPayload(413346624058173795)
15:27:48 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:27:48 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:27:48 INFO StarterBot Message#Unknown[🗣Contact<MacWeChat>]   <msg>
<op id='11'>
<name>HandOffMaster</name>
<arg><handofflist opcode
15:27:48 INFO <msg>
<op id='11'>
<name>HandOffMaster</name>
<arg><handofflist opcode="4" seq="1545" deviceid="A1ce85b51b227c93" networkstatus="wifi">

</handofflist></arg>
</op>
</msg> 
15:27:48 VERB Puppet selfId()
15:27:53 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:27:53 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:28:53 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_READY)","timeout":60000}
15:28:53 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_READY))
15:28:53 VERB PuppetHostie stop()
15:28:53 VERB StateSwitch <PuppetHostie> off(pending) <- (false)
15:28:53 VERB PuppetHostie stopGrpcStream()
15:28:54 VERB PuppetHostie stopGrpcClient()
15:28:54 VERB Puppet selfId()
15:28:54 VERB StateSwitch <PuppetHostie> off(true) <- (pending)
15:28:54 INFO StarterBot Contact<MacWeChat> logout
15:28:54 VERB PuppetHostie start()
15:28:54 VERB StateSwitch <PuppetHostie> on(pending) <- (false)
15:28:54 VERB PuppetHostie startGrpcClient()
15:28:54 VERB PuppetHostie discoverHostieIp(a80c4ccb-da3e-49fb-b947-c1b10d1cfbfb)
15:28:55 VERB PuppetHostie startGrpcStream()
15:28:55 VERB StateSwitch <PuppetHostie> on(true) <- (pending)
15:28:56 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"zhengbolove"}"})
15:28:56 INFO StarterBot Contact<MacWeChat> login
15:28:57 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:28:57 VERB StateSwitch <WechatyReady> on(true) <- (true)
15:29:01 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
15:29:01 VERB StateSwitch <WechatyReady> on(true) <- (true)

wechaty is always disconnected and reconnected .....

padlocal gateway is running on dev.chatie.io

huan commented 3 years ago

It seems that your program did not get any heartbeat from the upstream, which make watchdog think the program has dead, and then it did a reset after 60 seconds.

Cloud you please:

  1. provide all the related source code / docker run scripts which show you those log messages
  2. provide reproducible steps for reproducing this issue

So that we can look into this problem deeper?

Jesn commented 3 years ago

padlocal Gateway 没有heartbeat 发送过来，以上情况在ts-wechaty 和 .net-wechaty 均会出现。经过本地nas测试，.net wechaty 和padlocal Gateway在同一台服务器上，不会出现类似情况，应该是和网络有关

huan commented 3 years ago

Link to #84

huan commented 3 years ago

I have reproduced this issue on a Tencent Cloud server hosted in Beijing.

The problem was caused by the leaking of heartbeats from PadLocal. @padlocal

Problem

Here are the details:

  1. Wechaty Puppet is designed to emit at least one event in 60 seconds. If we do not have any events to emit, then we need to emit a heartbeat event so that it can prove itself is alive and healthy. See: https://github.com/wechaty/wechaty-puppet/blob/bab9e29c088c33fa8bc6e148d9bdadbd453fd138/src/puppet.ts#L253-L254
  2. It seems that the PadLocal does not have any heartbeat event to emit when there are no other events, so if your bot idle for more than 60 seconds, then the Wechaty Puppet system will think the puppet provider has dead, so it will call reset to try to recover the puppet.

Logs:

02:00:13 INFO StarterBot Message#Text[🗣Contact<OssChat>@👥Room<ChatOps - Heartbeat 💖>]   [太阳]

02:01:13 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}
02:01:13 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_MESSAGE))
02:01:13 VERB PuppetService stop()
02:01:13 VERB StateSwitch <PuppetService> off(pending) <- (false)
02:01:13 VERB PuppetService stopGrpcStream()
02:01:13 VERB PuppetService stopGrpcClient()
02:01:13 VERB Puppet selfId()
02:01:13 VERB StateSwitch <PuppetService> off(true) <- (pending)
02:01:13 INFO StarterBot Contact<Mike (李卓桓)> logout
02:01:13 VERB PuppetService start()
02:01:13 VERB StateSwitch <PuppetService> on(pending) <- (false)
02:01:13 VERB PuppetService startGrpcClient()
02:01:13 VERB PuppetService discoverServiceIp(e49007b7-7523-4a80-bfdb-1be0de3844b9)
02:01:14 VERB PuppetService startGrpcStream()
02:01:14 VERB StateSwitch <PuppetService> on(true) <- (pending)
02:01:14 VERB PuppetService onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"wxid_a8d806dzznm822"}"})
02:01:14 INFO StarterBot Contact<Mike (李卓桓)> login
02:01:15 VERB PuppetService onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
02:01:15 VERB StateSwitch <WechatyReady> on(true) <- (true)
02:01:20 VERB PuppetService onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"})
02:01:20 VERB StateSwitch <WechatyReady> on(true) <- (true)

Solution

Add heartbeat event to PadLocal.

Here's an example from our puppeteer puppet, which emits heartbeats in the browser, so if the browser dead, we will get to know because the heartbeat has lost.

@padlocal I hope I have described the design of heartbeat clearly, so please help us to add heartbeat to PadLocal, and let me know if you have any questions. Thanks!

yswtrue commented 3 years ago

Same bug if padlocal with matrix-appservice-wechaty

matrix-appservice-wechaty    | 09:12:25 WARN Puppet dogReset() reason: {"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}
matrix-appservice-wechaty    | 09:12:25 SILL Puppet throttleReset() payload: "{"data":"onGrpcStreamEvent(EVENT_TYPE_MESSAGE)","timeout":60000}"
matrix-appservice-wechaty    | 09:12:25 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: "onGrpcStreamEvent(EVENT_TYPE_MESSAGE)"
matrix-appservice-wechaty    | 09:12:25 VERB Puppet reset(onGrpcStreamEvent(EVENT_TYPE_MESSAGE))
matrix-appservice-wechaty    | 09:12:25 VERB PuppetService stop()
matrix-appservice-wechaty    | 09:12:25 SILL StateSwitch <PuppetService> off() is false
matrix-appservice-wechaty    | 09:12:25 SILL StateSwitch <PuppetService> off() is false
matrix-appservice-wechaty    | 09:12:25 VERB StateSwitch <PuppetService> off(pending) <- (false)
matrix-appservice-wechaty    | 09:12:25 VERB PuppetService stopGrpcStream()
matrix-appservice-wechaty    | 09:12:25 VERB PuppetService startGrpcStream() eventStream.on(end)
matrix-appservice-wechaty    | 09:12:25 VERB PuppetService stopGrpcClient()
matrix-appservice-wechaty    | 09:12:25 VERB Puppet selfId()
matrix-appservice-wechaty    | 09:12:25 SILL Contact ready() @ Puppet#1<PuppetService>(@yswtrue:yswtrue.com) with id="wxid_1scxaiqf7a6t21"
matrix-appservice-wechaty    | 09:12:25 SILL Contact ready() isReady() true
matrix-appservice-wechaty    | 09:12:25 SILL StateSwitch <PuppetService> off() is pending
matrix-appservice-wechaty    | 09:12:25 VERB StateSwitch <PuppetService> off(true) <- (pending)
matrix-appservice-wechaty    | 09:12:25 VERB WechatyManager onLogout(Contact<Roy>)
matrix-appservice-wechaty    | 09:12:25 VERB ContactSelf name()
matrix-appservice-wechaty    | 09:12:25 VERB MiddleManager directMessageToMatrixConsumer("You are now logged out from Wechat. Your user name is: Roy. send `!login` to me to get a new QR Code to scan for logging in.", "Wechaty#ckkz7ngg9000107mn86nqh4wp<>(@yswtrue:yswtrue.com)")
padlocal commented 3 years ago

PadLocal puppet has not implemented heartbeat currently, will support this feature soon

huan commented 3 years ago

Great to know that the PadLocal will support heartbeat soon, cheers!

padlocal commented 3 years ago

Fixed in wechaty-puppet-padlocal@0.2.37