search

wechaty / puppet-service

Wechaty Puppet Provider for providing/consuming the Wechaty Puppet Service
https://paka.dev/npm/wechaty-puppet-service
Apache License 2.0
70 stars 18 forks source link

Question about this.onStreamingCallEnd() #44

Open su-chang opened 4 years ago

su-chang commented 4 years ago 
18:12:02 VERB EventStreamManager this.onStreamingCallEnd() this.eventStream.on(cancelled) fired with arguments: {}
18:12:02 VERB EventStreamManager connectPuppetEventToStreamingCall() unconnect() 13 callbacks
18:12:03 SILL Io initWebSocket() ws.on(message): {"name":"jsonrpc","payload":{"id":-9007199254740445,"jsonrpc":"2.0","method":"getHostieGrpcPort"}}
18:12:03 INFO Io on(jsonrpc): [object Object]
18:12:03 VERB Io on(jsonrpc) send({"id":-9007199254740445,"jsonrpc":"2.0","result":8803})
18:12:03 SILL Io send({"name":"jsonrpc","payload":{"id":-9007199254740445,"jsonrpc":"2.0","result":8803}})
18:12:04 SILL Io initWebSocket() ws.on(message): {"name":"sys","payload":"roger"}
18:12:04 VERB PuppetServiceImpl start()
18:12:04 VERB PuppetDonut start()
18:12:04 SILL StateSwitch <PuppetDonut> on() is true
18:12:04 WARN PuppetDonut start() is called on a ON puppet. await ready(on) and return.
18:12:04 VERB StateSwitch <PuppetDonut> ready(on, false)
18:12:04 SILL StateSwitch <PuppetDonut> ready(on, false) resolved.
18:12:04 VERB PuppetServiceImpl event()
18:12:04 VERB EventStreamManager start(stream)
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() for Puppet#0<PuppetDonut>(donut-docker-002)
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(friendship) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(login) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(logout) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(message) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-invite) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-join) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-leave) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(room-topic) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(scan) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(dong) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(error) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(heartbeat) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(ready) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() this.puppet.on(reset) (listenerCount:0) registering...
18:12:04 VERB EventStreamManager onStreamingCallEnd(callback)
18:12:04 VERB EventStreamManager start() puppet is logged in, emit a login event for downstream
18:12:04 VERB Puppet selfId()
18:12:04 VERB EventStreamManager grpcEmit(EVENT_TYPE_LOGIN[25], {"contactId":"wxid_8kg1wdu3jvk322"})
18:12:04 VERB EventStreamManager this.onStreamingCallEnd() this.eventStream.on(cancelled) fired with arguments: {}
18:12:04 VERB EventStreamManager connectPuppetEventToStreamingCall() unconnect() 13 callbacks

I do not where emit the cancelled event, and why does it happened?

Could you please provide some advices for it? @huan

Thank you very much.

Other Related Log

18:11:48 INFO Listening on port 44521
18:11:48 INFO Connected to stream blender.
18:11:50 INFO BOT LOGIN: Contact<疫情小助手>login
18:11:50 INFO loginListener 【疫情小助手】login. id: 5ecf8e44ebcc920074db6cf7, wxid: wxid_8kg1wdu3jvk322, weixin: null
18:12:01 INFO BotAction syncContact() contact list from wechaty has 512 contacts
18:12:01 INFO BotAction syncContact() contact list from db has 512 contacts
18:12:01 INFO BotAction syncContact() add contact 0 in total.
18:12:01 INFO BotAction syncContact() update contact 0 in total.
18:12:01 WARN Wechaty self() DEPRECATED. use userSelf() instead.
18:12:02 INFO BotAction syncRoom() room list from wechaty has 22 in total.
18:12:02 INFO BotAction syncRoom() room list from db has 22 in total.
18:12:02 INFO BotAction Processed 10/22 rooms.
18:12:02 INFO BotAction Processed 20/22 rooms.
18:12:02 INFO logoutListener BOT LOGOUT: 疫情小助手 logout
18:12:02 ERR BotAction syncRoom() error happened Error: 2 UNKNOWN: Stream removed
    at Object.exports.createStatusError (/xiaoju-bot/node_modules/grpc/src/common.js:91:15)
    at Object.onReceiveStatus (/xiaoju-bot/node_modules/grpc/src/client_interceptors.js:1209:28)
    at InterceptingListener._callNext (/xiaoju-bot/node_modules/grpc/src/client_interceptors.js:568:42)
    at InterceptingListener.onReceiveStatus (/xiaoju-bot/node_modules/grpc/src/client_interceptors.js:618:8)
    at callback (/xiaoju-bot/node_modules/grpc/src/client_interceptors.js:847:24)
18:12:02 ERR PuppetHostie stop() this.grpcClient.stop() rejection: 2 UNKNOWN: Stream removed
18:12:04 INFO BOT LOGIN: Contact<疫情小助手>login
18:12:04 INFO loginListener 【疫情小助手】login. id: 5ecf8e44ebcc920074db6cf7, wxid: wxid_8kg1wdu3jvk322, weixin: null
huan commented 4 years ago

If I remember right, the canceled event will be fired when the GRPC connection lost.

It was emitted by the GRPC itself, and we should try again for this case.

CANCELLED | 1 | The operation was cancelled, typically by the caller.

See: https://grpc.github.io/grpc/core/md_doc_statuscodes.html

Have there any problems with the re-connect /retry/recovery functions of our code?

su-chang commented 4 years ago

Thank you for your response very much!

There are some detail info about this issue: When hostie server side run in docker container, and the docker restart, the method stop() in puppet-hostie will emit logout event, and when it restart, UNKNOWN: Stream removed happened, maybe this problem is due to GRPC connection lost.

How to make hostie re-connect smoothly?

huan commented 4 years ago

In order to make the hostie re-connect smoothly, I believe that we should close the GRPC connect gracefully when we stop our puppet.

PR will be welcome, and please let me know if there has any issues with the recovery code with the current codebase.