Unexpected Exit: WebSocket reset can not be recovered automatically #160

huan · 2018-08-22T09:16:21Z

10:09:35 WARN PadchatRpc initWebSocket() ws.on(close) code: 1005, reason:
10:09:35 VERB PuppetPadchat startManager() manager.on(reconnect) for ws.on(close, 1005)
10:09:35 SILL PadchatRpc initWebSocket() Promise() ws.on(close)
10:09:36 VERB PuppetPadchat reconnect(), retry attempt left: 6
10:09:36 VERB PadchatRpc reconnect()
10:09:36 VERB PadchatRpc initWebSocket()
10:09:36 SILL PadchatRpc initWebSocket() Promise() ws.on(open)
10:09:36 SILL PadchatRpc rpcCall(init, [])
10:09:36 SILL PadchatRpc pre login rpcCall(init, [])
10:13:22 SILL Puppet constructor() watchdog.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
10:13:22 SILL Puppet constructor() this.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
10:13:22 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: {"data":"ws.on(message)","timeout":240000}
10:13:22 VERB Puppet reset({"data":"ws.on(message)","timeout":240000})
10:13:22 SILL StateSwitch <PuppetPadchat> off() is false
10:13:22 VERB PuppetPadchat stop()
10:13:22 SILL StateSwitch <PuppetPadchat> off() is false
10:13:22 SILL StateSwitch <PuppetPadchat> off() is false
10:13:22 VERB StateSwitch <PuppetPadchat> off(pending) <- (false)
10:13:22 VERB PuppetPadchat logout()
10:13:22 SILL Contact ready() @ Puppet#0<PuppetPadchat>(ding-dong-bot)/PuppetPadchat#0
10:13:22 SILL Contact ready() isReady() true
10:13:22 VERB PuppetPadchatManager logout()
10:13:22 VERB PuppetPadchatManager releaseCache()
10:13:22 SILL PuppetPadchatManager releaseCache() closing caches ...
10:13:22 VERB ContactSelf name()
李卓桓 logouted

The text was updated successfully, but these errors were encountered:

huan · 2018-08-24T15:27:10Z

This problem occurred again when watchdog timeout.

19:47:40 SILL Puppet constructor() watchdog.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
19:47:40 SILL Puppet constructor() this.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
19:47:40 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: {"data":"ws.on(message)","timeout":240000}
19:47:40 VERB Puppet reset({"data":"ws.on(message)","timeout":240000})
19:47:40 SILL StateSwitch <PuppetPadchat> off() is false
19:47:40 VERB PuppetPadchat stop()
19:47:40 SILL StateSwitch <PuppetPadchat> off() is false
19:47:40 SILL StateSwitch <PuppetPadchat> off() is false
19:47:40 VERB StateSwitch <PuppetPadchat> off(pending) <- (false)
19:47:40 VERB PuppetPadchat logout()
19:47:40 SILL Contact ready() @ Puppet#0<PuppetPadchat>(ding-dong-bot)/PuppetPadchat#0
19:47:40 SILL Contact ready() isReady() true
19:47:40 VERB PuppetPadchatManager logout()
19:47:40 VERB PuppetPadchatManager releaseCache()
19:47:40 SILL PuppetPadchatManager releaseCache() closing caches ...
19:47:40 VERB ContactSelf name()
李卓桓 logouted

huan · 2018-08-25T05:46:46Z

All the above logs caused the Wechaty program exit at last.

bitwater · 2018-08-29T02:31:21Z

00:59:53 WARN PadchatRpc initWebSocket() ws.on(close) code: 1006, reason:
(node:20324) UnhandledPromiseRejectionWarning: Error: WebSocket is not open: readyState 3 (CLOSED)
    at WebSocket.ping (/home/luomiao/caiyun-wechaty/node_modules/ws/lib/websocket.js:249:19)
    at WXHeartBeat.then.catch.finally (/home/luomiao/caiyun-wechaty/node_modules/wechaty-puppet-padchat/src/padchat-rpc.ts:419:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:68:7)
