Consumer connection closed / client reconnect #979

bpetersen · 2018-05-22T22:06:19Z

I'm sorry if this is the wrong place to post this. I'm having an issue when running my tests in CI (centos). They work fine locally on my mac. Here's the output I'm getting:

kafka-node:KafkaClient Connect attempt 1 +0ms
kafka-node:KafkaClient Trying to connect to host: localhost port: 29092 +14ms
kafka-node:KafkaClient Sending versions request to localhost:29092 +139ms
kafka-node:KafkaClient broker socket connected {"host":"localhost","port":"29092"} +15ms
kafka-node:KafkaClient Received versions response from localhost:29092 +81ms
kafka-node:KafkaClient setting api support to {"produce":{"min":0,"max":2,"usable":2},"fetch":{"min":0,"max":3,"usable":2},"offset":{"min":0,"max":1,"usable":0},"metadata":{"min":0,"max":2,"usable":0},"leader":{"min":0,"max":0,"usable":false},"stopReplica":{"min":0,"max":0,"usable":false},"updateMetadata":{"min":0,"max":3,"usable":false},"controlledShutdown":{"min":1,"max":1,"usable":false},"offsetCommit":{"min":0,"max":2,"usable":2},"offsetFetch":{"min":0,"max":2,"usable":1},"groupCoordinator":{"min":0,"max":0,"usable":0},"joinGroup":{"min":0,"max":1,"usable":0},"heartbeat":{"min":0,"max":0,"usable":0},"leaveGroup":{"min":0,"max":0,"usable":0},"syncGroup":{"min":0,"max":0,"usable":0},"describeGroups":{"min":0,"max":0,"usable":0},"listGroups":{"min":0,"max":0,"usable":0},"saslHandshake":{"min":0,"max":0,"usable":false},"apiVersions":{"min":0,"max":0,"usable":0},"createTopics":{"min":0,"max":1,"usable":false},"deleteTopics":{"min":0,"max":0,"usable":false}} +1ms
kafka-node:KafkaClient updating metadatas +138ms
READY! undefined
kafka-node:KafkaClient updating metadatas +3s
kafka-node:KafkaClient checking payload topic/partitions has leaders +2ms
kafka-node:KafkaClient found leaders for all +0ms
kafka-node:KafkaClient grouped requests by 1 brokers ["1"] +1ms
kafka-node:KafkaClient missing apiSupport waiting until broker is ready... +62ms
kafka-node:Consumer connection closed +44ms
kafka-node:KafkaClient kafka-node-client reconnecting to kafka:29092 +1s
kafka-node:Consumer connection closed +68ms
kafka-node:KafkaClient kafka-node-client reconnecting to kafka:29092 +1s
kafka-node:Consumer connection closed +55ms
...That KafkaClient reconnect followed by Consumer connection closed over and over.

Any ideas on how I can troubleshoot this?

hyperlink · 2018-05-23T15:17:52Z

Take a look at the kafka broker logs maybe it can provide some clues as to why it's disconnecting.

mrwillis · 2018-06-14T22:27:35Z

I have a very similar issue. I know there is kafka available at 10.0.2.2 and 10.0.2.2 is resolvable (as you can see it does resolve). For some reason it doesn't continue with the connection and falls back to 127.0.0.1?? Bizarre. I am in kubernetes using minikube trying to access the host. Here are my logs:

