search

juzibot / donut-tester

40 stars 4 forks source link

Unknow reason for PuppetServiceImpl stop() #5

Open su-chang opened 4 years ago

su-chang commented 4 years ago

Important：Please file the issue follow the template, or we won't help you to solve the problem.

0. Report Issue Guide

  1. Please run the following command and check whether the problem has been fixed：

    rm -rf package-lock.json
rm -rf node_modules
npm install

  2. Please search in FAQ List first, and make sure your problem has not been solved before.

  3. Please search in the issue first, and make sure your problem had not been reported before

1. Versions

2. Describe the bug

Give a clear and concise description of what the bug is.

3. To Reproduce

This part is very important: if you can not provide any reproduce steps, then the problem will be very hard to be recognized.

Steps to reproduce the behavior:

  1. run '...'
  2. ...
  3. ...

4. Expected behavior

Give a clear and concise description of what you expected to happen.

5. Actual behavior

If applicable, add screenshots to help explain your problem. But do not paste log screenshots here.

6. Full Output Logs

Set env WECHATY_LOG=silly in order to set log level to silly, then we can get the full log (If you dosen't set log env, log level is info as default, we cannot get the full log)

We need full log instead of log screenshot or log fragments!

Show Logs ```shell $ WECHATY_LOG=silly node yourbot.js Question: Paste your FULL(DO NOT ONLY PROVIDE FRAGMENTS) log messages Answer: 18:09:58 VERB PuppetDonut messageRawPayloadParser({"at_user_list":[],"from_wxid":"wxid_orp7dihe2pm112","is_pc":0,"msg":"dong","msgid":"7392016307941416295","room_wxid":"17962906510@chatroom","timestamp":1586945397,"to_wxid":"17962906510@chatroom","wx_type":1}) 18:09:58 VERB Room ready() 18:09:58 VERB IoClient onMessage(Message#Text[🗣Contact@👥Room] dong) 18:09:59 VERB PuppetServiceImpl messagePayload() 18:09:59 VERB Puppet messagePayload(7392016307941416295) 18:10:14 VERB PuppetServiceImpl ding() 18:10:14 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:10:29 VERB PuppetServiceImpl ding() 18:10:29 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:10:46 VERB PuppetServiceImpl ding() 18:10:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:11:02 VERB PuppetServiceImpl ding() 18:11:02 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:11:21 VERB PuppetServiceImpl ding() 18:11:21 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:11:37 VERB PuppetServiceImpl ding() 18:11:37 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:11:53 VERB PuppetServiceImpl ding() 18:11:53 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:12:08 VERB PuppetServiceImpl ding() 18:12:08 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:12:23 VERB PuppetServiceImpl ding() 18:12:23 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:12:39 VERB PuppetServiceImpl ding() 18:12:39 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:12:55 VERB PuppetServiceImpl ding() 18:12:55 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:13:11 VERB PuppetServiceImpl ding() 18:13:11 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:13:28 VERB PuppetServiceImpl ding() 18:13:28 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:13:46 VERB PuppetServiceImpl ding() 18:13:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:14:01 VERB PuppetServiceImpl ding() 18:14:01 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:14:17 VERB PuppetServiceImpl ding() 18:14:17 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:14:32 VERB PuppetServiceImpl ding() 18:14:32 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:15:03 VERB PuppetServiceImpl ding() 18:15:03 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:15:23 VERB PuppetServiceImpl ding() 18:15:23 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:15:40 VERB PuppetServiceImpl ding() 18:15:40 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:15:59 VERB PuppetServiceImpl ding() 18:15:59 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:16:18 VERB PuppetServiceImpl ding() 18:16:18 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:16:36 VERB PuppetServiceImpl ding() 18:16:36 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:19:04 VERB PuppetServiceImpl ding() 18:19:04 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"}) 18:19:04 VERB PuppetServiceImpl stop() 18:19:04 VERB EventStreamManager stop() 18:19:04 VERB EventStreamManager this.onStreamingCallEnd() this.eventStream.on(finish) fired 18:19:04 VERB EventStreamManager connectPuppetEventToStreamingCall() unconnect() 13 callbacks 18:19:04 VERB PuppetDonut stop() 18:19:04 VERB StateSwitch off(pending) <- (false) 18:19:04 VERB PuppetDonut stopBridge() 18:19:04 VERB Bridge stop() 18:19:04 VERB CacheManager release() 18:19:04 VERB CacheManager releaseCache() 18:31:52 WARN Io initWebSocket() close event[1001: CloudFlare WebSocket proxy restarting] 18:31:52 VERB Io reconnect() 18:31:52 WARN Io reconnect() will reconnect after 0 s 18:31:52 VERB Io initWebSocket() 18:31:53 VERB Io initWebSocket() connected with protocol [io|0.0.1|ck910t2di0000j8tkadnl77nh] ```

7. Additional context

Add any other context about the problem here.

[bug]

su-chang commented 4 years ago

Heroku Logs

2020-04-19T05:39:41.875460+00:00 app[web.1]: 05:39:41 VERB PuppetHostie constructor() recover$().subscribe() next({"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000})
2020-04-19T05:39:42.144947+00:00 app[web.1]: 05:39:42 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_DONG(3), payload:"{"data":"recover$() CPR"}"})
2020-04-19T05:39:42.145122+00:00 app[web.1]: 05:39:42 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
2020-04-19T05:39:42.145266+00:00 app[web.1]: 05:39:42 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
2020-04-19T05:39:57.415594+00:00 app[web.1]: 05:39:57 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_DONG(3), payload:"{"data":"recover$() CPR"}"})
2020-04-19T05:39:57.415749+00:00 app[web.1]: 05:39:57 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
2020-04-19T05:39:57.415879+00:00 app[web.1]: 05:39:57 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
2020-04-19T05:40:12.416444+00:00 app[web.1]: 05:40:12 VERB Puppet recover$() heartbeatDing()
2020-04-19T05:40:12.417005+00:00 app[web.1]: 05:40:12 VERB PuppetHostie constructor() recover$().subscribe() next({"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000})
2020-04-19T05:40:13.172735+00:00 app[web.1]: 05:40:13 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_DONG(3), payload:"{"data":"recover$() CPR"}"})
2020-04-19T05:40:13.172952+00:00 app[web.1]: 05:40:13 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
2020-04-19T05:40:13.173212+00:00 app[web.1]: 05:40:13 VERB Puppet recover$() heartbeat: {"data":"onGrpcStreamEvent(EVENT_TYPE_DONG)","timeout":60000}
Disconnected from log stream. There may be events happening that you do not see here! Attempting to reconnect...
2020-04-19T05:54:37.960695+00:00 app[web.1]: 05:54:37 VERB StateSwitch <PuppetHostie> ready(off, false)
2020-04-19T05:54:37.961011+00:00 app[web.1]: 05:54:37 VERB StateSwitch <Wechaty> off(true) <- (pending)
2020-04-19T05:54:37.961448+00:00 app[web.1]: finis: exit code: 0
2020-04-19T05:54:37.962232+00:00 app[web.1]: 05:54:37 INFO RestartReporter finis(0, exit)
2020-04-19T05:54:37.962444+00:00 app[web.1]: 05:54:37 INFO RestartReporter finis() bot had been logout-ed
2020-04-19T05:54:37.962581+00:00 app[web.1]: 05:54:37 INFO RestartReporter finis() setTimeoutprocess.exit(), 10 * 1000)
2020-04-19T05:54:37.962686+00:00 app[web.1]: 05:54:37 INFO RestartReporter finis() setTimeout() going to exit with 0
2020-04-19T05:54:37.962857+00:00 app[web.1]: 05:54:37 INFO Wechaty <wechaty-puppet-hostie> stop() v0.39.8 is stoping ...
2020-04-19T05:54:37.963044+00:00 app[web.1]: 05:54:37 VERB StateSwitch <Wechaty> ready(off, false)
2020-04-19T05:54:38.044576+00:00 heroku[web.1]: State changed from up to crashed

