Loading...

XML

Word

Printable

Type: Bug
Resolution: Won't Do
Priority: Major
Fix Version/s: 1.5.0.GA
Affects Version/s: None
Component/s: None
Labels:
- StrimziReportPortal
- StrimziST

Target Release:

1.5.0.GA

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

Back link to Report Portal:

Link to defect

Test execution log:

Test execution log

 Time: 04/15/2020 06:31:07, Level: INFO, Log: 2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:94] Start time of operation TEST_EXECUTION is correctly stored
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [TestSeparator:27] ############################################################################
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [TestSeparator:28] io.strimzi.systemtest.RollingUpdateST.testKafkaAndZookeeperScaleUpScaleDown-STARTED
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:89] Setting pointer to method resources
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:94] Start time of operation CLUSTER_RECOVERY-6556d7b8 is correctly stored
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of Kafka my-cluster in namespace rolling-update-cluster-test
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [KafkaResource:213] Waiting for Kafka my-cluster in namespace rolling-update-cluster-test
2020-04-15 04:15:48 &amp#27;[32mINFO &amp#27;[m [KafkaResource:215] Waiting for Zookeeper pods
2020-04-15 04:16:33 &amp#27;[32mINFO &amp#27;[m [KafkaResource:217] Zookeeper pods are ready
2020-04-15 04:16:33 &amp#27;[32mINFO &amp#27;[m [KafkaResource:219] Waiting for Kafka pods
2020-04-15 04:17:10 &amp#27;[32mINFO &amp#27;[m [KafkaResource:221] Kafka pods are ready
2020-04-15 04:17:10 &amp#27;[32mINFO &amp#27;[m [KafkaResource:225] Waiting for Entity Operator pods
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [KafkaResource:227] Entity Operator pods are ready
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [KafkaUserResource:64] Created KafkaUser alice
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of KafkaUser alice in namespace rolling-update-cluster-test
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [KafkaUserResource:81] Waiting for Kafka User alice
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [KafkaUserUtils:24] Waiting for Kafka user creation alice
2020-04-15 04:17:31 &amp#27;[32mINFO &amp#27;[m [SecretUtils:40] Waiting for Kafka user secret alice
2020-04-15 04:17:32 &amp#27;[32mINFO &amp#27;[m [SecretUtils:44] Kafka user secret alice created
2020-04-15 04:17:33 &amp#27;[32mINFO &amp#27;[m [KafkaUserUtils:35] Kafka user alice created
2020-04-15 04:17:33 &amp#27;[32mINFO &amp#27;[m [KafkaUserResource:83] Kafka User alice is ready
2020-04-15 04:17:33 &amp#27;[32mINFO &amp#27;[m [BaseST:680] Verifying docker image names
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [BaseST:720] Docker images verified
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [RecoveryST:288] Running kafkaScaleUpScaleDown my-cluster
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [KafkaTopicResource:66] Created KafkaTopic test-topic-925556285
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of KafkaTopic test-topic-925556285 in namespace rolling-update-cluster-test
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [KafkaTopicResource:83] Waiting for Kafka Topic test-topic-925556285
2020-04-15 04:17:34 &amp#27;[32mINFO &amp#27;[m [KafkaTopicUtils:45] Waiting for Kafka topic creation test-topic-925556285
2020-04-15 04:17:37 &amp#27;[32mINFO &amp#27;[m [KafkaTopicResource:85] Kafka Topic test-topic-925556285 is ready
2020-04-15 04:17:37 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of Deployment my-cluster-kafka-clients in namespace (not set)
2020-04-15 04:17:37 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:422] Waiting for deployment my-cluster-kafka-clients
2020-04-15 04:17:58 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:424] Deployment my-cluster-kafka-clients is ready
2020-04-15 04:17:58 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:113] Starting verifiableClient tls producer with following configuration VerifiableClient{allowedArguments=[TOPIC, BROKER_LIST, MAX_MESSAGES, THROUGHPUT, ACKS, PRODUCER_CONFIG, MESSAGE_CREATE_TIME, VALUE_PREFIX, REPEATING_KEYS, USER], lock=java.lang.Object@44c2e8a8, messages=[], arguments=[--broker-list, my-cluster-kafka-bootstrap:9093, USER=alice, --max-messages, 100, --topic, test-topic-925556285], executable='/opt/kafka/producer.sh', executor=null, clientType=CLI_KAFKA_VERIFIABLE_PRODUCER, podName='my-cluster-kafka-clients-6bc9868958-xn746', podNamespace='rolling-update-cluster-test', bootstrapServer='my-cluster-kafka-bootstrap:9093', topicName='test-topic-925556285', maxMessages=100, kafkaUsername='alice', consumerGroupName='null', consumerInstanceId='null', clientArgumentMap=io.strimzi.systemtest.kafkaclients.internalClients.ClientArgumentMap@3340ff7c}
2020-04-15 04:17:58 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:114] Sending 100 messages to my-cluster-kafka-bootstrap:9093#test-topic-925556285
2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [VerifiableClient:194] VerifiableClient CLI_KAFKA_VERIFIABLE_PRODUCER Return code - 0
2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [VerifiableClient:196] VerifiableClient CLI_KAFKA_VERIFIABLE_PRODUCER stdout : /tmp/alice.properties
Starting Producer with configuration:
acks=all
security.protocol=SSL
ssl.truststore.location=/tmp/alice-truststore.p12
ssl.truststore.type=pkcs12
ssl.keystore.location=/tmp/alice-keystore.p12
ssl.keystore.type=pkcs12

ssl.keystore.password=xhqLzko6Npi6LX6FTpSDjyYyQkOHcv_L
ssl.truststore.password=xhqLzko6Npi6LX6FTpSDjyYyQkOHcv_L
[2020-04-15 04:17:59,718] INFO ProducerConfig values: 
	acks = all
	batch.size = 16384
	bootstrap.servers = [my-cluster-kafka-bootstrap:9093]
	buffer.memory = 33554432
	client.dns.lookup = default
	client.id = 
	compression.type = none
	connections.max.idle.ms = 540000
	delivery.timeout.ms = 120000
	enable.idempotence = false
	interceptor.classes = []
	key.serializer = class org.apache.kafka.common.serialization.StringSerializer
	linger.ms = 0
	max.block.ms = 60000
	max.in.flight.requests.per.connection = 5
	max.request.size = 1048576
	metadata.max.age.ms = 300000
	metric.reporters = []
	metrics.num.samples = 2
	metrics.recording.level = INFO
	metrics.sample.window.ms = 30000
	partitioner.class = class org.apache.kafka.clients.producer.internals.DefaultPartitioner
	receive.buffer.bytes = 32768
	reconnect.backoff.max.ms = 1000
	reconnect.backoff.ms = 50
	request.timeout.ms = 30000
	retries = 0
	retry.backoff.ms = 100
	sasl.client.callback.handler.class = null
	sasl.jaas.config = null
	sasl.kerberos.kinit.cmd = /usr/bin/kinit
	sasl.kerberos.min.time.before.relogin = 60000
	sasl.kerberos.service.name = null
	sasl.kerberos.ticket.renew.jitter = 0.05
	sasl.kerberos.ticket.renew.window.factor = 0.8
	sasl.login.callback.handler.class = null
	sasl.login.class = null
	sasl.login.refresh.buffer.seconds = 300
	sasl.login.refresh.min.period.seconds = 60
	sasl.login.refresh.window.factor = 0.8
	sasl.login.refresh.window.jitter = 0.05
	sasl.mechanism = GSSAPI
	security.protocol = SSL
	security.providers = null
	send.buffer.bytes = 131072
	ssl.cipher.suites = null
	ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
	ssl.endpoint.identification.algorithm = https
	ssl.key.password = null
	ssl.keymanager.algorithm = SunX509
	ssl.keystore.location = /tmp/alice-keystore.p12
	ssl.keystore.password = [hidden]
	ssl.keystore.type = pkcs12
	ssl.protocol = TLS
	ssl.provider = null
	ssl.secure.random.implementation = null
	ssl.trustmanager.algorithm = PKIX
	ssl.truststore.location = /tmp/alice-truststore.p12
	ssl.truststore.password = [hidden]
	ssl.truststore.type = pkcs12
	transaction.timeout.ms = 60000
	transactional.id = null
	value.serializer = class org.apache.kafka.common.serialization.StringSerializer
 (ProducerConfig:347)
