search

moleculerjs / moleculer

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

kafka transporter: Seeing connection lost #207

Closed mailaneel closed 6 years ago

mailaneel commented 6 years ago 
convoservice_1  | [2018-02-28T09:51:41.185Z] INFO  localservices/BROKER: Moleculer v0.12.0-rc1 is starting...
convoservice_1  | [2018-02-28T09:51:41.188Z] INFO  localservices/BROKER: Node ID: localservices
convoservice_1  | [2018-02-28T09:51:41.189Z] INFO  localservices/BROKER: Namespace: <not defined>
convoservice_1  | [2018-02-28T09:51:41.190Z] INFO  localservices/REGISTRY: Strategy: RoundRobinStrategy
convoservice_1  | [2018-02-28T09:51:41.193Z] INFO  localservices/BROKER: Transporter: KafkaTransporter
convoservice_1  | [2018-02-28T09:51:41.202Z] INFO  localservices/REGISTRY: '$node' service is registered.
convoservice_1  | [2018-02-28T09:51:41.361Z] INFO  localservices/REGISTRY: 'ds' service is registered.
convoservice_1  | [2018-02-28T09:51:41.367Z] INFO  localservices/REGISTRY: 'sendJoinMessage.worker' service is registered.
convoservice_1  | [2018-02-28T09:51:41.377Z] INFO  localservices/TRANSIT: Connecting to the transporter...
convoservice_1  | [2018-02-28T09:51:41.378Z] WARN  localservices/TRANSPORTER: Kafka Transporter is an EXPERIMENTAL transporter. Do NOT use it in production yet!
convoservice_1  | [2018-02-28T09:52:06.396Z] INFO  localservices/BROKER: ServiceBroker with 3 service(s) is started successfully.
convoservice_1  | [2018-02-28T10:13:23.892Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Exception: CONNECTION_LOSS[-4]
convoservice_1  | [2018-02-28T10:13:23.893Z] ERROR localservices/TRANSPORTER: Kafka Client error Exception: CONNECTION_LOSS[-4]
convoservice_1  | [2018-02-28T10:13:23.894Z] ERROR localservices/TRANSPORTER: Kafka Producer error Exception: CONNECTION_LOSS[-4]
convoservice_1  | [2018-02-28T10:13:23.915Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
convoservice_1  | [2018-02-28T10:13:23.919Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
convoservice_1  | [2018-02-28T10:13:24.006Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
mailaneel commented 6 years ago

I see these topics

MOL.DISCONNECT
MOL.DISCOVER
MOL.DISCOVER.localservices
MOL.EVENT.localservices
MOL.HEARTBEAT
MOL.INFO
MOL.INFO.localservices
MOL.PING
MOL.PING.localservices
MOL.PONG.localservices
MOL.REQ.localservices
MOL.RES.localservices
icebob commented 6 years ago

Please show the transporter config in broker options.

mailaneel commented 6 years ago 
module.exports = {
  nodeID: process.env.NODEID || 'local-services',
  logger: true,
  logLevel: process.env.LOG_LEVEL || 'info',
  transporter: 'kafka://zookeeper:2181',
  requestTimeout: 5 * 1000,
  ContextFactory,
  circuitBreaker: {
    enabled: true
  },
  metrics: false,
  statistics: false
}
icebob commented 6 years ago

Thanks, it seems correct. Try to set debug loglevel. Probably prints some useful message.

mailaneel commented 6 years ago 
convoservice_1  | [2018-02-28T10:40:30.900Z] INFO  localservices/BROKER: Moleculer v0.12.0-rc1 is starting...
convoservice_1  | [2018-02-28T10:40:30.905Z] INFO  localservices/BROKER: Node ID: localservices
convoservice_1  | [2018-02-28T10:40:30.906Z] INFO  localservices/BROKER: Namespace: <not defined>
convoservice_1  | [2018-02-28T10:40:30.908Z] INFO  localservices/REGISTRY: Strategy: RoundRobinStrategy
convoservice_1  | [2018-02-28T10:40:30.912Z] INFO  localservices/BROKER: Transporter: KafkaTransporter
convoservice_1  | [2018-02-28T10:40:30.926Z] INFO  localservices/REGISTRY: '$node' service is registered.
convoservice_1  | [2018-02-28T10:40:30.927Z] DEBUG localservices/BROKER: Broadcast '$services.changed' local event.
convoservice_1  | [2018-02-28T10:40:30.929Z] DEBUG localservices/BROKER: Search services in './src/services/datastore/**/*.service.js'...
convoservice_1  | [2018-02-28T10:40:30.935Z] DEBUG localservices/BROKER: Load service 'datastore.service.js'...
convoservice_1  | [2018-02-28T10:40:31.128Z] INFO  localservices/REGISTRY: 'ds' service is registered.
convoservice_1  | [2018-02-28T10:40:31.128Z] DEBUG localservices/BROKER: Broadcast '$services.changed' local event.
convoservice_1  | [2018-02-28T10:40:31.129Z] DEBUG localservices/BROKER: Search services in './src/workers/*.worker.js'...
convoservice_1  | [2018-02-28T10:40:31.131Z] DEBUG localservices/BROKER: Load service 'sendJoinMessage.worker.js'...
convoservice_1  | [2018-02-28T10:40:31.137Z] INFO  localservices/REGISTRY: 'sendJoinMessage.worker' service is registered.
convoservice_1  | [2018-02-28T10:40:31.137Z] DEBUG localservices/BROKER: Broadcast '$services.changed' local event.
convoservice_1  | [2018-02-28T10:40:31.171Z] INFO  localservices/TRANSIT: Connecting to the transporter...
convoservice_1  | [2018-02-28T10:40:31.173Z] WARN  localservices/TRANSPORTER: Kafka Transporter is an EXPERIMENTAL transporter. Do NOT use it in production yet!
convoservice_1  | [2018-02-28T10:40:56.323Z] DEBUG localservices/TRANSIT: Send DISCOVER packet to 'all nodes'
convoservice_1  | [2018-02-28T10:40:56.854Z] DEBUG localservices/BROKER: Broadcast '$transporter.connected' local event.
convoservice_1  | [2018-02-28T10:40:56.859Z] INFO  localservices/BROKER: ServiceBroker with 3 service(s) is started successfully.
convoservice_1  | [2018-02-28T10:40:56.862Z] DEBUG localservices/TRANSIT: Send INFO packet to 'all nodes'
convoservice_1  | [2018-02-28T10:41:02.065Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T10:41:07.066Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T10:41:12.065Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'

and still going after 30 mins..

convoservice_1  | [2018-02-28T11:07:17.532Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T11:07:22.533Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T11:07:27.534Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'

but my previous session timed out after 10 mins and did not re-connect. I will try to replicate and report it with debug log

icebob commented 6 years ago

I tried it on my PC but I didn't find any problem with Kafka transporter.

I tested with https://github.com/wurstmeister/kafka-docker.git and docker-compose -f docker-compose-single-broker.yml up

mailaneel commented 6 years ago

I have used bitnami with 3 node https://github.com/bitnami/bitnami-docker-kafka/blob/master/README.md

icebob commented 6 years ago

I will try it. It seems it is a similar issue: https://github.com/SOHU-Co/kafka-node/issues/452#issuecomment-242709087

mailaneel commented 6 years ago

some more logs

onvoservice_1  | [2018-02-28T20:55:52.677Z] DEBUG localservices/TRANSPORTER: { Exception: CONNECTION_LOSS[-4]
convoservice_1  |     at ConnectionManager.cleanupPendingQueue (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:189:46)
convoservice_1  |     at ConnectionManager.onSocketClosed (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:274:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at TCP._handle.close [as _onclose] (net.js:559:12)
convoservice_1  |   code: -4,
convoservice_1  |   name: 'CONNECTION_LOSS',
convoservice_1  |   path: undefined,
convoservice_1  |   message: 'Exception: CONNECTION_LOSS[-4]' }
convoservice_1  | [2018-02-28T20:55:52.679Z] ERROR localservices/TRANSPORTER: Kafka Client error Exception: CONNECTION_LOSS[-4]
convoservice_1  | [2018-02-28T20:55:52.680Z] DEBUG localservices/TRANSPORTER: { Exception: CONNECTION_LOSS[-4]
convoservice_1  |     at ConnectionManager.cleanupPendingQueue (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:189:46)
convoservice_1  |     at ConnectionManager.onSocketClosed (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:274:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at TCP._handle.close [as _onclose] (net.js:559:12)
convoservice_1  |   code: -4,
convoservice_1  |   name: 'CONNECTION_LOSS',
convoservice_1  |   path: undefined,
convoservice_1  |   message: 'Exception: CONNECTION_LOSS[-4]' }
convoservice_1  | [2018-02-28T20:55:52.681Z] ERROR localservices/TRANSPORTER: Kafka Producer error Exception: CONNECTION_LOSS[-4]
convoservice_1  | [2018-02-28T20:55:52.681Z] DEBUG localservices/TRANSPORTER: { Exception: CONNECTION_LOSS[-4]
convoservice_1  |     at ConnectionManager.cleanupPendingQueue (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:189:46)
convoservice_1  |     at ConnectionManager.onSocketClosed (/app/node_modules/node-zookeeper-client/lib/ConnectionManager.js:274:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at TCP._handle.close [as _onclose] (net.js:559:12)
convoservice_1  |   code: -4,
convoservice_1  |   name: 'CONNECTION_LOSS',
convoservice_1  |   path: undefined,
convoservice_1  |   message: 'Exception: CONNECTION_LOSS[-4]' }
convoservice_1  | [2018-02-28T20:55:52.703Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
convoservice_1  | [2018-02-28T20:55:52.704Z] DEBUG localservices/TRANSPORTER: { BrokerNotAvailableError: Could not find the leader
convoservice_1  |     at new BrokerNotAvailableError (/app/node_modules/kafka-node/lib/errors/BrokerNotAvailableError.js:11:9)
convoservice_1  |     at Client.<anonymous> (/app/node_modules/kafka-node/lib/client.js:548:19)
convoservice_1  |     at Client.handleReceivedData (/app/node_modules/kafka-node/lib/client.js:770:60)
convoservice_1  |     at Socket.<anonymous> (/app/node_modules/kafka-node/lib/client.js:729:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at addChunk (_stream_readable.js:269:12)
convoservice_1  |     at readableAddChunk (_stream_readable.js:256:11)
convoservice_1  |     at Socket.Readable.push (_stream_readable.js:213:10)
convoservice_1  |     at TCP.onread (net.js:599:20) message: 'Could not find the leader' }
convoservice_1  | [2018-02-28T20:55:52.705Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
convoservice_1  | [2018-02-28T20:55:52.706Z] DEBUG localservices/TRANSPORTER: { BrokerNotAvailableError: Could not find the leader
convoservice_1  |     at new BrokerNotAvailableError (/app/node_modules/kafka-node/lib/errors/BrokerNotAvailableError.js:11:9)
convoservice_1  |     at Client.<anonymous> (/app/node_modules/kafka-node/lib/client.js:548:19)
convoservice_1  |     at Client.handleReceivedData (/app/node_modules/kafka-node/lib/client.js:770:60)
convoservice_1  |     at Socket.<anonymous> (/app/node_modules/kafka-node/lib/client.js:729:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at addChunk (_stream_readable.js:269:12)
convoservice_1  |     at readableAddChunk (_stream_readable.js:256:11)
convoservice_1  |     at Socket.Readable.push (_stream_readable.js:213:10)
convoservice_1  |     at TCP.onread (net.js:599:20) message: 'Could not find the leader' }
convoservice_1  | [2018-02-28T20:55:52.720Z] ERROR localservices/TRANSPORTER: Kafka Consumer error Could not find the leader
convoservice_1  | [2018-02-28T20:55:52.721Z] DEBUG localservices/TRANSPORTER: { BrokerNotAvailableError: Could not find the leader
convoservice_1  |     at new BrokerNotAvailableError (/app/node_modules/kafka-node/lib/errors/BrokerNotAvailableError.js:11:9)
convoservice_1  |     at Client.<anonymous> (/app/node_modules/kafka-node/lib/client.js:548:19)
convoservice_1  |     at Client.handleReceivedData (/app/node_modules/kafka-node/lib/client.js:770:60)
convoservice_1  |     at Socket.<anonymous> (/app/node_modules/kafka-node/lib/client.js:729:10)
convoservice_1  |     at Socket.emit (events.js:160:13)
convoservice_1  |     at addChunk (_stream_readable.js:269:12)
convoservice_1  |     at readableAddChunk (_stream_readable.js:256:11)
convoservice_1  |     at Socket.Readable.push (_stream_readable.js:213:10)
convoservice_1  |     at TCP.onread (net.js:599:20) message: 'Could not find the leader' }
convoservice_1  | [2018-02-28T20:55:57.607Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T20:56:02.608Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'
convoservice_1  | [2018-02-28T20:56:07.607Z] DEBUG localservices/TRANSIT: Send HEARTBEAT packet to 'all nodes'

On disconnect we are seeing correct info logs I think we are missing a reconnect info logs

icebob commented 6 years ago

I tried on a notebook. I disabled Wifi, same errors came "Could not find the leader", re-enabled the Wifi, and after a few secs client connected and everything working fine again. So I can't reproduce it. :disappointed:

mailaneel commented 6 years ago

I will close this now then. we can reopen if required