gracefulStopTimeout work weird

roytan883 commented 6 years ago

Prerequisites

Please answer the following questions for yourself before submitting an issue.

[x] I am running the latest version
[x] I checked the documentation and found no answer
[x] I checked to make sure that this issue has not already been filed
[x] I'm reporting the issue to the correct repository

Expected Behavior

gracefulStop should wait requests to be handled before stop

Current Behavior

broker stop directly

Steps to Reproduce

Please provide detailed steps for reproducing the issue.

config broker with:

let broker = new ServiceBroker({
trackContext: true, //for gracefulStopTimeout
gracefulStopTimeout: 1000 * 5, // waiting max 5 sec

create demo service with async action:

async helloAsync() {
let count = this.helloAsyncCount++
console.log(`${RtsConfig.nodeID} helloAsync Count = ${count} <<<<<<<<<<<<`)
await Bluebird.delay(4000)
let ret = `${RtsConfig.nodeID} helloAsync Count = ${count} ..............`;
console.log(ret)
return ret
}

another process remote call demo.helloAsync every second

check demo service log:

INFO broker: ServiceBroker with 2 service(s) is started successfully.
=====[rts-demo-dev-88-0]=====>>>>> started
rts-demo-dev-88-0 helloAsync Count = 0 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 1 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 2 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 3 <<<<<<<<<<<<
[RestartSelf] watch file change: /home/mydev/projects/rts/server/services/demo/version
[RestartSelf] wait 5s to check if content changed
[RestartSelf] watch file change: /home/mydev/projects/rts/server/services/demo/version
[RestartSelf] wait 5s to check if content changed
rts-demo-dev-88-0 helloAsync Count = 0 ..............
rts-demo-dev-88-0 helloAsync Count = 4 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 1 ..............
rts-demo-dev-88-0 helloAsync Count = 5 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 2 ..............
rts-demo-dev-88-0 helloAsync Count = 6 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 7 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 3 ..............
rts-demo-dev-88-0 helloAsync Count = 4 ..............
rts-demo-dev-88-0 helloAsync Count = 8 <<<<<<<<<<<<
[RestartSelf] watch file content changed: /home/mydev/projects/rts/server/services/demo/version
[RestartSelf] do gracefulShutdownCallback
called when graceful shutdown:  2018-7-2 14:57:51
wait 0s to shutdwon as ID[0]
called when graceful shutdown begin stop():  2018-7-2 14:57:51
INFO -> demo Service stopped.
INFO broker: ServiceBroker is stopped successfully. Good bye.
called when graceful shutdown stopped:  2018-7-2 14:57:51
[RestartSelf] process exit(0)

Context

Moleculer version: 0.12.8
NodeJS version: 8.11.1
Operating System: ubuntu server 16.04

comments

The weird part is that remote call not actived graceful stop (which stop immediately), but if call from demo service itself, graceful stop works as expect.

here is log , which call itself before stop , make graceful stop works:

async serviceCreated() {
    this.logger.info(`${this.name} Service created.`);
    selfRestart.init(path.join(__dirname, './version'), async () => {
      console.log("called when graceful shutdown: ", (new Date()).toLocaleString())
      console.log(`wait ${RtsConfig.id * 5}s to shutdwon as ID[${RtsConfig.id}]`)
      await Bluebird.delay(RtsConfig.id * 5 * 1000)
      //demo already has one action called
      this.broker.call('demo.helloAsync')
      console.log("called when graceful shutdown begin stop(): ", (new Date()).toLocaleString())
      await this.broker.stop()
      console.log("called when graceful shutdown stopped: ", (new Date()).toLocaleString())
    })
  }

[RestartSelf] watch file change: /home/mydev/projects/rts/server/services/demo/version
[RestartSelf] wait 5s to check if content changed
rts-demo-dev-88-0 helloAsync Count = 4 ..............
rts-demo-dev-88-0 helloAsync Count = 8 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 5 ..............
rts-demo-dev-88-0 helloAsync Count = 9 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 6 ..............
rts-demo-dev-88-0 helloAsync Count = 10 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 7 ..............
rts-demo-dev-88-0 helloAsync Count = 11 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 8 ..............
rts-demo-dev-88-0 helloAsync Count = 12 <<<<<<<<<<<<
[RestartSelf] watch file content changed: /home/mydev/projects/rts/server/services/demo/version
[RestartSelf] do gracefulShutdownCallback
called when graceful shutdown:  2018-7-2 15:19:55
wait 0s to shutdwon as ID[0]
rts-demo-dev-88-0 helloAsync Count = 13 <<<<<<<<<<<<
called when graceful shutdown begin stop():  2018-7-2 15:19:55
rts-demo-dev-88-0 helloAsync Count = 9 ..............
rts-demo-dev-88-0 helloAsync Count = 14 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 10 ..............
rts-demo-dev-88-0 helloAsync Count = 15 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 16 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 11 ..............
rts-demo-dev-88-0 helloAsync Count = 12 ..............
rts-demo-dev-88-0 helloAsync Count = 17 <<<<<<<<<<<<
rts-demo-dev-88-0 helloAsync Count = 13 ..............
INFO -> demo Service stopped.
INFO broker: ServiceBroker is stopped successfully. Good bye.
called when graceful shutdown stopped:  2018-7-2 15:19:59
[RestartSelf] process exit(0)

begin stop() and stopped has 5s waiting

roytan883 commented 6 years ago

Is there has status stopping ? I think the logic should be:

1, start stop 
2, broadcast stopping to other nodes(stopping) 
3, handle remain requests( meanwhile other nodes not send any new request to this node) 
4, handle all request finished or timeout 
5, broadcast stopped to other nodes(stopped) 
6, stop end

icebob commented 6 years ago

Yes the stopping logic doesn't work very properly, but I've fixed it, so it will be better in v0.13. Same for remote calls, 0.13 will do a graceful shutdown with remote calls too.

moleculerjs / moleculer