[2020-04-15 04:17:59,765] DEBUG Added sensor with name bufferpool-wait-time (Metrics:416)
[2020-04-15 04:17:59,775] DEBUG Added sensor with name buffer-exhausted-records (Metrics:416)
[2020-04-15 04:17:59,796] DEBUG Added sensor with name errors (Metrics:416)
[2020-04-15 04:18:00,067] DEBUG Created SSL context with keystore SecurityStore(path=/tmp/alice-keystore.p12, modificationTime=Wed Apr 15 04:17:58 UTC 2020), truststore SecurityStore(path=/tmp/alice-truststore.p12, modificationTime=Wed Apr 15 04:17:58 UTC 2020), provider SunJSSE. (SslEngineBuilder:159)
[2020-04-15 04:18:00,102] DEBUG Added sensor with name produce-throttle-time (Metrics:416)
[2020-04-15 04:18:00,115] DEBUG Added sensor with name connections-closed: (Metrics:416)
[2020-04-15 04:18:00,116] DEBUG Added sensor with name connections-created: (Metrics:416)
[2020-04-15 04:18:00,116] DEBUG Added sensor with name successful-authentication: (Metrics:416)
[2020-04-15 04:18:00,117] DEBUG Added sensor with name successful-reauthentication: (Metrics:416)
[2020-04-15 04:18:00,117] DEBUG Added sensor with name successful-authentication-no-reauth: (Metrics:416)
[2020-04-15 04:18:00,117] DEBUG Added sensor with name failed-authentication: (Metrics:416)
[2020-04-15 04:18:00,118] DEBUG Added sensor with name failed-reauthentication: (Metrics:416)
[2020-04-15 04:18:00,118] DEBUG Added sensor with name reauthentication-latency: (Metrics:416)
[2020-04-15 04:18:00,119] DEBUG Added sensor with name bytes-sent-received: (Metrics:416)
[2020-04-15 04:18:00,120] DEBUG Added sensor with name bytes-sent: (Metrics:416)
[2020-04-15 04:18:00,122] DEBUG Added sensor with name bytes-received: (Metrics:416)
[2020-04-15 04:18:00,123] DEBUG Added sensor with name select-time: (Metrics:416)
[2020-04-15 04:18:00,123] DEBUG Added sensor with name io-time: (Metrics:416)
[2020-04-15 04:18:00,131] DEBUG Added sensor with name batch-size (Metrics:416)
[2020-04-15 04:18:00,132] DEBUG Added sensor with name compression-rate (Metrics:416)
[2020-04-15 04:18:00,132] DEBUG Added sensor with name queue-time (Metrics:416)
[2020-04-15 04:18:00,133] DEBUG Added sensor with name request-time (Metrics:416)
[2020-04-15 04:18:00,134] DEBUG Added sensor with name records-per-request (Metrics:416)
[2020-04-15 04:18:00,134] DEBUG Added sensor with name record-retries (Metrics:416)
[2020-04-15 04:18:00,135] DEBUG Added sensor with name record-size (Metrics:416)
[2020-04-15 04:18:00,138] DEBUG Added sensor with name batch-split-rate (Metrics:416)
[2020-04-15 04:18:00,140] DEBUG [Producer clientId=producer-1] Starting Kafka producer I/O thread. (Sender:239)
[2020-04-15 04:18:00,141] DEBUG [Producer clientId=producer-1] Initialize connection to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) for sending metadata request (NetworkClient:1125)
[2020-04-15 04:18:00,143] INFO Kafka version: 2.4.0 (AppInfoParser:117)
[2020-04-15 04:18:00,144] INFO Kafka commitId: 77a89fcf8d7fa018 (AppInfoParser:118)
[2020-04-15 04:18:00,144] INFO Kafka startTimeMs: 1586924280139 (AppInfoParser:119)
[2020-04-15 04:18:00,144] DEBUG [Producer clientId=producer-1] Initiating connection to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) using address my-cluster-kafka-bootstrap/172.30.161.253 (NetworkClient:956)
[2020-04-15 04:18:00,148] DEBUG [Producer clientId=producer-1] Kafka producer started (KafkaProducer:427)
[2020-04-15 04:18:00,199] DEBUG Added sensor with name node--1.bytes-sent (Metrics:416)
[2020-04-15 04:18:00,200] DEBUG Added sensor with name node--1.bytes-received (Metrics:416)
[2020-04-15 04:18:00,201] DEBUG Added sensor with name node--1.latency (Metrics:416)
[2020-04-15 04:18:00,202] DEBUG [Producer clientId=producer-1] Created socket with SO_RCVBUF = 32768, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node -1 (Selector:535)
{"timestamp":1586924280485,"name":"startup_complete"}
[2020-04-15 04:18:00,569] DEBUG [Producer clientId=producer-1] Completed connection to node -1. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:00,912] DEBUG [SslTransportLayer channelId=-1 key=sun.nio.ch.SelectionKeyImpl@bfa349d] SSL handshake completed successfully with peerHost 'my-cluster-kafka-bootstrap' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:00,912] DEBUG [Producer clientId=producer-1] Successfully authenticated with my-cluster-kafka-bootstrap/172.30.161.253 (Selector:564)
[2020-04-15 04:18:00,913] DEBUG [Producer clientId=producer-1] Initiating API versions fetch from node -1. (NetworkClient:928)
[2020-04-15 04:18:01,150] DEBUG [Producer clientId=producer-1] Recorded API versions for node -1: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:01,153] DEBUG [Producer clientId=producer-1] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:01,195] DEBUG [Producer clientId=producer-1] Updating last seen epoch from null to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:01,197] DEBUG [Producer clientId=producer-1] Updating last seen epoch from null to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:01,198] DEBUG [Producer clientId=producer-1] Updating last seen epoch from null to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:01,223] INFO [Producer clientId=producer-1] Cluster ID: 0alK_KfiTVSGlbry73ZFeQ (Metadata:261)
[2020-04-15 04:18:01,225] DEBUG [Producer clientId=producer-1] Updated cluster metadata updateVersion 2 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:01,258] DEBUG [Producer clientId=producer-1] Initiating connection to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) using address my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (NetworkClient:956)
[2020-04-15 04:18:01,261] DEBUG Added sensor with name node-2.bytes-sent (Metrics:416)
[2020-04-15 04:18:01,266] DEBUG Added sensor with name node-2.bytes-received (Metrics:416)
[2020-04-15 04:18:01,267] DEBUG Added sensor with name node-2.latency (Metrics:416)
[2020-04-15 04:18:01,268] DEBUG [Producer clientId=producer-1] Created socket with SO_RCVBUF = 32768, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2 (Selector:535)
[2020-04-15 04:18:01,268] INFO [Producer clientId=producer-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms. (KafkaProducer:1183)
[2020-04-15 04:18:01,271] DEBUG [Producer clientId=producer-1] Completed connection to node 2. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:01,271] DEBUG [Producer clientId=producer-1] Beginning shutdown of Kafka producer I/O thread, sending remaining records. (Sender:250)
[2020-04-15 04:18:01,316] DEBUG [SslTransportLayer channelId=2 key=sun.nio.ch.SelectionKeyImpl@74324bff] SSL handshake completed successfully with peerHost 'my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:01,317] DEBUG [Producer clientId=producer-1] Successfully authenticated with my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (Selector:564)
[2020-04-15 04:18:01,317] DEBUG [Producer clientId=producer-1] Initiating API versions fetch from node 2. (NetworkClient:928)
[2020-04-15 04:18:01,327] DEBUG [Producer clientId=producer-1] Recorded API versions for node 2: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:01,331] DEBUG Added sensor with name topic.test-topic-925556285.records-per-batch (Metrics:416)
[2020-04-15 04:18:01,332] DEBUG Added sensor with name topic.test-topic-925556285.bytes (Metrics:416)
[2020-04-15 04:18:01,333] DEBUG Added sensor with name topic.test-topic-925556285.compression-rate (Metrics:416)
[2020-04-15 04:18:01,333] DEBUG Added sensor with name topic.test-topic-925556285.record-retries (Metrics:416)
[2020-04-15 04:18:01,334] DEBUG Added sensor with name topic.test-topic-925556285.record-errors (Metrics:416)
{"timestamp":1586924281550,"name":"producer_send_success","key":null,"value":"0","topic":"test-topic-925556285","partition":0,"offset":0}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"1","topic":"test-topic-925556285","partition":0,"offset":1}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"2","topic":"test-topic-925556285","partition":0,"offset":2}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"3","topic":"test-topic-925556285","partition":0,"offset":3}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"4","topic":"test-topic-925556285","partition":0,"offset":4}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"5","topic":"test-topic-925556285","partition":0,"offset":5}
{"timestamp":1586924281553,"name":"producer_send_success","key":null,"value":"6","topic":"test-topic-925556285","partition":0,"offset":6}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"7","topic":"test-topic-925556285","partition":0,"offset":7}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"8","topic":"test-topic-925556285","partition":0,"offset":8}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"9","topic":"test-topic-925556285","partition":0,"offset":9}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"10","topic":"test-topic-925556285","partition":0,"offset":10}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"11","topic":"test-topic-925556285","partition":0,"offset":11}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"12","topic":"test-topic-925556285","partition":0,"offset":12}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"13","topic":"test-topic-925556285","partition":0,"offset":13}
{"timestamp":1586924281554,"name":"producer_send_success","key":null,"value":"14","topic":"test-topic-925556285","partition":0,"offset":14}
{"timestamp":1586924281555,"name":"producer_send_success","key":null,"value":"15","topic":"test-topic-925556285","partition":0,"offset":15}
{"timestamp":1586924281556,"name":"producer_send_success","key":null,"value":"16","topic":"test-topic-925556285","partition":0,"offset":16}
{"timestamp":1586924281556,"name":"producer_send_success","key":null,"value":"17","topic":"test-topic-925556285","partition":0,"offset":17}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"18","topic":"test-topic-925556285","partition":0,"offset":18}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"19","topic":"test-topic-925556285","partition":0,"offset":19}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"20","topic":"test-topic-925556285","partition":0,"offset":20}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"21","topic":"test-topic-925556285","partition":0,"offset":21}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"22","topic":"test-topic-925556285","partition":0,"offset":22}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"23","topic":"test-topic-925556285","partition":0,"offset":23}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"24","topic":"test-topic-925556285","partition":0,"offset":24}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"25","topic":"test-topic-925556285","partition":0,"offset":25}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"26","topic":"test-topic-925556285","partition":0,"offset":26}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"27","topic":"test-topic-925556285","partition":0,"offset":27}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"28","topic":"test-topic-925556285","partition":0,"offset":28}
{"timestamp":1586924281557,"name":"producer_send_success","key":null,"value":"29","topic":"test-topic-925556285","partition":0,"offset":29}
{"timestamp":1586924281558,"name":"producer_send_success","key":null,"value":"30","topic":"test-topic-925556285","partition":0,"offset":30}
{"timestamp":1586924281558,"name":"producer_send_success","key":null,"value":"31","topic":"test-topic-925556285","partition":0,"offset":31}
{"timestamp":1586924281558,"name":"producer_send_success","key":null,"value":"32","topic":"test-topic-925556285","partition":0,"offset":32}
{"timestamp":1586924281558,"name":"producer_send_success","key":null,"value":"33","topic":"test-topic-925556285","partition":0,"offset":33}
{"timestamp":1586924281558,"name":"producer_send_success","key":null,"value":"34","topic":"test-topic-925556285","partition":0,"offset":34}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"35","topic":"test-topic-925556285","partition":0,"offset":35}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"36","topic":"test-topic-925556285","partition":0,"offset":36}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"37","topic":"test-topic-925556285","partition":0,"offset":37}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"38","topic":"test-topic-925556285","partition":0,"offset":38}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"39","topic":"test-topic-925556285","partition":0,"offset":39}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"40","topic":"test-topic-925556285","partition":0,"offset":40}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"41","topic":"test-topic-925556285","partition":0,"offset":41}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"42","topic":"test-topic-925556285","partition":0,"offset":42}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"43","topic":"test-topic-925556285","partition":0,"offset":43}
{"timestamp":1586924281559,"name":"producer_send_success","key":null,"value":"44","topic":"test-topic-925556285","partition":0,"offset":44}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"45","topic":"test-topic-925556285","partition":0,"offset":45}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"46","topic":"test-topic-925556285","partition":0,"offset":46}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"47","topic":"test-topic-925556285","partition":0,"offset":47}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"48","topic":"test-topic-925556285","partition":0,"offset":48}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"49","topic":"test-topic-925556285","partition":0,"offset":49}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"50","topic":"test-topic-925556285","partition":0,"offset":50}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"51","topic":"test-topic-925556285","partition":0,"offset":51}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"52","topic":"test-topic-925556285","partition":0,"offset":52}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"53","topic":"test-topic-925556285","partition":0,"offset":53}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"54","topic":"test-topic-925556285","partition":0,"offset":54}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"55","topic":"test-topic-925556285","partition":0,"offset":55}
{"timestamp":1586924281560,"name":"producer_send_success","key":null,"value":"56","topic":"test-topic-925556285","partition":0,"offset":56}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"57","topic":"test-topic-925556285","partition":0,"offset":57}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"58","topic":"test-topic-925556285","partition":0,"offset":58}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"59","topic":"test-topic-925556285","partition":0,"offset":59}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"60","topic":"test-topic-925556285","partition":0,"offset":60}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"61","topic":"test-topic-925556285","partition":0,"offset":61}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"62","topic":"test-topic-925556285","partition":0,"offset":62}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"63","topic":"test-topic-925556285","partition":0,"offset":63}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"64","topic":"test-topic-925556285","partition":0,"offset":64}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"65","topic":"test-topic-925556285","partition":0,"offset":65}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"66","topic":"test-topic-925556285","partition":0,"offset":66}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"67","topic":"test-topic-925556285","partition":0,"offset":67}
{"timestamp":1586924281561,"name":"producer_send_success","key":null,"value":"68","topic":"test-topic-925556285","partition":0,"offset":68}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"69","topic":"test-topic-925556285","partition":0,"offset":69}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"70","topic":"test-topic-925556285","partition":0,"offset":70}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"71","topic":"test-topic-925556285","partition":0,"offset":71}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"72","topic":"test-topic-925556285","partition":0,"offset":72}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"73","topic":"test-topic-925556285","partition":0,"offset":73}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"74","topic":"test-topic-925556285","partition":0,"offset":74}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"75","topic":"test-topic-925556285","partition":0,"offset":75}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"76","topic":"test-topic-925556285","partition":0,"offset":76}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"77","topic":"test-topic-925556285","partition":0,"offset":77}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"78","topic":"test-topic-925556285","partition":0,"offset":78}
{"timestamp":1586924281562,"name":"producer_send_success","key":null,"value":"79","topic":"test-topic-925556285","partition":0,"offset":79}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"80","topic":"test-topic-925556285","partition":0,"offset":80}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"81","topic":"test-topic-925556285","partition":0,"offset":81}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"82","topic":"test-topic-925556285","partition":0,"offset":82}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"83","topic":"test-topic-925556285","partition":0,"offset":83}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"84","topic":"test-topic-925556285","partition":0,"offset":84}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"85","topic":"test-topic-925556285","partition":0,"offset":85}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"86","topic":"test-topic-925556285","partition":0,"offset":86}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"87","topic":"test-topic-925556285","partition":0,"offset":87}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"88","topic":"test-topic-925556285","partition":0,"offset":88}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"89","topic":"test-topic-925556285","partition":0,"offset":89}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"90","topic":"test-topic-925556285","partition":0,"offset":90}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"91","topic":"test-topic-925556285","partition":0,"offset":91}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"92","topic":"test-topic-925556285","partition":0,"offset":92}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"93","topic":"test-topic-925556285","partition":0,"offset":93}
{"timestamp":1586924281563,"name":"producer_send_success","key":null,"value":"94","topic":"test-topic-925556285","partition":0,"offset":94}
{"timestamp":1586924281564,"name":"producer_send_success","key":null,"value":"95","topic":"test-topic-925556285","partition":0,"offset":95}
{"timestamp":1586924281564,"name":"producer_send_success","key":null,"value":"96","topic":"test-topic-925556285","partition":0,"offset":96}
{"timestamp":1586924281564,"name":"producer_send_success","key":null,"value":"97","topic":"test-topic-925556285","partition":0,"offset":97}
{"timestamp":1586924281564,"name":"producer_send_success","key":null,"value":"98","topic":"test-topic-925556285","partition":0,"offset":98}
{"timestamp":1586924281564,"name":"producer_send_success","key":null,"value":"99","topic":"test-topic-925556285","partition":0,"offset":99}
[2020-04-15 04:18:01,566] DEBUG Removed sensor with name connections-closed: (Metrics:449)
[2020-04-15 04:18:01,567] DEBUG Removed sensor with name connections-created: (Metrics:449)
[2020-04-15 04:18:01,567] DEBUG Removed sensor with name successful-authentication: (Metrics:449)
[2020-04-15 04:18:01,567] DEBUG Removed sensor with name successful-reauthentication: (Metrics:449)
[2020-04-15 04:18:01,567] DEBUG Removed sensor with name successful-authentication-no-reauth: (Metrics:449)
[2020-04-15 04:18:01,568] DEBUG Removed sensor with name failed-authentication: (Metrics:449)
[2020-04-15 04:18:01,568] DEBUG Removed sensor with name failed-reauthentication: (Metrics:449)
[2020-04-15 04:18:01,568] DEBUG Removed sensor with name reauthentication-latency: (Metrics:449)
[2020-04-15 04:18:01,569] DEBUG Removed sensor with name bytes-sent-received: (Metrics:449)
[2020-04-15 04:18:01,569] DEBUG Removed sensor with name bytes-sent: (Metrics:449)
[2020-04-15 04:18:01,570] DEBUG Removed sensor with name bytes-received: (Metrics:449)
[2020-04-15 04:18:01,570] DEBUG Removed sensor with name select-time: (Metrics:449)
[2020-04-15 04:18:01,570] DEBUG Removed sensor with name io-time: (Metrics:449)
[2020-04-15 04:18:01,571] DEBUG Removed sensor with name node--1.bytes-sent (Metrics:449)
[2020-04-15 04:18:01,571] DEBUG Removed sensor with name node--1.bytes-received (Metrics:449)
[2020-04-15 04:18:01,571] DEBUG Removed sensor with name node--1.latency (Metrics:449)
[2020-04-15 04:18:01,572] DEBUG Removed sensor with name node-2.bytes-sent (Metrics:449)
[2020-04-15 04:18:01,572] DEBUG Removed sensor with name node-2.bytes-received (Metrics:449)
[2020-04-15 04:18:01,572] DEBUG Removed sensor with name node-2.latency (Metrics:449)
[2020-04-15 04:18:01,572] DEBUG [Producer clientId=producer-1] Shutdown of Kafka producer I/O thread has completed. (Sender:292)
[2020-04-15 04:18:01,573] DEBUG [Producer clientId=producer-1] Kafka producer has been closed (KafkaProducer:1235)
{"timestamp":1586924281574,"name":"shutdown_complete"}
{"timestamp":1586924281576,"name":"tool_data","sent":100,"acked":100,"target_throughput":-1,"avg_throughput":90.99181073703366}

