moleculerjs / moleculer

:rocket: Progressive microservices framework for Node.js
https://moleculer.services/
MIT License
6.13k stars 580 forks source link

Strange behaviour on service restart #339

Closed chrvadala closed 6 years ago

chrvadala commented 6 years ago

Hi Icebob, I've just found a strange behaviour with a service that I gracefully stop and then restart. It seems that when the service goes up the second time the DISCOVER packet is ignored by others. As result, every other node can't call service actions served by this restarted service.

I use MQTT as transport I use the async stopped() hook that resolves after 5 seconds

I noticed that without a pause by few seconds on stop, the service doesn't have enough time to send its disconnect message. But this is related with https://github.com/moleculerjs/moleculer/issues/306.

Prerequisites

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

Expected Behavior

When the service is restarted actions should be correctly available again.

Current Behavior

After a service restart actions aren't available

Steps to Reproduce

  1. Start a service attached to an MQTT broker
  2. Attach moleculer-cli on the same broker
  3. Use the command actions on moleculer cli (actions are available)
  4. Stop service
  5. Start service
  6. Use the command actions on moleculer cli (actions aren't available)

Reproduce code snippet

NODEID=test2 TRANSPORTER=mqtt LOGLEVEL=debug ./node_modules/.bin/moleculer-runner test2.service.js

module.exports = {
    name: "test2",
    async stopped(){
        this.logger.info('pre')
        await new Promise(resolve => setTimeout(resolve, 5000))
        this.logger.info('post')
    },
    actions: {
        sayHi(ctx) {
            this.logger.info("hi")
        }
    }
}

Failure Logs

The log seems good

user:~/a$ NODEID=test2 TRANSPORTER=mqtt LOGLEVEL=debug ./node_modules/.bin/moleculer-runner test2.service.js
[2018-07-26T14:08:32.418Z] INFO  test2/BROKER: Moleculer v0.13.1 is starting...
[2018-07-26T14:08:32.420Z] INFO  test2/BROKER: Node ID: test2
[2018-07-26T14:08:32.421Z] INFO  test2/BROKER: Namespace: <not defined>
[2018-07-26T14:08:32.421Z] INFO  test2/REGISTRY: Strategy: RoundRobinStrategy
[2018-07-26T14:08:32.423Z] INFO  test2/BROKER: Serializer: JSONSerializer
[2018-07-26T14:08:32.424Z] INFO  test2/BROKER: Transporter: MqttTransporter
[2018-07-26T14:08:32.425Z] INFO  test2/BROKER: Registered 10 internal middleware(s).
[2018-07-26T14:08:32.430Z] DEBUG test2/BROKER: Load service 'test2.service.js'...
[2018-07-26T14:08:32.431Z] INFO  test2/TRANSIT: Connecting to the transporter...
[2018-07-26T14:08:32.510Z] INFO  test2/TRANSPORTER: MQTT client is connected.
[2018-07-26T14:08:32.514Z] DEBUG test2/TRANSIT: Send DISCOVER packet to '<all nodes>'
[2018-07-26T14:08:32.519Z] DEBUG test2/TRANSIT: Incoming INFO packet from 'cli-pc-17085'
[2018-07-26T14:08:32.521Z] DEBUG test2/BROKER: Broadcast '$node.connected' local event.
[2018-07-26T14:08:32.521Z] INFO  test2/REGISTRY: Node 'cli-pc-17085' connected.
[2018-07-26T14:08:33.019Z] DEBUG test2/BROKER: Broadcast '$transporter.connected' local event.
[2018-07-26T14:08:33.023Z] INFO  test2/REGISTRY: '$node' service is registered.
[2018-07-26T14:08:33.023Z] DEBUG test2/BROKER: Broadcast '$services.changed' local event.
[2018-07-26T14:08:33.023Z] INFO  test2/REGISTRY: 'test2' service is registered.
[2018-07-26T14:08:33.024Z] DEBUG test2/BROKER: Broadcast '$services.changed' local event.
[2018-07-26T14:08:33.024Z] INFO  test2/BROKER: ServiceBroker with 2 service(s) is started successfully.
[2018-07-26T14:08:33.026Z] DEBUG test2/TRANSIT: Send INFO packet to '<all nodes>'
[2018-07-26T14:08:33.068Z] DEBUG test2/TRANSIT: Incoming HEARTBEAT packet from 'cli-pc-17085'
[2018-07-26T14:08:38.074Z] DEBUG test2/TRANSIT: Incoming HEARTBEAT packet from 'cli-pc-17085'
[2018-07-26T14:08:38.234Z] DEBUG test2/TRANSIT: Send HEARTBEAT packet to '<all nodes>'
^C[2018-07-26T14:08:40.776Z] DEBUG test2/TRANSIT: Send INFO packet to '<all nodes>'
[2018-07-26T14:08:40.777Z] INFO  test2/TEST2: pre
[2018-07-26T14:08:43.077Z] DEBUG test2/TRANSIT: Incoming HEARTBEAT packet from 'cli-pc-17085'
[2018-07-26T14:08:43.239Z] DEBUG test2/TRANSIT: Send HEARTBEAT packet to '<all nodes>'
[2018-07-26T14:08:45.782Z] INFO  test2/TEST2: post
[2018-07-26T14:08:45.783Z] DEBUG test2/BROKER: Broadcast '$transporter.disconnected' local event.
[2018-07-26T14:08:45.783Z] DEBUG test2/TRANSIT: Send DISCONNECT packet to '<all nodes>'
[2018-07-26T14:08:45.784Z] INFO  test2/BROKER: ServiceBroker is stopped. Good bye.
user:~/a$ NODEID=test2 TRANSPORTER=mqtt LOGLEVEL=debug ./node_modules/.bin/moleculer-runner test2.service.js
[2018-07-26T14:08:48.805Z] INFO  test2/BROKER: Moleculer v0.13.1 is starting...
[2018-07-26T14:08:48.807Z] INFO  test2/BROKER: Node ID: test2
[2018-07-26T14:08:48.807Z] INFO  test2/BROKER: Namespace: <not defined>
[2018-07-26T14:08:48.808Z] INFO  test2/REGISTRY: Strategy: RoundRobinStrategy
[2018-07-26T14:08:48.809Z] INFO  test2/BROKER: Serializer: JSONSerializer
[2018-07-26T14:08:48.810Z] INFO  test2/BROKER: Transporter: MqttTransporter
[2018-07-26T14:08:48.811Z] INFO  test2/BROKER: Registered 10 internal middleware(s).
[2018-07-26T14:08:48.816Z] DEBUG test2/BROKER: Load service 'test2.service.js'...
[2018-07-26T14:08:48.817Z] INFO  test2/TRANSIT: Connecting to the transporter...
[2018-07-26T14:08:48.893Z] INFO  test2/TRANSPORTER: MQTT client is connected.
[2018-07-26T14:08:48.897Z] DEBUG test2/TRANSIT: Send DISCOVER packet to '<all nodes>'
[2018-07-26T14:08:48.901Z] DEBUG test2/TRANSIT: Incoming INFO packet from 'cli-pc-17085'
[2018-07-26T14:08:48.903Z] DEBUG test2/BROKER: Broadcast '$node.connected' local event.
[2018-07-26T14:08:48.903Z] INFO  test2/REGISTRY: Node 'cli-pc-17085' connected.
[2018-07-26T14:08:49.403Z] DEBUG test2/BROKER: Broadcast '$transporter.connected' local event.
[2018-07-26T14:08:49.406Z] INFO  test2/REGISTRY: '$node' service is registered.
[2018-07-26T14:08:49.406Z] DEBUG test2/BROKER: Broadcast '$services.changed' local event.
[2018-07-26T14:08:49.407Z] INFO  test2/REGISTRY: 'test2' service is registered.
[2018-07-26T14:08:49.407Z] DEBUG test2/BROKER: Broadcast '$services.changed' local event.
[2018-07-26T14:08:49.407Z] INFO  test2/BROKER: ServiceBroker with 2 service(s) is started successfully.
[2018-07-26T14:08:49.409Z] DEBUG test2/TRANSIT: Send INFO packet to '<all nodes>'
[2018-07-26T14:08:53.085Z] DEBUG test2/TRANSIT: Incoming HEARTBEAT packet from 'cli-pc-17085'
[2018-07-26T14:08:54.616Z] DEBUG test2/TRANSIT: Send HEARTBEAT packet to '<all nodes>'
[2018-07-26T14:08:58.088Z] DEBUG test2/TRANSIT: Incoming HEARTBEAT packet from 'cli-pc-17085'
chrvadala commented 6 years ago

I found a better way to replicate this issue.

Now you can see that service B can't contact serviceA Hope that this way can help you.

serviceA.js

const {ServiceBroker} = require("moleculer");

let brokerA = new ServiceBroker({nodeID: "serviceA", transporter: "mqtt://localhost:1883"})

brokerA.createService({
    name: "serviceA",
    async stopped() {
        this.logger.info('pre - stop')
        await new Promise(resolve => setTimeout(resolve, 1000))
        this.logger.info('post - stop')
    },
    actions: {
        sayHi() {
            this.logger.info("hi")
        }
    }
})

brokerA.start()

serviceB.js

const {ServiceBroker} = require("moleculer");

let brokerB = new ServiceBroker({nodeID: "serviceB", transporter: "mqtt://localhost:1883"})

brokerB.createService({
    name: "serviceB",
    started() {
        this.timer = setInterval(() => {
            this.broker.call('serviceA.sayHi')
                .then(() => this.logger.info('OK'))
                .catch(() => this.logger.error('FAIL'))
        }, 1000)
    },
    stopped() {
        clearTimeout(this.timer)
    },
})

brokerB.start()
icebob commented 6 years ago

Thanks, I could reproduce. However, it works well with other transporters, except MQTT.

icebob commented 6 years ago

Fixed. MQTT client should wait for the in-flight messages (DISCONNECT) before closing the connection.

chrvadala commented 6 years ago

Just tested and it works very well. Thanks!