(node:20324) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 54)
00:59:53 WARN on-error onError(Error: Error: connect ENETUNREACH 54.223.73.175:8788)
00:59:53 WARN PadchatRpc initWebSocket() ws.on(close) code: 1006, reason:
00:59:58 WARN on-error onError(Error: Error: connect ENETUNREACH 54.223.73.175:8788)
00:59:58 WARN PadchatRpc initWebSocket() ws.on(close) code: 1006, reason:
01:00:03 WARN on-error onError(Error: Error: connect ENETUNREACH 54.223.73.175:8788)
01:00:03 WARN PadchatRpc initWebSocket() ws.on(close) code: 1006, reason:

huan · 2018-08-29T09:20:43Z

Again:

02:29:55 SILL PuppetPadchatManager refresh62Data() userId did not change since last login, keep the data as the same
02:29:55 SILL PadchatRpc rpcCall(WXGetLoginToken, [])
02:29:55 SILL PadchatRpc pre login rpcCall(WXGetLoginToken, [])
02:29:55 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXGetLoginToken","data":"%7B%22message%22%3A%22%22%2C%22status%22%3A0%2C%22token%22%3A%2
02:29:55 SILL PadchatRpc WXGetLoginToken result: {"message":"","status":0,"token":"CxPCBArq4x+4P+zuGIso00rySr7hIJAqJ3wYN+40obckvioj6HyeXj+iBc1p7aJYLMlTZD8biQAxmfbmZ1hRDD6p06l2UmF1c7jXgFu/vWA/5/BLw6J5adS+kxSpVFJem5GXRo2H4aeiV+mGqvB21AuucTCoz1Zeek+9m2uJBY79c4wgwyEjf1IQtt3FDuen25gcqrgvWK4QaQULFNYCEWiuR44ugzQo6vfVgfE+lHW660H0TjW1gAclG5RgoWDBv8UeHJfoJ0ldUH6SNFR9CP+eFyjFNTFecF9iA6Xkr5UwIk6/WGry3MmSe14eyY4CQEHNdjj8BnK8kEElPvx5atMB5Cu4xvcBvGHGjiWIw1088y/f8MUQzu/oLi0H+JqA1cadTi3Py0K5500aeEn7CkJwsi/q5g4ekOxgscnD1RMiG/rYFE6mgShFqMIgQkw5eDENExOIjvEYWGcPfrPaM/VWuhkdyHK3bEi/QWAxXWV7ywZvUP8dRAS9GQgGoaBJBcNFywEW38mRrBug95/zhcPAy1laDStdQiSETdLJdDkya6ib0rc3bTjpyZFgGyOOi1l0x9fx/Fkj8+gc66x+73bInJ5cHKe7xrALd07yqGKmBp0qrqapyyEpM7717N0+zXFxs+hrwx6UmDjvt4bChQ==","uin":1211516682}
02:29:55 VERB MemoryCard <puppet> set(WECHATY_PUPPET_PADCHAT, [object Object])
02:29:55 VERB MemoryCard <ding-dong-bot> save() to StorageFile</home/ubuntu/workspace/ding-dong-bot.memory-card.json>
02:29:55 VERB StorageFile save() to /home/ubuntu/workspace/ding-dong-bot.memory-card.json
02:33:32 SILL Puppet constructor() watchdog.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
02:33:32 SILL Puppet constructor() this.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
02:33:32 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: {"data":"ws.on(message)","timeout":240000}
02:33:32 VERB Puppet reset({"data":"ws.on(message)","timeout":240000})
02:33:32 SILL StateSwitch <PuppetPadchat> off() is false
02:33:32 VERB PuppetPadchat stop()
02:33:32 SILL StateSwitch <PuppetPadchat> off() is false
02:33:32 SILL StateSwitch <PuppetPadchat> off() is false
02:33:32 VERB StateSwitch <PuppetPadchat> off(pending) <- (false)
02:33:32 VERB PuppetPadchat logout()
02:33:32 SILL Contact ready() @ Puppet#0<PuppetPadchat>(ding-dong-bot)/PuppetPadchat#0
02:33:32 SILL Contact ready() isReady() true
02:33:32 VERB PuppetPadchatManager logout()
02:33:32 VERB PuppetPadchatManager releaseCache()
02:33:32 SILL PuppetPadchatManager releaseCache() closing caches ...
02:33:32 VERB ContactSelf name()
李卓桓 logouted