julian@wilson:~/Desktop/app/producer$ kubectl logs -f app-producer-deployment-74bb794cbb-22wrz
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Connect attempt 1
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Trying to connect to host: 10.0.2.2 port: 9092
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Connect attempt 1
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Sending versions request to 10.0.2.2:9092
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient broker socket connected {"host":"10.0.2.2","port":"9092"}
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient Received versions response from 10.0.2.2:9092
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient setting api support to {"21":{"min":0,"max":0,"usable":false},"22":{"min":0,"max":0,"usable":false},"23":{"min":0,"max":0,"usable":false},"24":{"min":0,"max":0,"usable":false},"25":{"min":0,"max":0,"usable":false},"26":{"min":0,"max":0,"usable":false},"27":{"min":0,"max":0,"usable":false},"28":{"min":0,"max":0,"usable":false},"29":{"min":0,"max":0,"usable":false},"30":{"min":0,"max":0,"usable":false},"31":{"min":0,"max":0,"usable":false},"32":{"min":0,"max":1,"usable":false},"33":{"min":0,"max":0,"usable":false},"34":{"min":0,"max":0,"usable":false},"35":{"min":0,"max":0,"usable":false},"36":{"min":0,"max":0,"usable":false},"37":{"min":0,"max":0,"usable":false},"38":{"min":0,"max":0,"usable":false},"39":{"min":0,"max":0,"usable":false},"40":{"min":0,"max":0,"usable":false},"41":{"min":0,"max":0,"usable":false},"42":{"min":0,"max":0,"usable":false},"produce":{"min":0,"max":5,"usable":2},"fetch":{"min":0,"max":7,"usable":2},"offset":{"min":0,"max":2,"usable":0},"metadata":{"min":0,"max":5,"usable":0},"leader":{"min":0,"max":1,"usable":false},"stopReplica":{"min":0,"max":0,"usable":false},"updateMetadata":{"min":0,"max":4,"usable":false},"controlledShutdown":{"min":0,"max":1,"usable":false},"offsetCommit":{"min":0,"max":3,"usable":2},"offsetFetch":{"min":0,"max":3,"usable":1},"groupCoordinator":{"min":0,"max":1,"usable":0},"joinGroup":{"min":0,"max":2,"usable":0},"heartbeat":{"min":0,"max":1,"usable":0},"leaveGroup":{"min":0,"max":1,"usable":0},"syncGroup":{"min":0,"max":1,"usable":0},"describeGroups":{"min":0,"max":1,"usable":0},"listGroups":{"min":0,"max":1,"usable":0},"saslHandshake":{"min":0,"max":1,"usable":false},"apiVersions":{"min":0,"max":1,"usable":0},"createTopics":{"min":0,"max":2,"usable":false},"deleteTopics":{"min":0,"max":1,"usable":false}}
Thu, 14 Jun 2018 22:21:19 GMT kafka-node:KafkaClient updating metadatas
Got 2586 streams to subscribe to
Connected to CryptoCompare socket.io endpoint.
Sent 2586 coins to subscribe.
Thu, 14 Jun 2018 22:21:20 GMT kafka-node:ProducerStream _write
Thu, 14 Jun 2018 22:21:20 GMT kafka-node:KafkaClient Connect attempt 2
Thu, 14 Jun 2018 22:21:20 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:21:20 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:20 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:22 GMT kafka-node:KafkaClient Connect attempt 3
Thu, 14 Jun 2018 22:21:22 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:21:22 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:22 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:29 GMT kafka-node:KafkaClient Connect attempt 4
Thu, 14 Jun 2018 22:21:29 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:21:29 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:29 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:45 GMT kafka-node:KafkaClient Connect attempt 5
Thu, 14 Jun 2018 22:21:45 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:21:45 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:21:45 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:22:15 GMT kafka-node:KafkaClient Connect attempt 6
Thu, 14 Jun 2018 22:22:15 GMT kafka-node:KafkaClient Trying to connect to host: 127.0.0.1 port: 9092
Thu, 14 Jun 2018 22:22:15 GMT kafka-node:KafkaClient Socket Error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:22:15 GMT kafka-node:KafkaClient failed to connect because of  { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
Thu, 14 Jun 2018 22:22:15 GMT kafka-node:KafkaClient exhausted retries. Main error { Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 9092 }
events.js:167
      throw er; // Unhandled 'error' event
      ^

Error: connect ECONNREFUSED 127.0.0.1:9092
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1158:14)
Emitted 'error' event at:
    at ProducerStream.onerror (/app/node_modules/readable-stream/lib/_stream_readable.js:640:52)
    at ProducerStream.emit (events.js:182:13)
    at HighLevelProducer.ProducerStream.producer.on.error (/app/node_modules/kafka-node/lib/producerStream.js:32:45)
    at HighLevelProducer.emit (events.js:182:13)
    at KafkaClient.<anonymous> (/app/node_modules/kafka-node/lib/baseProducer.js:101:10)
    at KafkaClient.emit (events.js:182:13)
    at async.series.error (/app/node_modules/kafka-node/lib/kafkaClient.js:156:16)
    at /app/node_modules/async/dist/async.js:3888:9
    at /app/node_modules/async/dist/async.js:473:16
    at iterateeCallback (/app/node_modules/async/dist/async.js:988:17)

