Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Question] New Consumer+Producer randomly fails to access broker #2519

Closed
kerenor23 opened this issue Sep 10, 2019 · 8 comments
Closed

[Question] New Consumer+Producer randomly fails to access broker #2519

kerenor23 opened this issue Sep 10, 2019 · 8 comments

Comments

@kerenor23
Copy link

Description

I have a python app, working with confluent-kafka 1.0.1

version(): ('1.0.1', 16777472)
libversion(): ('1.0.1', 16777727)

Part of the app's flow is to regularly fork new processes for some data handling, closing them when done. Each of the new processes creates a Consumer and Producer.
Only randomly and only occasionally, one of the processes (not necessarily the same one, but there seems to be a preference to the one called IM in the logs I attach) will fail to connect to the broker.
The broker is running on a docker locally.
Once a process succeeded connecting, it will continue correctly. Once failed, it will not recover, forcing us to stop this data handling processing and restart.

Settings

The Producer and Consumers are created in-process (i.e. they are not forked).
Each client config (for the Producers) is either this:

{
      "bootstrap.servers": 0,
      "session.timeout.ms": 6000,
      "queue.buffering.max.ms": 50,
      "fetch.wait.max.ms": 50,
      "fetch.error.backoff.ms": 50
}

or, for minimal latency,

{
      "bootstrap.servers": 0,
      "session.timeout.ms": 6000,
      "queue.buffering.max.ms": 0,
      "fetch.wait.max.ms": 10,
      "fetch.error.backoff.ms": 10
}

Each Consumer of each process is its own new consumer group (group.id is generated automatically) listening to a new topic designated to this Consumer alone. "auto.offset.reset" is set to latest.

We rely on automatic topic creation for all our topics.

There is no guaranteed way to reproduce it; it seems to really happen randomly.

Logs

I'm adding a general log of all the processes; each process's Producer logs with "debug": "broker,topic,msg" and Consumer logs with "debug": "cgrp,topic,consumer".

The relevant part is how all processes except for the one with PID 19163 started correctly, and that specific one didn't.
They were all started at the same time, running on the same machine (which is ubuntu 18.04 btw), yet that one failed to access the local broker. Running the same scenario again, it might or might not work.
The broker logs don't show any request from this process.
Any ideas as to what to check/change would be appreciated.
Thanks!

