[
https://issues.apache.org/jira/browse/KAFKA-7921?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Colin P. McCabe resolved KAFKA-7921.
------------------------------------
Resolution: Fixed
Let's re-open this if we see another failure.
> Instable KafkaStreamsTest
> -------------------------
>
> Key: KAFKA-7921
> URL: https://issues.apache.org/jira/browse/KAFKA-7921
> Project: Kafka
> Issue Type: Bug
> Components: streams, unit tests
> Affects Versions: 2.3.0
> Reporter: Matthias J. Sax
> Priority: Critical
> Labels: flaky-test
> Fix For: 2.3.0
>
>
> {{KafkaStreamsTest}} failed multiple times, eg,
> {quote}java.lang.AssertionError: Condition not met within timeout 15000.
> Streams never started.
> at org.apache.kafka.test.TestUtils.waitForCondition(TestUtils.java:365)
> at org.apache.kafka.test.TestUtils.waitForCondition(TestUtils.java:325)
> at
> org.apache.kafka.streams.KafkaStreamsTest.shouldThrowOnCleanupWhileRunning(KafkaStreamsTest.java:556){quote}
> or
> {quote}java.lang.AssertionError: Condition not met within timeout 15000.
> Streams never started.
> at org.apache.kafka.test.TestUtils.waitForCondition(TestUtils.java:365)
> at org.apache.kafka.test.TestUtils.waitForCondition(TestUtils.java:325)
> at
> org.apache.kafka.streams.KafkaStreamsTest.testStateThreadClose(KafkaStreamsTest.java:255){quote}
>
> The preserved logs are as follows:
> {quote}[2019-02-12 07:02:17,198] INFO Kafka version: 2.3.0-SNAPSHOT
> (org.apache.kafka.common.utils.AppInfoParser:109)
> [2019-02-12 07:02:17,198] INFO Kafka commitId: 08036fa4b1e5b822
> (org.apache.kafka.common.utils.AppInfoParser:110)
> [2019-02-12 07:02:17,199] INFO stream-client [clientId] State transition from
> CREATED to REBALANCING (org.apache.kafka.streams.KafkaStreams:263)
> [2019-02-12 07:02:17,200] INFO stream-thread [clientId-StreamThread-238]
> Starting (org.apache.kafka.streams.processor.internals.StreamThread:767)
> [2019-02-12 07:02:17,200] INFO stream-client [clientId] State transition from
> REBALANCING to PENDING_SHUTDOWN (org.apache.kafka.streams.KafkaStreams:263)
> [2019-02-12 07:02:17,200] INFO stream-thread [clientId-StreamThread-239]
> Starting (org.apache.kafka.streams.processor.internals.StreamThread:767)
> [2019-02-12 07:02:17,200] INFO stream-thread [clientId-StreamThread-238]
> State transition from CREATED to STARTING
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:17,200] INFO stream-thread [clientId-StreamThread-239]
> State transition from CREATED to STARTING
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:17,200] INFO stream-thread [clientId-StreamThread-238]
> Informed to shut down
> (org.apache.kafka.streams.processor.internals.StreamThread:1192)
> [2019-02-12 07:02:17,201] INFO stream-thread [clientId-StreamThread-238]
> State transition from STARTING to PENDING_SHUTDOWN
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:17,201] INFO stream-thread [clientId-StreamThread-239]
> Informed to shut down
> (org.apache.kafka.streams.processor.internals.StreamThread:1192)
> [2019-02-12 07:02:17,201] INFO stream-thread [clientId-StreamThread-239]
> State transition from STARTING to PENDING_SHUTDOWN
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:17,205] INFO Cluster ID: J8uJhiTKQx-Y_i9LzT0iLg
> (org.apache.kafka.clients.Metadata:365)
> [2019-02-12 07:02:17,205] INFO Cluster ID: J8uJhiTKQx-Y_i9LzT0iLg
> (org.apache.kafka.clients.Metadata:365)
> [2019-02-12 07:02:17,205] INFO [Consumer
> clientId=clientId-StreamThread-238-consumer, groupId=appId] Discovered group
> coordinator localhost:36122 (id: 2147483647 rack: null)
> (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:675)
> [2019-02-12 07:02:17,205] INFO [Consumer
> clientId=clientId-StreamThread-239-consumer, groupId=appId] Discovered group
> coordinator localhost:36122 (id: 2147483647 rack: null)
> (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:675)
> [2019-02-12 07:02:17,206] INFO [Consumer
> clientId=clientId-StreamThread-238-consumer, groupId=appId] Revoking
> previously assigned partitions []
> (org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:458)
> [2019-02-12 07:02:17,206] INFO [Consumer
> clientId=clientId-StreamThread-239-consumer, groupId=appId] Revoking
> previously assigned partitions []
> (org.apache.kafka.clients.consumer.internals.ConsumerCoordinator:458)
> [2019-02-12 07:02:17,206] INFO [Consumer
> clientId=clientId-StreamThread-238-consumer, groupId=appId] (Re-)joining
> group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:491)
> [2019-02-12 07:02:17,206] INFO [Consumer
> clientId=clientId-StreamThread-239-consumer, groupId=appId] (Re-)joining
> group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:491)
> [2019-02-12 07:02:17,208] INFO [Consumer
> clientId=clientId-StreamThread-239-consumer, groupId=appId] (Re-)joining
> group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:491)
> [2019-02-12 07:02:17,208] INFO [Consumer
> clientId=clientId-StreamThread-238-consumer, groupId=appId] (Re-)joining
> group (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:491)
> [2019-02-12 07:02:17,278] INFO Cluster ID: J8uJhiTKQx-Y_i9LzT0iLg
> (org.apache.kafka.clients.Metadata:365)
> [2019-02-12 07:02:17,293] INFO Cluster ID: J8uJhiTKQx-Y_i9LzT0iLg
> (org.apache.kafka.clients.Metadata:365)
> [2019-02-12 07:02:17,301] INFO stream-thread [clientId-StreamThread-239]
> Shutting down (org.apache.kafka.streams.processor.internals.StreamThread:1206)
> [2019-02-12 07:02:17,301] INFO [Consumer
> clientId=clientId-StreamThread-239-restore-consumer, groupId=null]
> Unsubscribed all topics or patterns and assigned partitions
> (org.apache.kafka.clients.consumer.KafkaConsumer:1042)
> [2019-02-12 07:02:17,301] INFO stream-thread [clientId-StreamThread-238]
> Shutting down (org.apache.kafka.streams.processor.internals.StreamThread:1206)
> [2019-02-12 07:02:17,301] INFO [Consumer
> clientId=clientId-StreamThread-238-restore-consumer, groupId=null]
> Unsubscribed all topics or patterns and assigned partitions
> (org.apache.kafka.clients.consumer.KafkaConsumer:1042)
> [2019-02-12 07:02:17,302] INFO [Producer
> clientId=clientId-StreamThread-238-producer] Closing the Kafka producer with
> timeoutMillis = 9223372036854775807 ms.
> (org.apache.kafka.clients.producer.KafkaProducer:1139)
> [2019-02-12 07:02:17,301] INFO [Producer
> clientId=clientId-StreamThread-239-producer] Closing the Kafka producer with
> timeoutMillis = 9223372036854775807 ms.
> (org.apache.kafka.clients.producer.KafkaProducer:1139)
> [2019-02-12 07:02:17,863] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:18,766] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:19,769] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:20,872] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:21,775] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:22,678] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:23,882] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:24,885] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:25,888] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:26,991] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:28,095] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:28,998] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:29,901] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:31,004] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:32,108] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:33,311] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:34,515] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:35,718] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:36,921] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:37,924] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:38,927] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:40,029] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:41,232] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:42,235] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:43,337] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:44,340] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:45,442] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:46,444] WARN [AdminClient clientId=adminclient-233]
> Connection to node 0 (localhost/127.0.0.1:41539) could not be established.
> Broker may not be available. (org.apache.kafka.clients.NetworkClient:722)
> [2019-02-12 07:02:47,305] WARN [Consumer
> clientId=clientId-StreamThread-239-consumer, groupId=appId] Close timed out
> with 1 pending requests to coordinator, terminating client connections
> (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:800)
> [2019-02-12 07:02:47,307] INFO stream-thread [clientId-StreamThread-239]
> State transition from PENDING_SHUTDOWN to DEAD
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:47,307] INFO stream-thread [clientId-StreamThread-239]
> Shutdown complete
> (org.apache.kafka.streams.processor.internals.StreamThread:1226)
> [2019-02-12 07:02:47,308] WARN [Consumer
> clientId=clientId-StreamThread-238-consumer, groupId=appId] Close timed out
> with 1 pending requests to coordinator, terminating client connections
> (org.apache.kafka.clients.consumer.internals.AbstractCoordinator:800)
> [2019-02-12 07:02:47,313] INFO stream-thread [clientId-StreamThread-238]
> State transition from PENDING_SHUTDOWN to DEAD
> (org.apache.kafka.streams.processor.internals.StreamThread:214)
> [2019-02-12 07:02:47,313] INFO stream-thread [clientId-StreamThread-238]
> Shutdown complete
> (org.apache.kafka.streams.processor.internals.StreamThread:1226)
> [2019-02-12 07:02:47,315] INFO stream-client [clientId] State transition from
> PENDING_SHUTDOWN to NOT_RUNNING (org.apache.kafka.streams.KafkaStreams:263)
> [2019-02-12 07:02:47,315] INFO stream-client [clientId] Streams client
> stopped completely (org.apache.kafka.streams.KafkaStreams:899)
> [2019-02-12 07:02:47,316] INFO stream-client [clientId] Already in the
> pending shutdown state, wait to complete shutdown
> (org.apache.kafka.streams.KafkaStreams:849)
> [2019-02-12 07:02:47,316] INFO stream-client [clientId] Streams client
> stopped completely (org.apache.kafka.streams.KafkaStreams:899){quote}
>
> Note, that the instance goes from
> {quote}[2019-02-12 07:02:17,199] INFO stream-client [clientId] State
> transition from CREATED to REBALANCING
> (org.apache.kafka.streams.KafkaStreams:263){quote}
> to
> {quote}[2019-02-12 07:02:17,200] INFO stream-client [clientId] State
> transition from REBALANCING to PENDING_SHUTDOWN
> (org.apache.kafka.streams.KafkaStreams:263){quote}
> in the very beginning. It's unclear why this happens. Note, that the log
> before the copied snipped is unfortunately not complete (thank you Jenkins):
> {quote}...[truncated 1593438 chars]...{quote}
> Later, `AdminClient` seems to not be able to connect to the brokers (also
> unclear why) and the test times out. If the `AdminClient` issue is related to
> the first issue is unclear atm).
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