hyperlink · 2018-06-21T17:55:13Z

Looks like your kafka broker isn't setup correctly.

Kafka node will connect to the broker and pull the metadata of other brokers and connect to them as necessary. I believe the broker metadata coming from the broker is referring to 127.0.0.1 in this case.

chan71 · 2019-02-23T16:40:37Z

I had an issue where the log says as follows. My kafka instance is part of the devicehive stack which is running in a docker container.

$ DEBUG=* node index.js
Fri Feb 22 2019 22:19:25 GMT+1100 (AEDT) [INFO   ] [kafka-test] initializing consumer..
  kafka-node:KafkaClient Connect attempt 1 +0ms
  kafka-node:KafkaClient Trying to connect to host: localhost port: 9092 +3ms
  kafka-node:KafkaClient createBroker localhost 9092 +1ms
Fri Feb 22 2019 22:19:25 GMT+1100 (AEDT) [INFO   ] [kafka-test] waiting connection...
  kafka-node:KafkaClient Sending versions request to localhost:9092 +7ms
  kafka-node:KafkaClient broker socket connected {"host":"localhost","port":"9092"} +3ms
  kafka-node:KafkaClient connected to socket, trying to load initial metadata +2ms
  kafka-node:KafkaClient missing apiSupport waiting until broker is ready... +0ms
  kafka-node:KafkaClient waitUntilReady [BrokerWrapper localhost:9092 (connected: true) (ready: false) (idle: false) (needAuthentication: false) (authenticated: false)] +1ms
  kafka-node:KafkaClient Received versions response from localhost:9092 +6ms
  kafka-node:KafkaClient setting api support to {... } +0ms
  kafka-node:KafkaClient broker is now ready +13ms
  kafka-node:KafkaClient updating metadatas +13ms
  kafka-node:Consumer consumer ready +2ms
  kafka-node:KafkaClient updating metadatas +15ms
  kafka-node:KafkaClient createBroker e1a965baf098 9092 +3ms
  kafka-node:KafkaClient waitUntilReady [BrokerWrapper e1a965baf098:9092 (connected: true) (ready: false) (idle: false) (needAuthentication: false) (authenticated: false)] +1ms
  kafka-node:Consumer connection closed +1ms
  kafka-node:KafkaClient consumer-node reconnecting to e1a965baf098:9092 +1s
  kafka-node:KafkaClient createBroker e1a965baf098 9092 +0ms
  kafka-node:Consumer connection closed +2ms
  kafka-node:KafkaClient consumer-node reconnecting to e1a965baf098:9092 +1s
  kafka-node:KafkaClient createBroker e1a965baf098 9092 +0ms
  kafka-node:Consumer connection closed +1ms
  kafka-node:KafkaClient consumer-node reconnecting to e1a965baf098:9092 +1s
  kafka-node:KafkaClient createBroker e1a965baf098 9092 +1ms

A temporary solution was to add docker container id 'e1a965baf098' to /etc/hosts file. This will let me proceed but a every redeployment of docker needs updating hosts file.

hyperlink · 2019-02-23T17:08:57Z

@chan71 you should look into updating the advertised listeners to reference localhost. Example in our docker-compose.

chan71 · 2019-02-25T03:18:52Z

