error_listener: get room timeout

[why2lyj]

After merged PR#56

start ding-dong-bot.py demo for a while, program begins to get bugs. Error msg as follow:

INFO wechaty.py receive event <(<Status.INTERNAL: 13>, 'get room timeout', None) INFO wechaty.py receive event <(<Status.INTERNAL: 13>, 'get room timeout', None) INFO wechaty.py receive event <(<Status.INTERNAL: 13>, 'get room timeout', None) INFO wechaty.py receive event <(<Status.INTERNAL: 13>, 'get room timeout', None) INFO wechaty.py receive event <(<Status.INTERNAL: 13>, 'get room timeout', None)

My wechat information as below for your reference:

10+rooms, 150+ contacters per room, every rooms is chatting all the time. Chatting msg include mini program, pictures, and so on.

[wj-Mcat]

It seems that this bug occurs at specific scene. We will keep a long watchful eye on it. We will try to make this issue be reappeared.

[why2lyj]

2020-06-01 09:10:35 ERROR base_events.py Exception in callback AsyncIOEventEmitter._emit_run.._callback(<Task finishe...meout', None)>) at /usr/local/lib/python3.7/site-packages/pyee/_asyncio.py:55 handle: <Handle AsyncIOEventEmitter._emit_run.._callback(<Task finishe...meout', None)>) at /usr/local/lib/python3.7/site-packages/pyee/_asyncio.py:55> Traceback (most recent call last): File "/usr/local/lib/python3.7/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/local/lib/python3.7/site-packages/pyee/_asyncio.py", line 62, in _callback self.emit('error', exc) File "/usr/local/lib/python3.7/site-packages/pyee/_base.py", line 111, in emit self._emit_handle_potential_error(event, args[0] if args else None) File "/usr/local/lib/python3.7/site-packages/pyee/_base.py", line 83, in _emit_handle_potential_error raise error File "/usr/local/lib/python3.7/site-packages/wechaty/wechaty.py", line 473, in room_leave_listener await room.ready(force_sync=True) File "/usr/local/lib/python3.7/site-packages/wechaty/user/room.py", line 227, in ready self.payload = await self.puppet.room_payload(self.room_id) File "/usr/local/lib/python3.7/site-packages/wechaty_puppet_hostie/puppet.py", line 569, in room_payload response = await self.puppet_stub.room_payload(id=room_id) File "/usr/local/lib/python3.7/site-packages/chatie_grpc/wechaty.py", line 940, in room_payload "/wechaty.Puppet/RoomPayload", request, RoomPayloadResponse, File "/usr/local/lib/python3.7/site-packages/betterproto/init.py", line 1019, in _unary_unary response = await stream.recv_message() File "/usr/local/lib/python3.7/site-packages/grpclib/client.py", line 387, in recv_message await self.recv_initial_metadata() File "/usr/local/lib/python3.7/site-packages/grpclib/client.py", line 355, in recv_initial_metadata self._raise_for_grpc_status(headers_map) File "/usr/local/lib/python3.7/site-packages/grpclib/client.py", line 316, in _raise_for_grpc_status raise GRPCError(status, message, details) grpclib.exceptions.GRPCError: (<Status.INTERNAL: 13>, 'get room timeout', None)

I ignore puppet even belong to 'error' and got this issue detail.

@wj-Mcat I believe we need @huan pay more attention to this issue

[huan]

Thanks for reporting this issue, it seems that the problem highly depends on your bot code.

Please provide a minimum code snip for reproducing your problem, and describe the steps in detail so that your case can be understood and investigated.

Please understand that we will not be able to resolve an issue if we can not reproduce it.

[why2lyj]

Just run ding-dong-bot.py without any change

[huan]

~/python-wechaty-getting-started$ make bot
python3 examples/ding-dong-bot.py
2020-06-01 14:06:39,671 - Wechaty - INFO - on() listen event <message> with <<function on_message at 0x7f46e2d787a0>>
2020-06-01 14:06:39,672 - Wechaty - INFO - init_puppet_event_bridge() <<wechaty_puppet_hostie.puppet.HostiePuppet object at 0x7f46e1a7ab90>>
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(dong) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(error) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(heart-beat) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(ready) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - receive <reset> event <%s>
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(reset) (listenerCount:0) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(friendship) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(login) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(logout) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(message) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(room-invite) (listenerCount:1) registering...
2020-06-01 14:06:39,672 - Wechaty - INFO - initPuppetEventBridge() puppet.on(room-join) (listenerCount:1) registering...
2020-06-01 14:06:39,673 - Wechaty - INFO - initPuppetEventBridge() puppet.on(room-leave) (listenerCount:1) registering...
2020-06-01 14:06:39,673 - Wechaty - INFO - initPuppetEventBridge() puppet.on(room-topic) (listenerCount:1) registering...
2020-06-01 14:06:39,673 - Wechaty - INFO - initPuppetEventBridge() puppet.on(scan) (listenerCount:1) registering...
2020-06-01 14:06:39,673 - Wechaty - INFO - starting ...
2020-06-01 14:06:40,310 - Wechaty - INFO - receive <login> event <EventLoginPayload(contact_id='wxid_a8d806dzznm822')>
2020-06-01 14:06:40,314 - Contact - INFO - load contact <Contact <Huan LI (李卓桓)>>
2020-06-01 14:06:48,324 - Contact - INFO - load contact <Contact <Huan (李卓桓)>>
2020-06-01 14:06:48,324 - Wechaty - INFO - receive message <talker Contact <Huan (李卓桓)>, say to contact <Contact <Huan LI (李卓桓)>>, ding>
2020-06-01 14:06:48,324 - Message - INFO - say() <dong>
2020-06-01 14:06:48,869 - Message - INFO - say() <<wechaty_puppet.file_box.file_box.FileBox object at 0x7f46df27fd10>>
2020-06-01 14:06:52,876 - Contact - INFO - load contact <Contact <Powerhorse>>
2020-06-01 14:06:52,883 - Wechaty - INFO - receive message <room <Room <海福会>>, talker Contact <Powerhorse>, say to contact <Contact <>>, >
2020-06-01 14:06:54,144 - Contact - INFO - load contact <Contact <文利>>
2020-06-01 14:06:54,144 - Wechaty - INFO - receive message <room <Room <海福会>>, talker Contact <文利>, say to contact <Contact <>>, 这都一样[呲牙]>

Unfortunately, I can run the latest code from our python-wechaty-getting-started without any problem.

It works like a charm. 🎉

[why2lyj]

Yes, I can run it as well, but after a while it will hit the issue, and I don't think I'm the special one, I'm sure someone will get the same issue in the future as well, good to open this case, btw, my currently solution is ignore error puppet in wechaty-puppet

[huan]

@why2lyj Thank you very much for the additional information, that's very important!

Let's keep this issue open and to collect more feedback to see if we can get any reproducible steps.

[wj-Mcat]

We have fix continuous error event bugs. Please keep eyes on #79 . After it is merged, you can update wechaty version. Thank you for your issues.

[wj-Mcat]

Please install the latest python-wechaty version. And check if you can recurrence this issues. Waiting for your detail response. 🔥 🔥

[why2lyj]

Please install the latest python-wechaty version. And check if you can recurrence this issues. Waiting for your detail response.

let's close this issue, it's not happened any more after new version.