Donut Logs

13:52:04 VERB IoClient onMessage(Message#Text[🗣Contact<Friday BOT>]     dong)
13:52:04 SILL Io ioMessage() is a nop function before be overwriten from cloud
13:52:05 VERB PuppetServiceImpl messagePayload()
13:52:05 VERB Puppet messagePayload(816559097714514524)
13:52:14 SILL Io start() setInterval() ws.ping()
13:52:19 VERB PuppetServiceImpl ding()
13:52:19 SILL PuppetDonut ding(recover$() CPR)
13:52:19 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:52:24 SILL Io start() setInterval() ws.ping()
13:52:32 SILL Wechaty start() setInterval() this timer is to keep Wechaty running...
13:52:34 SILL Io start() setInterval() ws.ping()
13:52:35 VERB PuppetServiceImpl ding()
13:52:35 SILL PuppetDonut ding(recover$() CPR)
13:52:35 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:52:44 SILL Io start() setInterval() ws.ping()
13:52:50 VERB PuppetServiceImpl ding()
13:52:50 SILL PuppetDonut ding(recover$() CPR)
13:52:50 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:52:54 SILL Io start() setInterval() ws.ping()
13:53:04 SILL Io start() setInterval() ws.ping()
13:53:05 VERB PuppetServiceImpl ding()
13:53:05 SILL PuppetDonut ding(recover$() CPR)
13:53:05 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:53:14 SILL Io start() setInterval() ws.ping()
13:53:21 VERB PuppetServiceImpl ding()
13:53:21 SILL PuppetDonut ding(recover$() CPR)
13:53:21 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:53:24 SILL Io start() setInterval() ws.ping()
13:53:34 SILL Io start() setInterval() ws.ping()
13:53:37 VERB PuppetServiceImpl ding()
13:53:37 SILL PuppetDonut ding(recover$() CPR)
13:53:37 VERB EventStreamManager grpcEmit(EVENT_TYPE_DONG[3], {"data":"recover$() CPR"})
13:53:44 SILL Io start() setInterval() ws.ping()
13:53:46 VERB PuppetServiceImpl messageSendText()
13:53:46 VERB PuppetDonut messageSendText("18131996049@chatroom", Der! I'm going to exit now, see you, bye!
BOT5 v0.2.42)
13:53:46 SILL request(SEND_TEXTMSG, [object Object])
13:53:46 VERB Donut(ffi-adapter) SendWeChatData(2,{"data":{"content":"Der! I'm going to exit now, see you, bye!\nBOT5 v0.2.42","to_wxid":"18131996049@chatroom"},"type":11036})
13:53:46 VERB ffi-adapter Backend.lib(0: "C:\Users\Administrator\Desktop\testPuppetDonut\wechaty\node_modules\@juzibot\wechaty-puppet-donut\dlls\WxLoader.dll")
13:53:46 VERB Bridge processEvent(RECV_TEXT_MSG)
13:53:46 VERB PuppetDonut onMessage({"at_user_list":[],"from_wxid":"wxid_4wkls7tu62ua12","is_pc":1,"msg":"Der! I'm going to exit now, see you, bye!\nBOT5 v0.2.42","msgid":"6623876563199914286","room_wxid":"18131996049@chatroom","timestamp":1587275626,"to_wxid":"18131996049@chatroom","wx_type":1})
13:53:46 VERB PuppetDonut contactRawPayload(wxid_4wkls7tu62ua12)
13:53:46 VERB Bridge contactRawPayload(wxid_4wkls7tu62ua12)
13:53:46 SILL Bridge contactRawPayload() cache HIT
13:53:46 VERB Message static load(6623876563199914286)
13:53:46 SILL Accessory #1063<Message> constructor()
13:53:46 VERB Message constructor(6623876563199914286) for class Message
13:53:46 VERB Message ready()
13:53:46 VERB Puppet messagePayload(6623876563199914286)
13:53:46 SILL Puppet messagePayloadCache(6623876563199914286) cache MISS
13:53:46 VERB PuppetDonut messageRawPayload(6623876563199914286)
13:53:46 VERB Bridge messageRawPayload(6623876563199914286)
13:53:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"6623876563199914286"})
13:53:46 VERB PuppetDonut messageRawPayloadParser()
13:53:46 SILL Puppet messagePayload(6623876563199914286) cache SET
13:53:46 VERB Room ready()
13:53:46 SILL Contact ready() @ Puppet#0<PuppetDonut>(donut-friday) with id="wxid_4wkls7tu62ua12"
13:53:46 SILL Contact ready() isReady() true
13:53:46 VERB IoClient onMessage(Message#Text[🗣Contact<Friday BOT>@👥Room<ChatOps - Friday BOT>]        Der! I'm going to exit now, see you, bye!
BOT5 v0.2.42)
13:53:46 SILL Io ioMessage() is a nop function before be overwriten from cloud
13:53:46 VERB PuppetServiceImpl messageSendText()
13:53:46 VERB PuppetDonut messageSendText("wxid_4wkls7tu62ua12", Der! I'm going to exit now, see you, bye!
BOT5 v0.2.42)
13:53:46 SILL request(SEND_TEXTMSG, [object Object])
13:53:46 VERB Donut(ffi-adapter) SendWeChatData(2,{"data":{"content":"Der! I'm going to exit now, see you, bye!\nBOT5 v0.2.42","to_wxid":"wxid_4wkls7tu62ua12"},"type":11036})
13:53:46 VERB ffi-adapter Backend.lib(0: "C:\Users\Administrator\Desktop\testPuppetDonut\wechaty\node_modules\@juzibot\wechaty-puppet-donut\dlls\WxLoader.dll")
13:53:46 VERB Bridge processEvent(RECV_TEXT_MSG)
13:53:46 VERB PuppetDonut onMessage({"at_user_list":[],"from_wxid":"wxid_4wkls7tu62ua12","is_pc":1,"msg":"Der! I'm going to exit now, see you, bye!\nBOT5 v0.2.42","msgid":"317212853680299920","room_wxid":"","timestamp":1587275626,"to_wxid":"wxid_4wkls7tu62ua12","wx_type":1})
13:53:46 VERB PuppetDonut contactRawPayload(wxid_4wkls7tu62ua12)
13:53:46 VERB Bridge contactRawPayload(wxid_4wkls7tu62ua12)
13:53:46 SILL Bridge contactRawPayload() cache HIT
13:53:46 VERB Message static load(317212853680299920)
13:53:46 SILL Accessory #1064<Message> constructor()
13:53:46 VERB Message constructor(317212853680299920) for class Message
13:53:46 VERB Message ready()
13:53:46 VERB Puppet messagePayload(317212853680299920)
13:53:46 SILL Puppet messagePayloadCache(317212853680299920) cache MISS
13:53:46 VERB PuppetDonut messageRawPayload(317212853680299920)
13:53:46 VERB Bridge messageRawPayload(317212853680299920)
13:53:46 VERB EventStreamManager grpcEmit(EVENT_TYPE_MESSAGE[2], {"messageId":"317212853680299920"})
13:53:46 VERB PuppetDonut messageRawPayloadParser()
13:53:46 SILL Puppet messagePayload(317212853680299920) cache SET
13:53:46 SILL Contact ready() @ Puppet#0<PuppetDonut>(donut-friday) with id="wxid_4wkls7tu62ua12"
13:53:46 SILL Contact ready() isReady() true
13:53:46 SILL Contact ready() @ Puppet#0<PuppetDonut>(donut-friday) with id="wxid_4wkls7tu62ua12"
13:53:46 SILL Contact ready() isReady() true
13:53:46 VERB IoClient onMessage(Message#Text[🗣Contact<Friday BOT>]     Der! I'm going to exit now, see you, bye!
BOT5 v0.2.42)
13:53:46 SILL Io ioMessage() is a nop function before be overwriten from cloud
13:53:47 VERB PuppetServiceImpl messagePayload()
13:53:47 VERB Puppet messagePayload(6623876563199914286)
13:53:47 VERB PuppetServiceImpl messagePayload()
13:53:47 VERB Puppet messagePayload(317212853680299920)
13:53:54 SILL Io start() setInterval() ws.ping()
13:53:57 VERB PuppetServiceImpl stop()
13:53:57 VERB EventStreamManager stop()
13:53:57 VERB EventStreamManager this.onStreamingCallEnd() this.eventStream.on(finish) fired
13:53:57 VERB EventStreamManager connectPuppetEventToStreamingCall() unconnect() 13 callbacks
13:53:57 VERB PuppetDonut stop()
13:53:57 SILL StateSwitch <PuppetDonut> off() is false
13:53:57 SILL StateSwitch <PuppetDonut> off() is false
13:53:57 VERB StateSwitch <PuppetDonut> off(pending) <- (false)
13:53:57 VERB PuppetDonut stopBridge()
13:53:57 SILL StateSwitch <PuppetDonut> on() is false
13:53:57 VERB Bridge stop()
13:53:57 VERB CacheManager release()
13:53:57 VERB CacheManager releaseCache()
13:53:57 SILL CacheManager releaseCache() closing caches ...
13:53:57 SILL CacheManager releaseCache() cache closed.
13:53:57 SILL StateSwitch <PuppetDonut> off() is pending
13:53:57 VERB StateSwitch <PuppetDonut> off(true) <- (pending)
13:54:04 SILL Io start() setInterval() ws.ping()
13:54:10 SILL Io initWebSocket() ws.on(message): {"name":"online","payload":"puppet-hostie"}
13:54:10 WARN Io UNKNOWN on(online): puppet-hostie
13:54:10 SILL Io initWebSocket() ws.on(message): {"name":"offline","payload":"puppet-hostie"}
13:54:10 WARN Io UNKNOWN on(offline): puppet-hostie
13:54:14 SILL Io start() setInterval() ws.ping()
13:54:24 SILL Io start() setInterval() ws.ping()
13:54:34 SILL Io start() setInterval() ws.ping()
13:54:37 SILL Io initWebSocket() ws.on(message): {"name":"online","payload":"puppet-hostie"}
13:54:37 WARN Io UNKNOWN on(online): puppet-hostie
13:54:37 SILL Io initWebSocket() ws.on(message): {"name":"offline","payload":"puppet-hostie"}
13:54:37 WARN Io UNKNOWN on(offline): puppet-hostie
13:54:44 SILL Io start() setInterval() ws.ping()
huan commented 4 years ago

Disconnected from log stream. There may be events happening that you do not see here! Attempting to reconnect... means that you have lost all the logs between the prev line and the next line.

Use heroku logs -t -a bot-friday for getting logs to your local terminal.