You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@kafka.apache.org by Liam Clarke-Hutchinson <li...@adscale.co.nz> on 2020/05/02 13:32:59 UTC
Re: Consumer not receiving messages after connection loss
Hi Goran,
Glad you figured it out :) And interesting that there was nothing in the
server logs (as far as I can tell, it's a bit hard to read) which showed
why the server was terminating the connection. Just wanted to provide
feedback that your second attempt at sending the logs was really hard to
read also. Could I suggest something like pastebin.com or gist.github.com
for future issues? They keep the formatting intact and make it easier to
delve into your logs.
Cheers,
Liam Clarke-Hutchinson
On Tue, Apr 28, 2020 at 5:59 AM Goran Sliskovic <gs...@yahoo.com.invalid>
wrote:
> Apparently the issue is the fact that client tries to fetch more bytes
> than network can handle in response timeout (request.timeout.ms client
> property), So in my case request could not finish in 30 seconds, gets
> cancelled an reissued. An it fail again and agian. So either lowering
> max.partion.fetch,bytes or increasing request.timeout.ms should allow
> kafka client to consume under low speed condition. Diagnostic would be nice
> in the kafka log though, at least at the info level..
>
> .
> On Sunday, April 26, 2020, 01:41:34 PM GMT+2, Goran Sliskovic
> <gs...@yahoo.com.invalid> wrote:
>
> Sorry, apparently logs get formatted to unreadable state. Attached this
> time.
>
>
> On Sunday, April 26, 2020, 01:35:38 PM GMT+2, Goran Sliskovic
> <gs...@yahoo.com.invalid> wrote:
>
> Hi,
> I'm tracking an issue in production system (data flow stops suddenly for
> hours). That seems to bi triggered by network errors, however communication
> is not restored for hours event though networking is restored.I have
> managed to put test system in similar state. Symptoms:
> Client (java application) is apparently connected, goes through the
> infinite poll loop but no records are returned. I can see by sendq from
> netstat (and confirm with wireshark) that subscription data is coming
> through socket.
> netstat (windows, java client):netstat -n | findstr 9092
> TCP 192.168.128.196:55759 192.168.128.89:9092 ESTABLISHED TCP
> 192.168.128.196:56069 192.168.128.89:9092 ESTABLISHED
> Linux ( kafka_2.12-2.5.0):
> netstat -n | grep 9092 | grep 196
> tcp6 0 0 192.168.128.89:9092 192.168.128.196:55759
> ESTABLISHEDtcp6 0 121040 192.168.128.89:9092
> 192.168.128.196:56069 ESTABLISHED
>
> Client logs:
> 2020-04-26 12:56:26,410 [Thread-0] ConsumerConfig : ConsumerConfig
> values: allow.auto.create.topics = true auto.commit.interval.ms = 1000
> auto.offset.reset = earliest bootstrap.servers = [192.168.128.89:9092]
> check.crcs = true client.dns.lookup = default client.id = client.rack =
> connections.max.idle.ms = 540000 default.api.timeout.ms = 60000
> enable.auto.commit = false exclude.internal.topics = true fetch.max.bytes =
> 52428800 fetch.max.wait.ms = 500 fetch.min.bytes = 1 group.id =
> test_dummy_group4 group.instance.id = null heartbeat.interval.ms = 3000
> interceptor.classes = [] internal.leave.group.on.close = true
> isolation.level = read_uncommitted key.deserializer = class
> org.apache.kafka.common.serialization.StringDeserializer
> max.partition.fetch.bytes = 1048576 max.poll.interval.ms = 120000
> max.poll.records = 1 metadata.max.age.ms = 300000 metric.reporters = []
> metrics.num.samples = 2 metrics.recording.level = INFO
> metrics.sample.window.ms = 30000 partition.assignment.strategy = [class
> org.apache.kafka.clients.consumer.RangeAssignor] receive.buffer.bytes =
> 65536 reconnect.backoff.max.ms = 1000 reconnect.backoff.ms = 50
> request.timeout.ms = 30000 retry.backoff.ms = 100
> sasl.client.callback.handler.class = null sasl.jaas.config = null
> sasl.kerberos.kinit.cmd = /usr/bin/kinit
> sasl.kerberos.min.time.before.relogin = 60000 sasl.kerberos.service.name
> = null sasl.kerberos.ticket.renew.jitter = 0.05
> sasl.kerberos.ticket.renew.window.factor = 0.8
> sasl.login.callback.handler.class = null sasl.login.class = null
> sasl.login.refresh.buffer.seconds = 300
> sasl.login.refresh.min.period.seconds = 60 sasl.login.refresh.window.factor
> = 0.8 sasl.login.refresh.window.jitter = 0.05 sasl.mechanism = GSSAPI
> security.protocol = PLAINTEXT security.providers = null send.buffer.bytes =
> 131072 session.timeout.ms = 30000 ssl.cipher.suites = null
> ssl.enabled.protocols = [TLSv1.2] ssl.endpoint.identification.algorithm =
> https ssl.key.password = null ssl.keymanager.algorithm = SunX509
> ssl.keystore.location = null ssl.keystore.password = null ssl.keystore.type
> = JKS ssl.protocol = TLSv1.2 ssl.provider = null
> ssl.secure.random.implementation = null ssl.trustmanager.algorithm = PKIX
> ssl.truststore.location = null ssl.truststore.password = null
> ssl.truststore.type = JKS value.deserializer = class
> org.apache.kafka.common.serialization.ByteArrayDeserializer
> INFO 2020-04-26 12:56:27,158 [Thread-0] AppInfoParser : Kafka version:
> 2.5.0INFO 2020-04-26 12:56:27,158 [Thread-0] AppInfoParser : Kafka
> commitId: 66563e712b0b9f84INFO 2020-04-26 12:56:27,158 [Thread-0]
> AppInfoParser : Kafka startTimeMs: 1587898587150INFO 2020-04-26
> 12:56:27,160 [Thread-0] KafkaConsumer : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4]
> Subscribed to topic(s): KPITrafficVolume, KPIQueueLength, KPIWaitTime,
> KPIUnfinishedGreen, KPIWasteGreen, KPIPassThroughVehicles,
> KPIMaxWaitCycles, KPILoadRate, KPIGiveWayDelay, KPILevelOfService,
> KPIRedLightNegation, KPIGreenEndingTooSoon, KPICycleGreenTime,
> KPICycleRedTime, KPISpeed, KPISpecialSituationCount, KPICycleTime,
> KPIMaxCycleQueueLength, KPICycleWaitTime, KPICycleUnfinishedGreen,
> KPILevelOfServiceReport, TPMAlarm, TPMAlarmConfig, TPMAlarmCommand,
> TPMAlarmCommandResponse, TPMAlarmSynchronization, TPMNetworkConfig,
> TPMHeartbeatINFO 2020-04-26 12:56:27,626 [Thread-0] Metadata : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Cluster
> ID: 51Ki2MyAR6CybEEn1z4PHwINFO 2020-04-26 12:56:27,639 [Thread-0]
> AbstractCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Discovered group coordinator
> 192.168.128.89:9092 (id: 2147483647 rack: null)INFO 2020-04-26
> 12:56:27,640 [Thread-0] AbstractCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4]
> (Re-)joining groupINFO 2020-04-26 12:56:27,804 [Thread-0]
> AbstractCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Join group failed with
> org.apache.kafka.common.errors.MemberIdRequiredException: The group member
> needs to have a valid member id before actually entering a consumer
> groupINFO 2020-04-26 12:56:27,804 [Thread-0] AbstractCoordinator :
> [Consumer clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4]
> (Re-)joining groupINFO 2020-04-26 12:56:27,873 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Finished assignment for group at generation 5:
> {consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a=Assignment(partitions=[TPMAlarm-0,
> KPIQueueLength-0, KPILevelOfService-0, KPIUnfinishedGreen-0,
> TPMNetworkConfig-0, KPISpecialSituationCount-0, KPIPassThroughVehicles-0,
> KPIRedLightNegation-0, TPMAlarmCommandResponse-0, KPILoadRate-0,
> KPIMaxCycleQueueLength-0, KPITrafficVolume-0, KPIWasteGreen-0, KPISpeed-0,
> KPIGiveWayDelay-0, TPMHeartbeat-0, KPICycleWaitTime-0, TPMAlarmConfig-0,
> TPMAlarmCommand-0, KPICycleRedTime-0, KPIMaxWaitCycles-0,
> KPILevelOfServiceReport-0, KPICycleUnfinishedGreen-0, KPIWaitTime-0,
> KPICycleTime-0, KPIGreenEndingTooSoon-0, TPMAlarmSynchronization-0,
> KPICycleGreenTime-0])}INFO 2020-04-26 12:56:27,926 [Thread-0]
> AbstractCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Successfully joined group with generation 5INFO
> 2020-04-26 12:56:27,942 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Adding
> newly assigned partitions: KPILevelOfService-0, TPMAlarm-0,
> KPIUnfinishedGreen-0, KPIPassThroughVehicles-0, KPIQueueLength-0,
> KPISpecialSituationCount-0, KPIRedLightNegation-0,
> TPMAlarmCommandResponse-0, KPIMaxCycleQueueLength-0, KPILoadRate-0,
> KPITrafficVolume-0, KPIWasteGreen-0, KPIGiveWayDelay-0, KPISpeed-0,
> KPICycleTime-0, TPMHeartbeat-0, TPMAlarmConfig-0, KPICycleWaitTime-0,
> TPMAlarmCommand-0, KPIMaxWaitCycles-0, KPICycleRedTime-0, KPIWaitTime-0,
> KPICycleUnfinishedGreen-0, KPILevelOfServiceReport-0,
> KPIGreenEndingTooSoon-0, TPMNetworkConfig-0, KPICycleGreenTime-0,
> TPMAlarmSynchronization-0INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPILevelOfService-0
> to the committed offset FetchPosition{offset=8, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition TPMAlarm-0 to the
> committed offset FetchPosition{offset=0, offsetEpoch=Optional.empty,
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> KPIUnfinishedGreen-0 to the committed offset FetchPosition{offset=4,
> offsetEpoch=Optional[0], currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:28,011 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Setting
> offset for partition KPIPassThroughVehicles-0 to the committed offset
> FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPIQueueLength-0 to
> the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> KPISpecialSituationCount-0 to the committed offset FetchPosition{offset=5,
> offsetEpoch=Optional[0], currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:28,011 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Setting
> offset for partition KPIRedLightNegation-0 to the committed offset
> FetchPosition{offset=1, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> TPMAlarmCommandResponse-0 to the committed offset FetchPosition{offset=0,
> offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:28,011 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Setting
> offset for partition KPIMaxCycleQueueLength-0 to the committed offset
> FetchPosition{offset=5, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPILoadRate-0 to
> the committed offset FetchPosition{offset=8, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPITrafficVolume-0
> to the committed offset FetchPosition{offset=43, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPIWasteGreen-0 to
> the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPIGiveWayDelay-0
> to the committed offset FetchPosition{offset=7, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPISpeed-0 to the
> committed offset FetchPosition{offset=1, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPICycleTime-0 to
> the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition TPMHeartbeat-0 to
> the committed offset FetchPosition{offset=0, offsetEpoch=Optional.empty,
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition TPMAlarmConfig-0 to
> the committed offset FetchPosition{offset=0, offsetEpoch=Optional.empty,
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPICycleWaitTime-0
> to the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition TPMAlarmCommand-0
> to the committed offset FetchPosition{offset=0, offsetEpoch=Optional.empty,
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPICycleRedTime-0
> to the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPIMaxWaitCycles-0
> to the committed offset FetchPosition{offset=1, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPIWaitTime-0 to
> the committed offset FetchPosition{offset=4, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> KPICycleUnfinishedGreen-0 to the committed offset FetchPosition{offset=1,
> offsetEpoch=Optional[0], currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:28,011 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Setting
> offset for partition KPILevelOfServiceReport-0 to the committed offset
> FetchPosition{offset=1, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> KPIGreenEndingTooSoon-0 to the committed offset FetchPosition{offset=4,
> offsetEpoch=Optional[0], currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:28,011 [Thread-0] ConsumerCoordinator : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Setting
> offset for partition TPMNetworkConfig-0 to the committed offset
> FetchPosition{offset=0, offsetEpoch=Optional.empty,
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition KPICycleGreenTime-0
> to the committed offset FetchPosition{offset=3, offsetEpoch=Optional[0],
> currentLeader=LeaderAndEpoch{leader=Optional[192.168.128.89:9092 (id: 0
> rack: null)], epoch=0}}INFO 2020-04-26 12:56:28,011 [Thread-0]
> ConsumerCoordinator : [Consumer clientId=consumer-test_dummy_group4-1,
> groupId=test_dummy_group4] Setting offset for partition
> TPMAlarmSynchronization-0 to the committed offset FetchPosition{offset=0,
> offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=Optional[
> 192.168.128.89:9092 (id: 0 rack: null)], epoch=0}}INFO 2020-04-26
> 12:56:59,264 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=2) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 12:57:29,878 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 12:58:00,781 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 12:58:30,944 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 12:59:01,509 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 12:59:32,158 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:00:02,940 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:00:33,508 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:01:04,086 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:01:34,841 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:02:05,616 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:02:36,232 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:03:07,138 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:03:37,947 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:04:08,490 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:04:39,245 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:05:09,890 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:05:40,522 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:06:11,086 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:06:41,660 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectException
> INFO 2020-04-26 13:07:12,240 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:07:42,903 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:08:13,478 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectExceptionINFO 2020-04-26
> 13:08:44,028 [Thread-0] FetchSessionHandler : [Consumer
> clientId=consumer-test_dummy_group4-1, groupId=test_dummy_group4] Error
> sending fetch request (sessionId=1171785342, epoch=INITIAL) to node 0:
> {}.org.apache.kafka.common.errors.DisconnectException
>
>
>
> Kafka server:
> [2020-04-26 12:53:53,593] INFO [GroupMetadataManager brokerId=0] Finished
> loading offsets and group metadata from __consumer_offsets-30 in 0
> milliseconds. (kafka.coordinator.group.GroupMetadataManager)[2020-04-26
> 12:53:53,594] INFO [GroupMetadataManager brokerId=0] Finished loading
> offsets and group metadata from __consumer_offsets-36 in 0 milliseconds.
> (kafka.coordinator.group.GroupMetadataManager)[2020-04-26 12:53:53,595]
> INFO [GroupMetadataManager brokerId=0] Finished loading offsets and group
> metadata from __consumer_offsets-42 in 0 milliseconds.
> (kafka.coordinator.group.GroupMetadataManager)[2020-04-26 12:53:53,597]
> INFO [GroupMetadataManager brokerId=0] Finished loading offsets and group
> metadata from __consumer_offsets-48 in 0 milliseconds.
> (kafka.coordinator.group.GroupMetadataManager)[2020-04-26 12:53:54,032]
> INFO [GroupCoordinator 0]: Preparing to rebalance group test_dummy_group4
> in state PreparingRebalance with old generation 0 (__consumer_offsets-37)
> (reason: Adding new member
> consumer-t_dummy_group4-1-5d76a410-77d6-474c-b28a-d015a522f254 with group
> instance id None) (kafka.coordinator.group.GroupCoordinator)[2020-04-26
> 12:53:54,056] INFO [GroupCoordinator 0]: Stabilized group test_dummy_group4
> generation 1 (__consumer_offsets-37)
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:53:54,153] INFO
> [GroupCoordinator 0]: Assignment received from leader for group
> test_dummy_group4 for generation 1
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:54:55,354] INFO
> [GroupCoordinator 0]: Member
> consumer-test_dummy_group4-1-5d76a410-77d6-474c-b28a-d015a522f254 in group
> test_dummy_group4 has failed, removing it from the group
> (kafka.coordinatoroup.GroupCoordinator)[2020-04-26 12:54:55,354] INFO
> [GroupCoordinator 0]: Preparing to rebalance group test_dummy_group4 in
> state PreparingRebalance with old generation 1 (__consumer_offsets-37)
> (reason: removing member
> consumer-tedummy_group4-1-5d76a410-77d6-474c-b28a-d015a522f254 on heartbeat
> expiration) (kafka.coordinator.group.GroupCoordinator)[2020-04-26
> 12:54:55,360] INFO [GroupCoordinator 0]: Group test_dummy_group4 with
> generation 2 is now empty (__consumer_offsets-37)
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:55:11,246] INFO
> [GroupCoordinator 0]: Preparing to rebalance group test_dummy_group4 in
> state PreparingRebalance with old generation 2 (__consumer_offsets-37)
> (reason: Adding new member
> consumer-t_dummy_group4-1-1be5963f-6545-48d5-a2ee-6860ce2177ec with group
> instance id None) (kafka.coordinator.group.GroupCoordinator)[2020-04-26
> 12:55:11,249] INFO [GroupCoordinator 0]: Stabilized group test_dummy_group4
> generation 3 (__consumer_offsets-37)
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:55:11,331] INFO
> [GroupCoordinator 0]: Assignment received from leader for group
> test_dummy_group4 for generation 3
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:55:49,411] INFO
> [GroupCoordinator 0]: Member
> consumer-test_dummy_group4-1-1be5963f-6545-48d5-a2ee-6860ce2177ec in group
> test_dummy_group4 has failed, removing it from the group
> (kafka.coordinatoroup.GroupCoordinator)[2020-04-26 12:55:49,411] INFO
> [GroupCoordinator 0]: Preparing to rebalance group test_dummy_group4 in
> state PreparingRebalance with old generation 3 (__consumer_offsets-37)
> (reason: removing member
> consumer-tedummy_group4-1-1be5963f-6545-48d5-a2ee-6860ce2177ec on heartbeat
> expiration) (kafka.coordinator.group.GroupCoordinator)[2020-04-26
> 12:55:49,411] INFO [GroupCoordinator 0]: Group test_dummy_group4 with
> generation 4 is now empty (__consumer_offsets-37)
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:56:27,302] INFO
> [GroupCoordinator 0]: Preparing to rebalance group test_dummy_group4 in
> state PreparingRebalance with old generation 4 (__consumer_offsets-37)
> (reason: Adding new member
> consumer-t_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a with group
> instance id None) (kafka.coordinator.group.GroupCoordinator)[2020-04-26
> 12:56:27,305] INFO [GroupCoordinator 0]: Stabilized group test_dummy_group4
> generation 5 (__consumer_offsets-37)
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 12:56:27,368] INFO
> [GroupCoordinator 0]: Assignment received from leader for group
> test_dummy_group4 for generation 5
> (kafka.coordinator.group.GroupCoordinator)[2020-04-26 13:03:48,252] INFO
> [GroupMetadataManager brokerId=0] Removed 0 expired offsets in 10
> milliseconds. (kafka.coordinator.group.GroupMetadataManager)[2020-04-26
> 13:13:48,243] INFO [GroupMetadataManager brokerId=0] Removed 0 expired
> offsets in 0 milliseconds.
> (kafka.coordinator.group.GroupMetadataManager)[2020-04-26 13:23:48,242]
> INFO [GroupMetadataManager brokerId=0] Removed 0 expired offsets in 0
> milliseconds. (kafka.coordinator.group.GroupMetadataManager)
> Consumer status:
> kafka_2.12-2.5.0/bin$ ./kafka-consumer-groups.sh --bootstrap-server
> localhost:9092 --group test_dummy_group4 --describe
> GROUP TOPIC PARTITION CURRENT-OFFSET
> LOG-END-OFFSET LAG CONSUMER-ID
> HOST CLIENT-IDtest_dummy_group4
> KPILevelOfService 0 8 734 726
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4 KPIWaitTime
> 0 4 550 546
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4 KPICycleTime
> 0 4 652 648
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4
> TPMAlarmCommandResponse 0 0 0 0
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4
> KPIGreenEndingTooSoon 0 4 546 542
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4
> TPMAlarmSynchronization 0 0 0 0
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_grouptest_dummy_group4
> KPIRedLightNegation 0 1 772 771
> consumer-test_dummy_group4-1-ff8f3b8c-f4bc-4997-bbcb-a4dfd559a06a /
> 192.168.128.196 consumer-test_dummy_group... (shortened, all topics show
> similar pattern, lag)
> Any info is welcome, I'm pretty stuck.
> Regards,Goran
Re: Consumer not receiving messages after connection loss
Posted by Goran Sliskovic <gs...@yahoo.com.INVALID>.
Hi,
It's the client that closes the connection, you can see some disconnectExceptions in the client log, however it would be nice if there was a log: "Closing connection due to request timeout" somwhere. This would save me some time parsing wireshark logs, though when you look at that carefully you see it's the client closing. But when you diagnose something that happens in the production it's always a bit more stressfull, so you can miss such things (wireshark captures are not known for bravity).
Regards,Goran
On Saturday, May 2, 2020, 03:33:24 PM GMT+2, Liam Clarke-Hutchinson <li...@adscale.co.nz> wrote:
Hi Goran,
Glad you figured it out :) And interesting that there was nothing in the
server logs (as far as I can tell, it's a bit hard to read) which showed
why the server was terminating the connection. Just wanted to provide
feedback that your second attempt at sending the logs was really hard to
read also. Could I suggest something like pastebin.com or gist.github.com
for future issues? They keep the formatting intact and make it easier to
delve into your logs.
Cheers,
Liam Clarke-Hutchinson
..