@hyperlink thanks for the suggestion. That helped to get the localhost added to the listeners. However, the following error is displayed when a consumer is invoked.

<top part is similar to my earlier stack trace>
  kafka-node:KafkaClient broker is now ready +1ms
  kafka-node:KafkaClient updating metadatas +16ms
  kafka-node:Consumer consumer ready +1ms
  kafka-node:KafkaClient updating metadatas +10ms
Mon Feb 25 2019 14:14:53 GMT+1100 (AEDT) [ERROR  ] [kafka-test] Kafka error: LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable

And this error when producer in invoked.

<top part is similar to my earlier stack trace>
  kafka-node:KafkaClient broker is now ready +0ms
  kafka-node:KafkaClient updating metadatas +17ms
Mon Feb 25 2019 14:18:21 GMT+1100 (AEDT) [INFO   ] [kafka-test] producer ready
  kafka-node:KafkaClient compressing messages if needed +2ms
  kafka-node:KafkaClient payloads has no leaders! Our metadata could be out of date try refreshingMetadata [ { topic: 'sensor_data',
    partition: 0,
    messages: [ [Object] ],
    attributes: 0 },
  { topic: 'another_topic',
    partition: 0,
    messages: [ [Object] ],
    attributes: 0 } ] +1ms
  kafka-node:BaseClient refresh metadata currentAttempt 1 +3ms
  kafka-node:BaseClient refresh metadata currentAttempt 2 +205ms
  kafka-node:BaseClient refresh metadata currentAttempt 3 +406ms
  kafka-node:BaseClient refresh metadata currentAttempt 4 +807ms
  kafka-node:BaseClient refresh metadata currentAttempt 5 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 6 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 7 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 8 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 9 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 10 +1s
  kafka-node:BaseClient refresh metadata currentAttempt 11 +1s
  kafka-node:BaseClient refresh metadata error LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable +4ms
Mon Feb 25 2019 14:18:29 GMT+1100 (AEDT) [ERROR  ] [kafka-test] error occured: Error: LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable,LeaderNotAvailable
{ '0': 'payload sent: undefined' }

chan71 · 2019-02-25T12:29:28Z

Sorry @hyperlink I must have misunderstood your suggestion. I added the following line to docker compose file.

      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://localhost:9092

While adding the localhost to kafka_adcertised_listeners has fixed the continuous attempt to retrieve metadata and closing connection, it threw LeaderNotAvailable after 10+ attempts to refresh metadata. It looks like that other references to hostname might have caused this error.

So, I added the localhost to the kafka_advertised_host_name env variable and it fixed the issue.

      KAFKA_ADVERTISED_HOST_NAME: localhost
      KAFKA_ADVERTISED_LISTENERS: PLAINTEXT://localhost:9092

Thanks for your help.

bpetersen changed the title ~~Consumer connection closed/~~ Consumer connection closed / client reconnect May 22, 2018

chan71 mentioned this issue Feb 27, 2019

Retrieve messages from kafka topic devicehive/devicehive-docker#66

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Consumer connection closed / client reconnect #979

Consumer connection closed / client reconnect #979

bpetersen commented May 22, 2018

hyperlink commented May 23, 2018

mrwillis commented Jun 14, 2018

hyperlink commented Jun 21, 2018

chan71 commented Feb 23, 2019 •

edited

hyperlink commented Feb 23, 2019

chan71 commented Feb 25, 2019 •

edited

chan71 commented Feb 25, 2019

Consumer connection closed / client reconnect #979

Consumer connection closed / client reconnect #979

Comments

bpetersen commented May 22, 2018

hyperlink commented May 23, 2018

mrwillis commented Jun 14, 2018

hyperlink commented Jun 21, 2018

chan71 commented Feb 23, 2019 • edited

hyperlink commented Feb 23, 2019

chan71 commented Feb 25, 2019 • edited

chan71 commented Feb 25, 2019

chan71 commented Feb 23, 2019 •

edited

chan71 commented Feb 25, 2019 •

edited