-
Bug
-
Resolution: Done
-
Major
-
1.5.0.GA
-
None
Back link to Report Portal:
Test Item comments:
NullPointer in log probably
Test execution log:
Time: 04/19/2020 07:07:59, Level: INFO, Log: 2020-04-19 05:11:19 [32mINFO [m [TimeMeasuringSystem:94] Start time of operation TEST_EXECUTION is correctly stored 2020-04-19 05:11:19 [32mINFO [m [TestSeparator:27] ############################################################################ 2020-04-19 05:11:19 [32mINFO [m [TestSeparator:28] io.strimzi.systemtest.RollingUpdateST.testClusterCaRemovedTriggersRollingUpdate-STARTED 2020-04-19 05:11:19 [32mINFO [m [ResourceManager:89] Setting pointer to method resources 2020-04-19 05:11:20 [32mINFO [m [ResourceManager:106] Scheduled deletion of Kafka my-cluster in namespace rolling-update-cluster-test 2020-04-19 05:11:20 [32mINFO [m [KafkaResource:213] Waiting for Kafka my-cluster in namespace rolling-update-cluster-test 2020-04-19 05:11:20 [32mINFO [m [KafkaResource:215] Waiting for Zookeeper pods 2020-04-19 05:12:06 [32mINFO [m [KafkaResource:217] Zookeeper pods are ready 2020-04-19 05:12:06 [32mINFO [m [KafkaResource:219] Waiting for Kafka pods 2020-04-19 05:12:47 [32mINFO [m [KafkaResource:221] Kafka pods are ready 2020-04-19 05:12:47 [32mINFO [m [KafkaResource:225] Waiting for Entity Operator pods 2020-04-19 05:13:07 [32mINFO [m [KafkaResource:227] Entity Operator pods are ready 2020-04-19 05:13:07 [32mINFO [m [KafkaTopicResource:66] Created KafkaTopic test-topic-1275275556 2020-04-19 05:13:07 [32mINFO [m [ResourceManager:106] Scheduled deletion of KafkaTopic test-topic-1275275556 in namespace rolling-update-cluster-test 2020-04-19 05:13:07 [32mINFO [m [KafkaTopicResource:83] Waiting for Kafka Topic test-topic-1275275556 2020-04-19 05:13:07 [32mINFO [m [KafkaTopicUtils:46] Waiting for Kafka topic creation test-topic-1275275556 2020-04-19 05:13:10 [32mINFO [m [KafkaTopicResource:85] Kafka Topic test-topic-1275275556 is ready 2020-04-19 05:13:10 [32mINFO [m [KafkaUserResource:60] Created KafkaUser user-name-example 2020-04-19 05:13:10 [32mINFO [m [ResourceManager:106] Scheduled deletion of KafkaUser user-name-example in namespace rolling-update-cluster-test 2020-04-19 05:13:10 [32mINFO [m [KafkaUserResource:73] Waiting for Kafka User user-name-example 2020-04-19 05:13:10 [32mINFO [m [KafkaUserUtils:24] Waiting for Kafka user creation user-name-example 2020-04-19 05:13:10 [32mINFO [m [SecretUtils:40] Waiting for Kafka user secret user-name-example 2020-04-19 05:13:11 [32mINFO [m [SecretUtils:44] Kafka user secret user-name-example created 2020-04-19 05:13:11 [32mINFO [m [KafkaUserUtils:35] Kafka user user-name-example created 2020-04-19 05:13:11 [32mINFO [m [KafkaUserResource:75] Kafka User user-name-example is ready 2020-04-19 05:13:12 [32mINFO [m [ResourceManager:106] Scheduled deletion of Deployment my-cluster-kafka-clients in namespace (not set) 2020-04-19 05:13:12 [32mINFO [m [KubernetesResource:427] Waiting for deployment my-cluster-kafka-clients 2020-04-19 05:13:33 [32mINFO [m [KubernetesResource:429] Deployment my-cluster-kafka-clients is ready 2020-04-19 05:13:33 [32mINFO [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@bd703bb, messages=[], arguments=[USER=user_name_example, --topic, test-topic-1275275556, --broker-list, my-cluster-kafka-bootstrap:9093, --max-messages, 100], executable='/opt/kafka/producer.sh', executor=null, clientType=CLI_KAFKA_VERIFIABLE_PRODUCER, podName='my-cluster-kafka-clients-94f5b4ffb-b9ntp', podNamespace='rolling-update-cluster-test', bootstrapServer='my-cluster-kafka-bootstrap:9093', topicName='test-topic-1275275556', maxMessages=100, kafkaUsername='user-name-example', consumerGroupName='null', consumerInstanceId='null', clientArgumentMap=io.strimzi.systemtest.kafkaclients.internalClients.ClientArgumentMap@2a9565d7} 2020-04-19 05:13:33 [32mINFO [m [InternalKafkaClient:114] Sending 100 messages to my-cluster-kafka-bootstrap:9093#test-topic-1275275556 2020-04-19 05:13:38 [32mINFO [m [VerifiableClient:203] VerifiableClient CLI_KAFKA_VERIFIABLE_PRODUCER Return code - 0 2020-04-19 05:13:38 [32mINFO [m [VerifiableClient:205] VerifiableClient CLI_KAFKA_VERIFIABLE_PRODUCER stdout : /tmp/user_name_example.properties Starting Producer with configuration: acks=all security.protocol=SSL ssl.truststore.location=/tmp/user-name-example-truststore.p12 ssl.truststore.type=pkcs12 ssl.keystore.location=/tmp/user-name-example-keystore.p12 ssl.keystore.type=pkcs12 ssl.keystore.password=uzjl2haHz3aGFKzJ9lpo1JSwd_LOe_cN ssl.truststore.password=uzjl2haHz3aGFKzJ9lpo1JSwd_LOe_cN [2020-04-19 05:13:34,684] 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/user-name-example-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/user-name-example-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-19 05:13:34,733] DEBUG Added sensor with name bufferpool-wait-time (Metrics:416) [2020-04-19 05:13:34,742] DEBUG Added sensor with name buffer-exhausted-records (Metrics:416) [2020-04-19 05:13:34,754] DEBUG Added sensor with name errors (Metrics:416) [2020-04-19 05:13:35,088] DEBUG Created SSL context with keystore SecurityStore(path=/tmp/user-name-example-keystore.p12, modificationTime=Sun Apr 19 05:13:33 UTC 2020), truststore SecurityStore(path=/tmp/user-name-example-truststore.p12, modificationTime=Sun Apr 19 05:13:33 UTC 2020), provider SunJSSE. (SslEngineBuilder:159) [2020-04-19 05:13:35,120] DEBUG Added sensor with name produce-throttle-time (Metrics:416) [2020-04-19 05:13:35,132] DEBUG Added sensor with name connections-closed: (Metrics:416) [2020-04-19 05:13:35,133] DEBUG Added sensor with name connections-created: (Metrics:416) [2020-04-19 05:13:35,135] DEBUG Added sensor with name successful-authentication: (Metrics:416) [2020-04-19 05:13:35,137] DEBUG Added sensor with name successful-reauthentication: (Metrics:416) [2020-04-19 05:13:35,139] DEBUG Added sensor with name successful-authentication-no-reauth: (Metrics:416) [2020-04-19 05:13:35,140] DEBUG Added sensor with name failed-authentication: (Metrics:416) [2020-04-19 05:13:35,141] DEBUG Added sensor with name failed-reauthentication: (Metrics:416) [2020-04-19 05:13:35,141] DEBUG Added sensor with name reauthentication-latency: (Metrics:416) [2020-04-19 05:13:35,143] DEBUG Added sensor with name bytes-sent-received: (Metrics:416) [2020-04-19 05:13:35,144] DEBUG Added sensor with name bytes-sent: (Metrics:416) [2020-04-19 05:13:35,147] DEBUG Added sensor with name bytes-received: (Metrics:416) [2020-04-19 05:13:35,149] DEBUG Added sensor with name select-time: (Metrics:416) [2020-04-19 05:13:35,152] DEBUG Added sensor with name io-time: (Metrics:416) [2020-04-19 05:13:35,164] DEBUG Added sensor with name batch-size (Metrics:416) [2020-04-19 05:13:35,165] DEBUG Added sensor with name compression-rate (Metrics:416) [2020-04-19 05:13:35,166] DEBUG Added sensor with name queue-time (Metrics:416) [2020-04-19 05:13:35,166] DEBUG Added sensor with name request-time (Metrics:416) [2020-04-19 05:13:35,167] DEBUG Added sensor with name records-per-request (Metrics:416) [2020-04-19 05:13:35,168] DEBUG Added sensor with name record-retries (Metrics:416) [2020-04-19 05:13:35,169] DEBUG Added sensor with name record-size (Metrics:416) [2020-04-19 05:13:35,174] DEBUG Added sensor with name batch-split-rate (Metrics:416) [2020-04-19 05:13:35,176] DEBUG [Producer clientId=producer-1] Starting Kafka producer I/O thread. (Sender:239) [2020-04-19 05:13:35,177] 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-19 05:13:35,178] 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.203.201 (NetworkClient:956) [2020-04-19 05:13:35,179] INFO Kafka version: 2.4.0 (AppInfoParser:117) [2020-04-19 05:13:35,179] INFO Kafka commitId: 77a89fcf8d7fa018 (AppInfoParser:118) [2020-04-19 05:13:35,179] INFO Kafka startTimeMs: 1587273215176 (AppInfoParser:119) [2020-04-19 05:13:35,183] DEBUG [Producer clientId=producer-1] Kafka producer started (KafkaProducer:427) [2020-04-19 05:13:35,212] DEBUG Added sensor with name node--1.bytes-sent (Metrics:416) [2020-04-19 05:13:35,213] DEBUG Added sensor with name node--1.bytes-received (Metrics:416) [2020-04-19 05:13:35,224] DEBUG Added sensor with name node--1.latency (Metrics:416) [2020-04-19 05:13:35,224] DEBUG [Producer clientId=producer-1] Created socket with SO_RCVBUF = 32768, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node -1 (Selector:535) {"timestamp":1587273215511,"name":"startup_complete"} [2020-04-19 05:13:35,703] DEBUG [Producer clientId=producer-1] Completed connection to node -1. Fetching API versions. (NetworkClient:914) [2020-04-19 05:13:35,983] DEBUG [SslTransportLayer channelId=-1 key=sun.nio.ch.SelectionKeyImpl@8180690] 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-19 05:13:35,983] DEBUG [Producer clientId=producer-1] Successfully authenticated with my-cluster-kafka-bootstrap/172.30.203.201 (Selector:564) [2020-04-19 05:13:35,985] DEBUG [Producer clientId=producer-1] Initiating API versions fetch from node -1. (NetworkClient:928) [2020-04-19 05:13:36,214] 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-19 05:13:36,216] DEBUG [Producer clientId=producer-1] Sending metadata request MetadataRequestData(topics=[MetadataRequestTopic(name='test-topic-1275275556')], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to node my-cluster-kafka-bootstrap:9093 (id: -1 rack: null) (NetworkClient:1109) [2020-04-19 05:13:36,272] DEBUG [Producer clientId=producer-1] Updating last seen epoch from null to 0 for partition test-topic-1275275556-0 (Metadata:178) [2020-04-19 05:13:36,278] DEBUG [Producer clientId=producer-1] Updating last seen epoch from null to 0 for partition test-topic-1275275556-1 (Metadata:178) [2020-04-19 05:13:36,290] INFO [Producer clientId=producer-1] Cluster ID: M__CPMegQ4WTLc-3JJmBGg (Metadata:261) [2020-04-19 05:13:36,295] DEBUG [Producer clientId=producer-1] Updated cluster metadata updateVersion 2 to MetadataCache{clusterId='M__CPMegQ4WTLc-3JJmBGg', 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-1275275556, partition = 1, leader = 1, replicas = [1,0], isr = [1,0], offlineReplicas = []), epoch=0}, PartitionInfoAndEpoch{partitionInfo=Partition(topic = test-topic-1275275556, partition = 0, leader = 2, replicas = [2,1], isr = [2,1], offlineReplicas = []), epoch=0}], controller=my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc:9093 (id: 2 rack: null)} (Metadata:265) [2020-04-19 05:13:36,357] 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.226 (NetworkClient:956) [2020-04-19 05:13:36,364] DEBUG Added sensor with name node-2.bytes-sent (Metrics:416) [2020-04-19 05:13:36,369] DEBUG Added sensor with name node-2.bytes-received (Metrics:416) [2020-04-19 05:13:36,373] DEBUG Added sensor with name node-2.latency (Metrics:416) [2020-04-19 05:13:36,393] DEBUG [Producer clientId=producer-1] Created socket with SO_RCVBUF = 32768, SO_SNDBUF = 131072, SO_TIMEOUT = 0 to node 2 (Selector:535) [2020-04-19 05:13:36,396] DEBUG [Producer clientId=producer-1] Completed connection to node 2. Fetching API versions. (NetworkClient:914) [2020-04-19 05:13:36,420] INFO [Producer clientId=producer-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms. (KafkaProducer:1183) [2020-04-19 05:13:36,422] DEBUG [Producer clientId=producer-1] Beginning shutdown of Kafka producer I/O thread, sending remaining records. (Sender:250) [2020-04-19 05:13:36,457] DEBUG [SslTransportLayer channelId=2 key=sun.nio.ch.SelectionKeyImpl@500c5d07] 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-19 05:13:36,457] DEBUG [Producer clientId=producer-1] Successfully authenticated with my-cluster-kafka-2.my-cluster-kafka-brokers.rolling-update-cluster-test.svc/10.128.1.226 (Selector:564) [2020-04-19 05:13:36,457] DEBUG [Producer clientId=producer-1] Initiating API versions fetch from node 2. (NetworkClient:928) [2020-04-19 05:13:36,474] 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-19 05:13:36,482] DEBUG Added sensor with name topic.test-topic-1275275556.records-per-batch (Metrics:416) [2020-04-19 05:13:36,483] DEBUG Added sensor with name topic.test-topic-1275275556.bytes (Metrics:416) [2020-04-19 05:13:36,483] DEBUG Added sensor with name topic.test-topic-1275275556.compression-rate (Metrics:416) [2020-04-19 05:13:36,483] DEBUG Added sensor with name topic.test-topic-1275275556.record-retries (Metrics:416) [2020-04-19 05:13:36,483] DEBUG Added sensor with name topic.test-topic-1275275556.record-errors (Metrics:416) {"timestamp":1587273216831,"name":"producer_send_success","key":null,"value":"0","topic":"test-topic-1275275556","partition":0,"offset":0} {"timestamp":1587273216838,"name":"producer_send_success","key":null,"value":"1","topic":"test-topic-1275275556","partition":0,"offset":1} {"timestamp":1587273216840,"name":"producer_send_success","key":null,"value":"2","topic":"test-topic-1275275556","partition":0,"offset":2} {"timestamp":1587273216841,"name":"producer_send_success","key":null,"value":"3","topic":"test-topic-1275275556","partition":0,"offset":3} {"timestamp":1587273216843,"name":"producer_send_success","key":null,"value":"4","topic":"test-topic-1275275556","partition":0,"offset":4} {"timestamp":1587273216847,"name":"producer_send_success","key":null,"value":"5","topic":"test-topic-1275275556","partition":0,"offset":5} {"timestamp":1587273216848,"name":"producer_send_success","key":null,"value":"6","topic":"test-topic-1275275556","partition":0,"offset":6} {"timestamp":1587273216848,"name":"producer_send_success","key":null,"value":"7","topic":"test-topic-1275275556","partition":0,"offset":7} {"timestamp":1587273216850,"name":"producer_send_success","key":null,"value":"8","topic":"test-topic-1275275556","partition":0,"offset":8} {"timestamp":1587273216850,"name":"producer_send_success","key":null,"value":"9","topic":"test-topic-1275275556","partition":0,"offset":9} {"timestamp":1587273216851,"name":"producer_send_success","key":null,"value":"10","topic":"test-topic-1275275556","partition":0,"offset":10} {"timestamp":1587273216851,"name":"producer_send_success","key":null,"value":"11","topic":"test-topic-1275275556","partition":0,"offset":11} {"timestamp":1587273216852,"name":"producer_send_success","key":null,"value":"12","topic":"test-topic-1275275556","partition":0,"offset":12} {"timestamp":1587273216852,"name":"producer_send_success","key":null,"value":"13","topic":"test-topic-1275275556","partition":0,"offset":13} {"timestamp":1587273216853,"name":"producer_send_success","key":null,"value":"14","topic":"test-topic-1275275556","partition":0,"offset":14} {"timestamp":1587273216856,"name":"producer_send_success","key":null,"value":"15","topic":"test-topic-1275275556","partition":0,"offset":15} {"timestamp":1587273216860,"name":"producer_send_success","key":null,"value":"16","topic":"test-topic-1275275556","partition":0,"offset":16} {"timestamp":1587273216861,"name":"producer_send_success","key":null,"value":"17","topic":"test-topic-1275275556","partition":0,"offset":17} {"timestamp":1587273216862,"name":"producer_send_success","key":null,"value":"18","topic":"test-topic-1275275556","partition":0,"offset":18} {"timestamp":1587273216862,"name":"producer_send_success","key":null,"value":"19","topic":"test-topic-1275275556","partition":0,"offset":19} {"timestamp":1587273216863,"name":"producer_send_success","key":null,"value":"20","topic":"test-topic-1275275556","partition":0,"offset":20} {"timestamp":1587273216863,"name":"producer_send_success","key":null,"value":"21","topic":"test-topic-1275275556","partition":0,"offset":21} {"timestamp":1587273216863,"name":"producer_send_success","key":null,"value":"22","topic":"test-topic-1275275556","partition":0,"offset":22} {"timestamp":1587273216864,"name":"producer_send_success","key":null,"value":"23","topic":"test-topic-1275275556","partition":0,"offset":23} {"timestamp":1587273216865,"name":"producer_send_success","key":null,"value":"24","topic":"test-topic-1275275556","partition":0,"offset":24} {"timestamp":1587273216865,"name":"producer_send_success","key":null,"value":"25","topic":"test-topic-1275275556","partition":0,"offset":25} {"timestamp":1587273216866,"name":"producer_send_success","key":null,"value":"26","topic":"test-topic-1275275556","partition":0,"offset":26} {"timestamp":1587273216866,"name":"producer_send_success","key":null,"value":"27","topic":"test-topic-1275275556","partition":0,"offset":27} {"timestamp":1587273216866,"name":"producer_send_success","key":null,"value":"28","topic":"test-topic-1275275556","partition":0,"offset":28} {"timestamp":1587273216867,"name":"producer_send_success","key":null,"value":"29","topic":"test-topic-1275275556","partition":0,"offset":29} {"timestamp":1587273216867,"name":"producer_send_success","key":null,"value":"30","topic":"test-topic-1275275556","partition":0,"offset":30} {"timestamp":1587273216867,"name":"producer_send_success","key":null,"value":"31","topic":"test-topic-1275275556","partition":0,"offset":31} {"timestamp":1587273216868,"name":"producer_send_success","key":null,"value":"32","topic":"test-topic-1275275556","partition":0,"offset":32} {"timestamp":1587273216869,"name":"producer_send_success","key":null,"value":"33","topic":"test-topic-1275275556","partition":0,"offset":33} {"timestamp":1587273216869,"name":"producer_send_success","key":null,"value":"34","topic":"test-topic-1275275556","partition":0,"offset":34} {"timestamp":1587273216870,"name":"producer_send_success","key":null,"value":"35","topic":"test-topic-1275275556","partition":0,"offset":35} {"timestamp":1587273216870,"name":"producer_send_success","key":null,"value":"36","topic":"test-topic-1275275556","partition":0,"offset":36} {"timestamp":1587273216872,"name":"producer_send_success","key":null,"value":"37","topic":"test-topic-1275275556","partition":0,"offset":37} {"timestamp":1587273216873,"name":"producer_send_success","key":null,"value":"38","topic":"test-topic-1275275556","partition":0,"offset":38} {"timestamp":1587273216873,"name":"producer_send_success","key":null,"value":"39","topic":"test-topic-1275275556","partition":0,"offset":39} {"timestamp":1587273216874,"name":"producer_send_success","key":null,"value":"40","topic":"test-topic-1275275556","partition":0,"offset":40} {"timestamp":1587273216874,"name":"producer_send_success","key":null,"value":"41","topic":"test-topic-1275275556","partition":0,"offset":41} {"timestamp":1587273216875,"name":"producer_send_success","key":null,"value":"42","topic":"test-topic-1275275556","partition":0,"offset":42} {"timestamp":1587273216875,"name":"producer_send_success","key":null,"value":"43","topic":"test-topic-1275275556","partition":0,"offset":43} {"timestamp":1587273216876,"name":"producer_send_success","key":null,"value":"44","topic":"test-topic-1275275556","partition":0,"offset":44} {"timestamp":1587273216876,"name":"producer_send_success","key":null,"value":"45","topic":"test-topic-1275275556","partition":0,"offset":45} {"timestamp":1587273216878,"name":"producer_send_success","key":null,"value":"46","topic":"test-topic-1275275556","partition":0,"offset":46} {"timestamp":1587273216879,"name":"producer_send_success","key":null,"value":"47","topic":"test-topic-1275275556","partition":0,"offset":47} {"timestamp":1587273216881,"name":"producer_send_success","key":null,"value":"48","topic":"test-topic-1275275556","partition":0,"offset":48} {"timestamp":1587273216882,"name":"producer_send_success","key":null,"value":"49","topic":"test-topic-1275275556","partition":0,"offset":49} {"timestamp":1587273216882,"name":"producer_send_success","key":null,"value":"50","topic":"test-topic-1275275556","partition":0,"offset":50} {"timestamp":1587273216883,"name":"producer_send_success","key":null,"value":"51","topic":"test-topic-1275275556","partition":0,"offset":51} {"timestamp":1587273216883,"name":"producer_send_success","key":null,"value":"52","topic":"test-topic-1275275556","partition":0,"offset":52} {"timestamp":1587273216884,"name":"producer_send_success","key":null,"value":"53","topic":"test-topic-1275275556","partition":0,"offset":53} {"timestamp":1587273216884,"name":"producer_send_success","key":null,"value":"54","topic":"test-topic-1275275556","partition":0,"offset":54} {"timestamp":1587273216886,"name":"producer_send_success","key":null,"value":"55","topic":"test-topic-1275275556","partition":0,"offset":55} {"timestamp":1587273216888,"name":"producer_send_success","key":null,"value":"56","topic":"test-topic-1275275556","partition":0,"offset":56} {"timestamp":1587273216889,"name":"producer_send_success","key":null,"value":"57","topic":"test-topic-1275275556","partition":0,"offset":57} {"timestamp":1587273216889,"name":"producer_send_success","key":null,"value":"58","topic":"test-topic-1275275556","partition":0,"offset":58} {"timestamp":1587273216890,"name":"producer_send_success","key":null,"value":"59","topic":"test-topic-1275275556","partition":0,"offset":59} {"timestamp":1587273216891,"name":"producer_send_success","key":null,"value":"60","topic":"test-topic-1275275556","partition":0,"offset":60} {"timestamp":1587273216891,"name":"producer_send_success","key":null,"value":"61","topic":"test-topic-1275275556","partition":0,"offset":61} {"timestamp":1587273216892,"name":"producer_send_success","key":null,"value":"62","topic":"test-topic-1275275556","partition":0,"offset":62} {"timestamp":1587273216893,"name":"producer_send_success","key":null,"value":"63","topic":"test-topic-1275275556","partition":0,"offset":63} {"timestamp":1587273216894,"name":"producer_send_success","key":null,"value":"64","topic":"test-topic-1275275556","partition":0,"offset":64} {"timestamp":1587273216895,"name":"producer_send_success","key":null,"value":"65","topic":"test-topic-1275275556","partition":0,"offset":65} {"timestamp":1587273216895,"name":"producer_send_success","key":null,"value":"66","topic":"test-topic-1275275556","partition":0,"offset":66} {"timestamp":1587273216897,"name":"producer_send_success","key":null,"value":"67","topic":"test-topic-1275275556","partition":0,"offset":67} {"timestamp":1587273216897,"name":"producer_send_success","key":null,"value":"68","topic":"test-topic-1275275556","partition":0,"offset":68} {"timestamp":1587273216897,"name":"producer_send_success","key":null,"value":"69","topic":"test-topic-1275275556","partition":0,"offset":69} {"timestamp":1587273216898,"name":"producer_send_success","key":null,"value":"70","topic":"test-topic-1275275556","partition":0,"offset":70} {"timestamp":1587273216898,"name":"producer_send_success","key":null,"value":"71","topic":"test-topic-1275275556","partition":0,"offset":71} {"timestamp":1587273216899,"name":"producer_send_success","key":null,"value":"72","topic":"test-topic-1275275556","partition":0,"offset":72} {"timestamp":1587273216900,"name":"producer_send_success","key":null,"value":"73","topic":"test-topic-1275275556","partition":0,"offset":73} {"timestamp":1587273216901,"name":"producer_send_success","key":null,"value":"74","topic":"test-topic-1275275556","partition":0,"offset":74} {"timestamp":1587273216901,"name":"producer_send_success","key":null,"value":"75","topic":"test-topic-1275275556","partition":0,"offset":75} {"timestamp":1587273216902,"name":"producer_send_success","key":null,"value":"76","topic":"test-topic-1275275556","partition":0,"offset":76} {"timestamp":1587273216902,"name":"producer_send_success","key":null,"value":"77","topic":"test-topic-1275275556","partition":0,"offset":77} {"timestamp":1587273216903,"name":"producer_send_success","key":null,"value":"78","topic":"test-topic-1275275556","partition":0,"offset":78} {"timestamp":1587273216904,"name":"producer_send_success","key":null,"value":"79","topic":"test-topic-1275275556","partition":0,"offset":79} {"timestamp":1587273216904,"name":"producer_send_success","key":null,"value":"80","topic":"test-topic-1275275556","partition":0,"offset":80} {"timestamp":1587273216905,"name":"producer_send_success","key":null,"value":"81","topic":"test-topic-1275275556","partition":0,"offset":81} {"timestamp":1587273216906,"name":"producer_send_success","key":null,"value":"82","topic":"test-topic-1275275556","partition":0,"offset":82} {"timestamp":1587273216906,"name":"producer_send_success","key":null,"value":"83","topic":"test-topic-1275275556","partition":0,"offset":83} {"timestamp":1587273216907,"name":"producer_send_success","key":null,"value":"84","topic":"test-topic-1275275556","partition":0,"offset":84} {"timestamp":1587273216908,"name":"producer_send_success","key":null,"value":"85","topic":"test-topic-1275275556","partition":0,"offset":85} {"timestamp":1587273216908,"name":"producer_send_success","key":null,"value":"86","topic":"test-topic-1275275556","partition":0,"offset":86} {"timestamp":1587273216910,"name":"producer_send_success","key":null,"value":"87","topic":"test-topic-1275275556","partition":0,"offset":87} {"timestamp":1587273216911,"name":"producer_send_success","key":null,"value":"88","topic":"test-topic-1275275556","partition":0,"offset":88} {"timestamp":1587273216912,"name":"producer_send_success","key":null,"value":"89","topic":"test-topic-1275275556","partition":0,"offset":89} {"timestamp":1587273216912,"name":"producer_send_success","key":null,"value":"90","topic":"test-topic-1275275556","partition":0,"offset":90} {"timestamp":1587273216913,"name":"producer_send_success","key":null,"value":"91","topic":"test-topic-1275275556","partition":0,"offset":91} {"timestamp":1587273216914,"name":"producer_send_success","key":null,"value":"92","topic":"test-topic-1275275556","partition":0,"offset":92} {"timestamp":1587273216915,"name":"producer_send_success","key":null,"value":"93","topic":"test-topic-1275275556","partition":0,"offset":93} {"timestamp":1587273216916,"name":"producer_send_success","key":null,"value":"94","topic":"test-topic-1275275556","partition":0,"offset":94} {"timestamp":1587273216917,"name":"producer_send_success","key":null,"value":"95","topic":"test-topic-1275275556","partition":0,"offset":95} {"timestamp":1587273216918,"name":"producer_send_success","key":null,"value":"96","topic":"test-topic-1275275556","partition":0,"offset":96} {"timestamp":1587273216919,"name":"producer_send_success","key":null,"value":"97","topic":"test-topic-1275275556","partition":0,"offset":97} {"timestamp":1587273216919,"name":"producer_send_success","key":null,"value":"98","topic":"test-topic-1275275556","partition":0,"offset":98} {"timestamp":1587273216919,"name":"producer_send_success","key":null,"value":"99","topic":"test-topic-1275275556","partition":0,"offset":99} [2020-04-19 05:13:36,922] DEBUG Removed sensor with name connections-closed: (Metrics:449) [2020-04-19 05:13:36,923] DEBUG Removed sensor with name connections-created: (Metrics:449) [2020-04-19 05:13:36,924] DEBUG Removed sensor with name successful-authentication: (Metrics:449) [2020-04-19 05:13:36,924] DEBUG Removed sensor with name successful-reauthentication: (Metrics:449) [2020-04-19 05:13:36,925] DEBUG Removed sensor with name successful-authentication-no-reauth: (Metrics:449) [2020-04-19 05:13:36,925] DEBUG Removed sensor with name failed-authentication: (Metrics:449) [2020-04-19 05:13:36,926] DEBUG Removed sensor with name failed-reauthentication: (Metrics:449) [2020-04-19 05:13:36,926] DEBUG Removed sensor with name reauthentication-latency: (Metrics:449) [2020-04-19 05:13:36,927] DEBUG Removed sensor with name bytes-sent-received: (Metrics:449) [2020-04-19 05:13:36,927] DEBUG Removed sensor with name bytes-sent: (Metrics:449) [2020-04-19 05:13:36,928] DEBUG Removed sensor with name bytes-received: (Metrics:449) [2020-04-19 05:13:36,929] DEBUG Removed sensor with name select-time: (Metrics:449) [2020-04-19 05:13:36,929] DEBUG Removed sensor with name io-time: (Metrics:449) [2020-04-19 05:13:36,930] DEBUG Removed sensor with name node--1.bytes-sent (Metrics:449) [2020-04-19 05:13:36,931] DEBUG Removed sensor with name node--1.bytes-received (Metrics:449) [2020-04-19 05:13:36,931] DEBUG Removed sensor with name node--1.latency (Metrics:449) [2020-04-19 05:13:36,932] DEBUG Removed sensor with name node-2.bytes-sent (Metrics:449) [2020-04-19 05:13:36,932] DEBUG Removed sensor with name node-2.bytes-received (Metrics:449) [2020-04-19 05:13:36,933] DEBUG Removed sensor with name node-2.latency (Metrics:449) [2020-04-19 05:13:36,933] DEBUG [Producer clientId=producer-1] Shutdown of Kafka producer I/O thread has completed. (Sender:292) [2020-04-19 05:13:36,934] DEBUG [Producer clientId=producer-1] Kafka producer has been closed (KafkaProducer:1235) {"timestamp":1587273216935,"name":"shutdown_complete"} {"timestamp":1587273216937,"name":"tool_data","sent":100,"acked":100,"target_throughput":-1,"avg_throughput":69.68641114982579} 2020-04-19 05:13:38 [32mINFO [m [InternalKafkaClient:117] Producer finished correctly: true 2020-04-19 05:13:38 [32mINFO [m [InternalKafkaClient:121] Producer produced 100 messages 2020-04-19 05:13:38 [32mINFO [m [StatefulSetUtils:101] Waiting for StatefulSet my-cluster-kafka rolling update 2020-04-19 05:27:38 [32mINFO [m [LogCollector:64] Collecting events in namespace rolling-update-cluster-test 2020-04-19 05:27:39 [32mINFO [m [LogCollector:71] Collecting configmaps in namespace rolling-update-cluster-test 2020-04-19 05:27:39 [32mINFO [m [LogCollector:44] Collecting logs for pods in namespace rolling-update-cluster-test 2020-04-19 05:27:43 [32mINFO [m [LogCollector:78] Collecting Deployments in namespaces rolling-update-cluster-test 2020-04-19 05:27:43 [32mINFO [m [LogCollector:83] Collecting StatefulSets in namespaces rolling-update-cluster-test 2020-04-19 05:27:43 [32mINFO [m [LogCollector:88] Collecting ReplicaSet in namespaces rolling-update-cluster-test 2020-04-19 05:27:43 [32mINFO [m [LogCollector:93] Collecting CR in namespaces rolling-update-cluster-test 2020-04-19 05:27:44 [32mINFO [m [Exec:166] Command: [oc, get, strimzi, -o, yaml, -n, rolling-update-cluster-test] 2020-04-19 05:27:44 [32mINFO [m [Exec:167] Return code: 0 2020-04-19 05:27:44 [32mINFO [m [Exec:168] stdout: apiVersion: v1 items: - apiVersion: kafka.strimzi.io/v1beta1 kind: KafkaTopic metadata: creationTimestamp: "2020-04-19T05:04:29Z" generation: 1 labels: strimzi.io/cluster: my-cluster name: consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a namespace: rolling-update-cluster-test resourceVersion: "528839" selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkatopics/consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a uid: 78c745b2-0444-4d4b-abc3-a7b6c403704c 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-19T05:14:29.632Z" status: "True" type: Ready observedGeneration: 1 - apiVersion: kafka.strimzi.io/v1beta1 kind: KafkaTopic metadata: creationTimestamp: "2020-04-19T05:13:06Z" generation: 2 labels: strimzi.io/cluster: my-cluster name: test-topic-1275275556 namespace: rolling-update-cluster-test resourceVersion: "528546" selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkatopics/test-topic-1275275556 uid: 0308a878-0ce8-4212-9e02-da7abfdb5413 spec: config: message.format.version: 2.4-IV1 min.insync.replicas: "2" retention.ms: "7200000" segment.bytes: "1073741824" partitions: 2 replicas: 2 topicName: test-topic-1275275556 status: conditions: - lastTransitionTime: "2020-04-19T05:13:09.515Z" status: "True" type: Ready observedGeneration: 2 - apiVersion: kafka.strimzi.io/v1beta1 kind: Kafka metadata: creationTimestamp: "2020-04-19T05:11:18Z" generation: 1 name: my-cluster namespace: rolling-update-cluster-test resourceVersion: "529061" selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkas/my-cluster uid: 54de89d7-43a7-4261-8761-8f7aa32f69f2 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: 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: 3 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-19T05:15:37+0000 message: Failed to connect to Zookeeper my-cluster-zookeeper-0.my-cluster-zookeeper-nodes.rolling-update-cluster-test.svc:2181,my-cluster-zookeeper-1.my-cluster-zookeeper-nodes.rolling-update-cluster-test.svc:2181,my-cluster-zookeeper-2.my-cluster-zookeeper-nodes.rolling-update-cluster-test.svc:2181. Connection was not ready in 30000 ms. reason: ZookeeperScalingException status: "True" type: NotReady observedGeneration: 1 - apiVersion: kafka.strimzi.io/v1beta1 kind: KafkaUser metadata: creationTimestamp: "2020-04-19T05:13:09Z" generation: 1 labels: strimzi.io/cluster: my-cluster name: user-name-example namespace: rolling-update-cluster-test resourceVersion: "528551" selfLink: /apis/kafka.strimzi.io/v1beta1/namespaces/rolling-update-cluster-test/kafkausers/user-name-example uid: 2b362d83-c52b-42d5-9ff5-6703b0dddee5 spec: authentication: type: tls status: conditions: - lastTransitionTime: "2020-04-19T05:13:10.566Z" status: "True" type: Ready observedGeneration: 1 secret: user-name-example username: CN=user-name-example kind: List metadata: resourceVersion: "" selfLink: "" 2020-04-19 05:27:44 [32mINFO [m [Exec:169] stderr: 2020-04-19 05:27:44 [32mINFO [m [BaseST:666] Search in strimzi-cluster-operator log for errors in last 0 seconds 2020-04-19 05:27:44 [32mINFO [m [BaseST:750] Test execution contains exception, going to recreate test environment 2020-04-19 05:27:44 [32mINFO [m [ResourceManager:341] Going to clear all method resources 2020-04-19 05:27:44 [32mINFO [m [ResourceManager:177] Deleting Deployment my-cluster-kafka-clients 2020-04-19 05:27:44 [32mINFO [m [ResourceManager:323] Waiting when all the pods are terminated for Deployment my-cluster-kafka-clients 2020-04-19 05:27:44 [33mWARN [m [DeploymentUtils:187] Deployment my-cluster-kafka-clients is not deleted yet! Triggering force delete by cmd client! 2020-04-19 05:27:49 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-kafka-clients-94f5b4ffb-b9ntp will be deleted 2020-04-19 05:28:31 [32mINFO [m [PodUtils:153] Pod my-cluster-kafka-clients-94f5b4ffb-b9ntp deleted 2020-04-19 05:28:31 [32mINFO [m [ResourceManager:216] Deleting KafkaUser user-name-example in namespace rolling-update-cluster-test 2020-04-19 05:28:31 [32mINFO [m [ResourceManager:216] Deleting KafkaTopic test-topic-1275275556 in namespace rolling-update-cluster-test 2020-04-19 05:28:31 [32mINFO [m [ResourceManager:111] Deleting Kafka my-cluster in namespace rolling-update-cluster-test 2020-04-19 05:28:31 [32mINFO [m [ResourceManager:229] Waiting when all the pods are terminated for Kafka my-cluster 2020-04-19 05:28:31 [33mWARN [m [StatefulSetUtils:159] StatefulSet my-cluster-zookeeper is not deleted yet! Triggering force delete by cmd client! 2020-04-19 05:28:36 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-0 will be deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:153] Pod my-cluster-zookeeper-0 deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-1 will be deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:153] Pod my-cluster-zookeeper-1 deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-zookeeper-2 will be deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:153] Pod my-cluster-zookeeper-2 deleted 2020-04-19 05:28:51 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-kafka-0 will be deleted 2020-04-19 05:29:10 [32mINFO [m [PodUtils:153] Pod my-cluster-kafka-0 deleted 2020-04-19 05:29:10 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-kafka-1 will be deleted 2020-04-19 05:29:10 [32mINFO [m [PodUtils:153] Pod my-cluster-kafka-1 deleted 2020-04-19 05:29:10 [32mINFO [m [PodUtils:138] Waiting when Pod my-cluster-kafka-2 will be deleted 2020-04-19 05:29:10 [32mINFO [m [PodUtils:153] Pod my-cluster-kafka-2 deleted 2020-04-19 05:29:10 [32mINFO [m [SecretUtils:95] Waiting for Kafka cluster my-cluster secrets deletion 2020-04-19 05:29:10 [32mINFO [m [SecretUtils:109] Kafka cluster my-cluster secrets deleted 2020-04-19 05:29:10 [32mINFO [m [PersistentVolumeClaimUtils:58] Waiting till PVC deletion for cluster my-cluster 2020-04-19 05:29:10 [32mINFO [m [PersistentVolumeClaimUtils:72] PVC for cluster my-cluster was deleted 2020-04-19 05:29:10 [32mINFO [m [ConfigMapUtils:66] Waiting till ConfigMaps deletion for cluster my-cluster-kafka-config 2020-04-19 05:29:10 [32mINFO [m [ConfigMapUtils:80] ConfigMaps for cluster my-cluster-kafka-config were deleted 2020-04-19 05:29:10 [32mINFO [m [ConfigMapUtils:66] Waiting till ConfigMaps deletion for cluster my-cluster-zookeeper-config 2020-04-19 05:29:10 [32mINFO [m [ConfigMapUtils:80] ConfigMaps for cluster my-cluster-zookeeper-config were deleted 2020-04-19 05:29:10 [32mINFO [m [ResourceManager:333] Going to clear all class resources 2020-04-19 05:29:10 [32mINFO [m [ResourceManager:216] Deleting NetworkPolicy global-network-policy in namespace rolling-update-cluster-test 2020-04-19 05:29:10 [32mINFO [m [ResourceManager:177] Deleting Deployment strimzi-cluster-operator 2020-04-19 05:29:10 [32mINFO [m [ResourceManager:323] Waiting when all the pods are terminated for Deployment strimzi-cluster-operator 2020-04-19 05:29:10 [33mWARN [m [DeploymentUtils:187] Deployment strimzi-cluster-operator is not deleted yet! Triggering force delete by cmd client! 2020-04-19 05:29:15 [32mINFO [m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator-topic-operator-delegation 2020-04-19 05:29:15 [32mINFO [m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator-entity-operator-delegation 2020-04-19 05:29:15 [32mINFO [m [ResourceManager:184] Deleting ClusterRoleBinding strimzi-cluster-operator-kafka-broker-delegation 2020-04-19 05:29:15 [32mINFO [m [ResourceManager:184] Deleting ClusterRoleBinding strimzi-cluster-operator 2020-04-19 05:29:15 [32mINFO [m [ResourceManager:191] Deleting RoleBinding strimzi-cluster-operator 2020-04-19 05:29:15 [32mINFO [m [TimeMeasuringSystem:94] Start time of operation CO_DELETION is correctly stored 2020-04-19 05:29:15 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/048-Crd-kafkamirrormaker2.yaml 2020-04-19 05:29:15 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/047-Crd-kafkaconnector.yaml 2020-04-19 05:29:16 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/046-Crd-kafkabridge.yaml 2020-04-19 05:29:16 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/045-Crd-kafkamirrormaker.yaml 2020-04-19 05:29:16 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/044-Crd-kafkauser.yaml 2020-04-19 05:29:16 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/043-Crd-kafkatopic.yaml 2020-04-19 05:29:17 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/042-Crd-kafkaconnects2i.yaml 2020-04-19 05:29:17 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/041-Crd-kafkaconnect.yaml 2020-04-19 05:29:18 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/040-Crd-kafka.yaml 2020-04-19 05:29:18 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/032-ClusterRole-strimzi-topic-operator.yaml 2020-04-19 05:29:18 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/031-ClusterRole-strimzi-entity-operator.yaml 2020-04-19 05:29:18 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/030-ClusterRole-strimzi-kafka-broker.yaml 2020-04-19 05:29:19 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/021-ClusterRole-strimzi-cluster-operator-role.yaml 2020-04-19 05:29:19 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/020-ClusterRole-strimzi-cluster-operator-role.yaml 2020-04-19 05:29:19 [32mINFO [m [KubeClusterResource:185] Deleting configuration file: ../install/cluster-operator/010-ServiceAccount-strimzi-cluster-operator.yaml 2020-04-19 05:29:19 [32mINFO [m [TimeMeasuringSystem:113] End time of operation CO_DELETION is correctly stored 2020-04-19 05:29:19 [32mINFO [m [KubeClusterResource:231] Deleting namespace: rolling-update-cluster-test 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:237] Using namespace rolling-update-cluster-test 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:125] Changing to rolling-update-cluster-test namespace 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:206] Creating namespace: rolling-update-cluster-test 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:212] Using namespace rolling-update-cluster-test 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:125] Changing to rolling-update-cluster-test namespace 2020-04-19 05:29:31 [32mINFO [m [TimeMeasuringSystem:94] Start time of operation CO_CREATION is correctly stored 2020-04-19 05:29:31 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/010-ServiceAccount-strimzi-cluster-operator.yaml 2020-04-19 05:29:32 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/020-ClusterRole-strimzi-cluster-operator-role.yaml 2020-04-19 05:29:32 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/021-ClusterRole-strimzi-cluster-operator-role.yaml 2020-04-19 05:29:32 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/030-ClusterRole-strimzi-kafka-broker.yaml 2020-04-19 05:29:33 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/031-ClusterRole-strimzi-entity-operator.yaml 2020-04-19 05:29:33 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/032-ClusterRole-strimzi-topic-operator.yaml 2020-04-19 05:29:34 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/040-Crd-kafka.yaml 2020-04-19 05:29:34 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/041-Crd-kafkaconnect.yaml 2020-04-19 05:29:35 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/042-Crd-kafkaconnects2i.yaml 2020-04-19 05:29:35 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/043-Crd-kafkatopic.yaml 2020-04-19 05:29:36 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/044-Crd-kafkauser.yaml 2020-04-19 05:29:36 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/045-Crd-kafkamirrormaker.yaml 2020-04-19 05:29:36 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/046-Crd-kafkabridge.yaml 2020-04-19 05:29:37 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/047-Crd-kafkaconnector.yaml 2020-04-19 05:29:37 [32mINFO [m [KubeClusterResource:103] Applying configuration file: ../install/cluster-operator/048-Crd-kafkamirrormaker2.yaml 2020-04-19 05:29:38 [32mINFO [m [TimeMeasuringSystem:113] End time of operation CO_CREATION is correctly stored 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:94] Setting pointer to class resources 2020-04-19 05:29:38 [32mINFO [m [KubernetesResource:142] Creating RoleBinding from ../install/cluster-operator/020-RoleBinding-strimzi-cluster-operator.yaml in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator in namespace (not set) 2020-04-19 05:29:38 [32mINFO [m [KubernetesResource:158] Creating ClusterRoleBinding from ../install/cluster-operator/021-ClusterRoleBinding-strimzi-cluster-operator.yaml in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [KubernetesResource:167] Apply ClusterRoleBinding in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of ClusterRoleBinding strimzi-cluster-operator in namespace (not set) 2020-04-19 05:29:38 [32mINFO [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-19 05:29:38 [32mINFO [m [KubernetesResource:167] Apply ClusterRoleBinding in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of ClusterRoleBinding strimzi-cluster-operator-kafka-broker-delegation in namespace (not set) 2020-04-19 05:29:38 [32mINFO [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-19 05:29:38 [32mINFO [m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator-entity-operator-delegation in namespace (not set) 2020-04-19 05:29:38 [32mINFO [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-19 05:29:38 [32mINFO [m [KubernetesResource:151] Apply RoleBinding in namespace rolling-update-cluster-test 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of RoleBinding strimzi-cluster-operator-topic-operator-delegation in namespace (not set) 2020-04-19 05:29:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of Deployment strimzi-cluster-operator in namespace (not set) 2020-04-19 05:29:38 [32mINFO [m [KubernetesResource:427] Waiting for deployment strimzi-cluster-operator 2020-04-19 05:30:38 [32mINFO [m [KubernetesResource:429] Deployment strimzi-cluster-operator is ready 2020-04-19 05:30:38 [32mINFO [m [ResourceManager:106] Scheduled deletion of NetworkPolicy global-network-policy in namespace rolling-update-cluster-test 2020-04-19 05:30:38 [32mINFO [m [KubernetesResource:407] Network policy successfully set to: DEFAULT_TO_DENY 2020-04-19 05:30:38 [32mINFO [m [KubernetesResource:324] NetworkPolicy successfully set to: true for namespace: rolling-update-cluster-test 2020-04-19 05:30:38 [32mINFO [m [BaseST:753] Env recreated. 2020-04-19 05:30:38 [32mINFO [m [ResourceManager:341] Going to clear all method resources 2020-04-19 05:30:38 [33mWARN [m [TimeMeasuringSystem:115] End time of operation TEST_EXECUTION is not set due to exception: java.lang.NullPointerException 2020-04-19 05:30:38 [32mINFO [m [TestSeparator:34] io.strimzi.systemtest.RollingUpdateST.testClusterCaRemovedTriggersRollingUpdate-FINISHED 2020-04-19 05:30:38 [32mINFO [m [TestSeparator:35] ############################################################################
Time: 04/19/2020 07:07:59, Level: ERROR, Log: Timeout after 840000 ms waiting for StatefulSet my-cluster-kafka rolling update
Time: 04/19/2020 07:07:59, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-tls-sidecar.log
[^5e9bf8d22e738600015a4ddf.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-tls-sidecar.log
[^5e9bf8d22e738600015a4de2.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-topic-operator.log
[^5e9bf8d22e738600015a4de5.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-topic-operator.log
[^5e9bf8d22e738600015a4de8.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-user-operator.log
[^5e9bf8d22e738600015a4deb.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-entity-operator-5d4c85f7c5-c8l6z-container-user-operator.log
[^5e9bf8d22e738600015a4dee.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-0-container-kafka.log
[^5e9bf8d22e738600015a4df1.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-0-container-kafka.log
[^5e9bf8d32e738600015a4df5.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-0-container-tls-sidecar.log
[^5e9bf8d32e738600015a4df8.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-0-container-tls-sidecar.log
[^5e9bf8d32e738600015a4dfb.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-1-container-kafka.log
[^5e9bf8d32e738600015a4dfe.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-1-container-kafka.log
[^5e9bf8d32e738600015a4e02.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-1-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e05.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-1-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e08.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-2-container-kafka.log
[^5e9bf8d32e738600015a4e0b.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-2-container-kafka.log
[^5e9bf8d32e738600015a4e0f.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-2-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e12.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-2-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e15.txt]
Time: 04/19/2020 07:08:00, Level: INFO, Log: logs-pod-my-cluster-kafka-clients-94f5b4ffb-b9ntp-container-my-cluster-kafka-clients.log
[^5e9bf8d32e738600015a4e18.bin]
Time: 04/19/2020 07:08:00, Level: INFO, Log: describe-pod-my-cluster-kafka-clients-94f5b4ffb-b9ntp-container-my-cluster-kafka-clients.log
[^5e9bf8d32e738600015a4e1a.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-0-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e1d.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-0-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e20.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-0-container-zookeeper.log
[^5e9bf8d32e738600015a4e23.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-0-container-zookeeper.log
[^5e9bf8d32e738600015a4e27.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-1-container-tls-sidecar.log
[^5e9bf8d32e738600015a4e2a.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-1-container-tls-sidecar.log
[^5e9bf8d42e738600015a4e2d.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-1-container-zookeeper.log
[^5e9bf8d42e738600015a4e30.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-1-container-zookeeper.log
[^5e9bf8d42e738600015a4e35.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-2-container-tls-sidecar.log
[^5e9bf8d42e738600015a4e38.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-2-container-tls-sidecar.log
[^5e9bf8d42e738600015a4e3b.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-my-cluster-zookeeper-2-container-zookeeper.log
[^5e9bf8d42e738600015a4e3e.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-my-cluster-zookeeper-2-container-zookeeper.log
[^5e9bf8d42e738600015a4e43.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: logs-pod-strimzi-cluster-operator-54998fb758-pwph5-container-strimzi-cluster-operator.log
[^5e9bf8d42e738600015a4e4d.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: describe-pod-strimzi-cluster-operator-54998fb758-pwph5-container-strimzi-cluster-operator.log
[^5e9bf8d42e738600015a4e52.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: deployments.log
[^5e9bf8d42e738600015a4e55.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: statefulsets.log
[^5e9bf8d42e738600015a4e58.txt]
Time: 04/19/2020 07:08:01, Level: INFO, Log: replicasets.log
[^5e9bf8d42e738600015a4e5b.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: strimzi-custom-resources.log
[^5e9bf8d42e738600015a4e5e.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: events-in-namespacerolling-update-cluster-test.log
[^5e9bf8d42e738600015a4e61.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: my-cluster-entity-topic-operator-config-rolling-update-cluster-test.log
[^5e9bf8d42e738600015a4e64.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: my-cluster-entity-user-operator-config-rolling-update-cluster-test.log
[^5e9bf8d42e738600015a4e67.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: my-cluster-kafka-config-rolling-update-cluster-test.log
[^5e9bf8d42e738600015a4e6a.txt]
Time: 04/19/2020 07:08:02, Level: INFO, Log: my-cluster-zookeeper-config-rolling-update-cluster-test.log
[^5e9bf8d52e738600015a4e6d.txt]