windmemory · 2018-08-31T03:00:50Z

Seems like this is duplicate with #163

Close for now, please reopen if this is not same issue as the issue pasted above.

huan · 2018-08-31T03:04:55Z

No, it's not a duplicate.

In this issue, the puppet-padchat program exited after a WebSocket reset.
In the other issue, the puppet-padchat program got stuck after the watchdog reset(WebSocket has no response for a long time), because when reset event emitted, the puppet state is off(), which should be on() as I expected.

windmemory · 2018-08-31T03:08:12Z

Okay, thanks for the explanation.

huan · 2018-09-01T01:18:46Z

Again:

01:52:45 SILL Contact ready() @ Puppet#0<PuppetPadchat>(ding-dong-bot)/PuppetPadchat#0
01:52:45 SILL Contact ready() isReady() true
01:52:45 SILL Message toString() for message type: Url(12)
Message#Url(👥Room<原资蛋全球创客中心VIP>🗣Contact<朱乐旺>👤Contact<李卓桓>)
Message discarded because it does not match ding/ping/bing/code
01:53:05 SILL PadchatRpc initHeartbeat() debounceQueue.subscribe(ws.on(message))
01:53:05 SILL PadchatRpc rpcCall(WXHeartBeat, [])
01:53:05 SILL PadchatRpc pre login rpcCall(WXHeartBeat, [])
01:53:06 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXHeartBeat","data":"%7B%22status%22%3A0%2C%22message%22%3A%22ok%22%7D","msgId":"-900719
01:53:06 SILL PadchatRpc initHeartbeat() throttleQueue.subscribe(ws.on(message))
01:53:06 SILL PuppetPadchat startWatchdog() padchatManager.on(heartbeat)
01:53:06 SILL Wechaty memoryCheck() free: 3973 MB, require: 4 MB
01:53:06 SILL PadchatRpc WXHeartBeat result: {"status":0,"message":"ok"}
01:53:06 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:06 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:07 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"","data":"%5B%7B%22continue%22%3A0%2C%22msg_type%22%3A32768%2C%22status%22%3A1%2C%22uin%
01:53:07 SILL PadchatRpc onSocketTencent() discard empty message msg_id payoad: {"continue":0,"msg_type":32768,"status":1,"uin":1211516682}
01:53:27 SILL PadchatRpc initHeartbeat() debounceQueue.subscribe(ws.on(message))
01:53:27 SILL PadchatRpc rpcCall(WXHeartBeat, [])
01:53:27 SILL PadchatRpc pre login rpcCall(WXHeartBeat, [])
01:53:27 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXHeartBeat","data":"%7B%22status%22%3A0%2C%22message%22%3A%22ok%22%7D","msgId":"-900719
01:53:27 SILL PadchatRpc initHeartbeat() throttleQueue.subscribe(ws.on(message))
01:53:27 SILL PuppetPadchat startWatchdog() padchatManager.on(heartbeat)
01:53:27 SILL Wechaty memoryCheck() free: 3978 MB, require: 4 MB
01:53:27 SILL PadchatRpc WXHeartBeat result: {"status":0,"message":"ok"}
01:53:27 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:27 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:28 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"","data":"%5B%7B%22continue%22%3A0%2C%22msg_type%22%3A32768%2C%22status%22%3A1%2C%22uin%
01:53:28 SILL PadchatRpc onSocketTencent() discard empty message msg_id payoad: {"continue":0,"msg_type":32768,"status":1,"uin":1211516682}
01:53:48 SILL PadchatRpc initHeartbeat() debounceQueue.subscribe(ws.on(message))
01:53:48 SILL PadchatRpc rpcCall(WXHeartBeat, [])
01:53:48 SILL PadchatRpc pre login rpcCall(WXHeartBeat, [])
01:53:48 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXHeartBeat","data":"%7B%22status%22%3A0%2C%22message%22%3A%22ok%22%7D","msgId":"-900719
01:53:48 SILL PadchatRpc initHeartbeat() throttleQueue.subscribe(ws.on(message))
01:53:48 SILL PuppetPadchat startWatchdog() padchatManager.on(heartbeat)
01:53:48 SILL Wechaty memoryCheck() free: 3973 MB, require: 4 MB
01:53:48 SILL PadchatRpc WXHeartBeat result: {"status":0,"message":"ok"}
01:53:49 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:49 SILL PadchatRpc initWebSocket() ws.on(pong)
01:53:49 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"","data":"%5B%7B%22continue%22%3A0%2C%22msg_type%22%3A32768%2C%22status%22%3A1%2C%22uin%
01:53:49 SILL PadchatRpc onSocketTencent() discard empty message msg_id payoad: {"continue":0,"msg_type":32768,"status":1,"uin":1211516682}
01:53:57 WARN PadchatRpc initWebSocket() ws.on(close) code: 1005, reason:
01:53:57 VERB PuppetPadchat startManager() manager.on(reconnect) for ws.on(close, 1005)
01:53:57 SILL PadchatRpc initWebSocket() Promise() ws.on(close)
01:53:58 VERB PuppetPadchat reconnect(), retry attempt left: 6
01:53:58 VERB PadchatRpc reconnect()
01:53:58 VERB PadchatRpc initWebSocket()
01:53:59 SILL PadchatRpc initWebSocket() Promise() ws.on(open)
01:53:59 SILL PadchatRpc rpcCall(init, [])
01:53:59 SILL PadchatRpc pre login rpcCall(init, [])
01:53:59 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"init","data":"%7B%22message%22%3A%22%E5%88%9D%E5%A7%8B%E5%8C%96%E8%BF%9E%E6%8E%A5%E6%88%
01:53:59 SILL PadchatRpc init result: {"message":"初始化连接成功","status":0}
01:53:59 VERB PadchatRpc WXInitialize()
01:53:59 SILL PadchatRpc rpcCall(WXInitialize, [])
01:53:59 SILL PadchatRpc pre login rpcCall(WXInitialize, [])
01:53:59 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXInitialize","data":"%7B%22message%22%3A%22%E5%88%9D%E5%A7%8B%E5%8C%96%E5%BE%AE%E4%BF%A
01:53:59 SILL PadchatRpc WXInitialize result: {"message":"初始化微信信息成功","status":0}
01:53:59 VERB PuppetPadchatManager tryLoad62Data()
01:53:59 SILL PuppetPadchatManager tryLoad62Data() 62 data found: "YnBsaXN0MDDUAQIDBAUGCQpYJHZlcnNpb25YJG9iamVjdHNZJGFyY2hpdmVyVCR0b3ASAAGGoKIHCFUkbnVsbF8QIDJlMWUwZDI5NjZkOGZhNzdkNjQ0YjcwYmFhYTA4NzVkXxAPTlNLZXllZEFyY2hpdmVy0QsMVHJvb3SAAQgRGiMtMjc6QGN1eH0AAAAAAAABAQAAAAAAAAANAAAAAAAAAAAAAAAAAAAAfw=="
01:53:59 SILL PadchatRpc rpcCall(WXLoadWxDat, ["YnBsaXN0MDDUAQIDBAUGCQpYJHZlcnNpb25YJG9iamVjdHNZJGFyY2hpdmVyVCR0b3ASAAGGoKIHCFUkbnVsbF8QIDJlMWUwZDI5NjZkOGZhNzdkNjQ0YjcwYmFhYTA4NzVkXxAPTlNLZXllZEFyY2hpdmVy0QsMVHJvb3SAAQgRGiMtMjc6QGN1eH0AAAAAAAABAQAAAAAAAAANAAAAAAAAAAAAAAAAAAAAfw=="])
01:53:59 SILL PadchatRpc pre login rpcCall(WXLoadWxDat, ["YnBsaXN0MDDUAQIDBAUGCQpYJHZlcnNpb25YJG9iamVjdHNZJGFyY2hpdmVyVCR0b3ASAAGGoKIHCFUkbnVsbF8QIDJlMWUwZDI5NjZkOGZhNzdkNjQ0YjcwYmFhYTA4NzVkXxAPTlNLZXllZEFyY2hpdmVy0QsMVHJvb3SAAQgRGiMtMjc6QGN1eH0AAAAAAAABAQ)
01:54:00 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXLoadWxDat","data":"%7B%22message%22%3A%22%22%2C%22status%22%3A0%7D%0A","msgId":"-90071
01:54:00 SILL PadchatRpc WXLoadWxDat result: {"message":"","status":0}
01:54:00 VERB PuppetPadchatManager tryAutoLogin(wxid_a8d806dzznm822)
01:54:00 SILL PadchatRpc rpcCall(WXAutoLogin, ["GPbNJqf3rjgmEYypSMbCeLcXiF9BogFS7EtB4XU8t1KL7g33fuu+ed3d+Q4afF12PFCHB1cUng3B3hk5kNQi3n2ZTD1k7PnixCw0TgSROYTULgThIMWuZ69pPA6PgWxJl9Ivq76vHdv5cy+NEtWn+tJcT7of24qM0wbjqc6VP/ULAHn9N1hOlF6twB/Ywna73gqzq0wDCm8nMIx/UpTK5ggFRmwD3e/61QAWuuO/ar31qwK7rX4AuEEs18yPpqkizUJyJM1k8/9XIvz4ZvI1dTvSwJ38x37ixfkM6CXtkU2MTegBbYe/+Heb2QGXu2fPa/zkxWnhNDHEtHJdP7LCc/j8iP+2hqzjRvsBj7Rd2gdObFvHLma5M6RrWcplDxSdIlJkVTLPDj1GjcHhHzLzE9gqcczS6uK9uHcutsyZoMjOr7UUjBdFgKa/ERJQoVkK5zmcKqiKCCb20CNLBa4JTR6Qm89ZvFZZdH/tIyfcTzD4JoFF4Q)
01:54:00 SILL PadchatRpc pre login rpcCall(WXAutoLogin, ["GPbNJqf3rjgmEYypSMbCeLcXiF9BogFS7EtB4XU8t1KL7g33fuu+ed3d+Q4afF12PFCHB1cUng3B3hk5kNQi3n2ZTD1k7PnixCw0TgSROYTULgThIMWuZ69pPA6PgWxJl9Ivq76vHdv5cy+NEtWn+tJcT7of24qM0wbjqc6VP/ULAHn9N1hOlF6twB/Ywna73gqzq0)
01:54:00 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXAutoLogin","data":"%7B%22email%22%3A%22%22%2C%22external%22%3A%220%22%2C%22long_link_s
01:54:00 SILL PadchatRpc WXAutoLogin result: {"email":"","external":"0","long_link_server":"","message":"\n\u0010Everything is ok","nick_name":"","phone_number":"","qq":0,"short_link_server":"","status":0,"uin":1211516682,"user_name":"wxid_a8d806dzznm822"}, type: object
01:54:00 VERB PuppetPadchatManager login(wxid_a8d806dzznm822)
01:54:00 VERB PuppetPadchatManager reconnected(wxid_a8d806dzznm822)
01:54:00 VERB PuppetPadchatManager refresh62Data(wxid_a8d806dzznm822, undefined)
01:54:00 SILL PadchatRpc rpcCall(WXHeartBeat, [])
01:54:00 SILL PadchatRpc pre login rpcCall(WXHeartBeat, [])
01:54:01 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXHeartBeat","data":"%7B%22status%22%3A0%2C%22message%22%3A%22ok%22%7D","msgId":"-900719
01:54:01 SILL PadchatRpc WXHeartBeat result: {"status":0,"message":"ok"}
01:54:01 SILL PuppetPadchatManager refresh62Data() userId did not change since last login, keep the data as the same
01:54:01 SILL PadchatRpc rpcCall(WXGetLoginToken, [])
01:54:01 SILL PadchatRpc pre login rpcCall(WXGetLoginToken, [])
01:54:01 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"WXGetLoginToken","data":"%7B%22message%22%3A%22%22%2C%22status%22%3A0%2C%22token%22%3A%2
01:54:01 SILL PadchatRpc WXGetLoginToken result: {"message":"","status":0,"token":"GdaP2113QYljyyyb7h30iveWhiYc66vPyb8lMfYmVkmXJ8oYbIrdrrzgvwmvKUliVW1uvP8M2MZw4GA6WI5+OFBteeluVVyMH4HoHUts+FQ34F6g4izBqJHd+/HgY0sp3pJwfiUjik58XRagFRFXRCD8iRi9NwYDMAUgVd9dTIIAtvtLpO8bl+9InkwWBAP5wS/z9FMZx/QqeBSaHMAtLFavt/0SeD7KV7Gg+UiskJwkkQblPQvpDVtCPefOArTFn6uGWzYKsz//930gZM1MrV5gJzQ0X3M1zwORGiCf/evOcw/7yZtXchqZe6TcK+jcyExMpWNI9+glEe8ZOEjYBLjV8yUp5K23vpMO9Rje1JKBtblF6ayREAuTkD6b5BAV3KcfwzWvPkrjWFDRF97jwleySRsIwgE2Eixq1Dk3xB1Z4CLUj+swGYNhfhFpKp8nYc+r1gkLfoUbbHAyYHeM3pwCrfEaiUDrbYTUX8Qq2+5vFWTNshfAdp+L5lEG0nmpdCUhkSkbMvmLQsDNOEx1A/dU1JArZwpmlhkRiX7McfJ3bPVJQI1UFfCo/kmuKDPi88/D6JtEMU016zyFqxbwHRtHuQqjMiniCy0iPCLhM3EO5EAcXT2hwcKhm81P+DuUVrSAHBenozWPwfqReuQcbg==","uin":1211516682}
01:54:01 VERB MemoryCard <puppet> set(WECHATY_PUPPET_PADCHAT, [object Object])
01:54:01 VERB MemoryCard <ding-dong-bot> save() to StorageFile</home/ubuntu/workspace/ding-dong-bot.memory-card.json>
01:54:01 VERB StorageFile save() to /home/ubuntu/workspace/ding-dong-bot.memory-card.json
01:54:02 WARN PadchatRpc initWebSocket() ws.on(close) code: 1005, reason:
01:54:02 SILL PadchatRpc initWebSocket() Promise() ws.on(close)
01:54:09 SILL PadchatRpc initHeartbeat() debounceQueue.subscribe(ws.on(message))
01:54:09 SILL PadchatRpc rpcCall(WXHeartBeat, [])
01:54:09 SILL PadchatRpc pre login rpcCall(WXHeartBeat, [])
01:54:09 VERB PadchatRpc initHeartbeat() debounceQueue.subscribe(ws.on(message)) error happened: Error: WebSocket is not open: readyState 3 (CLOSED)
01:54:09 ERR Config ###########################
01:54:09 ERR Config unhandledRejection: Error: WebSocket is not open: readyState 3 (CLOSED) [object Promise]
01:54:09 ERR Config ###########################
01:54:09 ERR Config process.on(unhandledRejection) promise.catch(WebSocket is not open: readyState 3 (CLOSED))
Config Error: WebSocket is not open: readyState 3 (CLOSED)
    at WebSocket.ping (/home/ubuntu/workspace/node_modules/ws/lib/websocket.js:249:19)
    at WXHeartBeat.then.catch.finally (/home/ubuntu/workspace/node_modules/wechaty-puppet-padchat/src/padchat-rpc.ts:412:16)
    at <anonymous>
    at process._tickCallback (internal/process/next_tick.js:68:7)
01:57:48 SILL Puppet constructor() watchdog.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
01:57:48 SILL Puppet constructor() this.on(reset) reason: {"data":"ws.on(message)","timeout":240000}
01:57:48 SILL Puppet constructor() resetThrottleQueue.subscribe() reason: {"data":"ws.on(message)","timeout":240000}
01:57:48 VERB Puppet reset({"data":"ws.on(message)","timeout":240000})
01:57:48 SILL StateSwitch <PuppetPadchat> off() is false
(node:264986) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 110)
01:57:48 VERB PuppetPadchat stop()
01:57:48 SILL StateSwitch <PuppetPadchat> off() is false
01:57:48 SILL StateSwitch <PuppetPadchat> off() is false
01:57:48 VERB StateSwitch <PuppetPadchat> off(pending) <- (false)
01:57:48 VERB PuppetPadchat logout()
01:57:48 SILL Contact ready() @ Puppet#0<PuppetPadchat>(ding-dong-bot)/PuppetPadchat#0
01:57:48 SILL Contact ready() isReady() true
01:57:48 VERB PuppetPadchatManager logout()
01:57:48 VERB PuppetPadchatManager releaseCache()
01:57:48 SILL PuppetPadchatManager releaseCache() closing caches ...
01:57:48 VERB ContactSelf name()
李卓桓 logouted

bitwater · 2018-09-03T03:23:16Z

2018-09-02T15:08:35.609415+00:00 app[web.1]: 23:08:35 VERB PadchatRpc initHeartbeat()
2018-09-02T15:08:35.610113+00:00 app[web.1]: 23:08:35 SILL PadchatRpc pre login rpcCall(init, [])
2018-09-02T15:08:35.841416+00:00 app[web.1]: 23:08:35 SILL PadchatRpc initWebSocket() ws.on(message): {"apiName":"init","data":"%7B%22message%22%3A%22%E5%88%9D%E5%A7%8B%E5%8C%96%E8%BF%9E%E6%8E%A5%E6%88%
2018-09-02T15:08:35.845684+00:00 app[web.1]: 23:08:35 SILL PadchatRpc init result: {"message":"初始化连接成功","status":0}
2018-09-02T15:08:35.846053+00:00 app[web.1]: 23:08:35 VERB PadchatRpc WXInitialize()
2018-09-02T15:08:35.846226+00:00 app[web.1]: 23:08:35 SILL PadchatRpc rpcCall(WXInitialize, [])
2018-09-02T15:08:35.846387+00:00 app[web.1]: 23:08:35 SILL PadchatRpc pre login rpcCall(WXInitialize, [])
2018-09-02T15:08:35.750996+00:00 heroku[web.1]: State changed from starting to up
2018-09-02T15:08:36.301664+00:00 app[web.1]: 23:08:36 WARN PadchatRpc initWebSocket() ws.on(close) code: 1005, reason: 
2018-09-02T15:08:36.301831+00:00 app[web.1]: 23:08:36 SILL PadchatRpc initWebSocket() Promise() ws.on(close)

windmemory · 2018-10-24T08:25:23Z

I'm trying to debug this issue and I saw an error at the end of line saying segmentation fault.

Then I searched this error, seems like this is related to a leveldb issue. I found this one: Level/leveldown#157

Here is the end of my logs

16:16:49 VERB PuppetPadchat stop()
16:16:49 SILL StateSwitch <PuppetPadchat> off() is false
16:16:49 SILL StateSwitch <PuppetPadchat> off() is false
16:16:49 VERB StateSwitch <PuppetPadchat> off(pending) <- (false)
16:16:49 VERB PuppetPadchat logout()
16:16:49 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
16:16:49 SILL Contact ready() isReady() true
16:16:49 VERB PuppetPadchatManager logout()
16:16:49 VERB PuppetPadchatManager releaseCache()
16:16:49 SILL PuppetPadchatManager releaseCache() closing caches ...
Logout: Contact<一颗树>
zsh: segmentation fault  BROLOG_LEVEL=silly ts-node bot.ts

@zixia What did you do to avoid the error before?

I've tested it several times, calling reset manually is able to reproduce this bug consistently, but calling logout will not, sometimes it won't crash.

My minimal code is here:

import { Wechaty } from 'wechaty';
import { PuppetPadchat } from 'wechaty-puppet-padchat';

const puppet = new PuppetPadchat({
  token: 'my-secret-token'
});

const bot = new Wechaty({
  profile: 'test',
  puppet
});

bot
.on('scan', (qrcode, status) => {
  generate(qrcode, { small: true })

  const qrcodeImageUrl = [
    'https://api.qrserver.com/v1/create-qr-code/?data=',
    encodeURIComponent(qrcode),
  ].join('')

  console.log(`[${status}] ${qrcodeImageUrl}\nScan QR Code above to log in: `)
})
.on('login', async user => {
  console.log(`Login: ${user}`);
  setTimeout(() => bot.reset(), 10000)
})
.start()

huan · 2018-10-24T09:13:07Z

@windmemory Yes, it's related with the flash-store.

According to huan/flash-store#13 , if we use nosql-leveldb then we will not get the segfault error. However, the nosql-leveldb requires the local build when install.

So at last, I switched it back to the leveldown which can just be installed without any compiling job, it will sometimes get the segfault error.

huan · 2018-10-24T09:15:11Z

I can switch to use nosql-leveldb back.

So please feel free to let me know if you believe it's necessary.

windmemory · 2018-10-24T09:39:12Z

What if I switch the FlashStoreSync to FlashStore, will that solve the problem?

windmemory · 2018-10-24T11:44:02Z

Doesn't work :(

windmemory · 2018-10-24T12:03:10Z

Seems like we need to switch back to nosql-leveldb...

I tested with flash-store v0.7.1, which is the latest version that use nosql-leveldb, it won't crash.

huan · 2018-10-24T14:02:59Z

@windmemory Yes, please use flash-store@0.7 for your environment.

There are no much changes between the v0.7 with the latest version, except the nosql-leveldb related changes.

windmemory · 2018-10-24T14:22:59Z

Great! I will revert the version of flash-store back to 0.7.

Thanks!

huan changed the title ~~WebSocket reset can not recover automatically~~ WebSocket reset can not be recovered automatically Aug 22, 2018

windmemory closed this as completed Aug 31, 2018

windmemory added the duplicate This issue or pull request already exists label Aug 31, 2018

huan reopened this Aug 31, 2018

huan removed the duplicate This issue or pull request already exists label Aug 31, 2018

windmemory added the bug Something isn't working label Aug 31, 2018

huan mentioned this issue Aug 31, 2018

watchdog.on(reset) reason: {"data":"ws.on(message)","timeout":240000} #159

Closed

huan changed the title ~~WebSocket reset can not be recovered automatically~~ Unexpected Exit: WebSocket reset can not be recovered automatically Sep 1, 2018

windmemory closed this as completed in 19f7852 Oct 24, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unexpected Exit: WebSocket reset can not be recovered automatically #160

Unexpected Exit: WebSocket reset can not be recovered automatically #160

huan commented Aug 22, 2018

huan commented Aug 24, 2018

huan commented Aug 25, 2018

bitwater commented Aug 29, 2018

huan commented Aug 29, 2018

windmemory commented Aug 31, 2018

huan commented Aug 31, 2018 •

edited

Loading

windmemory commented Aug 31, 2018

huan commented Sep 1, 2018

bitwater commented Sep 3, 2018 •

edited

Loading

windmemory commented Oct 24, 2018 •

edited

Loading

huan commented Oct 24, 2018 •

edited

Loading

huan commented Oct 24, 2018

windmemory commented Oct 24, 2018

windmemory commented Oct 24, 2018

windmemory commented Oct 24, 2018 •

edited

Loading

huan commented Oct 24, 2018

windmemory commented Oct 24, 2018

Unexpected Exit: WebSocket reset can not be recovered automatically #160

Unexpected Exit: WebSocket reset can not be recovered automatically #160

Comments

huan commented Aug 22, 2018

huan commented Aug 24, 2018

huan commented Aug 25, 2018

bitwater commented Aug 29, 2018

huan commented Aug 29, 2018

windmemory commented Aug 31, 2018

huan commented Aug 31, 2018 • edited Loading

windmemory commented Aug 31, 2018

huan commented Sep 1, 2018

bitwater commented Sep 3, 2018 • edited Loading

windmemory commented Oct 24, 2018 • edited Loading

huan commented Oct 24, 2018 • edited Loading

huan commented Oct 24, 2018

windmemory commented Oct 24, 2018

windmemory commented Oct 24, 2018

windmemory commented Oct 24, 2018 • edited Loading

huan commented Oct 24, 2018

windmemory commented Oct 24, 2018

huan commented Aug 31, 2018 •

edited

Loading

bitwater commented Sep 3, 2018 •

edited

Loading

windmemory commented Oct 24, 2018 •

edited

Loading

huan commented Oct 24, 2018 •

edited

Loading

windmemory commented Oct 24, 2018 •

edited

Loading