2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:117] Producer finished correctly: true
2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:121] Producer produced 100 messages
2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:181] Starting verifiableClient tls consumer with following configuration VerifiableClient{allowedArguments=[BROKER_LIST, TOPIC, GROUP_ID, MAX_MESSAGES, SESSION_TIMEOUT, VERBOSE, ENABLE_AUTOCOMMIT, RESET_POLICY, ASSIGMENT_STRATEGY, CONSUMER_CONFIG, USER, GROUP_INSTANCE_ID], lock=java.lang.Object@42e4431, messages=[], arguments=[--broker-list, my-cluster-kafka-bootstrap:9093, USER=alice, --group-id, my-consumer-group-1790120516, --max-messages, 100, --topic, test-topic-925556285, --group-instance-id, instance633684571], executable='/opt/kafka/consumer.sh', executor=null, clientType=CLI_KAFKA_VERIFIABLE_CONSUMER, podName='my-cluster-kafka-clients-6bc9868958-xn746', podNamespace='rolling-update-cluster-test', bootstrapServer='my-cluster-kafka-bootstrap:9093', topicName='test-topic-925556285', maxMessages=100, kafkaUsername='alice', consumerGroupName='my-consumer-group-1790120516', consumerInstanceId='instance633684571', clientArgumentMap=io.strimzi.systemtest.kafkaclients.internalClients.ClientArgumentMap@5e198c40}
2020-04-15 04:18:03 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:182] Wait for receive 100 messages from my-cluster-kafka-bootstrap:9093#test-topic-925556285
2020-04-15 04:18:14 &amp#27;[32mINFO &amp#27;[m [VerifiableClient:194] VerifiableClient CLI_KAFKA_VERIFIABLE_CONSUMER Return code - 0
2020-04-15 04:18:14 &amp#27;[32mINFO &amp#27;[m [VerifiableClient:196] VerifiableClient CLI_KAFKA_VERIFIABLE_CONSUMER stdout : /tmp/alice.properties
Starting Consumer with configuration:
=auto.offset.reset=earliest
security.protocol=SSL
ssl.truststore.location=/tmp/alice-truststore.p12
ssl.truststore.type=pkcs12
ssl.keystore.location=/tmp/alice-keystore.p12
ssl.keystore.type=pkcs12

ssl.keystore.password=AtJWC3ycOVTHgtpIdSdDOgYCgdJqYv56
ssl.truststore.password=AtJWC3ycOVTHgtpIdSdDOgYCgdJqYv56
[2020-04-15 04:18:04,301] INFO ConsumerConfig values: 
	allow.auto.create.topics = true
	auto.commit.interval.ms = 5000
	auto.offset.reset = earliest
	bootstrap.servers = [my-cluster-kafka-bootstrap:9093]
	check.crcs = true
	client.dns.lookup = default
	client.id = 
	client.rack = 
	connections.max.idle.ms = 540000
	default.api.timeout.ms = 60000
	enable.auto.commit = false
	exclude.internal.topics = true
	fetch.max.bytes = 52428800
	fetch.max.wait.ms = 500
	fetch.min.bytes = 1
	group.id = my-consumer-group-1790120516
	group.instance.id = instance633684571
	heartbeat.interval.ms = 3000
	interceptor.classes = []
	internal.leave.group.on.close = true
	isolation.level = read_uncommitted
	key.deserializer = class org.apache.kafka.common.serialization.StringDeserializer
	max.partition.fetch.bytes = 1048576
	max.poll.interval.ms = 300000
	max.poll.records = 500
	metadata.max.age.ms = 300000
	metric.reporters = []
	metrics.num.samples = 2
	metrics.recording.level = INFO
	metrics.sample.window.ms = 30000
	partition.assignment.strategy = [org.apache.kafka.clients.consumer.RangeAssignor]
	receive.buffer.bytes = 65536
	reconnect.backoff.max.ms = 1000
	reconnect.backoff.ms = 50
	request.timeout.ms = 30000
	retry.backoff.ms = 100
	sasl.client.callback.handler.class = null
	sasl.jaas.config = null
	sasl.kerberos.kinit.cmd = /usr/bin/kinit
	sasl.kerberos.min.time.before.relogin = 60000
	sasl.kerberos.service.name = null
	sasl.kerberos.ticket.renew.jitter = 0.05
	sasl.kerberos.ticket.renew.window.factor = 0.8
	sasl.login.callback.handler.class = null
	sasl.login.class = null
	sasl.login.refresh.buffer.seconds = 300
	sasl.login.refresh.min.period.seconds = 60
	sasl.login.refresh.window.factor = 0.8
	sasl.login.refresh.window.jitter = 0.05
	sasl.mechanism = GSSAPI
	security.protocol = SSL
	security.providers = null
	send.buffer.bytes = 131072
	session.timeout.ms = 30000
	ssl.cipher.suites = null
	ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
	ssl.endpoint.identification.algorithm = https
	ssl.key.password = null
	ssl.keymanager.algorithm = SunX509
	ssl.keystore.location = /tmp/alice-keystore.p12
	ssl.keystore.password = [hidden]
	ssl.keystore.type = pkcs12
	ssl.protocol = TLS
	ssl.provider = null
	ssl.secure.random.implementation = null
	ssl.trustmanager.algorithm = PKIX
	ssl.truststore.location = /tmp/alice-truststore.p12
	ssl.truststore.password = [hidden]
	ssl.truststore.type = pkcs12
	value.deserializer = class org.apache.kafka.common.serialization.StringDeserializer
 (ConsumerConfig:347)