2019-09-10 17:09:43,285 PID: 19076 | s_a2b371a4.Consumer  	MEMBERID [rdkafka#consumer-13] [thrd:app]: Group "DMC": updating member id "(not-set)" -> ""
2019-09-10 17:09:43,286 PID: 19076 | s_a2b371a4.Consumer  	INIT [rdkafka#consumer-13] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-13 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2104)
2019-09-10 17:09:43,286 PID: 19076 | s_a2b371a4.Consumer  	CGRPOP [rdkafka#consumer-13] [thrd:main]: Group "DMC" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-10 17:09:43,287 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIBE [rdkafka#consumer-13] [thrd:main]: Group "DMC": subscribe to new subscription of 1 topics (join state init)
2019-09-10 17:09:43,287 PID: 19076 | s_a2b371a4.Consumer  	UNSUBSCRIBE [rdkafka#consumer-13] [thrd:main]: Group "DMC": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-10 17:09:43,288 PID: 19076 | s_a2b371a4.Consumer  	GRPLEADER [rdkafka#consumer-13] [thrd:main]: Group "DMC": resetting group leader info: unsubscribe
2019-09-10 17:09:43,288 PID: 19076 | s_a2b371a4.Consumer  	REBALANCE [rdkafka#consumer-13] [thrd:main]: Group "DMC" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-10 17:09:43,289 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state init -> wait-unassign (v1, state init)
2019-09-10 17:09:43,291 PID: 19076 | s_a2b371a4.Consumer  	UNASSIGN [rdkafka#consumer-13] [thrd:main]: Group "DMC": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:43,294 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state wait-unassign -> init (v1, state init)
2019-09-10 17:09:43,294 PID: 19076 | s_a2b371a4.Consumer  	CGRPSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed state init -> query-coord (v1, join-state init)
2019-09-10 17:09:43,296 PID: 19076 | s_a2b371a4.Consumer  	CGRPQUERY [rdkafka#consumer-13] [thrd:main]: Group "DMC": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:43,296 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]: Group "DMC": no topics in metadata matched subscription
2019-09-10 17:09:44,281 PID: 19076 | s_a2b371a4.Consumer  	CGRPQUERY [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: Group "DMC": querying for coordinator: intervaled in state query-coord
2019-09-10 17:09:44,281 PID: 19076 | s_a2b371a4.Consumer  	CGRPSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed state query-coord -> wait-coord (v1, join-state init)
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPCOORD [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: Group "DMC" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPCOORD [rdkafka#consumer-13] [thrd:main]: Group "DMC" changing coordinator -1 -> 0
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	COORDSET [rdkafka#consumer-13] [thrd:main]: Group "DMC" coordinator set to broker 127.0.0.1:9092/0
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed state wait-coord -> wait-broker-transport (v1, join-state init)
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPQUERY [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: Group "DMC": querying for coordinator: intervaled in state wait-broker-transport
2019-09-10 17:09:44,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPCOORD [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: Group "DMC" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:44,283 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]: Group "DMC": no topics in metadata matched subscription
2019-09-10 17:09:44,283 PID: 19076 | s_a2b371a4.Consumer  	CGRPSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed state wait-broker-transport -> up (v1, join-state init)
2019-09-10 17:09:44,283 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:44,283 PID: 19076 | s_a2b371a4.Consumer  	CGRPMETADATA [rdkafka#consumer-13] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:44,283 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": postponing join until up-to-date metadata is available
2019-09-10 17:09:44,295 PID: 19076 | s_a2b371a4.Consumer  	METADATA [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: Temporary error in metadata reply for topic FROM_DM_TO_a2b371a4 (PartCnt 0): Broker: Leader not available: ignoring
2019-09-10 17:09:44,295 PID: 19076 | s_a2b371a4.Consumer  	METADATA [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:44,296 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]: Group "DMC": no topics in metadata matched subscription
2019-09-10 17:09:44,296 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]: Group "DMC": no topics in metadata matched subscription
2019-09-10 17:09:45,249 PID: 19076 | s_a2b371a4.Producer 	BRKMAIN [rdkafka#producer-12] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:45,249 PID: 19076 | s_a2b371a4.Producer 	BROKER [rdkafka#producer-12] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	CONNECT [rdkafka#producer-12] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	INIT [rdkafka#producer-12] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-12 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	BRKMAIN [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	CONNECT [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	STATE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	CONNECT [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:45,250 PID: 19076 | s_a2b371a4.Producer 	STATE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	CONNECT [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 155
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	CONNECT [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	CONNECTED [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	FEATURE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	STATE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	FEATURE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-10 17:09:45,251 PID: 19076 | s_a2b371a4.Producer 	STATE [rdkafka#producer-12] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	BROKER [rdkafka#producer-12] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	CLUSTERID [rdkafka#producer-12] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "xocTXNnwS0eEOUWzDqa1Zw"
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	CONTROLLERID [rdkafka#producer-12] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	BRKMAIN [rdkafka#producer-12] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	TOPIC [rdkafka#producer-12] [thrd:app]: New local topic: TO_DISPLAY_MANAGER
2019-09-10 17:09:45,252 PID: 19076 | s_a2b371a4.Producer 	TOPPARNEW [rdkafka#producer-12] [thrd:app]: NEW TO_DISPLAY_MANAGER [-1] 0x4075770 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:46,281 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:46,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPMETADATA [rdkafka#consumer-13] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:46,282 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": postponing join until up-to-date metadata is available
2019-09-10 17:09:46,282 PID: 19076 | s_a2b371a4.Consumer  	METADATA [rdkafka#consumer-13] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:46,282 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]: Group "DMC": effective subscription list changed from 0 to 1 topic(s):
2019-09-10 17:09:46,282 PID: 19076 | s_a2b371a4.Consumer  	SUBSCRIPTION [rdkafka#consumer-13] [thrd:main]:  Topic FROM_DM_TO_a2b371a4 with 1 partition(s)
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	REJOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": subscription updated from metadata change: rejoining group
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	GRPLEADER [rdkafka#consumer-13] [thrd:main]: Group "DMC": resetting group leader info: Group rejoin
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	REJOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC" rejoining in join-state init without an assignment
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	REBALANCE [rdkafka#consumer-13] [thrd:main]: Group "DMC" is rebalancing in state up (join-state init) without assignment: group rejoin
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state init -> wait-unassign (v1, state up)
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	UNASSIGN [rdkafka#consumer-13] [thrd:main]: Group "DMC": unassign done in state up (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:46,283 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state wait-unassign -> init (v1, state up)
2019-09-10 17:09:47,281 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: Group "DMC": join with 1 (1) subscribed topic(s)
2019-09-10 17:09:47,281 PID: 19076 | s_a2b371a4.Consumer  	CGRPMETADATA [rdkafka#consumer-13] [thrd:main]: consumer join: metadata for subscription is up to date (999ms old)
2019-09-10 17:09:47,282 PID: 19076 | s_a2b371a4.Consumer  	JOIN [rdkafka#consumer-13] [thrd:main]: 127.0.0.1:9092/0: Joining group "DMC" with 1 subscribed topic(s)
2019-09-10 17:09:47,282 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state init -> wait-join (v1, state up)
2019-09-10 17:09:47,345 PID: 19076 | s_a2b371a4.Consumer  	JOINGROUP [rdkafka#consumer-13] [thrd:main]: JoinGroup response: GenerationId 40, Protocol range, LeaderId rdkafka-1e7351b6-7009-4ae6-9c6b-20913b68c164, my MemberId rdkafka-1c8f4855-e670-47f3-aab6-693f4ea6b012, 0 members in group: (no error)
2019-09-10 17:09:47,346 PID: 19076 | s_a2b371a4.Consumer  	MEMBERID [rdkafka#consumer-13] [thrd:main]: Group "DMC": updating member id "" -> "rdkafka-1c8f4855-e670-47f3-aab6-693f4ea6b012"
2019-09-10 17:09:47,346 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state wait-join -> wait-sync (v1, state up)
2019-09-10 17:09:47,346 PID: 19076 | s_a2b371a4.Consumer  	SYNCGROUP [rdkafka#consumer-13] [thrd:main]: SyncGroup response: Success (88 bytes of MemberState data)
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	ASSIGN [rdkafka#consumer-13] [thrd:main]: Group "DMC": delegating assign of 1 partition(s) to application rebalance callback on queue rd_kafka_cgrp_new: new assignment
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state wait-sync -> wait-assign-rebalance_cb (v1, state up)
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	HEARTBEAT [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: Heartbeat for group "DMC" generation id 40
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	CGRPOP [rdkafka#consumer-13] [thrd:main]: Group "DMC" received op ASSIGN (v0) in state up (join state wait-assign-rebalance_cb, v1 vs 0)
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	ASSIGN [rdkafka#consumer-13] [thrd:main]: Group "DMC": new assignment of 1 partition(s) in join state wait-assign-rebalance_cb
2019-09-10 17:09:47,347 PID: 19076 | s_a2b371a4.Consumer  	TOPIC [rdkafka#consumer-13] [thrd:main]: New local topic: FROM_DM_TO_a2b371a4
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	TOPPARNEW [rdkafka#consumer-13] [thrd:main]: NEW FROM_DM_TO_a2b371a4 [-1] 0x7f86e800b0a0 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	STATE [rdkafka#consumer-13] [thrd:main]: Topic FROM_DM_TO_a2b371a4 changed state unknown -> exists
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	PARTCNT [rdkafka#consumer-13] [thrd:main]: Topic FROM_DM_TO_a2b371a4 partition count changed from 0 to 1
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	TOPPARNEW [rdkafka#consumer-13] [thrd:main]: NEW FROM_DM_TO_a2b371a4 [0] 0x7f86e800b4e0 (at rd_kafka_topic_partition_cnt_update:620)
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	METADATA [rdkafka#consumer-13] [thrd:main]:   Topic FROM_DM_TO_a2b371a4 partition 0 Leader 0
2019-09-10 17:09:47,348 PID: 19076 | s_a2b371a4.Consumer  	BRKDELGT [rdkafka#consumer-13] [thrd:main]: FROM_DM_TO_a2b371a4 [0]: delegate to broker 127.0.0.1:9092/0 (rktp 0x7f86e800b4e0, term 0, ref 2, remove 0)
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	BRKDELGT [rdkafka#consumer-13] [thrd:main]: FROM_DM_TO_a2b371a4 [0]: broker 127.0.0.1:9092/0 is now leader for partition with 0 messages (0 bytes) queued
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	BRKMIGR [rdkafka#consumer-13] [thrd:main]: Migrating topic FROM_DM_TO_a2b371a4 [0] 0x7f86e800b4e0 from (none) to 127.0.0.1:9092/0 (sending PARTITION_JOIN to 127.0.0.1:9092/0)
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	DESP [rdkafka#consumer-13] [thrd:main]: Setting topic FROM_DM_TO_a2b371a4 [0] partition as desired
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	BARRIER [rdkafka#consumer-13] [thrd:main]: Group "DMC": rd_kafka_cgrp_assign:2354: new version barrier v2
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	ASSIGN [rdkafka#consumer-13] [thrd:main]: Group "DMC": assigning 1 partition(s) in join state wait-assign-rebalance_cb
2019-09-10 17:09:47,349 PID: 19076 | s_a2b371a4.Consumer  	TOPBRK [rdkafka#consumer-13] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic FROM_DM_TO_a2b371a4 [0]: joining broker (rktp 0x7f86e800b4e0, 0 message(s) queued)
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state wait-assign-rebalance_cb -> assigned (v2, state up)
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	BARRIER [rdkafka#consumer-13] [thrd:main]: Group "DMC": rd_kafka_cgrp_partitions_fetch_start0:1674: new version barrier v3
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]: Group "DMC": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=no, v3, line 2399)
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]: List with 1 partition(s):
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]:  FROM_DM_TO_a2b371a4 [0] offset INVALID
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: OffsetFetchRequest(v1) for 1/1 partition(s)
2019-09-10 17:09:47,350 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: Fetch committed offsets for 1/1 partition(s)
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	OFFSETFETCH [rdkafka#consumer-13] [thrd:main]: List with 1 partition(s):
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	OFFSETFETCH [rdkafka#consumer-13] [thrd:main]:  FROM_DM_TO_a2b371a4 [0] offset INVALID
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: Topic FROM_DM_TO_a2b371a4 [0]: setting default offset INVALID
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	OFFSETFETCH [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: OffsetFetchResponse: FROM_DM_TO_a2b371a4 [0] offset -1
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	OFFFETCH [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: OffsetFetch for 1/1 partition(s) returned Success
2019-09-10 17:09:47,351 PID: 19076 | s_a2b371a4.Consumer  	BARRIER [rdkafka#consumer-13] [thrd:main]: Group "DMC": rd_kafka_cgrp_partitions_fetch_start0:1674: new version barrier v4
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]: Group "DMC": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=yes, v4, line 1606)
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]: List with 1 partition(s):
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	FETCHSTART [rdkafka#consumer-13] [thrd:main]:  FROM_DM_TO_a2b371a4 [0] offset INVALID
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	CGRPJOINSTATE [rdkafka#consumer-13] [thrd:main]: Group "DMC" changed join state assigned -> started (v4, state up)
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	BARRIER [rdkafka#consumer-13] [thrd:main]: FROM_DM_TO_a2b371a4 [0]: rd_kafka_toppar_op_fetch_start:2226: new version barrier v2
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	CONSUMER [rdkafka#consumer-13] [thrd:main]: Start consuming FROM_DM_TO_a2b371a4 [0] at offset INVALID (v2)
2019-09-10 17:09:47,352 PID: 19076 | s_a2b371a4.Consumer  	OP [rdkafka#consumer-13] [thrd:main]: FROM_DM_TO_a2b371a4 [0] received op FETCH_START (v2) in fetch-state none (opv1)
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	FETCH [rdkafka#consumer-13] [thrd:main]: Start fetch for FROM_DM_TO_a2b371a4 [0] in state none at offset INVALID (v2)
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	PARTSTATE [rdkafka#consumer-13] [thrd:main]: Partition FROM_DM_TO_a2b371a4 [0] changed fetch state none -> offset-query
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: FROM_DM_TO_a2b371a4 [0]: offset reset (at offset INVALID) to BEGINNING: no previously committed offset available: Local: No offset stored
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	OFFREQ [rdkafka#consumer-13] [thrd:main]: 127.0.0.1:9092/0: Partition FROM_DM_TO_a2b371a4 [0]: querying for logical offset BEGINNING (opv 2)
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: 127.0.0.1:9092/0: OffsetRequest (v0, opv 0) for 1 topic(s) and 1 partition(s)
2019-09-10 17:09:47,353 PID: 19076 | s_a2b371a4.Consumer  	PARTSTATE [rdkafka#consumer-13] [thrd:main]: Partition FROM_DM_TO_a2b371a4 [0] changed fetch state offset-query -> offset-wait
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	CGRPOP [rdkafka#consumer-13] [thrd:main]: Group "DMC" received op PARTITION_JOIN in state up (join state started, v4) for FROM_DM_TO_a2b371a4 [0]
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	PARTADD [rdkafka#consumer-13] [thrd:main]: Group "DMC": add FROM_DM_TO_a2b371a4 [0]
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: 127.0.0.1:9092/0: Offset reply for topic FROM_DM_TO_a2b371a4 [0] (v2 vs v2)
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: Offset BEGINNING request for FROM_DM_TO_a2b371a4 [0] returned offset 0 (0)
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	PARTSTATE [rdkafka#consumer-13] [thrd:main]: Partition FROM_DM_TO_a2b371a4 [0] changed fetch state offset-wait -> active
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	FETCH [rdkafka#consumer-13] [thrd:main]: Partition FROM_DM_TO_a2b371a4 [0] start fetching at offset 0
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	FETCHDEC [rdkafka#consumer-13] [thrd:127.0.0.1:9092/0]: Topic FROM_DM_TO_a2b371a4 [0]: fetch decide: updating to version 2 (was 0) at offset 0 (was 0)
2019-09-10 17:09:47,354 PID: 19076 | s_a2b371a4.Consumer  	FETCHADD [rdkafka#consumer-13] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Added FROM_DM_TO_a2b371a4 [0] to fetch list (1 entries, opv 2, 0 messages queued)
2019-09-10 17:09:47,369 PID: 19163 | s_a2b371a4.IM.Consumer  	MEMBERID [rdkafka#consumer-17] [thrd:app]: Group "IM_19163": updating member id "(not-set)" -> ""
2019-09-10 17:09:47,370 PID: 19163 | s_a2b371a4.IM.Consumer  	INIT [rdkafka#consumer-17] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-17 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2104)
2019-09-10 17:09:47,371 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPOP [rdkafka#consumer-17] [thrd:main]: Group "IM_19163" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-10 17:09:47,371 PID: 19163 | s_a2b371a4.IM.Consumer  	SUBSCRIBE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": subscribe to new subscription of 1 topics (join state init)
2019-09-10 17:09:47,371 PID: 19163 | s_a2b371a4.IM.Consumer  	UNSUBSCRIBE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-10 17:09:47,371 PID: 19163 | s_a2b371a4.IM.Consumer  	GRPLEADER [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": resetting group leader info: unsubscribe
2019-09-10 17:09:47,372 PID: 19163 | s_a2b371a4.IM.Consumer  	REBALANCE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-10 17:09:47,372 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163" changed join state init -> wait-unassign (v1, state init)
2019-09-10 17:09:47,372 PID: 19163 | s_a2b371a4.IM.Consumer  	UNASSIGN [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:47,372 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163" changed join state wait-unassign -> init (v1, state init)
2019-09-10 17:09:47,372 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPSTATE [rdkafka#consumer-17] [thrd:main]: Group "IM_19163" changed state init -> query-coord (v1, join-state init)
2019-09-10 17:09:47,373 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPQUERY [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:47,391 PID: 19076 | s_a2b371a4.EM.Consumer  	MEMBERID [rdkafka#consumer-18] [thrd:app]: Group "EP": updating member id "(not-set)" -> ""
2019-09-10 17:09:47,393 PID: 19076 | s_a2b371a4.EM.Consumer  	INIT [rdkafka#consumer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2104)
2019-09-10 17:09:47,393 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPOP [rdkafka#consumer-18] [thrd:main]: Group "EP" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-10 17:09:47,393 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "EP": subscribe to new subscription of 1 topics (join state init)
2019-09-10 17:09:47,393 PID: 19076 | s_a2b371a4.EM.Consumer  	UNSUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "EP": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-10 17:09:47,394 PID: 19076 | s_a2b371a4.EM.Consumer  	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "EP": resetting group leader info: unsubscribe
2019-09-10 17:09:47,394 PID: 19076 | s_a2b371a4.EM.Consumer  	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "EP" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-10 17:09:47,394 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed join state init -> wait-unassign (v1, state init)
2019-09-10 17:09:47,394 PID: 19076 | s_a2b371a4.EM.Consumer  	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "EP": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:47,395 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed join state wait-unassign -> init (v1, state init)
2019-09-10 17:09:47,395 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed state init -> query-coord (v1, join-state init)
2019-09-10 17:09:47,395 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: Group "EP": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:47,396 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "EP": no topics in metadata matched subscription
2019-09-10 17:09:47,396 PID: 19200 | s_a2b371a4.RMr.Consumer  	MEMBERID [rdkafka#consumer-18] [thrd:app]: Group "RM_19200": updating member id "(not-set)" -> ""
2019-09-10 17:09:47,398 PID: 19200 | s_a2b371a4.RMr.Consumer  	INIT [rdkafka#consumer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2104)
2019-09-10 17:09:47,399 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPOP [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-10 17:09:47,399 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": subscribe to new subscription of 1 topics (join state init)
2019-09-10 17:09:47,400 PID: 19200 | s_a2b371a4.RMr.Consumer  	UNSUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-10 17:09:47,400 PID: 19200 | s_a2b371a4.RMr.Consumer  	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": resetting group leader info: unsubscribe
2019-09-10 17:09:47,400 PID: 19200 | s_a2b371a4.RMr.Consumer  	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-10 17:09:47,400 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed join state init -> wait-unassign (v1, state init)
2019-09-10 17:09:47,401 PID: 19200 | s_a2b371a4.RMr.Consumer  	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:47,401 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed join state wait-unassign -> init (v1, state init)
2019-09-10 17:09:47,401 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed state init -> query-coord (v1, join-state init)
2019-09-10 17:09:47,401 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:47,401 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": no topics in metadata matched subscription
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	BRKMAIN [rdkafka#producer-18] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	BROKER [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	BRKMAIN [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	INIT [rdkafka#producer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	TOPIC [rdkafka#producer-18] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	TOPPARNEW [rdkafka#producer-18] [thrd:app]: NEW TO_PL [-1] 0x7f86e400aa40 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:47,877 PID: 19186 | s_a2b371a4.TM.Producer 	BROKER [rdkafka#producer-16] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,878 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECT [rdkafka#producer-16] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,878 PID: 19186 | s_a2b371a4.TM.Producer 	INIT [rdkafka#producer-16] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-16 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,879 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 211
2019-09-10 17:09:47,880 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-10 17:09:47,880 PID: 19186 | s_a2b371a4.TM.Producer 	CONNECTED [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-10 17:09:47,880 PID: 19186 | s_a2b371a4.TM.Producer 	FEATURE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-10 17:09:47,881 PID: 19186 | s_a2b371a4.TM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-10 17:09:47,881 PID: 19186 | s_a2b371a4.TM.Producer 	FEATURE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	BROKER [rdkafka#producer-16] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	CLUSTERID [rdkafka#producer-16] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "xocTXNnwS0eEOUWzDqa1Zw"
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	CONTROLLERID [rdkafka#producer-16] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread
2019-09-10 17:09:47,882 PID: 19186 | s_a2b371a4.TM.Producer 	TOPIC [rdkafka#producer-16] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,883 PID: 19186 | s_a2b371a4.TM.Producer 	TOPPARNEW [rdkafka#producer-16] [thrd:app]: NEW TO_PL [-1] 0x7f870801d7e0 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:47,888 PID: 19076 | s_a2b371a4.EM.Producer 	BROKER [rdkafka#producer-16] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,888 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECT [rdkafka#producer-16] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 217
2019-09-10 17:09:47,889 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECT [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-10 17:09:47,890 PID: 19076 | s_a2b371a4.EM.Producer 	CONNECTED [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-10 17:09:47,890 PID: 19076 | s_a2b371a4.EM.Producer 	FEATURE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-10 17:09:47,890 PID: 19076 | s_a2b371a4.EM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-10 17:09:47,890 PID: 19076 | s_a2b371a4.EM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:47,890 PID: 19076 | s_a2b371a4.EM.Producer 	INIT [rdkafka#producer-16] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-16 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,891 PID: 19076 | s_a2b371a4.EM.Producer 	FEATURE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-10 17:09:47,891 PID: 19076 | s_a2b371a4.EM.Producer 	STATE [rdkafka#producer-16] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-10 17:09:47,891 PID: 19076 | s_a2b371a4.EM.Producer 	BROKER [rdkafka#producer-16] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-10 17:09:47,891 PID: 19076 | s_a2b371a4.EM.Producer 	CLUSTERID [rdkafka#producer-16] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "xocTXNnwS0eEOUWzDqa1Zw"
2019-09-10 17:09:47,891 PID: 19076 | s_a2b371a4.EM.Producer 	CONTROLLERID [rdkafka#producer-16] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-10 17:09:47,892 PID: 19076 | s_a2b371a4.EM.Producer 	BRKMAIN [rdkafka#producer-16] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread
2019-09-10 17:09:47,892 PID: 19076 | s_a2b371a4.CAP.Producer 	BROKER [rdkafka#producer-17] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,892 PID: 19076 | s_a2b371a4.EM.Producer 	TOPIC [rdkafka#producer-16] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,892 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECT [rdkafka#producer-17] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,893 PID: 19076 | s_a2b371a4.EM.Producer 	TOPPARNEW [rdkafka#producer-16] [thrd:app]: NEW TO_PL [-1] 0x7f86680092b0 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:47,893 PID: 19076 | s_a2b371a4.CAP.Producer 	BRKMAIN [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,893 PID: 19076 | s_a2b371a4.CAP.Producer 	BRKMAIN [rdkafka#producer-17] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	INIT [rdkafka#producer-17] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-17 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,894 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 228
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	CONNECTED [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	FEATURE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	FEATURE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-10 17:09:47,895 PID: 19076 | s_a2b371a4.CAP.Producer 	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	BROKER [rdkafka#producer-17] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	CLUSTERID [rdkafka#producer-17] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "xocTXNnwS0eEOUWzDqa1Zw"
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	CONTROLLERID [rdkafka#producer-17] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	BRKMAIN [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	TOPIC [rdkafka#producer-17] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,896 PID: 19076 | s_a2b371a4.CAP.Producer 	TOPPARNEW [rdkafka#producer-17] [thrd:app]: NEW TO_PL [-1] 0x7f863c01a130 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:47,899 PID: 19200 | s_a2b371a4.RMr.Producer 	BROKER [rdkafka#producer-19] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,899 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECT [rdkafka#producer-19] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,900 PID: 19200 | s_a2b371a4.RMr.Producer 	INIT [rdkafka#producer-19] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-19 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,900 PID: 19200 | s_a2b371a4.RMr.Producer 	BRKMAIN [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,900 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECT [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,900 PID: 19200 | s_a2b371a4.RMr.Producer 	STATE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,900 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECT [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	STATE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECT [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 237
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECT [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	CONNECTED [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	FEATURE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-10 17:09:47,901 PID: 19200 | s_a2b371a4.RMr.Producer 	STATE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	BRKMAIN [rdkafka#producer-19] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	FEATURE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	STATE [rdkafka#producer-19] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	BROKER [rdkafka#producer-19] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	CLUSTERID [rdkafka#producer-19] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "xocTXNnwS0eEOUWzDqa1Zw"
2019-09-10 17:09:47,902 PID: 19200 | s_a2b371a4.RMr.Producer 	CONTROLLERID [rdkafka#producer-19] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-10 17:09:47,903 PID: 19200 | s_a2b371a4.RMr.Producer 	BRKMAIN [rdkafka#producer-19] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread
2019-09-10 17:09:47,903 PID: 19200 | s_a2b371a4.RMr.Producer 	TOPIC [rdkafka#producer-19] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,903 PID: 19200 | s_a2b371a4.RMr.Producer 	TOPPARNEW [rdkafka#producer-19] [thrd:app]: NEW TO_PL [-1] 0x7f86a0009c10 (at rd_kafka_topic_new0:393)
2019-09-10 17:09:48,281 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: Topic FROM_DM_TO_a2b371a4 [0]: stored offset 1, committed offset -1001: setting stored offset 1 for commit
2019-09-10 17:09:48,281 PID: 19076 | s_a2b371a4.Consumer  	COMMIT [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: Committing offsets for 1 partition(s): cgrp auto commit timer
2019-09-10 17:09:48,282 PID: 19076 | s_a2b371a4.Consumer  	OFFSET [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: Enqueue OffsetCommitRequest(v1, 1/1 partition(s))): cgrp auto commit timer
2019-09-10 17:09:48,282 PID: 19076 | s_a2b371a4.Consumer  	COMMIT [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: OffsetCommit for 1 partition(s): cgrp auto commit timer: returned: Success
2019-09-10 17:09:48,367 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPQUERY [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:48,386 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "EP": querying for coordinator: intervaled in state query-coord
2019-09-10 17:09:48,387 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed state query-coord -> wait-coord (v1, join-state init)
2019-09-10 17:09:48,387 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "EP" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:48,387 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: Group "EP" changing coordinator -1 -> 0
2019-09-10 17:09:48,387 PID: 19076 | s_a2b371a4.EM.Consumer  	COORDSET [rdkafka#consumer-18] [thrd:main]: Group "EP" coordinator set to broker 127.0.0.1:9092/0
2019-09-10 17:09:48,387 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed state wait-coord -> wait-broker-transport (v1, join-state init)
2019-09-10 17:09:48,388 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "EP": querying for coordinator: intervaled in state wait-broker-transport
2019-09-10 17:09:48,388 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "EP" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:48,388 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "EP": no topics in metadata matched subscription
2019-09-10 17:09:48,388 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed state wait-broker-transport -> up (v1, join-state init)
2019-09-10 17:09:48,388 PID: 19076 | s_a2b371a4.EM.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "EP": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:48,389 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:48,389 PID: 19076 | s_a2b371a4.EM.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "EP": postponing join until up-to-date metadata is available
2019-09-10 17:09:48,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "RM_19200": querying for coordinator: intervaled in state query-coord
2019-09-10 17:09:48,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed state query-coord -> wait-coord (v1, join-state init)
2019-09-10 17:09:48,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "RM_19200" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:48,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changing coordinator -1 -> 0
2019-09-10 17:09:48,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	COORDSET [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" coordinator set to broker 127.0.0.1:9092/0
2019-09-10 17:09:48,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed state wait-coord -> wait-broker-transport (v1, join-state init)
2019-09-10 17:09:48,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "RM_19200": querying for coordinator: intervaled in state wait-broker-transport
2019-09-10 17:09:48,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "RM_19200" coordinator is 127.0.0.1:9092 id 0
2019-09-10 17:09:48,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": no topics in metadata matched subscription
2019-09-10 17:09:48,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed state wait-broker-transport -> up (v1, join-state init)
2019-09-10 17:09:48,395 PID: 19200 | s_a2b371a4.RMr.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:48,395 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:48,395 PID: 19200 | s_a2b371a4.RMr.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": postponing join until up-to-date metadata is available
2019-09-10 17:09:48,396 PID: 19076 | s_a2b371a4.EM.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Temporary error in metadata reply for topic FROM_ETD_TO_a2b371a4 (PartCnt 0): Broker: Leader not available: ignoring
2019-09-10 17:09:48,396 PID: 19076 | s_a2b371a4.EM.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:48,396 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "EP": no topics in metadata matched subscription
2019-09-10 17:09:48,397 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "EP": no topics in metadata matched subscription
2019-09-10 17:09:48,403 PID: 19200 | s_a2b371a4.RMr.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Temporary error in metadata reply for topic FROM_MR_TO_a2b371a4 (PartCnt 0): Broker: Leader not available: ignoring
2019-09-10 17:09:48,404 PID: 19200 | s_a2b371a4.RMr.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:48,404 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": no topics in metadata matched subscription
2019-09-10 17:09:48,404 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": no topics in metadata matched subscription
2019-09-10 17:09:49,367 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPQUERY [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:50,347 PID: 19076 | s_a2b371a4.Consumer  	HEARTBEAT [rdkafka#consumer-13] [thrd:main]: GroupCoordinator/0: Heartbeat for group "DMC" generation id 40
2019-09-10 17:09:50,366 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPQUERY [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": no broker available for coordinator query: intervaled in state query-coord
2019-09-10 17:09:50,385 PID: 19076 | s_a2b371a4.EM.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "EP": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "EP": postponing join until up-to-date metadata is available
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "EP": effective subscription list changed from 0 to 1 topic(s):
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]:  Topic FROM_ETD_TO_a2b371a4 with 1 partition(s)
2019-09-10 17:09:50,386 PID: 19076 | s_a2b371a4.EM.Consumer  	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "EP": subscription updated from metadata change: rejoining group
2019-09-10 17:09:50,387 PID: 19076 | s_a2b371a4.EM.Consumer  	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "EP": resetting group leader info: Group rejoin
2019-09-10 17:09:50,387 PID: 19076 | s_a2b371a4.EM.Consumer  	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "EP" rejoining in join-state init without an assignment
2019-09-10 17:09:50,387 PID: 19076 | s_a2b371a4.EM.Consumer  	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "EP" is rebalancing in state up (join-state init) without assignment: group rejoin
2019-09-10 17:09:50,387 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed join state init -> wait-unassign (v1, state up)
2019-09-10 17:09:50,387 PID: 19076 | s_a2b371a4.EM.Consumer  	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "EP": unassign done in state up (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:50,388 PID: 19076 | s_a2b371a4.EM.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "EP" changed join state wait-unassign -> init (v1, state up)
2019-09-10 17:09:50,391 PID: 19200 | s_a2b371a4.RMr.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": join with 0 (1) subscribed topic(s)
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	JOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": postponing join until up-to-date metadata is available
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	METADATA [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: 1/1 requested topic(s) seen in metadata
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": effective subscription list changed from 0 to 1 topic(s):
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]:  Topic FROM_MR_TO_a2b371a4 with 1 partition(s)
2019-09-10 17:09:50,392 PID: 19200 | s_a2b371a4.RMr.Consumer  	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": subscription updated from metadata change: rejoining group
2019-09-10 17:09:50,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": resetting group leader info: Group rejoin
2019-09-10 17:09:50,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" rejoining in join-state init without an assignment
2019-09-10 17:09:50,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" is rebalancing in state up (join-state init) without assignment: group rejoin
2019-09-10 17:09:50,393 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed join state init -> wait-unassign (v1, state up)
2019-09-10 17:09:50,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "RM_19200": unassign done in state up (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-10 17:09:50,394 PID: 19200 | s_a2b371a4.RMr.Consumer  	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "RM_19200" changed join state wait-unassign -> init (v1, state up)
2019-09-10 17:09:51,367 PID: 19163 | s_a2b371a4.IM.Consumer  	CGRPQUERY [rdkafka#consumer-17] [thrd:main]: Group "IM_19163": no broker available for coordinator query: intervaled in state query-coord

(.... and it goes on like that of course)

@edenhill
Copy link
Contributor

I don't see any errors in the logs unfortunately, so not much to go on.

But it does seem a bit strange that the producer/consumer ids ("producer-NN") are increasing, they start at 1 for each process, this might indicate that clients are infact forked after creation or that multiple clients (18??) are instantiated in the same process.

To cut down on noise it would be interesting with just debug=broker to see if the clients even try to connect to the broker or not.

@kerenor23
Copy link
Author

kerenor23 commented Sep 10, 2019

Yup, looks like no actual errors, but one process's Consumer is constantly at
no broker available for coordinator query: intervaled in state query-coord
(while the other processes found the broker correctly).

I believe they're definitely trying to connect, see this excerpt for producer18

BROKER [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	BRKMAIN [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-10 17:09:47,870 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	INIT [rdkafka#producer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x46)
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	TOPIC [rdkafka#producer-18] [thrd:app]: New local topic: TO_PL
2019-09-10 17:09:47,871 PID: 19163 | s_a2b371a4.IM.Producer 	TOPPARNEW [rdkafka#producer-18] [thrd:app]: NEW TO_PL [-1] 0x7f86e400aa40 (at rd_kafka_topic_new0:393)

I will set the debug to log only broker and retry... might take a bit to reproduce, as said.
But what you say about the ids is indeed strange - I know for a fact they are instantiated only in the process itself.
But, the import (from confluent_kafka import Producer, KafkaError, Consumer) happens before forking the processes.
Does confluent_kafka initialize things at the import level itself? If yes, how would you recommend to go about this?

@edenhill
Copy link
Contributor

There will be no instantiation at import time, and even if it was it wouldn't explain instance id's starting at 13, so something is indeed fishy.

@edenhill
Copy link
Contributor

Is it possible that your container is running out of fds, or possibly threads?

@kerenor23
Copy link
Author

kerenor23 commented Sep 11, 2019

Is it possible that your container is running out of fds, or possibly threads?

Highly doubtful. Does kafka impose any fds/threads limits besides the OS ones?

There will be no instantiation at import time, and even if it was it wouldn't explain instance id's starting at 13, so something is indeed fishy.

They don't start at 13, this log is not from the start of the entire application. It's only the logs of processes that started together with the problematic 19163 process.

Consider this scenario -
we have a process that created Consumer + Producer, their id's are #1 and #2 .
This process forks a new process, that in turn creates Consumer + Producer on its own.
They will be 3+4, despite being the first Consumer+Producer of the child process. I guess that, like FDs, the forked process inherits them as well.

(Still trying to reproduce the issue with broker debug prints only)

@kerenor23
Copy link
Author

@edenhill returning with some more logs.

This is the same scenario as described before, consider the following -

  1. The log isn't from the start of the app - only from the start of the relevant processes
  2. I left the entries of 1 producer and 1 consumer from 2 processes:
    Process 25279 started correctly and communicates flawlessly with the broker - its log entries are
    I.Consumer which is [rdkafka#consumer-18] of process 25279
    I.Producer which is [rdkafka#producer-17] of process 25279
    Process 25317 did not start correctly and does not communicate with the broker - its log entries are
    R.Consumer which is [rdkafka#consumer-20] of process 25317
    R.Producer which is [rdkafka#producer-18] of process 25317

About the id's, I suggested what I think is happening in the previous comment.

Do you believe the forking might be problematic? (reminder - the process we fork from has kafka objects on its own - but we don't use them in the forked processes - the forked processes create new Consumers+Producers)
Any suggestion / idea would be greatly appreciated

2019-09-16 16:17:34,208 DEBUG    PID: 25279 | I.Consumer 	MEMBERID [rdkafka#consumer-18] [thrd:app]: Group "IM_25279": updating member id "(not-set)" -> ""
2019-09-16 16:17:34,209 DEBUG    PID: 25279 | I.Consumer 	BROKER [rdkafka#consumer-18] [thrd:app]: GroupCoordinator: Added new broker with NodeId -1
2019-09-16 16:17:34,209 DEBUG    PID: 25279 | I.Consumer 	BRKMAIN [rdkafka#consumer-18] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-16 16:17:34,209 DEBUG    PID: 25279 | I.Consumer 	BROKER [rdkafka#consumer-18] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-16 16:17:34,209 DEBUG    PID: 25279 | I.Consumer 	BRKMAIN [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-16 16:17:34,209 DEBUG    PID: 25279 | I.Consumer 	BRKMAIN [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Enter main broker thread
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	INIT [rdkafka#consumer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x102)
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	CGRPOP [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": subscribe to new subscription of 1 topics (join state init)
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	UNSUBSCRIBE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": resetting group leader info: unsubscribe
2019-09-16 16:17:34,210 DEBUG    PID: 25279 | I.Consumer 	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state init -> wait-unassign (v1, state init)
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-unassign -> init (v1, state init)
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed state init -> query-coord (v1, join-state init)
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Selected for cluster connection: coordinator query (broker has 0 connection attempt(s))
2019-09-16 16:17:34,211 DEBUG    PID: 25279 | I.Consumer 	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 218
2019-09-16 16:17:34,212 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-16 16:17:34,213 DEBUG    PID: 25279 | I.Consumer 	CONNECTED [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-16 16:17:34,213 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-16 16:17:34,213 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-16 16:17:34,213 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-16 16:17:34,213 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-16 16:17:34,214 DEBUG    PID: 25279 | I.Consumer 	BROKER [rdkafka#consumer-18] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-16 16:17:34,214 DEBUG    PID: 25279 | I.Consumer 	CLUSTERID [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "N2fFgI8ASuqru8iR5mMURQ"
2019-09-16 16:17:34,214 DEBUG    PID: 25279 | I.Consumer 	CONTROLLERID [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-16 16:17:34,214 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": no topics in metadata matched subscription
2019-09-16 16:17:34,214 DEBUG    PID: 25279 | I.Consumer 	BRKMAIN [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread

2019-09-16 16:17:34,233 DEBUG    PID: 25317 | R.Consumer 	MEMBERID [rdkafka#consumer-20] [thrd:app]: Group "RM_25317": updating member id "(not-set)" -> ""
2019-09-16 16:17:34,233 DEBUG    PID: 25317 | R.Consumer 	BROKER [rdkafka#consumer-20] [thrd:app]: GroupCoordinator: Added new broker with NodeId -1
2019-09-16 16:17:34,233 DEBUG    PID: 25317 | R.Consumer 	BROKER [rdkafka#consumer-20] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	BRKMAIN [rdkafka#consumer-20] [thrd:GroupCoordinator]: GroupCoordinator: Enter main broker thread
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	BRKMAIN [rdkafka#consumer-20] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	INIT [rdkafka#consumer-20] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#consumer-20 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x102)
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	BRKMAIN [rdkafka#consumer-20] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	CGRPOP [rdkafka#consumer-20] [thrd:main]: Group "RM_25317" received op SUBSCRIBE (v0) in state init (join state init, v1 vs 0)
2019-09-16 16:17:34,234 DEBUG    PID: 25317 | R.Consumer 	SUBSCRIBE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": subscribe to new subscription of 1 topics (join state init)
2019-09-16 16:17:34,235 DEBUG    PID: 25317 | R.Consumer 	UNSUBSCRIBE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": unsubscribe from current unset subscription of 0 topics (leave group=no, join state init, v1)
2019-09-16 16:17:34,235 DEBUG    PID: 25317 | R.Consumer 	GRPLEADER [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": resetting group leader info: unsubscribe
2019-09-16 16:17:34,235 DEBUG    PID: 25317 | R.Consumer 	REBALANCE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317" is rebalancing in state init (join-state init) without assignment: unsubscribe
2019-09-16 16:17:34,235 DEBUG    PID: 25317 | R.Consumer 	CGRPJOINSTATE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317" changed join state init -> wait-unassign (v1, state init)
2019-09-16 16:17:34,235 DEBUG    PID: 25317 | R.Consumer 	UNASSIGN [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": unassign done in state init (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-16 16:17:34,236 DEBUG    PID: 25317 | R.Consumer 	CGRPJOINSTATE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317" changed join state wait-unassign -> init (v1, state init)
2019-09-16 16:17:34,236 DEBUG    PID: 25317 | R.Consumer 	CGRPSTATE [rdkafka#consumer-20] [thrd:main]: Group "RM_25317" changed state init -> query-coord (v1, join-state init)
2019-09-16 16:17:34,236 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: localhost:9092/bootstrap: Selected for cluster connection: coordinator query (broker has 0 connection attempt(s))
2019-09-16 16:17:34,237 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:34,237 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-16 16:17:34,237 DEBUG    PID: 25317 | R.Consumer 	STATE [rdkafka#consumer-20] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:34,237 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-16 16:17:34,237 DEBUG    PID: 25317 | R.Consumer 	STATE [rdkafka#consumer-20] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT

2019-09-16 16:17:35,205 DEBUG    PID: 25279 | I.Consumer 	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "IM_25279": querying for coordinator: intervaled in state query-coord
2019-09-16 16:17:35,205 DEBUG    PID: 25279 | I.Consumer 	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed state query-coord -> wait-coord (v1, join-state init)
2019-09-16 16:17:35,205 DEBUG    PID: 25279 | I.Consumer 	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "IM_25279" coordinator is 127.0.0.1:9092 id 0
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changing coordinator -1 -> 0
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	COORDSET [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" coordinator set to broker 127.0.0.1:9092/0
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed state wait-coord -> wait-broker-transport (v1, join-state init)
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	NODENAME [rdkafka#consumer-18] [thrd:main]: GroupCoordinator: Broker nodename changed from "" to "127.0.0.1:9092"
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	CGRPQUERY [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "IM_25279": querying for coordinator: intervaled in state wait-broker-transport
2019-09-16 16:17:35,206 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Received CONNECT op
2019-09-16 16:17:35,207 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:35,207 DEBUG    PID: 25279 | I.Consumer 	BROKERFAIL [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: failed: err: Local: Broker node update: (errno: Success)
2019-09-16 16:17:35,207 DEBUG    PID: 25279 | I.Consumer 	FAIL [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Closing connection due to nodename change (after 0ms in state TRY_CONNECT)
2019-09-16 16:17:35,207 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state TRY_CONNECT -> DOWN
2019-09-16 16:17:35,207 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state DOWN -> INIT
2019-09-16 16:17:35,208 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:35,208 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: broker in state TRY_CONNECT connecting
2019-09-16 16:17:35,208 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:35,208 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 226
2019-09-16 16:17:35,208 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: Connected to ipv4#127.0.0.1:9092
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	CONNECTED [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: Connected (#1)
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	CGRPCOORD [rdkafka#consumer-18] [thrd:main]: localhost:9092/bootstrap: Group "IM_25279" coordinator is 127.0.0.1:9092 id 0
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator/0: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-16 16:17:35,209 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:GroupCoordinator]: GroupCoordinator: Broker changed state APIVERSION_QUERY -> UP
2019-09-16 16:17:35,210 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": no topics in metadata matched subscription
2019-09-16 16:17:35,210 DEBUG    PID: 25279 | I.Consumer 	CGRPSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed state wait-broker-transport -> up (v1, join-state init)
2019-09-16 16:17:35,210 DEBUG    PID: 25279 | I.Consumer 	JOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": join with 0 (1) subscribed topic(s)
2019-09-16 16:17:35,210 DEBUG    PID: 25279 | I.Consumer 	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-16 16:17:35,210 DEBUG    PID: 25279 | I.Consumer 	JOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": postponing join until up-to-date metadata is available
2019-09-16 16:17:35,214 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": no topics in metadata matched subscription
2019-09-16 16:17:35,214 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": no topics in metadata matched subscription

2019-09-16 16:17:35,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:35,232 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:35,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection
2019-09-16 16:17:36,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:36,230 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:36,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:37,205 DEBUG    PID: 25279 | I.Consumer 	JOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": join with 0 (1) subscribed topic(s)
2019-09-16 16:17:37,206 DEBUG    PID: 25279 | I.Consumer 	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription only available for 0/1 topics (-1ms old)
2019-09-16 16:17:37,206 DEBUG    PID: 25279 | I.Consumer 	JOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": postponing join until up-to-date metadata is available
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": effective subscription list changed from 0 to 1 topic(s):
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	SUBSCRIPTION [rdkafka#consumer-18] [thrd:main]:  Topic FROM_IR_541fe81a with 1 partition(s)
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": subscription updated from metadata change: rejoining group
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": resetting group leader info: Group rejoin
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	REJOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" rejoining in join-state init without an assignment
2019-09-16 16:17:37,207 DEBUG    PID: 25279 | I.Consumer 	REBALANCE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" is rebalancing in state up (join-state init) without assignment: group rejoin
2019-09-16 16:17:37,208 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state init -> wait-unassign (v1, state up)
2019-09-16 16:17:37,208 DEBUG    PID: 25279 | I.Consumer 	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": unassign done in state up (join state wait-unassign): without new assignment: unassign (no previous assignment)
2019-09-16 16:17:37,208 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-unassign -> init (v1, state up)

2019-09-16 16:17:37,230 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:37,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:38,205 DEBUG    PID: 25279 | I.Consumer 	JOIN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": join with 1 (1) subscribed topic(s)
2019-09-16 16:17:38,206 DEBUG    PID: 25279 | I.Consumer 	CGRPMETADATA [rdkafka#consumer-18] [thrd:main]: consumer join: metadata for subscription is up to date (999ms old)
2019-09-16 16:17:38,206 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state init -> wait-join (v1, state up)

2019-09-16 16:17:38,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:38,230 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:38,231 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:38,232 DEBUG    PID: 25279 | I.Producer  	BRKMAIN [rdkafka#producer-17] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-16 16:17:38,232 DEBUG    PID: 25279 | I.Producer  	BROKER [rdkafka#producer-17] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-16 16:17:38,232 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-16 16:17:38,233 DEBUG    PID: 25279 | I.Producer  	INIT [rdkafka#producer-17] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-17 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2)
2019-09-16 16:17:38,233 DEBUG    PID: 25279 | I.Producer  	BRKMAIN [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-16 16:17:38,233 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-16 16:17:38,233 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:38,234 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-16 16:17:38,234 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:38,234 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 209
2019-09-16 16:17:38,234 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2019-09-16 16:17:38,235 DEBUG    PID: 25279 | I.Producer  	CONNECTED [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Connected (#1)
2019-09-16 16:17:38,235 DEBUG    PID: 25279 | I.Producer  	FEATURE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-16 16:17:38,235 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-16 16:17:38,236 DEBUG    PID: 25279 | I.Producer  	FEATURE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-16 16:17:38,236 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2019-09-16 16:17:38,236 DEBUG    PID: 25279 | I.Producer  	BROKER [rdkafka#producer-17] [thrd:main]: 127.0.0.1:9092/0: Added new broker with NodeId 0
2019-09-16 16:17:38,237 DEBUG    PID: 25279 | I.Producer  	CLUSTERID [rdkafka#producer-17] [thrd:main]: localhost:9092/bootstrap: ClusterId update "" -> "N2fFgI8ASuqru8iR5mMURQ"
2019-09-16 16:17:38,237 DEBUG    PID: 25279 | I.Producer  	CONTROLLERID [rdkafka#producer-17] [thrd:main]: localhost:9092/bootstrap: ControllerId update -1 -> 0
2019-09-16 16:17:38,237 DEBUG    PID: 25279 | I.Producer  	BRKMAIN [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Enter main broker thread

2019-09-16 16:17:38,449 DEBUG    PID: 25317 | R.Producer  	BRKMAIN [rdkafka#producer-18] [thrd::0/internal]: :0/internal: Enter main broker thread
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	BROKER [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Added new broker with NodeId -1
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:app]: localhost:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	BRKMAIN [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Enter main broker thread
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Received CONNECT op
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	INIT [rdkafka#producer-18] [thrd:app]: librdkafka v1.0.1 (0x10001ff) rdkafka#producer-18 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_plain,sasl_scram,plugins,zstd, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL ZSTD HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM CRC32C_HW, debug 0x2)
2019-09-16 16:17:38,450 DEBUG    PID: 25317 | R.Producer  	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: broker in state TRY_CONNECT connecting
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	STATE [rdkafka#producer-18] [thrd:localhost:9092/bootstrap]: localhost:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: no cluster connection
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: no cluster connection
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: no cluster connection
2019-09-16 16:17:38,451 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: no cluster connection

2019-09-16 16:17:39,205 DEBUG    PID: 25279 | I.Consumer 	COMMIT [rdkafka#consumer-18] [thrd:main]: OffsetCommit internal error: Local: No offset stored
2019-09-16 16:17:39,205 DEBUG    PID: 25279 | I.Consumer 	COMMIT [rdkafka#consumer-18] [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
2019-09-16 16:17:39,206 DEBUG    PID: 25279 | I.Consumer 	UNASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": unassign done in state up (join state wait-join): without new assignment: OffsetCommit done (__NO_OFFSET)
2019-09-16 16:17:39,206 DEBUG    PID: 25279 | I.Consumer 	JOINGROUP [rdkafka#consumer-18] [thrd:main]: JoinGroup response: GenerationId 1, Protocol range, LeaderId rdkafka-abcd019e-2c87-444c-9319-658625a91231 (me), my MemberId rdkafka-abcd019e-2c87-444c-9319-658625a91231, 1 members in group: (no error)
2019-09-16 16:17:39,206 DEBUG    PID: 25279 | I.Consumer 	MEMBERID [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": updating member id "" -> "rdkafka-abcd019e-2c87-444c-9319-658625a91231"
2019-09-16 16:17:39,207 DEBUG    PID: 25279 | I.Consumer 	JOINGROUP [rdkafka#consumer-18] [thrd:main]: Elected leader for group "IM_25279" with 1 member(s)
2019-09-16 16:17:39,207 DEBUG    PID: 25279 | I.Consumer 	GRPLEADER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": resetting group leader info: JoinGroup response clean-up
2019-09-16 16:17:39,208 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-join -> wait-metadata (v1, state up)
2019-09-16 16:17:39,208 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" running range assignment for 1 member(s):
2019-09-16 16:17:39,208 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]:  Member "rdkafka-abcd019e-2c87-444c-9319-658625a91231" (me) with 1 subscription(s):
2019-09-16 16:17:39,209 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]:   FROM_IR_541fe81a [-1]
2019-09-16 16:17:39,209 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: range: Topic FROM_IR_541fe81a with 1 partition(s) and 1 subscribing member(s)
2019-09-16 16:17:39,209 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: range: Member "rdkafka-abcd019e-2c87-444c-9319-658625a91231": assigned topic FROM_IR_541fe81a partitions 0..0
2019-09-16 16:17:39,209 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" range assignment for 1 member(s) finished in 0.014ms:
2019-09-16 16:17:39,210 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]:  Member "rdkafka-abcd019e-2c87-444c-9319-658625a91231" (me) assigned 1 partition(s):
2019-09-16 16:17:39,210 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]:   FROM_IR_541fe81a [0]
2019-09-16 16:17:39,210 DEBUG    PID: 25279 | I.Consumer 	ASSIGNOR [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": "range" assignor run for 1 member(s)
2019-09-16 16:17:39,210 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-metadata -> wait-sync (v1, state up)
2019-09-16 16:17:39,210 DEBUG    PID: 25279 | I.Consumer 	SYNCGROUP [rdkafka#consumer-18] [thrd:main]: SyncGroup response: Success (72 bytes of MemberState data)
2019-09-16 16:17:39,211 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": delegating assign of 1 partition(s) to application rebalance callback on queue rd_kafka_cgrp_new: new assignment
2019-09-16 16:17:39,211 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-sync -> wait-assign-rebalance_cb (v1, state up)
2019-09-16 16:17:39,211 DEBUG    PID: 25279 | I.Consumer 	HEARTBEAT [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: Heartbeat for group "IM_25279" generation id 1
2019-09-16 16:17:39,211 DEBUG    PID: 25279 | I.Consumer 	CGRPOP [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" received op ASSIGN (v0) in state up (join state wait-assign-rebalance_cb, v1 vs 0)
2019-09-16 16:17:39,212 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": new assignment of 1 partition(s) in join state wait-assign-rebalance_cb
2019-09-16 16:17:39,212 DEBUG    PID: 25279 | I.Consumer 	BARRIER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": rd_kafka_cgrp_assign:2354: new version barrier v2
2019-09-16 16:17:39,212 DEBUG    PID: 25279 | I.Consumer 	ASSIGN [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": assigning 1 partition(s) in join state wait-assign-rebalance_cb
2019-09-16 16:17:39,213 DEBUG    PID: 25279 | I.Consumer 	TOPBRK [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic FROM_IR_541fe81a [0]: joining broker (rktp 0x7f97e800ca10, 0 message(s) queued)
2019-09-16 16:17:39,214 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:39,214 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: broker in state TRY_CONNECT connecting
2019-09-16 16:17:39,214 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state wait-assign-rebalance_cb -> assigned (v2, state up)
2019-09-16 16:17:39,214 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:39,215 DEBUG    PID: 25279 | I.Consumer 	BARRIER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": rd_kafka_cgrp_partitions_fetch_start0:1674: new version barrier v3
2019-09-16 16:17:39,215 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=no, v3, line 2399)
2019-09-16 16:17:39,215 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]: List with 1 partition(s):
2019-09-16 16:17:39,215 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]:  FROM_IR_541fe81a [0] offset INVALID
2019-09-16 16:17:39,215 DEBUG    PID: 25279 | I.Consumer 	OFFSET [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: Fetch committed offsets for 1/1 partition(s)
2019-09-16 16:17:39,216 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 231
2019-09-16 16:17:39,216 DEBUG    PID: 25279 | I.Consumer 	CONNECT [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connected to ipv4#127.0.0.1:9092
2019-09-16 16:17:39,216 DEBUG    PID: 25279 | I.Consumer 	CONNECTED [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connected (#1)
2019-09-16 16:17:39,216 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-16 16:17:39,217 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-16 16:17:39,217 DEBUG    PID: 25279 | I.Consumer 	OFFSETFETCH [rdkafka#consumer-18] [thrd:main]: List with 1 partition(s):
2019-09-16 16:17:39,218 DEBUG    PID: 25279 | I.Consumer 	OFFSETFETCH [rdkafka#consumer-18] [thrd:main]:  FROM_IR_541fe81a [0] offset INVALID
2019-09-16 16:17:39,218 DEBUG    PID: 25279 | I.Consumer 	OFFSET [rdkafka#consumer-18] [thrd:main]: Topic FROM_IR_541fe81a [0]: setting default offset INVALID
2019-09-16 16:17:39,218 DEBUG    PID: 25279 | I.Consumer 	BARRIER [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": rd_kafka_cgrp_partitions_fetch_start0:1674: new version barrier v4
2019-09-16 16:17:39,219 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": starting fetchers for 1 assigned partition(s) in join-state assigned (usable_offsets=yes, v4, line 1606)
2019-09-16 16:17:39,219 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]: List with 1 partition(s):
2019-09-16 16:17:39,219 DEBUG    PID: 25279 | I.Consumer 	FETCHSTART [rdkafka#consumer-18] [thrd:main]:  FROM_IR_541fe81a [0] offset INVALID
2019-09-16 16:17:39,220 DEBUG    PID: 25279 | I.Consumer 	CGRPJOINSTATE [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" changed join state assigned -> started (v4, state up)
2019-09-16 16:17:39,220 DEBUG    PID: 25279 | I.Consumer 	CGRPOP [rdkafka#consumer-18] [thrd:main]: Group "IM_25279" received op PARTITION_JOIN in state up (join state started, v4) for FROM_IR_541fe81a [0]
2019-09-16 16:17:39,220 DEBUG    PID: 25279 | I.Consumer 	PARTADD [rdkafka#consumer-18] [thrd:main]: Group "IM_25279": add FROM_IR_541fe81a [0]
2019-09-16 16:17:39,221 DEBUG    PID: 25279 | I.Consumer 	FEATURE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-16 16:17:39,221 DEBUG    PID: 25279 | I.Consumer 	STATE [rdkafka#consumer-18] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state APIVERSION_QUERY -> UP
Y_CONNECT -> CONNECT
2019-09-16 16:17:39,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:39,231 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:39,231 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit internal error: Local: No offset stored
2019-09-16 16:17:39,232 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
2019-09-16 16:17:39,232 DEBUG    PID: 25317 | R.Consumer 	UNASSIGN [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": unassign done in state query-coord (join state init): without new assignment: OffsetCommit done (__NO_OFFSET)
2019-09-16 16:17:39,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 47ms: no cluster connection

2019-09-16 16:17:39,249 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IX [0]: joining broker (rktp 0x7f9800008520, 0 message(s) queued)
2019-09-16 16:17:39,249 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IX [1]: joining broker (rktp 0x7f9800008a20, 0 message(s) queued)
2019-09-16 16:17:39,250 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IX [2]: joining broker (rktp 0x7f9800008f20, 0 message(s) queued)
2019-09-16 16:17:39,250 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IX [3]: joining broker (rktp 0x7f9800009420, 0 message(s) queued)
2019-09-16 16:17:39,250 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IX [4]: joining broker (rktp 0x7f9800009920, 0 message(s) queued)
2019-09-16 16:17:39,250 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [0] 1 message(s) queued but broker not up
2019-09-16 16:17:39,251 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [1] 2 message(s) queued but broker not up
2019-09-16 16:17:39,251 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IR [0]: joining broker (rktp 0x7f980000a1d0, 0 message(s) queued)
2019-09-16 16:17:39,251 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IR [1]: joining broker (rktp 0x7f980000a6d0, 0 message(s) queued)
2019-09-16 16:17:39,251 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IR [2]: joining broker (rktp 0x7f980000abd0, 0 message(s) queued)
2019-09-16 16:17:39,251 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IR [3]: joining broker (rktp 0x7f980000b0d0, 0 message(s) queued)
2019-09-16 16:17:39,252 DEBUG    PID: 25279 | I.Producer  	TOPBRK [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Topic TO_IR [4]: joining broker (rktp 0x7f980000b5d0, 1 message(s) queued)
2019-09-16 16:17:39,252 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state INIT -> TRY_CONNECT
2019-09-16 16:17:39,252 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: broker in state TRY_CONNECT connecting
2019-09-16 16:17:39,253 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state TRY_CONNECT -> CONNECT
2019-09-16 16:17:39,253 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 230
2019-09-16 16:17:39,253 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [1] 2 message(s) queued but broker not up
2019-09-16 16:17:39,254 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IR [0] 1 message(s) queued but broker not up
2019-09-16 16:17:39,254 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IR [4] 1 message(s) queued but broker not up
2019-09-16 16:17:39,254 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [0] 1 message(s) queued but broker not up
2019-09-16 16:17:39,254 DEBUG    PID: 25279 | I.Producer  	CONNECT [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connected to ipv4#127.0.0.1:9092
2019-09-16 16:17:39,255 DEBUG    PID: 25279 | I.Producer  	CONNECTED [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Connected (#1)
2019-09-16 16:17:39,255 DEBUG    PID: 25279 | I.Producer  	FEATURE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Updated enabled protocol features +ApiVersion to ApiVersion
2019-09-16 16:17:39,255 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state CONNECT -> APIVERSION_QUERY
2019-09-16 16:17:39,255 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IR [0] 1 message(s) queued but broker not up
2019-09-16 16:17:39,255 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IR [4] 1 message(s) queued but broker not up
2019-09-16 16:17:39,256 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [0] 1 message(s) queued but broker not up
2019-09-16 16:17:39,256 DEBUG    PID: 25279 | I.Producer  	TOPPAR [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: TO_IX [1] 2 message(s) queued but broker not up
2019-09-16 16:17:39,256 DEBUG    PID: 25279 | I.Producer  	FEATURE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer
2019-09-16 16:17:39,256 DEBUG    PID: 25279 | I.Producer  	STATE [rdkafka#producer-17] [thrd:127.0.0.1:9092/0]: 127.0.0.1:9092/0: Broker changed state APIVERSION_QUERY -> UP

2019-09-16 16:17:39,353 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:39,353 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:39,354 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:40,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:40,232 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:40,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:40,310 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:40,310 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:40,310 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:41,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:41,232 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:41,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:41,540 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:41,541 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:41,541 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:42,212 DEBUG    PID: 25279 | I.Consumer 	HEARTBEAT [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: Heartbeat for group "IM_25279" generation id 1

2019-09-16 16:17:42,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:42,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:42,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:42,550 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:42,550 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:42,550 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:43,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:43,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:43,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:43,672 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:43,672 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:43,673 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:44,205 DEBUG    PID: 25279 | I.Consumer 	OFFSET [rdkafka#consumer-18] [thrd:main]: Topic FROM_IR_541fe81a [0]: stored offset 7, committed offset -1001: setting stored offset 7 for commit
2019-09-16 16:17:44,205 DEBUG    PID: 25279 | I.Consumer 	COMMIT [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: OffsetCommit for 1 partition(s): cgrp auto commit timer: returned: Success

2019-09-16 16:17:44,229 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:44,230 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:44,230 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit internal error: Local: No offset stored
2019-09-16 16:17:44,230 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
2019-09-16 16:17:44,231 DEBUG    PID: 25317 | R.Consumer 	UNASSIGN [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": unassign done in state query-coord (join state init): without new assignment: OffsetCommit done (__NO_OFFSET)
2019-09-16 16:17:44,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 47ms: no cluster connection

2019-09-16 16:17:44,582 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:44,582 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:44,582 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:45,212 DEBUG    PID: 25279 | I.Consumer 	HEARTBEAT [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: Heartbeat for group "IM_25279" generation id 1

2019-09-16 16:17:45,231 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:45,232 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:45,232 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:45,652 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:45,652 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:45,652 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:46,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:46,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:46,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:46,469 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:46,469 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:46,469 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:47,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:47,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:47,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:47,581 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:47,581 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:47,582 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:48,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:48,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:48,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:48,506 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:48,506 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:48,506 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:49,205 DEBUG    PID: 25279 | I.Consumer 	OFFSET [rdkafka#consumer-18] [thrd:main]: Topic FROM_IR_541fe81a [0]: stored offset 8, committed offset 7: setting stored offset 8 for commit
2019-09-16 16:17:49,205 DEBUG    PID: 25279 | I.Consumer 	COMMIT [rdkafka#consumer-18] [thrd:main]: GroupCoordinator/0: OffsetCommit for 1 partition(s): cgrp auto commit timer: returned: Success

2019-09-16 16:17:49,230 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:49,230 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:49,230 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit internal error: Local: No offset stored
2019-09-16 16:17:49,230 DEBUG    PID: 25317 | R.Consumer 	COMMIT [rdkafka#consumer-20] [thrd:main]: OffsetCommit for -1 partition(s): cgrp auto commit timer: returned: Local: No offset stored
2019-09-16 16:17:49,231 DEBUG    PID: 25317 | R.Consumer 	UNASSIGN [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": unassign done in state query-coord (join state init): without new assignment: OffsetCommit done (__NO_OFFSET)
2019-09-16 16:17:49,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 47ms: no cluster connection

2019-09-16 16:17:49,592 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Cluster connection already in progress: refresh unavailable topics
2019-09-16 16:17:49,592 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics
2019-09-16 16:17:49,592 DEBUG    PID: 25317 | R.Producer  	CONNECT [rdkafka#producer-18] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

2019-09-16 16:17:50,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Cluster connection already in progress: coordinator query
2019-09-16 16:17:50,233 DEBUG    PID: 25317 | R.Consumer 	CGRPQUERY [rdkafka#consumer-20] [thrd:main]: Group "RM_25317": no broker available for coordinator query: intervaled in state query-coord
2019-09-16 16:17:50,233 DEBUG    PID: 25317 | R.Consumer 	CONNECT [rdkafka#consumer-20] [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection

.... etc etc

@edenhill
Copy link
Contributor

edenhill commented Oct 7, 2019

@kerenor23 Thank you for the logs.

Unfortunately I can't find an explanation in the logs for why the producer can't connect to the broker at localhost:9092 while the consumer can.
My guess is still that there is a system limit in play somewhere.
Do you see the producer's connection attempt in netstat -anp for the given process?
Is there anything in the broker logs or dmesg?

@kerenor23
Copy link
Author

In the broker logs there's nothing about the Consumer & Producer that don't connect, as if no requests are even made.
Didn't get to try netstat/dmesg.
I'll keep in mind your idea about a system limit (haven't had this issue happen for a couple of weeks now), though I'd be a bit surprised if it is - the quick-fix for this is just to restart the not-connecting process (and the new process would of course require the same amount of producers & consumers... and it would connect correctly).
Anyways, will try monitor this and see where I get.
Thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants