[KAFKA-8022] Flaky Test RequestQuotaTest#testExemptRequestTime

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 0.11.0.3
• Fix Version/s: 2.2.0
• Component/s: core, unit tests
• Labels: flaky-test
• Assignee: Jun Rao
• Reporter: Matthias J. Sax
• Created: 01/Mar/19 07:28
• Updated: 08/Mar/19 18:10
• Resolved: 07/Mar/19 17:43

Description

https://builds.apache.org/blue/organizations/jenkins/kafka-trunk-jdk11/detail/kafka-trunk-jdk11/328/tests

kafka.zookeeper.ZooKeeperClientTimeoutException: Timed out waiting for connection while in state: CONNECTING
at kafka.zookeeper.ZooKeeperClient.$anonfun$waitUntilConnected$3(ZooKeeperClient.scala:242)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at kafka.utils.CoreUtils$.inLock(CoreUtils.scala:253)
at kafka.zookeeper.ZooKeeperClient.waitUntilConnected(ZooKeeperClient.scala:238)
at kafka.zookeeper.ZooKeeperClient.<init>(ZooKeeperClient.scala:96)
at kafka.zk.KafkaZkClient$.apply(KafkaZkClient.scala:1825)
at kafka.zk.ZooKeeperTestHarness.setUp(ZooKeeperTestHarness.scala:59)
at kafka.integration.KafkaServerTestHarness.setUp(KafkaServerTestHarness.scala:90)
at kafka.api.IntegrationTestHarness.doSetup(IntegrationTestHarness.scala:81)
at kafka.api.IntegrationTestHarness.setUp(IntegrationTestHarness.scala:73)
at kafka.server.RequestQuotaTest.setUp(RequestQuotaTest.scala:81)

STDOUT:

[2019-03-01 00:40:47,090] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-CONTROLLED_SHUTDOWN, correlationId=1, api=CONTROLLED_SHUTDOWN, body={broker_id=0,broker_epoch=9223372036854775807} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=2, connectionId=127.0.0.1:37894-127.0.0.1:54838-2, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,090] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-STOP_REPLICA, correlationId=1, api=STOP_REPLICA, body={controller_id=0,controller_epoch=2147483647,broker_epoch=9223372036854775807,delete_partitions=true,partitions=[

Unknown macro: {topic=topic-1,partition_ids=[0]}

]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=0, connectionId=127.0.0.1:37894-127.0.0.1:54822-1, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,091] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-UPDATE_METADATA, correlationId=1, api=UPDATE_METADATA, body={controller_id=0,controller_epoch=2147483647,broker_epoch=9223372036854775807,topic_states=[{topic=topic-1,partition_states=[

Unknown macro: {partition=0,controller_epoch=2147483647,leader=0,leader_epoch=2147483647,isr=[0],zk_version=2,replicas=[0],offline_replicas=[]}

]}],live_brokers=[{id=0,end_points=[

Unknown macro: {port=0,host=localhost,listener_name=PLAINTEXT,security_protocol_type=0}

],rack=null}]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=1, connectionId=127.0.0.1:37894-127.0.0.1:54836-2, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,090] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-LEADER_AND_ISR, correlationId=1, api=LEADER_AND_ISR, body={controller_id=0,controller_epoch=2147483647,broker_epoch=9223372036854775807,topic_states=[{topic=topic-1,partition_states=[

Unknown macro: {partition=0,controller_epoch=2147483647,leader=0,leader_epoch=2147483647,isr=[0],zk_version=2,replicas=[0],is_new=true}

]}],live_leaders=[\{id=0,host=localhost,port=0}]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=0, connectionId=127.0.0.1:37894-127.0.0.1:54834-2, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,106] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-WRITE_TXN_MARKERS, correlationId=1, api=WRITE_TXN_MARKERS, body={transaction_markers=[]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=0, connectionId=127.0.0.1:37894-127.0.0.1:54876-9, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,123] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-DESCRIBE_ACLS, correlationId=1, api=DESCRIBE_ACLS, body={resource_type=1,resource_name=null,resource_pattern_type_filter=1,principal=null,host=null,operation=1,permission_type=1} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=1, connectionId=127.0.0.1:37894-127.0.0.1:54908-14, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,124] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-DELETE_ACLS, correlationId=1, api=DELETE_ACLS, body={filters=[

Unknown macro: {resource_type=2,resource_name=null,resource_pattern_type_filter=3,principal=User}

]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=2, connectionId=127.0.0.1:37894-127.0.0.1:54910-14, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,123] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-CREATE_ACLS, correlationId=1, api=CREATE_ACLS, body={creations=[

Unknown macro: {resource_type=2,resource_name=mytopic,resource_pattten_type=3,principal=User}

]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=0, connectionId=127.0.0.1:37894-127.0.0.1:54906-14, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:40:47,168] ERROR [KafkaApi-0] Error when handling request: clientId=unauthorized-DELETE_ACLS, correlationId=2, api=DELETE_ACLS, body={filters=[

Unknown macro: {resource_type=2,resource_name=null,resource_pattern_type_filter=3,principal=User}

]} (kafka.server.KafkaApis:76)
org.apache.kafka.common.errors.ClusterAuthorizationException: Request Request(processor=2, connectionId=127.0.0.1:37894-127.0.0.1:54910-14, session=Session(User:Unauthorized,/127.0.0.1), listenerName=ListenerName(PLAINTEXT), securityProtocol=PLAINTEXT, buffer=null) is not authorized.
[2019-03-01 00:41:00,625] WARN Client session timed out, have not heard from server in 4001ms for sessionid 0x10299521c3d0000 (org.apache.zookeeper.ClientCnxn:1112)
[2019-03-01 00:41:00,628] WARN Unable to read additional data from client sessionid 0x10299521c3d0000, likely client has closed socket (org.apache.zookeeper.server.NIOServerCnxn:376)
[2019-03-01 00:41:02,135] WARN fsync-ing the write ahead log in SyncThread:0 took 4929ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide (org.apache.zookeeper.server.persistence.FileTxnLog:338)
[2019-03-01 00:41:08,156] WARN Client session timed out, have not heard from server in 6006ms for sessionid 0x0 (org.apache.zookeeper.ClientCnxn:1112)
[2019-03-01 00:41:13,861] WARN fsync-ing the write ahead log in SyncThread:0 took 11710ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide (org.apache.zookeeper.server.persistence.FileTxnLog:338)
[2019-03-01 00:41:13,863] WARN Unable to read additional data from client sessionid 0x102995240ed0000, likely client has closed socket (org.apache.zookeeper.server.NIOServerCnxn:376)