[2020-04-15 04:18:04,350] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initializing the Kafka consumer (KafkaConsumer:699)
[2020-04-15 04:18:04,706] DEBUG Created SSL context with keystore SecurityStore(path=/tmp/alice-keystore.p12, modificationTime=Wed Apr 15 04:18:02 UTC 2020), truststore SecurityStore(path=/tmp/alice-truststore.p12, modificationTime=Wed Apr 15 04:18:02 UTC 2020), provider SunJSSE. (SslEngineBuilder:159)
[2020-04-15 04:18:04,722] DEBUG Added sensor with name fetch-throttle-time (Metrics:416)
[2020-04-15 04:18:04,737] DEBUG Added sensor with name connections-closed: (Metrics:416)
[2020-04-15 04:18:04,741] DEBUG Added sensor with name connections-created: (Metrics:416)
[2020-04-15 04:18:04,742] DEBUG Added sensor with name successful-authentication: (Metrics:416)
[2020-04-15 04:18:04,743] DEBUG Added sensor with name successful-reauthentication: (Metrics:416)
[2020-04-15 04:18:04,743] DEBUG Added sensor with name successful-authentication-no-reauth: (Metrics:416)
[2020-04-15 04:18:04,744] DEBUG Added sensor with name failed-authentication: (Metrics:416)
[2020-04-15 04:18:04,744] DEBUG Added sensor with name failed-reauthentication: (Metrics:416)
[2020-04-15 04:18:04,745] DEBUG Added sensor with name reauthentication-latency: (Metrics:416)
[2020-04-15 04:18:04,762] DEBUG Added sensor with name bytes-sent-received: (Metrics:416)
[2020-04-15 04:18:04,762] DEBUG Added sensor with name bytes-sent: (Metrics:416)
[2020-04-15 04:18:04,763] DEBUG Added sensor with name bytes-received: (Metrics:416)
[2020-04-15 04:18:04,764] DEBUG Added sensor with name select-time: (Metrics:416)
[2020-04-15 04:18:04,767] DEBUG Added sensor with name io-time: (Metrics:416)
[2020-04-15 04:18:04,799] DEBUG Added sensor with name heartbeat-latency (Metrics:416)
[2020-04-15 04:18:04,800] DEBUG Added sensor with name join-latency (Metrics:416)
[2020-04-15 04:18:04,800] DEBUG Added sensor with name sync-latency (Metrics:416)
[2020-04-15 04:18:04,802] DEBUG Added sensor with name rebalance-latency (Metrics:416)
[2020-04-15 04:18:04,803] DEBUG Added sensor with name failed-rebalance (Metrics:416)
[2020-04-15 04:18:04,806] DEBUG Added sensor with name commit-latency (Metrics:416)
[2020-04-15 04:18:04,807] DEBUG Added sensor with name partition-revoked-latency (Metrics:416)
[2020-04-15 04:18:04,807] DEBUG Added sensor with name partition-assigned-latency (Metrics:416)
[2020-04-15 04:18:04,808] DEBUG Added sensor with name partition-lost-latency (Metrics:416)
[2020-04-15 04:18:04,812] DEBUG Added sensor with name bytes-fetched (Metrics:416)
[2020-04-15 04:18:04,813] DEBUG Added sensor with name records-fetched (Metrics:416)
[2020-04-15 04:18:04,813] DEBUG Added sensor with name fetch-latency (Metrics:416)
[2020-04-15 04:18:04,814] DEBUG Added sensor with name records-lag (Metrics:416)
[2020-04-15 04:18:04,814] DEBUG Added sensor with name records-lead (Metrics:416)
[2020-04-15 04:18:04,818] DEBUG Added sensor with name time-between-poll (Metrics:416)
[2020-04-15 04:18:04,818] DEBUG Added sensor with name poll-idle-ratio-avg (Metrics:416)
[2020-04-15 04:18:04,819] WARN The configuration '' was supplied but isn't a known config. (ConsumerConfig:355)
[2020-04-15 04:18:04,820] INFO Kafka version: 2.4.0 (AppInfoParser:117)
[2020-04-15 04:18:04,820] INFO Kafka commitId: 77a89fcf8d7fa018 (AppInfoParser:118)
[2020-04-15 04:18:04,820] INFO Kafka startTimeMs: 1586924284819 (AppInfoParser:119)
[2020-04-15 04:18:04,822] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Kafka consumer initialized (KafkaConsumer:815)
{"timestamp":1586924285041,"name":"startup_complete"}
[2020-04-15 04:18:05,106] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Subscribed to topic(s): test-topic-925556285 (KafkaConsumer:969)
[2020-04-15 04:18:05,109] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:05,342] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) using address my-cluster-kafka-bootstrap/172.30.161.253 (NetworkClient:956)
[2020-04-15 04:18:05,365] DEBUG Added sensor with name node--1.bytes-sent (Metrics:416)
[2020-04-15 04:18:05,367] DEBUG Added sensor with name node--1.bytes-received (Metrics:416)
[2020-04-15 04:18:05,368] DEBUG Added sensor with name node--1.latency (Metrics:416)
[2020-04-15 04:18:05,369] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node -1 (Selector:535)
[2020-04-15 04:18:05,383] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node -1. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:05,664] DEBUG [SslTransportLayer channelId=-1 key=sun.nio.ch.SelectionKeyImpl@140c9f39] SSL handshake completed successfully with peerHost 'my-cluster-kafka-bootstrap' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:05,665] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-bootstrap/172.30.161.253 (Selector:564)
[2020-04-15 04:18:05,667] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node -1. (NetworkClient:928)
[2020-04-15 04:18:05,888] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node -1: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:05,890] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:05,961] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from null to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:05,962] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from null to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:05,962] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from null to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:05,986] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Cluster ID: 0alK_KfiTVSGlbry73ZFeQ (Metadata:261)
[2020-04-15 04:18:05,988] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 2 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:06,171] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924286170, latencyMs=832, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=0), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:06,173] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:06,173] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:06,174] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initialize connection to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) for sending metadata request (NetworkClient:1125)
[2020-04-15 04:18:06,177] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) using address my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.180 (NetworkClient:956)
[2020-04-15 04:18:06,178] DEBUG Added sensor with name node-1.bytes-sent (Metrics:416)
[2020-04-15 04:18:06,179] DEBUG Added sensor with name node-1.bytes-received (Metrics:416)
[2020-04-15 04:18:06,180] DEBUG Added sensor with name node-1.latency (Metrics:416)
[2020-04-15 04:18:06,180] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 1 (Selector:535)
[2020-04-15 04:18:06,183] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node 1. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:06,259] DEBUG [SslTransportLayer channelId=1 key=sun.nio.ch.SelectionKeyImpl@5a7fe64f] SSL handshake completed successfully with peerHost 'my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:06,260] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.180 (Selector:564)
[2020-04-15 04:18:06,260] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node 1. (NetworkClient:928)
[2020-04-15 04:18:06,272] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node 1: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:06,274] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:06,305] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:06,306] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:06,306] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:06,308] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 3 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:06,308] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:06,524] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924286524, latencyMs=215, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=5), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:06,526] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:06,526] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:06,526] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:06,534] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:06,534] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:06,535] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:06,537] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 4 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:06,538] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:06,725] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924286725, latencyMs=187, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=7), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:06,726] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:06,726] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:06,726] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:06,758] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:06,759] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:06,759] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:06,762] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 5 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:06,763] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,004] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287004, latencyMs=241, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=9), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,005] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,005] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,005] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,013] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,013] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,013] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,018] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 6 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,018] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,122] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287122, latencyMs=103, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=11), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,124] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,125] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,125] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,138] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,138] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,139] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,142] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 7 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,142] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,206] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287206, latencyMs=64, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=13), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,206] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,207] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,237] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,251] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,252] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,253] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,255] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 8 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,256] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,300] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287300, latencyMs=44, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=15), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,301] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,301] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,352] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,362] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,363] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,364] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,366] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 9 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,368] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,409] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287409, latencyMs=40, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=17), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,409] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,411] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,462] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,475] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,475] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,479] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,480] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 10 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,484] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,521] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287521, latencyMs=37, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=19), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,521] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,522] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,576] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,583] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,583] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,583] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,585] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 11 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,585] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,637] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287637, latencyMs=51, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=21), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,643] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,643] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,682] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,708] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,708] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,709] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,714] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 12 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,715] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,754] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287754, latencyMs=39, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=23), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,754] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,755] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,809] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,820] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,821] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,821] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,822] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 13 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,822] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,855] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287855, latencyMs=32, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=25), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,855] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,855] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:07,919] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:07,930] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:07,931] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:07,932] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:07,934] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 14 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:07,935] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:07,963] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924287963, latencyMs=28, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=27), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:07,963] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:07,964] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:08,030] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:08,037] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:08,037] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:08,037] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:08,039] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 15 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:08,040] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,110] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288110, latencyMs=70, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=29), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,111] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:08,112] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:08,137] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:08,145] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:08,145] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:08,145] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:08,147] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 16 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:08,147] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,187] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288187, latencyMs=40, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=31), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,188] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:08,188] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:08,245] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:08,261] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:08,261] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:08,261] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:08,262] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 17 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:08,263] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,361] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288361, latencyMs=98, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=33), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,362] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:08,362] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:08,362] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:08,377] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:08,377] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:08,378] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:08,378] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 18 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:08,378] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,454] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288453, latencyMs=75, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=35), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=15, errorMessage='The coordinator is not available.', nodeId=-1, host='', port=-1)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,454] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator lookup failed: The coordinator is not available. (AbstractCoordinator:764)
[2020-04-15 04:18:08,454] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Coordinator discovery failed, refreshing metadata (AbstractCoordinator:239)
[2020-04-15 04:18:08,477] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-925556285')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (NetworkClient:1109)
[2020-04-15 04:18:08,490] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-0 (Metadata:178)
[2020-04-15 04:18:08,490] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-2 (Metadata:178)
[2020-04-15 04:18:08,490] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updating last seen epoch from 0 to 0 for partition test-topic-925556285-1 (Metadata:178)
[2020-04-15 04:18:08,491] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Updated cluster metadata updateVersion 19 to MetadataCache{clusterId='0alK_KfiTVSGlbry73ZFeQ', nodes=[my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)], partitions=[PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 0, leader = 2, replicas = [2,1,0], isr = [2,1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 1, leader = 1, replicas = [1,0,2], isr = [1,0,2], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-925556285, partition = 2, leader = 0, replicas = [0,2,1], isr = [0,2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null)} (Metadata:265)
[2020-04-15 04:18:08,492] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,508] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288507, latencyMs=14, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=37), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=0, errorMessage='NONE', nodeId=2, host='my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc', port=9093)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,508] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Discovered group coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) (AbstractCoordinator:756)
[2020-04-15 04:18:08,511] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) using address my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (NetworkClient:956)
[2020-04-15 04:18:08,516] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Executing onJoinPrepare with generation -1 and memberId  (ConsumerCoordinator:633)
[2020-04-15 04:18:08,516] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Heartbeat thread started (AbstractCoordinator:1192)
[2020-04-15 04:18:08,525] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Disabling heartbeat thread (AbstractCoordinator:1169)
[2020-04-15 04:18:08,528] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] (Re-)joining group (AbstractCoordinator:533)
[2020-04-15 04:18:08,530] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Joining group with current subscription: [test-topic-925556285] (ConsumerCoordinator:206)
[2020-04-15 04:18:08,533] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending JoinGroup (JoinGroupRequestData(groupId='my-consumer-group-1790120516', sessionTimeoutMs=30000, rebalanceTimeoutMs=300000, memberId='', groupInstanceId='instance633684571', protocolType='consumer', protocols=[JoinGroupRequestProtocol(name='range', metadata=[0, 1, 0, 0, 0, 1, 0, 20, 116, 101, 115, 116, 45, 116, 111, 112, 105, 99, 45, 57, 50, 53, 53, 53, 54, 50, 56, 53, -1, -1, -1, -1, 0, 0, 0, 0])])) to coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) (AbstractCoordinator:545)
[2020-04-15 04:18:08,535] DEBUG Added sensor with name node-2147483645.bytes-sent (Metrics:416)
[2020-04-15 04:18:08,537] DEBUG Added sensor with name node-2147483645.bytes-received (Metrics:416)
[2020-04-15 04:18:08,538] DEBUG Added sensor with name node-2147483645.latency (Metrics:416)
[2020-04-15 04:18:08,539] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2147483645 (Selector:535)
[2020-04-15 04:18:08,548] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node 2147483645. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:08,592] DEBUG [SslTransportLayer channelId=2147483645 key=sun.nio.ch.SelectionKeyImpl@3e0e1046] SSL handshake completed successfully with peerHost 'my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:08,592] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (Selector:564)
[2020-04-15 04:18:08,593] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node 2147483645. (NetworkClient:928)
[2020-04-15 04:18:08,599] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node 2147483645: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:08,615] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) is unavailable or invalid, will attempt rediscovery (AbstractCoordinator:808)
[2020-04-15 04:18:08,616] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Attempt to join group failed due to obsolete coordinator information: This is not the correct coordinator. (AbstractCoordinator:591)
[2020-04-15 04:18:08,717] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,720] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Manually disconnected from 2147483645. Removed requests: . (NetworkClient:327)
[2020-04-15 04:18:08,728] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288728, latencyMs=11, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=40), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=0, errorMessage='NONE', nodeId=2, host='my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc', port=9093)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,728] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Discovered group coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) (AbstractCoordinator:756)
[2020-04-15 04:18:08,729] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Group coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) is unavailable or invalid, will attempt rediscovery (AbstractCoordinator:808)
[2020-04-15 04:18:08,830] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending FindCoordinator request to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (AbstractCoordinator:727)
[2020-04-15 04:18:08,836] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received FindCoordinator response ClientResponse(receivedTimeMs=1586924288835, latencyMs=5, disconnected=false, requestHeader=RequestHeader(apiKey=FIND_COORDINATOR, apiVersion=3, clientId=consumer-my-consumer-group-1790120516-instance633684571, correlationId=41), responseBody=FindCoordinatorResponseData(throttleTimeMs=0, errorCode=0, errorMessage='NONE', nodeId=2, host='my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc', port=9093)) (AbstractCoordinator:741)
[2020-04-15 04:18:08,836] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Discovered group coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) (AbstractCoordinator:756)
[2020-04-15 04:18:08,836] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) using address my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (NetworkClient:956)
[2020-04-15 04:18:08,838] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Disabling heartbeat thread (AbstractCoordinator:1169)
[2020-04-15 04:18:08,838] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] (Re-)joining group (AbstractCoordinator:533)
[2020-04-15 04:18:08,838] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Joining group with current subscription: [test-topic-925556285] (ConsumerCoordinator:206)
[2020-04-15 04:18:08,839] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending JoinGroup (JoinGroupRequestData(groupId='my-consumer-group-1790120516', sessionTimeoutMs=30000, rebalanceTimeoutMs=300000, memberId='', groupInstanceId='instance633684571', protocolType='consumer', protocols=[JoinGroupRequestProtocol(name='range', metadata=[0, 1, 0, 0, 0, 1, 0, 20, 116, 101, 115, 116, 45, 116, 111, 112, 105, 99, 45, 57, 50, 53, 53, 53, 54, 50, 56, 53, -1, -1, -1, -1, 0, 0, 0, 0])])) to coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) (AbstractCoordinator:545)
[2020-04-15 04:18:08,839] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2147483645 (Selector:535)
[2020-04-15 04:18:08,843] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node 2147483645. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:08,885] DEBUG [SslTransportLayer channelId=2147483645 key=sun.nio.ch.SelectionKeyImpl@5be1d0a4] SSL handshake completed successfully with peerHost 'my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:08,894] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (Selector:564)
[2020-04-15 04:18:08,896] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node 2147483645. (NetworkClient:928)
[2020-04-15 04:18:08,903] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node 2147483645: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:11,999] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received successful JoinGroup response: JoinGroupResponseData(throttleTimeMs=0, errorCode=0, generationId=1, protocolName='range', leader='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', members=[JoinGroupResponseMember(memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', groupInstanceId='instance633684571', metadata=[0, 1, 0, 0, 0, 1, 0, 20, 116, 101, 115, 116, 45, 116, 111, 112, 105, 99, 45, 57, 50, 53, 53, 53, 54, 50, 56, 53, -1, -1, -1, -1, 0, 0, 0, 0])]) (AbstractCoordinator:560)
[2020-04-15 04:18:12,001] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Performing assignment using strategy range with subscriptions {instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99=org.apache.kafka.clients.consumer.ConsumerPartitionAssignor$Subscription@415b0b49} (ConsumerCoordinator:546)
[2020-04-15 04:18:12,007] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Finished assignment for group at generation 1: {instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99=org.apache.kafka.clients.consumer.ConsumerPartitionAssignor$Assignment@15d49048} (ConsumerCoordinator:585)
[2020-04-15 04:18:12,009] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending leader SyncGroup to coordinator my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2147483645 rack: null) at generation Generation{generationId=1, memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', protocol='range'}: SyncGroupRequestData(groupId='my-consumer-group-1790120516', generationId=1, memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', groupInstanceId='instance633684571', assignments=[SyncGroupRequestAssignment(memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', assignment=[0, 1, 0, 0, 0, 1, 0, 20, 116, 101, 115, 116, 45, 116, 111, 112, 105, 99, 45, 57, 50, 53, 53, 53, 54, 50, 56, 53, 0, 0, 0, 3, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 2, -1, -1, -1, -1])]) (AbstractCoordinator:670)
[2020-04-15 04:18:12,089] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully joined group with generation 1 (AbstractCoordinator:484)
[2020-04-15 04:18:12,089] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Enabling heartbeat thread (AbstractCoordinator:1160)
[2020-04-15 04:18:12,090] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Executing onJoinComplete with generation 1 and memberId instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99 (ConsumerCoordinator:328)
[2020-04-15 04:18:12,096] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Adding newly assigned partitions: test-topic-925556285-2, test-topic-925556285-0, test-topic-925556285-1 (ConsumerCoordinator:267)
{"timestamp":1586924292096,"name":"partitions_assigned","partitions":[{"topic":"test-topic-925556285","partition":2},{"topic":"test-topic-925556285","partition":0},{"topic":"test-topic-925556285","partition":1}]}
[2020-04-15 04:18:12,139] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Fetching committed offsets for partitions: [test-topic-925556285-2, test-topic-925556285-0, test-topic-925556285-1] (ConsumerCoordinator:1182)
[2020-04-15 04:18:12,186] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Found no committed offset for partition test-topic-925556285-2 (ConsumerCoordinator:1241)
[2020-04-15 04:18:12,186] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Found no committed offset for partition test-topic-925556285-0 (ConsumerCoordinator:1241)
[2020-04-15 04:18:12,186] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Found no committed offset for partition test-topic-925556285-1 (ConsumerCoordinator:1241)
[2020-04-15 04:18:12,193] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending ListOffsetRequest (type=ListOffsetRequest, replicaId=-1, partitionTimestamps={test-topic-925556285-0={timestamp: -2, maxNumOffsets: 1, currentLeaderEpoch: Optional[0]}}, isolationLevel=READ_UNCOMMITTED) to broker my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) (Fetcher:946)
[2020-04-15 04:18:12,196] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending ListOffsetRequest (type=ListOffsetRequest, replicaId=-1, partitionTimestamps={test-topic-925556285-2={timestamp: -2, maxNumOffsets: 1, currentLeaderEpoch: Optional[0]}}, isolationLevel=READ_UNCOMMITTED) to broker my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null) (Fetcher:946)
[2020-04-15 04:18:12,197] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending ListOffsetRequest (type=ListOffsetRequest, replicaId=-1, partitionTimestamps={test-topic-925556285-1={timestamp: -2, maxNumOffsets: 1, currentLeaderEpoch: Optional[0]}}, isolationLevel=READ_UNCOMMITTED) to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (Fetcher:946)
[2020-04-15 04:18:12,206] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) using address my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (NetworkClient:956)
[2020-04-15 04:18:12,210] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating connection to node my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null) using address my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.179 (NetworkClient:956)
[2020-04-15 04:18:12,215] DEBUG Added sensor with name node-2.bytes-sent (Metrics:416)
[2020-04-15 04:18:12,219] DEBUG Added sensor with name node-2.bytes-received (Metrics:416)
[2020-04-15 04:18:12,220] DEBUG Added sensor with name node-2.latency (Metrics:416)
[2020-04-15 04:18:12,220] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2 (Selector:535)
[2020-04-15 04:18:12,225] DEBUG Added sensor with name node-0.bytes-sent (Metrics:416)
[2020-04-15 04:18:12,226] DEBUG Added sensor with name node-0.bytes-received (Metrics:416)
[2020-04-15 04:18:12,227] DEBUG Added sensor with name node-0.latency (Metrics:416)
[2020-04-15 04:18:12,227] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Created socket with SO_RCVBUF = 65536, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 0 (Selector:535)
[2020-04-15 04:18:12,231] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node 2. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:12,232] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Completed connection to node 0. Fetching API versions. (NetworkClient:914)
[2020-04-15 04:18:12,276] DEBUG [SslTransportLayer channelId=2 key=sun.nio.ch.SelectionKeyImpl@2ca923bb] SSL handshake completed successfully with peerHost 'my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:12,276] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.181 (Selector:564)
[2020-04-15 04:18:12,279] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node 2. (NetworkClient:928)
[2020-04-15 04:18:12,280] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Handling ListOffsetResponse response for test-topic-925556285-1. Fetched offset 0, timestamp -1 (Fetcher:1002)
[2020-04-15 04:18:12,282] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Not replacing existing epoch 0 with new epoch 0 for partition test-topic-925556285-1 (Metadata:185)
[2020-04-15 04:18:12,282] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Resetting offset for partition test-topic-925556285-1 to offset 0. (SubscriptionState:385)
[2020-04-15 04:18:12,289] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Added READ_UNCOMMITTED fetch request for partition test-topic-925556285-1 at position FetchPosition{offset=0, offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null), epoch=0}} to node my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (Fetcher:1138)
[2020-04-15 04:18:12,289] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Built full fetch (sessionId=INVALID, epoch=INITIAL) for node 1 with 1 partition(s). (FetchSessionHandler:200)
[2020-04-15 04:18:12,290] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending READ_UNCOMMITTED FullFetchRequest(test-topic-925556285-1) to broker my-cluster-kafka-1.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 1 rack: null) (Fetcher:259)
[2020-04-15 04:18:12,308] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node 2: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:12,312] DEBUG [SslTransportLayer channelId=0 key=sun.nio.ch.SelectionKeyImpl@13df2a8c] SSL handshake completed successfully with peerHost 'my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc' peerPort 9093 peerPrincipal 'CN=my-cluster-kafka, O=io.strimzi' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384' (SslTransportLayer:424)
[2020-04-15 04:18:12,312] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Successfully authenticated with my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.179 (Selector:564)
[2020-04-15 04:18:12,312] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Initiating API versions fetch from node 0. (NetworkClient:928)
[2020-04-15 04:18:12,336] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Handling ListOffsetResponse response for test-topic-925556285-0. Fetched offset 0, timestamp -1 (Fetcher:1002)
[2020-04-15 04:18:12,337] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Not replacing existing epoch 0 with new epoch 0 for partition test-topic-925556285-0 (Metadata:185)
[2020-04-15 04:18:12,337] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Resetting offset for partition test-topic-925556285-0 to offset 0. (SubscriptionState:385)
[2020-04-15 04:18:12,337] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Added READ_UNCOMMITTED fetch request for partition test-topic-925556285-0 at position FetchPosition{offset=0, offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null), epoch=0}} to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) (Fetcher:1138)
[2020-04-15 04:18:12,338] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Built full fetch (sessionId=INVALID, epoch=INITIAL) for node 2 with 1 partition(s). (FetchSessionHandler:200)
[2020-04-15 04:18:12,338] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending READ_UNCOMMITTED FullFetchRequest(test-topic-925556285-0) to broker my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) (Fetcher:259)
[2020-04-15 04:18:12,349] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Recorded API versions for node 0: (Produce(0): 0 to 8 [usable: 8], Fetch(1): 0 to 11 [usable: 11], ListOffsets(2): 0 to 5 [usable: 5], Metadata(3): 0 to 9 [usable: 9], LeaderAndIsr(4): 0 to 4 [usable: 4], StopReplica(5): 0 to 2 [usable: 2], UpdateMetadata(6): 0 to 6 [usable: 6], ControlledShutdown(7): 0 to 3 [usable: 3], OffsetCommit(8): 0 to 8 [usable: 8], OffsetFetch(9): 0 to 6 [usable: 6], FindCoordinator(10): 0 to 3 [usable: 3], JoinGroup(11): 0 to 6 [usable: 6], Heartbeat(12): 0 to 4 [usable: 4], LeaveGroup(13): 0 to 4 [usable: 4], SyncGroup(14): 0 to 4 [usable: 4], DescribeGroups(15): 0 to 5 [usable: 5], ListGroups(16): 0 to 3 [usable: 3], SaslHandshake(17): 0 to 1 [usable: 1], ApiVersions(18): 0 to 3 [usable: 3], CreateTopics(19): 0 to 5 [usable: 5], DeleteTopics(20): 0 to 4 [usable: 4], DeleteRecords(21): 0 to 1 [usable: 1], InitProducerId(22): 0 to 2 [usable: 2], OffsetForLeaderEpoch(23): 0 to 3 [usable: 3], AddPartitionsToTxn(24): 0 to 1 [usable: 1], AddOffsetsToTxn(25): 0 to 1 [usable: 1], EndTxn(26): 0 to 1 [usable: 1], WriteTxnMarkers(27): 0 [usable: 0], TxnOffsetCommit(28): 0 to 2 [usable: 2], DescribeAcls(29): 0 to 1 [usable: 1], CreateAcls(30): 0 to 1 [usable: 1], DeleteAcls(31): 0 to 1 [usable: 1], DescribeConfigs(32): 0 to 2 [usable: 2], AlterConfigs(33): 0 to 1 [usable: 1], AlterReplicaLogDirs(34): 0 to 1 [usable: 1], DescribeLogDirs(35): 0 to 1 [usable: 1], SaslAuthenticate(36): 0 to 1 [usable: 1], CreatePartitions(37): 0 to 1 [usable: 1], CreateDelegationToken(38): 0 to 2 [usable: 2], RenewDelegationToken(39): 0 to 1 [usable: 1], ExpireDelegationToken(40): 0 to 1 [usable: 1], DescribeDelegationToken(41): 0 to 1 [usable: 1], DeleteGroups(42): 0 to 2 [usable: 2], ElectLeaders(43): 0 to 2 [usable: 2], IncrementalAlterConfigs(44): 0 to 1 [usable: 1], AlterPartitionReassignments(45): 0 [usable: 0], ListPartitionReassignments(46): 0 [usable: 0], OffsetDelete(47): 0 [usable: 0]) (NetworkClient:882)
[2020-04-15 04:18:12,384] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Handling ListOffsetResponse response for test-topic-925556285-2. Fetched offset 0, timestamp -1 (Fetcher:1002)
[2020-04-15 04:18:12,384] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Not replacing existing epoch 0 with new epoch 0 for partition test-topic-925556285-2 (Metadata:185)
[2020-04-15 04:18:12,384] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Resetting offset for partition test-topic-925556285-2 to offset 0. (SubscriptionState:385)
[2020-04-15 04:18:12,386] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Added READ_UNCOMMITTED fetch request for partition test-topic-925556285-2 at position FetchPosition{offset=0, offsetEpoch=Optional.empty, currentLeader=LeaderAndEpoch{leader=my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null), epoch=0}} to node my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null) (Fetcher:1138)
[2020-04-15 04:18:12,387] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Built full fetch (sessionId=INVALID, epoch=INITIAL) for node 0 with 1 partition(s). (FetchSessionHandler:200)
[2020-04-15 04:18:12,387] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending READ_UNCOMMITTED FullFetchRequest(test-topic-925556285-2) to broker my-cluster-kafka-0.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 0 rack: null) (Fetcher:259)
[2020-04-15 04:18:12,406] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Node 2 sent a full fetch response that created a new incremental fetch session 211424362 with 1 response partition(s) (FetchSessionHandler:407)
[2020-04-15 04:18:12,409] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Fetch READ_UNCOMMITTED at offset 0 for partition test-topic-925556285-0 returned fetch data (error=NONE, highWaterMark=100, lastStableOffset = 100, logStartOffset = 0, preferredReadReplica = absent, abortedTransactions = null, recordsSizeInBytes=987) (Fetcher:308)
[2020-04-15 04:18:12,426] DEBUG Added sensor with name topic.test-topic-925556285.bytes-fetched (Metrics:416)
[2020-04-15 04:18:12,427] DEBUG Added sensor with name topic.test-topic-925556285.records-fetched (Metrics:416)
[2020-04-15 04:18:12,427] DEBUG Added sensor with name test-topic-925556285-0.records-lag (Metrics:416)
[2020-04-15 04:18:12,428] DEBUG Added sensor with name test-topic-925556285-0.records-lead (Metrics:416)
[2020-04-15 04:18:12,429] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Added READ_UNCOMMITTED fetch request for partition test-topic-925556285-0 at position FetchPosition{offset=100, offsetEpoch=Optional[0], currentLeader=LeaderAndEpoch{leader=my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null), epoch=0}} to node my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) (Fetcher:1138)
[2020-04-15 04:18:12,429] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Built incremental fetch (sessionId=211424362, epoch=1) for node 2. Added 0 partition(s), altered 1 partition(s), removed 0 partition(s) out of 1 partition(s) (FetchSessionHandler:253)
[2020-04-15 04:18:12,430] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Sending READ_UNCOMMITTED IncrementalFetchRequest(toSend=(test-topic-925556285-0), toForget=(), implied=()) to broker my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null) (Fetcher:259)
{"timestamp":1586924292434,"name":"records_consumed","count":100,"partitions":[{"topic":"test-topic-925556285","partition":0,"count":100,"minOffset":0,"maxOffset":99}]}
[2020-04-15 04:18:12,745] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Committed offset 100 for partition test-topic-925556285-0 (ConsumerCoordinator:1103)
{"timestamp":1586924292748,"name":"offsets_committed","offsets":[{"topic":"test-topic-925556285","partition":0,"offset":100}],"success":true}
[2020-04-15 04:18:12,760] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Heartbeat thread has closed (AbstractCoordinator:1287)
[2020-04-15 04:18:12,770] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Executing onLeavePrepare with generation Generation{generationId=1, memberId='instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99', protocol='range'} and memberId instance633684571-4fa65905-a03d-408b-b785-e0ad36d50c99 (ConsumerCoordinator:699)
[2020-04-15 04:18:12,772] INFO [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Revoke previously assigned partitions test-topic-925556285-2, test-topic-925556285-0, test-topic-925556285-1 (ConsumerCoordinator:286)
{"timestamp":1586924292773,"name":"partitions_revoked","partitions":[{"topic":"test-topic-925556285","partition":2},{"topic":"test-topic-925556285","partition":0},{"topic":"test-topic-925556285","partition":1}]}
[2020-04-15 04:18:12,775] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Resetting generation due to consumer pro-actively leaving the group (AbstractCoordinator:860)
[2020-04-15 04:18:12,779] DEBUG Removed sensor with name connections-closed: (Metrics:449)
[2020-04-15 04:18:12,779] DEBUG Removed sensor with name connections-created: (Metrics:449)
[2020-04-15 04:18:12,780] DEBUG Removed sensor with name successful-authentication: (Metrics:449)
[2020-04-15 04:18:12,780] DEBUG Removed sensor with name successful-reauthentication: (Metrics:449)
[2020-04-15 04:18:12,785] DEBUG Removed sensor with name successful-authentication-no-reauth: (Metrics:449)
[2020-04-15 04:18:12,785] DEBUG Removed sensor with name failed-authentication: (Metrics:449)
[2020-04-15 04:18:12,787] DEBUG Removed sensor with name failed-reauthentication: (Metrics:449)
[2020-04-15 04:18:12,797] DEBUG Removed sensor with name reauthentication-latency: (Metrics:449)
[2020-04-15 04:18:12,806] DEBUG Removed sensor with name bytes-sent-received: (Metrics:449)
[2020-04-15 04:18:12,816] DEBUG Removed sensor with name bytes-sent: (Metrics:449)
[2020-04-15 04:18:12,831] DEBUG Removed sensor with name bytes-received: (Metrics:449)
[2020-04-15 04:18:12,847] DEBUG Removed sensor with name select-time: (Metrics:449)
[2020-04-15 04:18:12,849] DEBUG Removed sensor with name io-time: (Metrics:449)
[2020-04-15 04:18:12,854] DEBUG Removed sensor with name node--1.bytes-sent (Metrics:449)
[2020-04-15 04:18:12,855] DEBUG Removed sensor with name node--1.bytes-received (Metrics:449)
[2020-04-15 04:18:12,856] DEBUG Removed sensor with name node--1.latency (Metrics:449)
[2020-04-15 04:18:12,863] DEBUG Removed sensor with name node-1.bytes-sent (Metrics:449)
[2020-04-15 04:18:12,867] DEBUG Removed sensor with name node-1.bytes-received (Metrics:449)
[2020-04-15 04:18:12,868] DEBUG Removed sensor with name node-1.latency (Metrics:449)
[2020-04-15 04:18:12,870] DEBUG Removed sensor with name node-2147483645.bytes-sent (Metrics:449)
[2020-04-15 04:18:12,872] DEBUG Removed sensor with name node-2147483645.bytes-received (Metrics:449)
[2020-04-15 04:18:12,883] DEBUG Removed sensor with name node-2147483645.latency (Metrics:449)
[2020-04-15 04:18:12,885] DEBUG Removed sensor with name node-2.bytes-sent (Metrics:449)
[2020-04-15 04:18:12,888] DEBUG Removed sensor with name node-2.bytes-received (Metrics:449)
[2020-04-15 04:18:12,893] DEBUG Removed sensor with name node-2.latency (Metrics:449)
[2020-04-15 04:18:12,894] DEBUG Removed sensor with name node-0.bytes-sent (Metrics:449)
[2020-04-15 04:18:12,895] DEBUG Removed sensor with name node-0.bytes-received (Metrics:449)
[2020-04-15 04:18:12,898] DEBUG Removed sensor with name node-0.latency (Metrics:449)
[2020-04-15 04:18:12,899] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Kafka consumer has been closed (KafkaConsumer:2306)
{"timestamp":1586924292900,"name":"shutdown_complete"}
[2020-04-15 04:18:12,912] DEBUG [Consumer instanceId=instance633684571, clientId=consumer-my-consumer-group-1790120516-instance633684571, groupId=my-consumer-group-1790120516] Received user wakeup (ConsumerNetworkClient:186)
0

2020-04-15 04:18:14 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:185] Consumer finished correctly: true
2020-04-15 04:18:14 &amp#27;[32mINFO &amp#27;[m [InternalKafkaClient:188] Consumer consumed 100 messages
2020-04-15 04:18:14 &amp#27;[32mINFO &amp#27;[m [RecoveryST:319] Scale up Kafka to 7
2020-04-15 04:32:14 &amp#27;[32mINFO &amp#27;[m [StUtils:243] 
Kafka status:

