search

wechaty / wechaty-puppet-padplus

DEPRECATED: One puppet based on iPad protocal for Wechaty
https://wechaty.js.org/docs/puppet-services/
313 stars 64 forks source link

Error: can not get callback result of GET_CONTACT_SELF_INFO #318

Closed suntong closed 3 years ago

suntong commented 3 years ago

0. Report Issue Guide

  1. Please run the following command and check whether the problem has been fixed：
npm install wechaty-puppet-padlus@next

No.

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

1. Versions

2. Describe the bug

GRPC_GATEWAY connect timeout, cannot get anything, the first one being GET_CONTACT_SELF_INFO --

Error: can not get callback result of GET_CONTACT_SELF_INFO

3. To Reproduce

Steps to reproduce the behavior:

  1. run 'ding-dong-bot.js' from wechaty-getting-started/examples with wechaty-puppet-padplus
  2. wait for over 3 minutes
  3. GRPC_GATEWAY connect will timeout and print the following errors.

4. Expected behavior

GRPC_GATEWAY connect OK.

5. Actual behavior

GRPC_GATEWAY connect will timeout.

6. Full Output Logs

Set env WECHATY_LOG=silly in order to set log level to silly.

Show Logs ```shell $ WECHATY_LOG=silly node ding-dong-bot.js WECHATY_LOG=silly node index.js 23:26:42 SILL Puppet Config: WECHATY_LOG set level to silly 23:26:42 INFO Config registering process.on("unhandledRejection") for development/debug 23:26:42 VERB Config constructor() 23:26:43 VERB Wechaty constructor() 23:26:43 VERB StateSwitch constructor(Wechaty, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}") 23:26:43 VERB StateSwitch constructor(WechatyReady, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}") 23:26:43 VERB Wechaty on(scan, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty on(login, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty on(logout, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty on(message, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty on(error, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty on(friendship, listener) registering... listenerCount: 0 23:26:43 VERB Wechaty (default) start() v0.48.13 is starting... 23:26:43 VERB Wechaty id: ckh8m7aur00008zfufri5gwdb 23:26:43 SILL StateSwitch on() is false 23:26:43 SILL StateSwitch off() is true 23:26:43 VERB StateSwitch off(true) <- (true) 23:26:43 SILL StateSwitch on() is false 23:26:43 VERB StateSwitch on(pending) <- (false) 23:26:43 VERB MemoryCard constructor("default") 23:26:43 VERB MemoryCard getStorage() for storage type: N/A 23:26:43 VERB getStorage name: default, options: {"type":"file"} 23:26:43 VERB StorageFile constructor(default, ...) 23:26:43 VERB StorageBackend constructor(default, { type: file }) 23:26:43 VERB Wechaty initPuppet() 23:26:43 VERB MemoryCard multiplex(puppet) 23:26:43 VERB MemoryCard static multiplex(MemoryCard, puppet) 23:26:43 VERB PuppetManager resolve({puppet: wechaty-puppet-padplus, puppetOptions: undefined}) 23:26:43 VERB PuppetManager resolveName(wechaty-puppet-padplus) 23:26:43 VERB PuppetManager checkModule(wechaty-puppet-padplus) 23:26:43 SILL PuppetManager checkModule() wechaty-puppet-padplus installed version 0.7.41 satisfied range ^0.7.30 23:26:43 SILL Config PADPLUS_LOG set level to silly 23:26:43 VERB Puppet constructor({}) #0 23:26:43 VERB StateSwitch constructor(PuppetPadplus, "{"log":{"enableTimestamp":true,"logLevel":5,"prefixFilter":{}}}") 23:26:43 VERB MemoryCard constructor(undefined) 23:26:43 VERB MemoryCard getStorage() for storage type: N/A 23:26:43 VERB MemoryCard load() from storage: N/A 23:26:43 VERB MemoryCard load() no storage 23:26:43 VERB Puppet constructor() watchdog timeout set to 60 seconds 23:26:43 VERB HotImport callerResolve(., /path/to/node_modules/wechaty-puppet/dist/src/puppet.js) 23:26:43 SILL HotImport callerResolve() callsites() file=/path/to/node_modules/hot-import/dist/src/hot-import.js, type=Object 23:26:43 SILL HotImport callerResolve() callsites() file=/path/to/node_modules/wechaty-puppet/dist/src/puppet.js, type=null 23:26:43 SILL HotImport callerResolve() callsites() file=/path/to/node_modules/wechaty-puppet-padplus/dist/src/puppet-padplus.js, type=null 23:26:43 SILL HotImport callerResolve() callerFile=/path/to/node_modules/wechaty-puppet-padplus/dist/src/puppet-padplus.js 23:26:43 VERB Puppet constructor() childClassPath=/path/to/node_modules/wechaty-puppet-padplus/dist/src 23:26:43 VERB PadplusManager constructor() 23:26:43 VERB Puppet constructor() memory.load() done 23:26:43 VERB Puppet setMemory() 23:26:43 VERB Wechaty initPuppetEventBridge(Puppet#0(default)) 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(friendship) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(login) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(logout) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(message) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(room-invite) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(room-join) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(room-leave) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(room-topic) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(scan) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(dirty) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(dong) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(error) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(heartbeat) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(ready) (listenerCount:0) registering... 23:26:43 VERB Wechaty initPuppetEventBridge() puppet.on(reset) (listenerCount:0) registering... 23:26:43 VERB Wechaty wechatifyUserModules(Puppet#0(default)) 23:26:43 INFO PuppetPadplus start() 23:26:43 SILL StateSwitch on() is false 23:26:43 SILL StateSwitch on() is false 23:26:43 VERB StateSwitch on(pending) <- (false) 23:26:43 VERB PadplusManager on(scan, function) registered 23:26:43 VERB PadplusManager on(login, function) registered 23:26:43 VERB PadplusManager on(message, function) registered 23:26:43 VERB PadplusManager on(ready, function) registered 23:26:43 VERB PadplusManager on(reset, function) registered 23:26:43 VERB PadplusManager on(heartbeat, function) registered 23:26:43 VERB PadplusManager on(logout, function) registered 23:26:43 VERB PadplusManager on(room-leave, function) registered 23:26:43 VERB PadplusManager on(error, function) registered 23:26:43 SILL PadplusManager start() 23:26:43 SILL GRPC_GATEWAY init() 23:26:43 SILL GRPC_GATEWAY initSelf() 23:26:43 SILL GRPC_GATEWAY initGrpcGateway() 23:26:44 VERB MemoryCard get(WECHATY_PUPPET_PADPLUS) 23:26:44 SILL PadplusUser initInstance() 23:26:44 SILL RequestClient request() 23:26:44 SILL DedupeApi dedupe() no need to dedupe api INIT. 23:26:44 SILL GRPC_GATEWAY GRPC Request ApiType: INIT 23:26:45 SILL ==P==A==D==P==L==U==S====P==A==D==P==L==U==S== 23:26:45 SILL GRPC_GATEWAY responseType: AUTO_LOGIN, data : {"uin":2849091348,"online":true,"wechatUser":{"headImgUrl":"http://wx.qlogo.cn/mmhead/Iic9WLWEQMg0EftnmZ8p4wwFU2YkXiaibRQhZMEjwibxbsjEbHia8GzZfZA/0","nickName...,"verifyFlag":0}} 23:26:45 SILL ==P==A==D==P==L==U==S====P==A==D==P==L==U==S== 23:26:45 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:26:45 SILL PadplusManager setContactAndRoomData() 23:26:45 VERB PadplusManager setContactAndRoomData() can not proceed due to no cache. 23:26:45 SILL PadplusManager user name : { uin: ..., online: true, wechatUser: { headImgUrl: 'http://wx.qlogo.cn/mmhead/Iic9WLWEQMg0EftnmZ8p4wwFU2YkXiaibRQhZMEjwibxbsjEbHia8GzZfZA/0', nickName..., uin: ..., userName: 'wxid_dt09l3obz67v22', alias..., verifyFlag: 0 } } 23:26:45 VERB PadplusManager init cache manager 23:26:45 VERB CacheManager init() 23:26:45 VERB CacheManager initCache(wxid_dt09l3obz67v22,{"baseDir":"/path/to/mycode","type":"flashStore"}) 23:26:45 VERB CacheManager initCache() inited [object Promise] Contacts, cachedir="/home/me/.wechaty/puppet-padplus-cache/flash-store-v0.14/" 23:26:45 VERB Puppet login(wxid_dt09l3obz67v22) 23:26:45 VERB Contact load(wxid_dt09l3obz67v22) init pool 23:26:45 SILL Contact constructor(wxid_dt09l3obz67v22) 23:26:45 SILL Contact ready() @ Puppet#0(default) with id="wxid_dt09l3obz67v22" 23:26:45 SILL Puppet contactPayload(wxid_dt09l3obz67v22) cache MISS 23:26:45 SILL PadplusManager contactSelfInfo() 23:26:45 VERB PadplusContact getContactSelfInfo() 23:26:45 SILL RequestClient request() 23:26:45 SILL DedupeApi dedupe() no need to dedupe api GET_CONTACT_SELF_INFO. 23:26:45 SILL GRPC_GATEWAY GRPC Request ApiType: GET_CONTACT_SELF_INFO 23:26:45 SILL PadplusManager syncContacts() 23:26:45 VERB PadplusContact syncContacts() 23:26:45 SILL RequestClient request() 23:26:45 SILL DedupeApi dedupe() no need to dedupe api SYNC_CONTACT. 23:26:45 SILL GRPC_GATEWAY GRPC Request ApiType: SYNC_CONTACT 23:26:45 SILL PuppetPadplus contactRawPayloadParser() 23:26:45 SILL Puppet contactPayload(wxid_dt09l3obz67v22) cache SET 23:26:46 SILL PadplusUser init success 23:26:46 VERB MemoryCard get(WECHATY_PUPPET_PADPLUS) 23:26:46 SILL StateSwitch on() is pending 23:26:46 VERB StateSwitch on(true) <- (pending) 23:26:46 VERB Wechaty on(heartbeat, listener) registering... listenerCount: 0 23:26:46 SILL StateSwitch on() is pending 23:26:46 VERB StateSwitch on(true) <- (pending) 23:27:16 SILL GRPC_GATEWAY keepHeartbeat() 23:27:16 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT 23:27:16 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:27:16 SILL Wechaty memoryCheck() free: 392 MB, require: 4 MB 23:27:16 SILL PadplusManager setContactAndRoomData() 23:27:16 SILL PadplusManager setContactAndRoomData() initialize contact and room data. 23:27:46 SILL GRPC_GATEWAY keepHeartbeat() 23:27:46 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT 23:27:46 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:27:46 SILL Wechaty memoryCheck() free: 374 MB, require: 4 MB 23:27:46 SILL PadplusManager setContactAndRoomData() 23:27:47 SILL PadplusManager setContactAndRoomData() found contact, room, friend data no change. 23:28:16 SILL GRPC_GATEWAY keepHeartbeat() 23:28:16 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT 23:28:17 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:28:17 SILL Wechaty memoryCheck() free: 369 MB, require: 4 MB 23:28:17 SILL PadplusManager setContactAndRoomData() 23:28:17 SILL PadplusManager setContactAndRoomData() found contact, room, friend data no change. 23:28:47 SILL GRPC_GATEWAY keepHeartbeat() 23:28:47 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT 23:28:47 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:28:47 SILL Wechaty memoryCheck() free: 368 MB, require: 4 MB 23:28:47 SILL PadplusManager setContactAndRoomData() 23:28:47 SILL PadplusManager setContactAndRoomData() found contact, room, friend data no change. 23:29:17 SILL GRPC_GATEWAY keepHeartbeat() 23:29:17 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT 23:29:17 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:29:17 SILL Wechaty memoryCheck() free: 373 MB, require: 4 MB 23:29:17 SILL PadplusManager setContactAndRoomData() 23:29:18 SILL PadplusManager setContactAndRoomData() found contact, room, friend data no change. 23:29:45 ERR GRPC_GATEWAY ApiType: GET_CONTACT_SELF_INFO request timeout, traceId: eb74d027-6bed-44ed-9329-92289dae4b4c 23:29:45 ERR Config ########################### 23:29:45 ERR Config unhandledRejection: Error: can not get callback result of GET_CONTACT_SELF_INFO at PadplusContact. (/path/to/node_modules/wechaty-puppet-padplus/dist/src/padplus-manager/api-request/contact.js:148:23) at Generator.next () at fulfilled (/path/to/node_modules/wechaty-puppet-padplus/dist/src/padplus-manager/api-request/contact.js:5:58) [object Promise] 23:29:45 ERR Config ########################### 23:29:45 ERR Config process.on(unhandledRejection) promise.catch(can not get callback result of GET_CONTACT_SELF_INFO) Config Error: can not get callback result of GET_CONTACT_SELF_INFO at PadplusContact. (/path/to/node_modules/wechaty-puppet-padplus/dist/src/padplus-manager/api-request/contact.js:148:23) at Generator.next () at fulfilled (/path/to/node_modules/wechaty-puppet-padplus/dist/src/padplus-manager/api-request/contact.js:5:58) 23:29:47 SILL GRPC_GATEWAY keepHeartbeat() 23:29:47 SILL GRPC_GATEWAY GRPC Request ApiType: HEARTBEAT (node:2788019) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 1) 23:29:47 SILL GRPC_GATEWAY throttleQueue emit heartbeat. 23:29:47 SILL Wechaty memoryCheck() free: 369 MB, require: 4 MB 23:29:47 SILL PadplusManager setContactAndRoomData() 23:29:48 SILL PadplusManager setContactAndRoomData() found contact, room, friend data no change. ```

7. Additional context

Exactly same machine and same code, using a different user will not get into such problem. The differences between the two is mainly,

Also, confirmed that it is puppet-padplus's problem, because if I do

WECHATY_PUPPET=wechaty-puppet-puppeteer node ding-dong-bot.js

It works fine for my normal account, which is the one that has a huge WX contact list.

[bug]

suntong commented 3 years ago

Previously all were using cached login.

After I somehow triggered login from my mobile phone again, the connection issue then gone.