juzibot / donut-tester

40 stars 4 forks source link

The same message trigger on('message', ...) function twice. Reproduced in both nodejs and java projects. #71

Open Charles-Wu-Chen opened 3 years ago

Charles-Wu-Chen commented 3 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: Tried, but same issie.

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

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

1. Versions

2. Describe the bug

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

When ONE message send to the bot, the same message triggered on('message', ...) function twice.

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:

Follow the example in https://github.com/juzibot/donut-tester README.md. and use token puppet_donut_xxxxx

  1. set up donut.js in package.json. "donut": "cross-env WECHATY_LOG=verbose nodemon -w examples/ examples/donut.ts"
  2. run 'npm run donut'
  3. set ONLY ONE message to the bot.

4. Expected behavior

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

The test message shall only trigger on('message', ...) function only once and print only once in the log

5. Actual behavior

If applicable, add screenshots to help explain your problem. But do not paste log screenshots here. The same message print out twice and with exact same time and contents

15:31:22 VERB PuppetHostie contactRawPayload(wxid_1194601945911) 15:31:22 VERB PuppetHostie contactRawPayload(wxid_1194601945911) message: {"domain":null,"_events":{},"_eventsCount":0,"id":"1638160247976197174","payload":{"filename":"","fromId":"wxid_1194601945911","id":"1638160247976197174","mentionIdList":[],"roomId":"","text":"test","timestamp":1607747481000,"toId":"wxid_37gn4v1xgwvf22","type":7}} 15:31:22 VERB Puppet selfId() message: {"domain":null,"_events":{},"_eventsCount":0,"id":"1638160247976197174","payload":{"filename":"","fromId":"wxid_1194601945911","id":"1638160247976197174","mentionIdList":[],"roomId":"","text":"test","timestamp":1607747481000,"toId":"wxid_37gn4v1xgwvf22","type":7}} 15:31:22 VERB Puppet selfId()

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: 15:30:07 VERB PuppetManager resolveName(wechaty-puppet-hostie) 15:30:07 VERB PuppetManager checkModule(wechaty-puppet-hostie) 15:30:07 VERB Puppet constructor({"token":"xxxxx"}) #0 15:30:07 VERB StateSwitch constructor(PuppetHostie, "{"log":{"enableTimestamp":true,"logLevel":4,"prefixFilter":{}}}") 15:30:07 VERB MemoryCard constructor(undefined) 15:30:07 VERB MemoryCard getStorage() for storage type: N/A 15:30:07 VERB MemoryCard load() from storage: N/A 15:30:07 VERB MemoryCard load() no storage 15:30:07 VERB Puppet constructor() watchdog timeout set to 60 seconds 15:30:07 VERB HotImport callerResolve(., /Users/wuc/nodejsproject/wechaty-getting-started/node_modules/wechaty-puppet/dist/src/puppet.js) 15:30:07 VERB Puppet constructor() childClassPath=/Users/wuc/nodejsproject/wechaty-getting-started/node_modules/wechaty-puppet-hostie/dist/src/client 15:30:07 VERB Puppet setMemory() 15:30:07 VERB Wechaty initPuppetEventBridge(Puppet#0()) 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(friendship) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(login) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(logout) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(message) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(room-invite) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(room-join) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(room-leave) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(room-topic) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(scan) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(dirty) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(dong) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(error) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(heartbeat) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(ready) (listenerCount:0) registering... 15:30:07 VERB Wechaty initPuppetEventBridge() puppet.on(reset) (listenerCount:0) registering... 15:30:07 VERB Wechaty wechatifyUserModules(Puppet#0()) 15:30:07 VERB PuppetHostie start() 15:30:07 VERB StateSwitch on(pending) <- (false) 15:30:07 VERB PuppetHostie startGrpcClient() 15:30:07 VERB PuppetHostie discoverHostieIp(xxxxx) 15:30:08 VERB PuppetHostie startGrpcStream() 15:30:09 VERB StateSwitch on(true) <- (pending) 15:30:09 VERB Wechaty on(heartbeat, listener) registering... listenerCount: 0 15:30:09 VERB StateSwitch on(true) <- (pending) 15:30:09 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_LOGIN(25), payload:"{"contactId":"wxid_37gn4v1xgwvf22"}"}) 15:30:09 VERB Contact load(wxid_37gn4v1xgwvf22) init pool 15:30:09 VERB PuppetHostie contactRawPayload(wxid_37gn4v1xgwvf22) user: {"domain":null,"_events":{},"_eventsCount":0,"id":"wxid_37gn4v1xgwvf22","payload":{"address":" ","alias":"","avatar":"http://wx.qlogo.cn/mmhead/d2fJZTzRTumiajwGIibXD9ATVabOxibh6ShfLib6feIiahh8Rfs62iblcatQ/0","city":"","corporation":"","coworker":false,"description":"","friend":false,"gender":2,"id":"wxid_37gn4v1xgwvf22","name":"机器人","phone":[],"province":"","signature":"","star":false,"title":"","type":1,"weixin":""}} 15:30:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"}) 15:30:21 VERB StateSwitch on(true) <- (false) 15:30:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_READY(23), payload:"{"data":"ready"}"}) 15:30:21 VERB StateSwitch on(true) <- (true) 15:30:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]"}"}) 15:30:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object]","timeout":60000}"}) 15:30:51 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object]"}"}) 15:30:51 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object]","timeout":60000}"}) 15:31:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object]"}"}) 15:31:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_HEARTBEAT(1), payload:"{"data":"[object Object]","timeout":60000}"}) 15:31:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"1638160247976197174"}"}) 15:31:21 VERB Message static load(1638160247976197174) 15:31:21 VERB Message constructor(1638160247976197174) for class WechatifiedMessage 15:31:21 VERB Message ready() 15:31:21 VERB Puppet messagePayload(1638160247976197174) 15:31:21 VERB PuppetHostie messageRawPayload(1638160247976197174) 15:31:21 VERB PuppetHostie onGrpcStreamEvent({type:EVENT_TYPE_MESSAGE(2), payload:"{"messageId":"1638160247976197174"}"}) 15:31:21 VERB Message static load(1638160247976197174) 15:31:21 VERB Message constructor(1638160247976197174) for class WechatifiedMessage 15:31:21 VERB Message ready() 15:31:21 VERB Puppet messagePayload(1638160247976197174) 15:31:21 VERB PuppetHostie messageRawPayload(1638160247976197174) 15:31:22 VERB Contact load(wxid_1194601945911) init pool 15:31:22 VERB PuppetHostie contactRawPayload(wxid_1194601945911) 15:31:22 VERB PuppetHostie contactRawPayload(wxid_1194601945911) message: {"domain":null,"_events":{},"_eventsCount":0,"id":"1638160247976197174","payload":{"filename":"","fromId":"wxid_1194601945911","id":"1638160247976197174","mentionIdList":[],"roomId":"","text":"test","timestamp":1607747481000,"toId":"wxid_37gn4v1xgwvf22","type":7}} 15:31:22 VERB Puppet selfId() message: {"domain":null,"_events":{},"_eventsCount":0,"id":"1638160247976197174","payload":{"filename":"","fromId":"wxid_1194601945911","id":"1638160247976197174","mentionIdList":[],"roomId":"","text":"test","timestamp":1607747481000,"toId":"wxid_37gn4v1xgwvf22","type":7}} 15:31:22 VERB Puppet selfId() ```

7. Additional context

Add any other context about the problem here. The similar behavior can be reproduce in java project as well. no other logic and plugin involved. it is just the simplest get-started project with donut token. Does anyone have similar issue as this?

[bug]