Conditions:
	Type: NotReady
	Message: Error while waiting for non-restarted pod my-cluster-kafka-6 to become ready

Pods with conditions and messages:

my-cluster-entity-operator-5666c55b5-lb5wg:

my-cluster-kafka-0:

my-cluster-kafka-1:

my-cluster-kafka-2:

my-cluster-kafka-3:
	Type: PodScheduled
	Message: pod has unbound immediate PersistentVolumeClaims


my-cluster-kafka-4:
	Type: PodScheduled
	Message: pod has unbound immediate PersistentVolumeClaims


my-cluster-kafka-5:
	Type: PodScheduled
	Message: pod has unbound immediate PersistentVolumeClaims


my-cluster-kafka-6:
	Type: PodScheduled
	Message: pod has unbound immediate PersistentVolumeClaims


my-cluster-kafka-clients-6bc9868958-xn746:

my-cluster-zookeeper-0:

my-cluster-zookeeper-1:

my-cluster-zookeeper-2:


2020-04-15 04:32:14 &amp#27;[32mINFO &amp#27;[m [LogCollector:64] Collecting events in namespace rolling-update-cluster-test
2020-04-15 04:32:15 &amp#27;[32mINFO &amp#27;[m [LogCollector:71] Collecting configmaps in namespace rolling-update-cluster-test
2020-04-15 04:32:15 &amp#27;[32mINFO &amp#27;[m [LogCollector:44] Collecting logs for pods in namespace rolling-update-cluster-test
2020-04-15 04:32:19 &amp#27;[32mINFO &amp#27;[m [LogCollector:78] Collecting Deployments in namespaces rolling-update-cluster-test
2020-04-15 04:32:19 &amp#27;[32mINFO &amp#27;[m [LogCollector:83] Collecting StatefulSets in namespaces rolling-update-cluster-test
2020-04-15 04:32:19 &amp#27;[32mINFO &amp#27;[m [LogCollector:88] Collecting ReplicaSet in namespaces rolling-update-cluster-test
2020-04-15 04:32:19 &amp#27;[32mINFO &amp#27;[m [LogCollector:93] Collecting CR in namespaces rolling-update-cluster-test
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [Exec:166] Command: [oc, get, strimzi, -o, yaml, -n, rolling-update-cluster-test]
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [Exec:167] Return code: 0
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [Exec:168] stdout: 
apiVersion: v1
items:
- apiVersion: kafka.strimzi.io/v1beta1
  kind: KafkaUser
  metadata:
    creationTimestamp: "2020-04-15T04:17:30Z"
    generation: 1
    labels:
      strimzi.io/cluster: my-cluster
    name: alice
    namespace: rolling-update-cluster-test
    resourceVersion: "495848"
    selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkausers/alice
    uid: 3c77af2d-4b94-4177-9067-2d2dd888af58
  spec:
    authentication:
      type: tls
    authorization:
      acls:
      - host: '*'
        operation: Read
        resource:
          name: my-topic
          patternType: literal
          type: topic
        type: allow
      - host: '*'
        operation: Describe
        resource:
          name: my-topic
          patternType: literal
          type: topic
        type: allow
      - host: '*'
        operation: Read
        resource:
          name: my-group
          patternType: literal
          type: group
        type: allow
      - host: '*'
        operation: Write
        resource:
          name: my-topic
          patternType: literal
          type: topic
        type: allow
      - host: '*'
        operation: Create
        resource:
          name: my-topic
          patternType: literal
          type: topic
        type: allow
      - host: '*'
        operation: Describe
        resource:
          name: my-topic
          patternType: literal
          type: topic
        type: allow
      type: simple
  status:
    conditions:
    - lastTransitionTime: "2020-04-15T04:17:32.111Z"
      status: "True"
      type: Ready
    observedGeneration: 1
    secret: alice
    username: CN=alice
