kaiyuanshe / osschat

Apache Open Source Software Chat BOT
https://oss.chat/dashboard/
Apache License 2.0
184 stars 45 forks source link

Restart service when bot is off - [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return. #158

Open hailiang-wang opened 3 years ago

hailiang-wang commented 3 years ago

Service does not work, with following trace.

 21:00:54 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | ERROR (server):
osschat_1  |     type: "error"
osschat_1  | INFO (server): Connected
osschat_1  | 21:09:33 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 21:18:12 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 21:26:51 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 21:35:30 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 21:44:09 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 21:52:48 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:01:27 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:10:06 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:18:45 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:27:24 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:36:02 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:44:41 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 22:53:20 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.                                                     osschat_1  | 23:01:59 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.                                                     osschat_1  | 23:10:38 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 23:19:17 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 23:27:56 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 23:36:35 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 23:45:14 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 23:53:53 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 00:02:32 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 00:11:10 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 00:17:44 INFO Chatops roomMessage(21588818228@chatroom, https://github.com/chatopera/cskefu/issues/480#issuecomment-933057883)
osschat_1  | 00:17:44 ERR Chatops roomMessage() this.bot is offline
osschat_1  | 00:17:44 INFO Chatops roomMessage(21588818228@chatroom, UrlLink<https://github.com/chatopera/cskefu/issues/480#issuecomment-933057883>)
osschat_1  | 00:17:44 ERR Chatops roomMessage() this.bot is offline
osschat_1  | INFO (http): POST / 200 - 19ms
osschat_1  | INFO (server): POST http://localhost:3000/ - 200
osschat_1  | INFO (http): POST / 200 - 0ms
osschat_1  | INFO (server): POST http://localhost:3000/ - 200
osschat_1  | 00:19:49 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 00:19:55 INFO Config registering process.on("unhandledRejection") for development/debug
osschat_1  | 00:19:55 VERB Config constructor()
osschat_1  | 00:19:55 VERB Wechaty init() getRavenDsn() return undefined, skipped.
osschat_1  | 00:19:55 VERB wechaty-puppet-service monkeyPatchMetadataFromHttp2Headers()
osschat_1  | 00:19:55 VERB ResolverWechaty setup()
osschat_1  | 00:19:55 VERB getWechaty getHAWechaty()
osschat_1  | 00:19:55 VERB getMemory getMemory(heroku-wechaty)
osschat_1  | 00:19:55 VERB getMemory getMemory() creating new file memory
osschat_1  | 00:19:55 VERB MemoryCard constructor({"name":"heroku-wechaty"})

Describe the solution you'd like

When OSSChat is restarted, the bot is up and works.

Auto detect the error and exit, as later the server would auto restart with some monitor.

huan commented 3 years ago

It's very hard to understand the program situation without any reproducible steps.

HAWechaty definitely has lots of bugs (it's still WIP), and the PuppetPadlocal has issues sometimes too.

If we find any reproducible steps, I'd like to dig into them and see what happens.

hailiang-wang commented 3 years ago

更多日志

osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/observeOn.js:10:197
osschat_1  |     at QueueAction.work (/app/node_modules/rxjs/dist/cjs/internal/util/executeSchedule.js:8:9)
osschat_1  |     at QueueAction.AsyncAction._execute (/app/node_modules/rxjs/dist/cjs/internal/scheduler/AsyncAction.js:76:18)
osschat_1  |     at QueueAction.execute (/app/node_modules/rxjs/dist/cjs/internal/scheduler/QueueAction.js:41:18)
osschat_1  |     at QueueScheduler.AsyncScheduler.flush (/app/node_modules/rxjs/dist/cjs/internal/scheduler/AsyncScheduler.js:39:33)
osschat_1  |     at QueueAction.schedule (/app/node_modules/rxjs/dist/cjs/internal/scheduler/QueueAction.js:35:24)
osschat_1  |     at QueueScheduler.Scheduler.schedule (/app/node_modules/rxjs/dist/cjs/internal/Scheduler.js:13:57)
osschat_1  |     at Object.executeSchedule (/app/node_modules/rxjs/dist/cjs/internal/util/executeSchedule.js:7:42)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/observeOn.js:10:126
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/mergeInternals.js:28:28
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/mergeInternals.js:28:28
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/mergeInternals.js:28:28
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/switchMap.js:17:190
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/mergeInternals.js:28:28
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at /app/node_modules/rxjs/dist/cjs/internal/operators/map.js:10:24
osschat_1  |     at OperatorSubscriber._this._next (/app/node_modules/rxjs/dist/cjs/internal/operators/OperatorSubscriber.js:28:21)
osschat_1  |     at OperatorSubscriber.Subscriber.next (/app/node_modules/rxjs/dist/cjs/internal/Subscriber.js:72:18)
osschat_1  |     at AsyncAction.work (/app/node_modules/rxjs/dist/cjs/internal/observable/timer.js:28:28)
osschat_1  |     at AsyncAction._execute (/app/node_modules/rxjs/dist/cjs/internal/scheduler/AsyncAction.js:76:18)
osschat_1  |     at AsyncAction.execute (/app/node_modules/rxjs/dist/cjs/internal/scheduler/AsyncAction.js:64:26)
osschat_1  |     at AsyncScheduler.flush (/app/node_modules/rxjs/dist/cjs/internal/scheduler/AsyncScheduler.js:39:33)
osschat_1  |     at listOnTimeout (internal/timers.js:557:17)
osschat_1  |     at processTimers (internal/timers.js:500:7)
osschat_1  | 06:28:42 VERB StateSwitch <PuppetPadlocal> ready(off, noCross=false)
osschat_1  | 06:28:42 WARN [PuppetPadlocal] stop() is called on a OFF puppet. await ready(off) and return.
osschat_1  | 06:29:22 VERB Contact say(ding)
osschat_1  | 06:30:50 VERB Contact say(ding)
osschat_1  | 06:32:18 VERB Contact say(ding)
osschat_1  | 06:33:47 VERB Contact say(ding)