wechaty
VError: longlink fail to connect, host:120.241.21.110, port:80: longlink socket connect timeout
17:09:05 ERR Config ###########################
17:09:05 ERR Config unhandledRejection: VError: longlink fail to connect, host:120.241.21.110, port:80: longlink socket connect timeout
at WeChatLongLinkProxy.<anonymous> (/app/node_modules/padlocal-client-ts/dist/link/WeChatLongLinkProxy.js:91:23)
at Generator.throw (<anonymous>)
at rejected (/app/node_modules/padlocal-client-ts/dist/link/WeChatLongLinkProxy.js:6:65)
at runMicrotasks (<anonymous>)
at processTicksAndRejections (node:internal/process/task_queues:96:5) [object Promise]
17:09:05 ERR Config ###########################
17:09:05 ERR Config process.on(unhandledRejection) promise.catch(longlink fail to connect, host:120.241.21.110, port:80: longlink socket connect timeout)
Config IOError [VError]: longlink fail to connect, host:120.241.21.110, port:80: longlink socket connect timeout
at WeChatLongLinkProxy.<anonymous> (/app/node_modules/padlocal-client-ts/dist/link/WeChatLongLinkProxy.js:91:23)
at Generator.throw (<anonymous>)
at rejected (/app/node_modules/padlocal-client-ts/dist/link/WeChatLongLinkProxy.js:6:65)
at runMicrotasks (<anonymous>)
at processTicksAndRejections (node:internal/process/task_queues:96:5) {
jse_shortmsg: 'longlink fail to connect, host:120.241.21.110, port:80',
jse_cause: IOError [VError]: longlink socket connect timeout
at Timeout.<anonymous> (/app/node_modules/padlocal-client-ts/dist/link/WeChatLongLinkProxy.js:276:39)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7) {
jse_shortmsg: 'longlink socket connect timeout',
jse_info: {}
},
jse_info: {}
}
(node:17) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 2)
(Use `node --trace-warnings ...` to show where the warning was created)
WeChat has a cgi /cgi-bin/micromsg-bin/newgetdns for returning a set of dns lists, which will provide users with multiple optional server IPs.
In mars, the server will be selected in order. If the first ip connection fails, the second ip will be connected. The official app ensures higher usability through this mechanism.
Not sure if padlocal supports this mechanism?
Thanks for @binsee 's suggestion, it's a greate solution which will work hopefully.
But it's really hard to verify that whether the sibling server ip got via /cgi-bin/micromsg-bin/newgetdns will work, since the first ip fails which may be caused by network jitter.
Call for volunteers: if you are running into this issue frequently, leave your message in this thread. Then we can tune the new stragety together to see if it really works.
Today I have upgraded Friday BOT with Puppet PadLocal v1.11, and when AutoLogin it keeps retrying with the following error:
IOError: longlink socket connect timeout
Update: after about two hours retrying, login successfully finally.
21:44:52 INFO [PuppetPadlocal] start login with type: AutoLogin
21:45:03 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:45:04 INFO [PuppetPadlocal] start login with type: AutoLogin
21:45:18 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:45:33 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:45:48 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:03 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:05 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:06 INFO [PuppetPadlocal] start login with type: AutoLogin
21:46:20 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:28 ERR Config ###########################
21:46:28 ERR Config Wechaty unhandledRejection: IOError: longlink socket connect timeout
at Timeout.<anonymous> (/home/friday/git/friday/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:559:17)
at processTimers (node:internal/timers:502:7) [object Promise]
21:46:28 ERR Config ###########################
21:46:28 ERR Config process.on(unhandledRejection) promise.catch(longlink socket connect timeout)
Config IOError: longlink socket connect timeout
at Timeout.<anonymous> (/home/friday/git/friday/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:559:17)
at processTimers (node:internal/timers:502:7) {
jse_shortmsg: 'longlink socket connect timeout',
jse_info: {},
cause: [Function: ve_cause]
}
(node:783959) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 2)
(Use `node --trace-warnings ...` to show where the warning was created)
21:46:35 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:50 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:46:51 ERR Config ###########################
21:46:51 ERR Config Wechaty unhandledRejection: IOError: longlink socket connect timeout
at Timeout.<anonymous> (/home/friday/git/friday/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:559:17)
at processTimers (node:internal/timers:502:7) [object Promise]
21:46:51 ERR Config ###########################
21:46:51 ERR Config process.on(unhandledRejection) promise.catch(longlink socket connect timeout)
Config IOError: longlink socket connect timeout
at Timeout.<anonymous> (/home/friday/git/friday/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:559:17)
at processTimers (node:internal/timers:502:7) {
jse_shortmsg: 'longlink socket connect timeout',
jse_info: {},
cause: [Function: ve_cause]
}
(node:783959) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 3)
21:47:05 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:47:08 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
21:47:09 INFO [PuppetPadlocal] start login with type: AutoLogin
Old version (0.4) has the same problem
13:55:54 INFO [PuppetPadlocal] start login with type: AutoLogin
13:56:16 ERR Config ###########################
13:56:16 ERR Config unhandledRejection: VError: longlink socket connect timeout
at Timeout.<anonymous> (/wechaty/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7) [object Promise]
13:56:16 ERR Config ###########################
13:56:16 ERR Config process.on(unhandledRejection) promise.catch(longlink socket connect timeout)
Config IOError [VError]: longlink socket connect timeout
at Timeout.<anonymous> (/wechaty/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7) {
jse_shortmsg: 'longlink socket connect timeout',
jse_info: {}
}
13:56:54 VERB StateSwitch <PuppetState> off(pending) <- (false)
13:56:54 VERB StateSwitch <PuppetState> off(true) <- (pending)
13:56:55 VERB StateSwitch <PuppetState> on(pending) <- (false)
13:56:56 INFO [PuppetPadlocal] start login with type: AutoLogin
13:57:06 VERB StateSwitch <PuppetState> off(pending) <- (false)
13:57:06 VERB StateSwitch <PuppetState> off(true) <- (pending)
13:57:07 VERB StateSwitch <PuppetState> on(pending) <- (false)
13:57:07 INFO [PuppetPadlocal] start login with type: AutoLogin
13:57:29 ERR Config ###########################
13:57:29 ERR Config unhandledRejection: VError: longlink socket connect timeout
at Timeout.<anonymous> (/wechaty/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7) [object Promise]
13:57:29 ERR Config ###########################
13:57:29 ERR Config process.on(unhandledRejection) promise.catch(longlink socket connect timeout)
Config IOError [VError]: longlink socket connect timeout
at Timeout.<anonymous> (/wechaty/node_modules/padlocal-client-ts/src/link/WeChatLongLinkProxy.ts:365:25)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7) {
jse_shortmsg: 'longlink socket connect timeout',
jse_info: {}
}
OSS.Chat (running on Heroku) is experiencing the same problems today (with Wechaty Puppet PadLocal v0.4):
01:57:19 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:57:20 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:57:21 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:57:21 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:57:30 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:57:30 INFO [PuppetPadlocal] start login with type: AutoLogin
01:57:31 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:57:32 INFO [PuppetPadlocal] start login with type: AutoLogin
01:58:06 ERR [PadLocalClient] error while syncing onpush: VError: [tid:a17c2298] request has been cancelled for reason: SERVER_ERROR: 4 DEADLINE_EXCEEDED: Deadline exceeded
at Request._failAllPendingRequest (/app/node_modules/padlocal-client-ts/dist/Request.js:262:19)
at ClientDuplexStreamImpl.<anonymous> (/app/node_modules/padlocal-client-ts/dist/Request.js:56:18)
at ClientDuplexStreamImpl.emit (node:events:526:28)
at ClientDuplexStreamImpl.emit (node:domain:475:12)
at Object.onReceiveStatus (/app/node_modules/@grpc/grpc-js/build/src/client.js:391:28)
at Object.onReceiveStatus (/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:328:181)
at /app/node_modules/@grpc/grpc-js/build/src/call-stream.js:182:78
at processTicksAndRejections (node:internal/process/task_queues:78:11)
at runNextTicks (node:internal/process/task_queues:65:3)
at listOnTimeout (node:internal/timers:528:9)
at processTimers (node:internal/timers:502:7)
01:58:13 ERR [PadLocalClient] error while syncing onpush: VError: [tid:63cb7212] request has been cancelled for reason: SERVER_ERROR: 4 DEADLINE_EXCEEDED: Deadline exceeded
at Request._failAllPendingRequest (/app/node_modules/padlocal-client-ts/dist/Request.js:262:19)
at ClientDuplexStreamImpl.<anonymous> (/app/node_modules/padlocal-client-ts/dist/Request.js:56:18)
at ClientDuplexStreamImpl.emit (node:events:526:28)
at ClientDuplexStreamImpl.emit (node:domain:475:12)
at Object.onReceiveStatus (/app/node_modules/@grpc/grpc-js/build/src/client.js:391:28)
at Object.onReceiveStatus (/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:328:181)
at /app/node_modules/@grpc/grpc-js/build/src/call-stream.js:182:78
at processTicksAndRejections (node:internal/process/task_queues:78:11)
at runNextTicks (node:internal/process/task_queues:65:3)
at listOnTimeout (node:internal/timers:528:9)
at processTimers (node:internal/timers:502:7)
01:58:30 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:58:30 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:58:32 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:58:32 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:58:40 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:58:41 INFO [PuppetPadlocal] start login with type: AutoLogin
01:58:42 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:58:43 INFO [PuppetPadlocal] start login with type: AutoLogin
01:59:41 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:59:41 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:59:43 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
01:59:43 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
01:59:51 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:59:52 INFO [PuppetPadlocal] start login with type: AutoLogin
01:59:53 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
01:59:54 INFO [PuppetPadlocal] start login with type: AutoLogin
02:00:52 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:00:52 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:00:54 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:00:54 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:01:02 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:01:03 INFO [PuppetPadlocal] start login with type: AutoLogin
02:01:04 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:01:05 INFO [PuppetPadlocal] start login with type: AutoLogin
02:01:10 VERB HAWechaty nodes() total 3 wechaty instances are under management
02:02:03 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:02:04 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:02:05 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:02:05 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:02:14 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:02:14 INFO [PuppetPadlocal] start login with type: AutoLogin
02:02:15 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:02:16 INFO [PuppetPadlocal] start login with type: AutoLogin
02:03:14 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:03:15 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:03:16 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:03:16 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:03:25 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:03:25 INFO [PuppetPadlocal] start login with type: AutoLogin
02:03:26 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:03:27 INFO [PuppetPadlocal] start login with type: AutoLogin
02:04:25 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:04:25 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:04:27 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:04:27 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:04:35 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:04:36 INFO [PuppetPadlocal] start login with type: AutoLogin
02:04:37 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:04:38 INFO [PuppetPadlocal] start login with type: AutoLogin
02:05:36 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:05:36 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:05:38 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:05:38 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:05:46 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:05:47 INFO [PuppetPadlocal] start login with type: AutoLogin
02:05:48 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:05:49 INFO [PuppetPadlocal] start login with type: AutoLogin
02:06:47 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:06:47 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:06:49 VERB StateSwitch <PuppetPadlocal> off(pending) <- (false)
02:06:49 VERB StateSwitch <PuppetPadlocal> off(true) <- (pending)
02:06:57 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:06:58 INFO [PuppetPadlocal] start login with type: AutoLogin
02:06:59 VERB StateSwitch <PuppetPadlocal> on(pending) <- (false)
02:07:00 INFO [PuppetPadlocal] start login with type: AutoLogin
Retrying for more than ten times already.
Let's wait and see.
Longlink host fail over has been added in [email protected].
Please have a try and feedback is wecome.
friday@wechaty-contributors:~/git/friday$ npm ls wechaty-puppet-padlocal
[email protected] /home/friday/git/friday
└── [email protected]
00:15:25 ERR [Request] [tid:382e6e57], padlocal grpc request failed: 3, error: IOError: [tid:382e6e57] Exception while handling wechat request: long link send request timeout
00:15:25 WARN [LongLink] [120.241.21.110:80] close connection on error,IOError: long link init failed: [tid:382e6e57] request has been cancelled for reason: CLIENT_ERROR: [tid:382e6e57] Exception while handling wechat request: long link send request timeout
00:15:25 WARN [LongLink] longlink reconnect [2] after delay:1000ms
...
00:15:37 ERR [Request] [tid:0addbe21], padlocal grpc request failed: 3, error: IOError: [tid:0addbe21] Exception while handling wechat request: long link send request timeout
00:15:37 WARN [LongLink] [120.241.21.110:80] close connection on error,IOError: long link init failed: [tid:0addbe21] request has been cancelled for reason: CLIENT_ERROR: [tid:0addbe21] Exception while handling wechat request: long link send request timeout
00:15:37 WARN [LongLink] longlink reconnect [3] after delay:2000ms
00:15:46 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
...
00:15:49 ERR [Request] [tid:15f222c3], padlocal grpc request failed: 3, error: IOError: [tid:15f222c3] Exception while handling wechat request: long link send request timeout
00:15:49 WARN [LongLink] [120.241.21.110:80] close connection on error,IOError: long link init failed: [tid:15f222c3] request has been cancelled for reason: CLIENT_ERROR: [tid:15f222c3] Exception while handling wechat request: long link send request timeout
00:15:49 WARN [LongLink] longlink reconnect [4] after delay:3000ms
...
00:18:06 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
00:18:07 ERR [Request] [tid:ff2314a5], padlocal grpc request failed: 3, error: IOError: [tid:ff2314a5] Exception while handling wechat request: long link send request timeout
00:18:07 WARN [LongLink] [120.241.21.110:80] close connection on error,IOError: long link init failed: [tid:ff2314a5] request has been cancelled for reason: CLIENT_ERROR: [tid:ff2314a5] Exception while handling wechat request: long link send request timeout
00:18:07 WARN [LongLink] longlink reconnect [5] after delay:5000ms
00:18:07 ERR [Request] [tid:10202e19], padlocal grpc request failed: 1, error: Error: 2 UNKNOWN: [tid:10202e19] login failed
00:18:07 ERR start client failed: SubRequestCancelError: [tid:10202e19] request has been cancelled for reason: SERVER_ERROR: 2 UNKNOWN: [tid:10202e19] login failed
at Request._failAllPendingRequest (/home/friday/git/friday/node_modules/padlocal-client-ts/src/Request.ts:338:15)
at ClientDuplexStreamImpl.<anonymous> (/home/friday/git/friday/node_modules/padlocal-client-ts/src/Request.ts:82:12)
at ClientDuplexStreamImpl.emit (node:events:520:28)
at Object.onReceiveStatus (/home/friday/git/friday/node_modules/@grpc/grpc-js/src/client.ts:689:18)
at Object.onReceiveStatus (/home/friday/git/friday/node_modules/@grpc/grpc-js/src/client-interceptors.ts:424:48)
at /home/friday/git/friday/node_modules/@grpc/grpc-js/src/call-stream.ts:330:24
at processTicksAndRejections (node:internal/process/task_queues:78:11)
00:18:09 INFO WechatyPluginContrib EventLogger heartbeat: heartbeat@padlocal
00:18:10 INFO [PuppetPadlocal] start login with type: AutoLogin
...
00:18:21 ERR [Request] [tid:5a32546a], padlocal grpc request failed: 3, error: IOError: [tid:5a32546a] Exception while handling wechat request: long link send request timeout
00:18:21 WARN [LongLink] [120.241.21.110:80] close connection on error,IOError: long link init failed: [tid:5a32546a] request has been cancelled for reason: CLIENT_ERROR: [tid:5a32546a] Exception while handling wechat request: long link send request timeout
00:18:21 WARN [LongLink] longlink reconnect [1] after delay:1000ms
...
The above problem will result in a QR Code that can not show problem: from http://friday.chatie.io:5200/ we can not get any QR Code for scan.
Update (2 hours later)
It connects successes and the bot back online!
I met the err report today, but it seems like no matter, that receving and sending some message is running fine.
07:48:18 ERR [Request] [tid:d5272cfe], padlocal grpc request failed: 3, error: IOError: [tid:d5272cfe] Exception while handling wechat request: long link send request timeout
07:48:18 ERR [PadLocalClient] error while syncing onpush: VError: [tid:d5272cfe] request has been cancelled for reason: CLIENT_ERROR: [tid:d5272cfe] Exception while handling wechat request: long link send request timeout
at Request._failAllPendingRequest (xxx/node_modules/padlocal-client-ts/src/Request.ts:338:15)
at Request.error (xxx/node_modules/padlocal-client-ts/src/Request.ts:351:10)
at Request.<anonymous> (xxx/node_modules/padlocal-client-ts/src/Request.ts:221:16)
at Generator.throw (<anonymous>)
at rejected (xxx/node_modules/padlocal-client-ts/dist/Request.js:6:65)
17:07:42 ERR [Request] [tid:50f0aef6], padlocal grpc request failed: 3, error: IOError: [tid:50f0aef6] Exception while handling wechat request: long link send request timeout 17:07:42 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:50f0aef6] request has been cancelled for reason: CLIENT_ERROR: [tid:50f0aef6] Exception while handling wechat request: long link send request timeout 17:07:42 WARN [LongLink] longlink reconnect [1] after delay:1000ms
是的一直有这个错误
重新遇到这个问题，这里已经接收到 扫码和确认登录的事件。 版本：0.65 抑或是 1.20.1
09:52:32 INFO [PadLocalDemo] onScan: Scanned(3)
09:52:43 INFO [PadLocalDemo] onScan: Confirmed(4)
09:52:55 ERR [Request] [tid:e1c2e9b4], padlocal grpc request failed: 3, error: IOError: [tid:e1c2e9b4] Exception while handling wechat request: long link send request timeout
09:52:55 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:e1c2e9b4] request has been cancelled for reason: CLIENT_ERROR: [tid:e1c2e9b4] Exception while handling wechat request: long link send request timeout
09:52:55 WARN [LongLink] longlink reconnect [1] after delay:1000ms
09:53:07 ERR [Request] [tid:27f5451e], padlocal grpc request failed: 3, error: IOError: [tid:27f5451e] Exception while handling wechat request: long link send request timeout
09:53:07 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:27f5451e] request has been cancelled for reason: CLIENT_ERROR: [tid:27f5451e] Exception while handling wechat request: long link send request timeout
09:53:07 WARN [LongLink] longlink reconnect [2] after delay:1000ms
09:53:19 ERR [Request] [tid:03b7a4af], padlocal grpc request failed: 3, error: IOError: [tid:03b7a4af] Exception while handling wechat request: long link send request timeout
09:53:19 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:03b7a4af] request has been cancelled for reason: CLIENT_ERROR: [tid:03b7a4af] Exception while handling wechat request: long link send request timeout
09:53:19 WARN [LongLink] longlink reconnect [3] after delay:2000ms
09:53:32 ERR [Request] [tid:5f46612c], padlocal grpc request failed: 3, error: IOError: [tid:5f46612c] Exception while handling wechat request: long link send request timeout
09:53:32 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:5f46612c] request has been cancelled for reason: CLIENT_ERROR: [tid:5f46612c] Exception while handling wechat request: long link send request timeout
09:53:32 WARN [LongLink] longlink reconnect [4] after delay:3000ms
09:53:45 ERR [Request] [tid:47f6d370], padlocal grpc request failed: 1, error: Error: 2 UNKNOWN: [tid:47f6d370] login failed
09:53:45 ERR start client failed: VError: [tid:47f6d370] request has been cancelled for reason: SERVER_ERROR: 2 UNKNOWN: [tid:47f6d370] login failed
at Request._failAllPendingRequest (/home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/padlocal-client-ts/src/Request.ts:338:15)
at ClientDuplexStreamImpl.
重新遇到这个问题，这里已经接收到 扫码和确认登录的事件。 版本：0.65 抑或是 1.20.1
09:52:32 INFO [PadLocalDemo] onScan: Scanned(3)09:52:43 INFO [PadLocalDemo] onScan: Confirmed(4) 09:52:55 ERR [Request] [tid:e1c2e9b4], padlocal grpc request failed: 3, error: IOError: [tid:e1c2e9b4] Exception while handling wechat request: long link send request timeout 09:52:55 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:e1c2e9b4] request has been cancelled for reason: CLIENT_ERROR: [tid:e1c2e9b4] Exception while handling wechat request: long link send request timeout 09:52:55 WARN [LongLink] longlink reconnect [1] after delay:1000ms 09:53:07 ERR [Request] [tid:27f5451e], padlocal grpc request failed: 3, error: IOError: [tid:27f5451e] Exception while handling wechat request: long link send request timeout 09:53:07 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:27f5451e] request has been cancelled for reason: CLIENT_ERROR: [tid:27f5451e] Exception while handling wechat request: long link send request timeout 09:53:07 WARN [LongLink] longlink reconnect [2] after delay:1000ms 09:53:19 ERR [Request] [tid:03b7a4af], padlocal grpc request failed: 3, error: IOError: [tid:03b7a4af] Exception while handling wechat request: long link send request timeout 09:53:19 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:03b7a4af] request has been cancelled for reason: CLIENT_ERROR: [tid:03b7a4af] Exception while handling wechat request: long link send request timeout 09:53:19 WARN [LongLink] longlink reconnect [3] after delay:2000ms 09:53:32 ERR [Request] [tid:5f46612c], padlocal grpc request failed: 3, error: IOError: [tid:5f46612c] Exception while handling wechat request: long link send request timeout 09:53:32 WARN [LongLink] [120.232.51.42:80] close connection on error,IOError: long link init failed: [tid:5f46612c] request has been cancelled for reason: CLIENT_ERROR: [tid:5f46612c] Exception while handling wechat request: long link send request timeout 09:53:32 WARN [LongLink] longlink reconnect [4] after delay:3000ms 09:53:45 ERR [Request] [tid:47f6d370], padlocal grpc request failed: 1, error: Error: 2 UNKNOWN: [tid:47f6d370] login failed 09:53:45 ERR start client failed: VError: [tid:47f6d370] request has been cancelled for reason: SERVER_ERROR: 2 UNKNOWN: [tid:47f6d370] login failed at Request._failAllPendingRequest (/home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/padlocal-client-ts/src/Request.ts:338:15) at ClientDuplexStreamImpl. (/home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/padlocal-client-ts/src/Request.ts:82:12) at ClientDuplexStreamImpl.emit (node:events:513:28) at ClientDuplexStreamImpl.emit (node:domain:489:12) at Object.onReceiveStatus (/home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/@grpc/grpc-js/src/client.ts:692:18) at Object.onReceiveStatus (/home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/@grpc/grpc-js/src/client-interceptors.ts:417:48) at /home/ubuntu/wechaty-puppet-padlocal-demo/node_modules/@grpc/grpc-js/src/resolving-call.ts:111:24 at processTicksAndRejections (node:internal/process/task_queues:78:11) 09:53:48 INFO [PuppetPadlocal] start login with type: QrLogin 09:53:51 INFO [PadLocalDemo] onScan: Waiting(2)
Have you solved it?
遇到了huan那个问题，也不知道padlocal所说的1.11.14版本解决了么？看报错发现项目部署的环境突然ping不通120.232.51.42这个ip了，是我项目运行的ip地址被封了么，已经运行了几个月，突然报错的然后发现ping不通了。
20:17:37 ERR [Request] [tid:a39fe124], padlocal grpc request failed: 1, error: Error: 2 UNKNOWN: [tid:a39fe124] internal error
0|wx | SubRequestCancelError [VError]: [tid:a39fe124] request has been cancelled for reason: SERVER_ERROR: 2 UNKNOWN: [tid:a39fe124] internal error
0|wx | at Request._failAllPendingRequest (/root/pad-demo/node_modules/padlocal-client-ts/dist/Request.js:265:19)
0|wx | at ClientDuplexStreamImpl.<anonymous> (/root/pad-demo/node_modules/padlocal-client-ts/dist/Request.js:56:18)
0|wx | at ClientDuplexStreamImpl.emit (node:events:394:28)
0|wx | at Object.onReceiveStatus (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/client.js:410:28)
0|wx | at Object.onReceiveStatus (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
0|wx | at /root/pad-demo/node_modules/@grpc/grpc-js/build/src/resolving-call.js:94:78
0|wx | at processTicksAndRejections (node:internal/process/task_queues:78:11) {
0|wx | jse_shortmsg: '[tid:a39fe124] request has been cancelled for reason: SERVER_ERROR',
0|wx | jse_cause: Error: 2 UNKNOWN: [tid:a39fe124] internal error
0|wx | at callErrorFromStatus (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/call.js:31:19)
0|wx | at Object.onReceiveStatus (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/client.js:410:73)
0|wx | at Object.onReceiveStatus (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
0|wx | at /root/pad-demo/node_modules/@grpc/grpc-js/build/src/resolving-call.js:94:78
0|wx | at processTicksAndRejections (node:internal/process/task_queues:78:11)
0|wx | for call at
0|wx | at ServiceClientImpl.makeBidiStreamRequest (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/client.js:394:34)
0|wx | at ServiceClientImpl.action (/root/pad-demo/node_modules/@grpc/grpc-js/build/src/make-client.js:105:19)
0|wx | at new Request (/root/pad-demo/node_modules/padlocal-client-ts/dist/Request.js:41:51)
0|wx | at PadLocalClient.createRequest (/root/pad-demo/node_modules/padlocal-client-ts/dist/PadLocalClient.js:93:21)
0|wx | at PadLocalClientApi.<anonymous> (/root/pad-demo/node_modules/padlocal-client-ts/dist/PadLocalClientApi.js:276:41)
0|wx | at Generator.next (<anonymous>)
0|wx | at /root/pad-demo/node_modules/padlocal-client-ts/dist/PadLocalClientApi.js:27:71
0|wx | at new Promise (<anonymous>)
0|wx | at __awaiter (/root/pad-demo/node_modules/padlocal-client-ts/dist/PadLocalClientApi.js:23:12)
0|wx | at PadLocalClientApi.getMessageImage (/root/pad-demo/node_modules/padlocal-client-ts/dist/PadLocalClientApi.js:273:16) {
0|wx | code: 2,
0|wx | details: '[tid:a39fe124] internal error',
0|wx | metadata: Metadata { internalRepr: [Map], options: {} }
0|wx | },
0|wx | jse_info: {},
0|wx | reason: 1
0|wx | }
Hi @huan , is there any update on this? This issue caused the login not able to be shown up, which is a big issue here.
8 VERB PuppetMemoryMixin setMemory(PadLocalDemo) 13:34:58 VERB WechatyPuppetMixin init() setting memory ... done 13:34:58 VERB WechatyPuppetMixin init() setting up events ... 13:34:58 VERB WechatyPuppetMixin __setupPuppetEvents(Puppet<PuppetPadlocal>(PadLocalDemo)) 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(friendship) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(login) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(logout) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(message) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(post) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-invite) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-join) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-leave) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(room-topic) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(scan) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(dirty) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(dong) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(error) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(heartbeat) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(ready) (listenerCount:0) registering... 13:34:58 VERB PuppetMixin __setupPuppetEvents() puppet.on(reset) (listenerCount:0) registering... 13:34:58 VERB WechatyPuppetMixin __setupPuppetEvents() ... done 13:34:58 VERB WechatyPuppetMixin init() setting up events ... done 13:34:58 VERB WechatyPuppetMixin init() emitting "puppet" event ... 13:34:58 VERB WechatyPuppetMixin init() emitting "puppet" event ... done 13:34:58 VERB ServiceCtl<Wechaty> start() 13:34:58 SILL StateSwitch <Wechaty> active() is false 13:34:58 SILL StateSwitch <Wechaty> inactive() is true 13:34:58 SILL StateSwitch <Wechaty> active() is false 13:34:58 VERB StateSwitch <Wechaty> active(pending) <- (false) 13:34:58 VERB ServiceCtl<Wechaty> start() super.start() ... 13:34:58 VERB WechatyPuppetMixin start() 13:34:58 VERB WechatyPuppetMixin start() super.start() ... 13:34:58 VERB WechatyIoMixin start() 13:34:58 VERB WechatySkeleton start() 13:34:58 VERB WechatyLoginMixin init() 13:34:58 VERB WechatyPuppetMixin init() 13:34:58 VERB WechatifyUserModuleMixin init() 13:34:58 VERB WechatySkeleton init() 13:34:58 VERB Wechaty init() Raven disabled (import("raven") failed) 13:34:58 VERB WechatifyUserModuleMixin init() Wechaty User Module (WUM)s have already wechatified: skip 13:34:58 VERB WechatyPuppetMixin init() skipped because this puppet has already been inited before. 13:34:58 VERB WechatyPuppetMixin start() super.start() ... done 13:34:58 SILL StateSwitch <WechatyReady> active() is false 13:34:58 VERB WechatyPuppetMixin start() starting puppet ... 13:34:58 VERB ReadyMixin start() 13:34:58 VERB PuppetServiceMixin start() 13:34:58 VERB ServiceCtl<PuppetServiceMixin> start() 13:34:58 SILL StateSwitch <PuppetServiceMixin> active() is false 13:34:58 SILL StateSwitch <PuppetServiceMixin> inactive() is true 13:34:58 SILL StateSwitch <PuppetServiceMixin> active() is false 13:34:58 VERB StateSwitch <PuppetServiceMixin> active(pending) <- (false) 13:34:58 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ... 13:34:58 VERB PuppetCacheMixin start() 13:34:58 VERB PuppetLoginMixin start() 13:34:58 VERB PuppetMemoryMixin start() 13:34:58 VERB PuppetSkeleton start() 13:34:58 VERB PuppetCacheAgent start() 13:34:58 VERB PuppetCacheMixin start() "dirty" event listener added 13:34:58 VERB ServiceCtl<PuppetServiceMixin> start() super.start() ... done 13:34:58 VERB ServiceCtl<PuppetServiceMixin> start() this.onStart() ... 13:34:59 INFO ============================================================ Welcome to Wechaty PadLocal puppet!
- puppet-padlocal version: 1.20.1
- padlocal-ts-client version: 0.5.3
============================================================
13:34:59 SILL [Request] [tid:5b13a81b] send event to server, seq:1, ack:undefined, type: 200, payload: {"policy":0}
13:34:59 VERB ServiceCtl<PuppetServiceMixin> start() this.onStart() ... done
13:34:59 SILL StateSwitch <PuppetServiceMixin> active() is pending
13:34:59 VERB StateSwitch <PuppetServiceMixin> active(true) <- (pending)
13:34:59 VERB ServiceCtl<PuppetServiceMixin> start() ... done
13:34:59 VERB PuppetWatchdogAgent start() "heartbeat" event listener added
13:34:59 VERB PuppetWatchdogAgent start() "reset" event listener added
13:34:59 VERB WechatyPuppetMixin start() starting puppet ... done
13:34:59 VERB ServiceCtl<Wechaty> start() super.start() ... done
13:34:59 VERB ServiceCtl<Wechaty> start() this.onStart() ...
13:34:59 VERB Wechaty onStart()
13:34:59 VERB Wechaty <Puppet<PuppetPadlocal>(PadLocalDemo)>(PadLocalDemo) onStart() v1.20.2 is starting...
13:34:59 VERB Wechaty id: dcdba843-e8a4-4940-84da-84cc7f5a8026
13:34:59 VERB Wechaty onStart() ... done
13:34:59 VERB ServiceCtl<Wechaty> start() this.onStart() ... done
13:34:59 SILL StateSwitch <Wechaty> active() is pending
13:34:59 VERB StateSwitch <Wechaty> active(true) <- (pending)
13:34:59 VERB ServiceCtl<Wechaty> start() ... done
13:34:59 INFO StarterBot Starter Bot Started.
13:34:59 SILL [Request] [tid:5b13a81b] receive event from server, seq:1 ack:0, type:15, payload:{"longlinkupdateevent":{"longlinkhost":{"host":"117.184.242.106","port":80},"reconnectimmediately":false,"longlinkhostlistList":[{"host":"117.184.242.106","port":80},{"host":"117.184.242.105","port":80},{"host":"223.166.152.105","port":80},{"host":"223.166.152.106","port":80},{"host":"101.89.15.106","port":80},{"host":"101.89.15.105","port":80}]}}
13:34:59 SILL [Request] [tid:5b13a81b] send event to server, seq:undefined, ack:1, type: 16, payload: {}
13:34:59 SILL [LongLink] update longlink host: [{"host":"117.184.242.106","port":80,"quality":30,"initialQuality":30},{"host":"117.184.242.105","port":80,"quality":25,"initialQuality":25},{"host":"223.166.152.105","port":80,"quality":20,"initialQuality":20},{"host":"223.166.152.106","port":80,"quality":15,"initialQuality":15},{"host":"101.89.15.106","port":80,"quality":10,"initialQuality":10},{"host":"101.89.15.105","port":80,"quality":5,"initialQuality":5}]
13:35:00 SILL [Request] [tid:5b13a81b] receive event from server, seq:0 ack:0, type:201, payload:{"status":0,"logintype":1}
13:35:00 INFO [PuppetPadlocal] start login with type: AutoLogin
13:35:00 SILL [Request] [tid:5b13a81b] receive event from server, seq:2 ack:0, type:10, payload:{"longlinkrequest":{"messageid":"6e5ed507ed7d485389ca45be4c9ea6a2","longlinkid":"","initphase":false}}
13:35:00 SILL [LongLink] longlink start connect: 117.184.242.106:80
13:35:10 WARN [LongLink] [] longlink socket connect timeout
13:35:10 SILL [LongLink] adjust host quality:{"host":"117.184.242.106","port":80,"quality":28,"initialQuality":30}, connect success:false, host list:[{"host":"117.184.242.106","port":80,"quality":28,"initialQuality":30},{"host":"117.184.242.105","port":80,"quality":25,"initialQuality":25},{"host":"223.166.152.105","port":80,"quality":20,"initialQuality":20},{"host":"223.166.152.106","port":80,"quality":15,"initialQuality":15},{"host":"101.89.15.106","port":80,"quality":10,"initialQuality":10},{"host":"101.89.15.105","port":80,"quality":5,"initialQuality":5}]
13:35:10 WARN [LongLink] [] close connection on error,IOError: longlink socket connect timeout
13:35:10 WARN [LongLink] longlink reconnect [1] after delay:1000ms
13:35:10 ERR [Request] [tid:5b13a81b], padlocal grpc request failed: 3, error: IOError: [tid:5b13a81b] Exception while handling wechat request: longlink fail to connect: longlink socket connect timeout
13:35:10 ERR start client failed: VError: [tid:5b13a81b] request has been cancelled for reason: CLIENT_ERROR: [tid:5b13a81b] Exception while handling wechat request: longlink fail to connect: longlink socket connect timeout
at Request._failAllPendingRequest (E:\getting-started\node_modules\padlocal-client-ts\src\Request.ts:338:15)
at Request.error (E:\getting-started\node_modules\padlocal-client-ts\src\Request.ts:351:10)
at Request.
@padlocal , may I know what is the iplist of the longlink? why it returned those ips? And none of these ips can be pinged successfully, can you folks ping below ips successfully? Is there anything wrong here?
13:34:59 SILL [Request] [tid:5b13a81b] receive event from server, seq:1 ack:0, type:15, payload:{"longlinkupdateevent":{"longlinkhost":{"host":"117.184.242.106","port":80},"reconnectimmediately":false,"longlinkhostlistList":[{"host":"117.184.242.106","port":80},{"host":"117.184.242.105","port":80},{"host":"223.166.152.105","port":80},{"host":"223.166.152.106","port":80},{"host":"101.89.15.106","port":80},{"host":"101.89.15.105","port":80}]}} 13:34:59 SILL [Request] [tid:5b13a81b] send event to server, seq:undefined, ack:1, type: 16, payload: {} 13:34:59 SILL [LongLink] update longlink host: [{"host":"117.184.242.106","port":80,"quality":30,"initialQuality":30},{"host":"117.184.242.105","port":80,"quality":25,"initialQuality":25},{"host":"223.166.152.105","port":80,"quality":20,"initialQuality":20},{"host":"223.166.152.106","port":80,"quality":15,"initialQuality":15},{"host":"101.89.15.106","port":80,"quality":10,"initialQuality":10},{"host":"101.89.15.105","port":80,"quality":5,"initialQuality":5}]
these errors seems to be thrown from this class, https://github.com/padlocal/padlocal-client-ts/blob/master/src/Request.ts
May I know what does the Longlink do? and even I tried several different devices and different networks, they all returned the same set of ip list, is there any cache of it? Just curious is it possible to use some workaround to make me able to login? e.g. Not using this LongLink or switch to another protocol rather than grpc prototocol?
Thanks a lot @padlocal for helping with this! I switched to another token and it no longer has this issue, according to @padlocal it might because the ip list which was used long time ago(already invalid ips) were remebered or cached so that it returned the stale ip list, which of course will be timed out.
However, if this is the case, I would like to know, who remembered those ip list? the weixin server? Or wechaty server? It sounds like this is a bug from one certain side, if the ip cannot be connected, should we tell the server to not return the cached ip list, instead give us the newest ips? Otherwise we will timeout forever.
My problem has been resolved after I switched to another token. However, is there any client support in the community to refund or regenerate the old token for me? Since I have not received any the reply from wechat support.