- apiVersion: kafka.strimzi.io/v1beta1
  kind: Kafka
  metadata:
    creationTimestamp: "2020-04-15T04:15:47Z"
    generation: 2
    name: my-cluster
    namespace: rolling-update-cluster-test
    resourceVersion: "496351"
    selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkas/my-cluster
    uid: e1c94057-a0bd-4016-933a-04c51b0dfb81
  spec:
    entityOperator:
      topicOperator:
        image: docker.io/strimzi/operator:latest
        logging:
          loggers:
            rootLogger.level: DEBUG
          type: inline
        reconciliationIntervalSeconds: 90
        topicMetadataMaxAttempts: 6
        zookeeperSessionTimeoutSeconds: 20
      userOperator:
        image: docker.io/strimzi/operator:latest
        logging:
          loggers:
            rootLogger.level: DEBUG
          type: inline
        reconciliationIntervalSeconds: 120
        zookeeperSessionTimeoutSeconds: 6
    kafka:
      config:
        auto.create.topics.enable: "false"
        default.replication.factor: 1
        log.message.format.version: "2.4"
        offsets.topic.replication.factor: 3
        transaction.state.log.min.isr: 2
        transaction.state.log.replication.factor: 3
      listeners:
        plain: {}
        tls: {}
      logging:
        loggers:
          kafka.root.logger.level: DEBUG
        type: inline
      replicas: 7
      storage:
        deleteClaim: true
        size: "100"
        type: persistent-claim
      version: 2.4.0
    zookeeper:
      logging:
        loggers:
          zookeeper.root.logger: DEBUG
        type: inline
      replicas: 3
      storage:
        deleteClaim: true
        size: "100"
        type: persistent-claim
  status:
    conditions:
    - lastTransitionTime: 2020-04-15T04:19:06+0000
      message: Error while waiting for non-restarted pod my-cluster-kafka-6 to become
        ready
      reason: FatalProblem
      status: "True"
      type: NotReady
    listeners:
    - addresses:
      - host: my-cluster-kafka-bootstrap.rolling-update-cluster-test.svc
        port: 9092
      type: plain
    - addresses:
      - host: my-cluster-kafka-bootstrap.rolling-update-cluster-test.svc
        port: 9093
      type: tls
    observedGeneration: 2
- apiVersion: kafka.strimzi.io/v1beta1
  kind: KafkaTopic
  metadata:
    creationTimestamp: "2020-04-15T04:18:59Z"
    generation: 1
    labels:
      strimzi.io/cluster: my-cluster
    name: consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a
    namespace: rolling-update-cluster-test
    resourceVersion: "496326"
    selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkatopics/consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a
    uid: acce886a-4922-474b-bc77-2455d290f81b
  spec:
    config:
      cleanup.policy: compact
      compression.type: producer
      message.format.version: 2.4-IV1
      segment.bytes: "104857600"
    partitions: 50
    replicas: 3
    topicName: __consumer_offsets
  status:
    conditions:
    - lastTransitionTime: "2020-04-15T04:19:00.039Z"
      status: "True"
      type: Ready
    observedGeneration: 1
- apiVersion: kafka.strimzi.io/v1beta1
  kind: KafkaTopic
  metadata:
    creationTimestamp: "2020-04-15T04:17:33Z"
    generation: 2
    labels:
      strimzi.io/cluster: my-cluster
    name: test-topic-925556285
    namespace: rolling-update-cluster-test
    resourceVersion: "495881"
    selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkatopics/test-topic-925556285
    uid: 970ee3e8-f702-4cf2-b93d-fe3851564db3
  spec:
    config:
      message.format.version: 2.4-IV1
      min.insync.replicas: "3"
      retention.ms: "7200000"
      segment.bytes: "1073741824"
    partitions: 3
    replicas: 3
    topicName: test-topic-925556285
  status:
    conditions:
    - lastTransitionTime: "2020-04-15T04:17:36.405Z"
      status: "True"
      type: Ready
    observedGeneration: 2
kind: List
metadata:
  resourceVersion: ""
  selfLink: ""

2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [Exec:169] stderr: 

2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [BaseST:666] Search in strimzi-cluster-operator log for errors in last 0 seconds
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [BaseST:750] Test execution contains exception, going to recreate test environment
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [ResourceManager:341] Going to clear all method resources
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [ResourceManager:177] Deleting Deployment my-cluster-kafka-clients
2020-04-15 04:32:20 &amp#27;[32mINFO &amp#27;[m [ResourceManager:323] Waiting when all the pods are terminated for Deployment my-cluster-kafka-clients
2020-04-15 04:32:20 &amp#27;[33mWARN &amp#27;[m [DeploymentUtils:187] Deployment my-cluster-kafka-clients is not deleted yet! Triggering force delete by cmd client!
2020-04-15 04:32:26 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-kafka-clients-6bc9868958-xn746 will be deleted
2020-04-15 04:32:59 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-kafka-clients-6bc9868958-xn746 deleted
2020-04-15 04:32:59 &amp#27;[32mINFO &amp#27;[m [ResourceManager:216] Deleting KafkaTopic test-topic-925556285 in namespace rolling-update-cluster-test
2020-04-15 04:32:59 &amp#27;[32mINFO &amp#27;[m [ResourceManager:216] Deleting KafkaUser alice in namespace rolling-update-cluster-test
2020-04-15 04:32:59 &amp#27;[32mINFO &amp#27;[m [ResourceManager:111] Deleting Kafka my-cluster in namespace rolling-update-cluster-test
2020-04-15 04:32:59 &amp#27;[32mINFO &amp#27;[m [ResourceManager:229] Waiting when all the pods are terminated for Kafka my-cluster
2020-04-15 04:32:59 &amp#27;[33mWARN &amp#27;[m [StatefulSetUtils:159] StatefulSet my-cluster-zookeeper is not deleted yet! Triggering force delete by cmd client!
2020-04-15 04:33:04 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-0 will be deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-zookeeper-0 deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-1 will be deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-zookeeper-1 deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-2 will be deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-zookeeper-2 deleted
2020-04-15 04:33:18 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-kafka-0 will be deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-kafka-0 deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-kafka-1 will be deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-kafka-1 deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PodUtils:138] Waiting when Pod my-cluster-kafka-2 will be deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PodUtils:152] Pod my-cluster-kafka-2 deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [SecretUtils:95] Waiting for Kafka cluster my-cluster secrets deletion
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [SecretUtils:109] Kafka cluster my-cluster secrets deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PersistentVolumeClaimUtils:58] Waiting till PVC deletion for cluster my-cluster
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [PersistentVolumeClaimUtils:72] PVC for cluster my-cluster was deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ConfigMapUtils:66] Waiting till ConfigMaps deletion for cluster my-cluster-kafka-config
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ConfigMapUtils:80] ConfigMaps for cluster my-cluster-kafka-config were deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ConfigMapUtils:66] Waiting till ConfigMaps deletion for cluster my-cluster-zookeeper-config
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ConfigMapUtils:80] ConfigMaps for cluster my-cluster-zookeeper-config were deleted
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:333] Going to clear all class resources
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:216] Deleting NetworkPolicy global-network-policy in namespace rolling-update-cluster-test
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:177] Deleting Deployment strimzi-cluster-operator
2020-04-15 04:33:48 &amp#27;[32mINFO &amp#27;[m [ResourceManager:323] Waiting when all the pods are terminated for Deployment strimzi-cluster-operator
2020-04-15 04:33:48 &amp#27;[33mWARN &amp#27;[m [DeploymentUtils:187] Deployment strimzi-cluster-operator is not deleted yet! Triggering force delete by cmd client!
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator-topic-operator-delegation
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator-entity-operator-delegation
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [ResourceManager:184] Deleting ClusterRoleBinding strimzi-cluster-operator-kafka-broker-delegation
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [ResourceManager:184] Deleting ClusterRoleBinding strimzi-cluster-operator
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:94] Start time of operation CO_DELETION is correctly stored
2020-04-15 04:33:53 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/048-Crd-kafkamirrormaker2.yaml
2020-04-15 04:33:54 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/047-Crd-kafkaconnector.yaml
2020-04-15 04:33:54 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/046-Crd-kafkabridge.yaml
2020-04-15 04:33:54 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/045-Crd-kafkamirrormaker.yaml
2020-04-15 04:33:54 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/044-Crd-kafkauser.yaml
2020-04-15 04:33:54 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/043-Crd-kafkatopic.yaml
2020-04-15 04:33:55 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/042-Crd-kafkaconnects2i.yaml
2020-04-15 04:33:55 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/041-Crd-kafkaconnect.yaml
2020-04-15 04:33:55 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/040-Crd-kafka.yaml
2020-04-15 04:33:56 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/032-ClusterRole-strimzi-topic-operator.yaml
2020-04-15 04:33:56 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/031-ClusterRole-strimzi-entity-operator.yaml
2020-04-15 04:33:56 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/030-ClusterRole-strimzi-kafka-broker.yaml
2020-04-15 04:33:57 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/021-ClusterRole-strimzi-cluster-operator-role.yaml
2020-04-15 04:33:57 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/020-ClusterRole-strimzi-cluster-operator-role.yaml
2020-04-15 04:33:57 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/010-ServiceAccount-strimzi-cluster-operator.yaml
2020-04-15 04:33:57 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:113] End time of operation CO_DELETION is correctly stored
2020-04-15 04:33:57 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:231] Deleting namespace: rolling-update-cluster-test
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:237] Using namespace rolling-update-cluster-test
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:125] Changing to rolling-update-cluster-test namespace
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:206] Creating namespace: rolling-update-cluster-test
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:212] Using namespace rolling-update-cluster-test
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:125] Changing to rolling-update-cluster-test namespace
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:94] Start time of operation CO_CREATION is correctly stored
2020-04-15 04:34:06 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/010-ServiceAccount-strimzi-cluster-operator.yaml
2020-04-15 04:34:07 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/020-ClusterRole-strimzi-cluster-operator-role.yaml
2020-04-15 04:34:07 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/021-ClusterRole-strimzi-cluster-operator-role.yaml
2020-04-15 04:34:08 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/030-ClusterRole-strimzi-kafka-broker.yaml
2020-04-15 04:34:08 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/031-ClusterRole-strimzi-entity-operator.yaml
2020-04-15 04:34:08 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/032-ClusterRole-strimzi-topic-operator.yaml
2020-04-15 04:34:09 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/040-Crd-kafka.yaml
2020-04-15 04:34:09 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/041-Crd-kafkaconnect.yaml
2020-04-15 04:34:10 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/042-Crd-kafkaconnects2i.yaml
2020-04-15 04:34:10 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/043-Crd-kafkatopic.yaml
2020-04-15 04:34:10 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/044-Crd-kafkauser.yaml
2020-04-15 04:34:11 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/045-Crd-kafkamirrormaker.yaml
2020-04-15 04:34:11 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/046-Crd-kafkabridge.yaml
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/047-Crd-kafkaconnector.yaml
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/048-Crd-kafkamirrormaker2.yaml
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [TimeMeasuringSystem:113] End time of operation CO_CREATION is correctly stored
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [ResourceManager:94] Setting pointer to class resources
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:142] Creating RoleBinding from ../install/cluster-operator/020-RoleBinding-strimzi-cluster-operator.yaml in namespace rolling-update-cluster-test
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator in namespace (not set)
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:158] Creating ClusterRoleBinding from ../install/cluster-operator/021-ClusterRoleBinding-strimzi-cluster-operator.yaml in namespace rolling-update-cluster-test
2020-04-15 04:34:12 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:167] Apply ClusterRoleBinding in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of ClusterRoleBinding strimzi-cluster-operator in namespace (not set)
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:158] Creating ClusterRoleBinding from ../install/cluster-operator/030-ClusterRoleBinding-strimzi-cluster-operator-kafka-broker-delegation.yaml in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:167] Apply ClusterRoleBinding in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of ClusterRoleBinding strimzi-cluster-operator-kafka-broker-delegation in namespace (not set)
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:142] Creating RoleBinding from ../install/cluster-operator/031-RoleBinding-strimzi-cluster-operator-entity-operator-delegation.yaml in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator-entity-operator-delegation in namespace (not set)
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:142] Creating RoleBinding from ../install/cluster-operator/032-RoleBinding-strimzi-cluster-operator-topic-operator-delegation.yaml in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator-topic-operator-delegation in namespace (not set)
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of Deployment strimzi-cluster-operator in namespace (not set)
2020-04-15 04:34:13 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:422] Waiting for deployment strimzi-cluster-operator
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:424] Deployment strimzi-cluster-operator is ready
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [ResourceManager:106] Scheduled deletion of NetworkPolicy global-network-policy in namespace rolling-update-cluster-test
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:402] Network policy successfully set to: DEFAULT_TO_DENY
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [KubernetesResource:324] NetworkPolicy successfully set to: true for namespace: rolling-update-cluster-test
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [BaseST:753] Env recreated.
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [ResourceManager:341] Going to clear all method resources
2020-04-15 04:35:00 &amp#27;[33mWARN &amp#27;[m [TimeMeasuringSystem:115] End time of operation TEST_EXECUTION is not set due to exception: java.lang.NullPointerException
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [TestSeparator:34] io.strimzi.systemtest.RollingUpdateST.testKafkaAndZookeeperScaleUpScaleDown-FINISHED
2020-04-15 04:35:00 &amp#27;[32mINFO &amp#27;[m [TestSeparator:35] ############################################################################

 Time: 04/15/2020 06:31:07, Level: ERROR, Log: Timeout after 840000 ms waiting for All pods matching LabelSelector(matchExpressions=[], matchLabels={strimzi.io/cluster=my-cluster, strimzi.io/kind=Kafka, strimzi.io/name=my-cluster-kafka}, additionalProperties={})to be ready

 Time: 04/15/2020 06:31:07, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-tls-sidecar.log

[^5e96aa2dbba24d00014320a2.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-tls-sidecar.log

[^5e96aa2dbba24d00014320a5.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-topic-operator.log

[^5e96aa2dbba24d00014320a8.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-topic-operator.log

[^5e96aa2dbba24d00014320ab.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-user-operator.log

[^5e96aa2dbba24d00014320ae.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5666c55b5-lb5wg-container-user-operator.log

[^5e96aa2dbba24d00014320b1.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: logs-pod-my-cluster-kafka-0-container-kafka.log

[^5e96aa2dbba24d00014320b4.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: describe-pod-my-cluster-kafka-0-container-kafka.log

[^5e96aa2dbba24d00014320b8.txt]

 Time: 04/15/2020 06:31:07, Level: INFO, Log: logs-pod-my-cluster-kafka-0-container-tls-sidecar.log

[^5e96aa2dbba24d00014320bb.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: describe-pod-my-cluster-kafka-0-container-tls-sidecar.log

[^5e96aa2ebba24d00014320be.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: logs-pod-my-cluster-kafka-1-container-kafka.log

[^5e96aa2ebba24d00014320c1.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: describe-pod-my-cluster-kafka-1-container-kafka.log

[^5e96aa2ebba24d00014320c5.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: logs-pod-my-cluster-kafka-1-container-tls-sidecar.log

[^5e96aa2ebba24d00014320c8.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: describe-pod-my-cluster-kafka-1-container-tls-sidecar.log

[^5e96aa2ebba24d00014320cb.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: logs-pod-my-cluster-kafka-2-container-kafka.log

[^5e96aa2ebba24d00014320ce.txt]

 Time: 04/15/2020 06:31:08, Level: INFO, Log: describe-pod-my-cluster-kafka-2-container-kafka.log

[^5e96aa2fbba24d00014320d2.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: logs-pod-my-cluster-kafka-2-container-tls-sidecar.log

[^5e96aa2fbba24d00014320d5.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: describe-pod-my-cluster-kafka-2-container-tls-sidecar.log

[^5e96aa2fbba24d00014320d8.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: logs-pod-my-cluster-kafka-clients-6bc9868958-xn746-container-my-cluster-kafka-clients.log

[^5e96aa2fbba24d00014320db.bin]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: describe-pod-my-cluster-kafka-clients-6bc9868958-xn746-container-my-cluster-kafka-clients.log

[^5e96aa2fbba24d00014320dd.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: logs-pod-my-cluster-zookeeper-0-container-tls-sidecar.log

[^5e96aa2fbba24d00014320e0.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: describe-pod-my-cluster-zookeeper-0-container-tls-sidecar.log

[^5e96aa2fbba24d00014320e3.txt]

 Time: 04/15/2020 06:31:09, Level: INFO, Log: logs-pod-my-cluster-zookeeper-0-container-zookeeper.log

[^5e96aa2fbba24d00014320e6.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-my-cluster-zookeeper-0-container-zookeeper.log

[^5e96aa2fbba24d00014320ed.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: logs-pod-my-cluster-zookeeper-1-container-tls-sidecar.log

[^5e96aa30bba24d00014320f3.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-my-cluster-zookeeper-1-container-tls-sidecar.log

[^5e96aa30bba24d00014320f6.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: logs-pod-my-cluster-zookeeper-1-container-zookeeper.log

[^5e96aa30bba24d00014320f9.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-my-cluster-zookeeper-1-container-zookeeper.log

[^5e96aa30bba24d00014320fe.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: logs-pod-my-cluster-zookeeper-2-container-tls-sidecar.log

[^5e96aa30bba24d0001432101.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-my-cluster-zookeeper-2-container-tls-sidecar.log

[^5e96aa30bba24d0001432104.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: logs-pod-my-cluster-zookeeper-2-container-zookeeper.log

[^5e96aa30bba24d0001432107.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-my-cluster-zookeeper-2-container-zookeeper.log

[^5e96aa30bba24d000143210e.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: logs-pod-strimzi-cluster-operator-54998fb758-rck5q-container-strimzi-cluster-operator.log

[^5e96aa30bba24d0001432111.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: describe-pod-strimzi-cluster-operator-54998fb758-rck5q-container-strimzi-cluster-operator.log

[^5e96aa30bba24d0001432117.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: deployments.log

[^5e96aa30bba24d000143211a.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: statefulsets.log

[^5e96aa30bba24d000143211d.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: replicasets.log

[^5e96aa30bba24d0001432120.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: strimzi-custom-resources.log

[^5e96aa30bba24d0001432123.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: events-in-namespacerolling-update-cluster-test.log

[^5e96aa30bba24d0001432126.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: my-cluster-entity-topic-operator-config-rolling-update-cluster-test.log

[^5e96aa30bba24d0001432129.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: my-cluster-entity-user-operator-config-rolling-update-cluster-test.log

[^5e96aa30bba24d000143212c.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: my-cluster-kafka-config-rolling-update-cluster-test.log

[^5e96aa30bba24d000143212f.txt]

 Time: 04/15/2020 06:31:10, Level: INFO, Log: my-cluster-zookeeper-config-rolling-update-cluster-test.log

[^5e96aa30bba24d0001432132.txt]

Assignee:: Jakub Stejskal

Reporter:: Jakub Stejskal

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Created:: 2020/04/15 1:18 PM

Updated:: 2020/12/18 11:10 AM

Resolved:: 2020/04/19 8:32 AM

Details

Description

Back link to Report Portal:

Test execution log:

Attachments

Easy Agile Planning Poker

Activity

People

Dates