You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by "Colin P. McCabe (JIRA)" <ji...@apache.org> on 2019/05/20 18:26:00 UTC
[jira] [Resolved] (KAFKA-7921) Instable KafkaStreamsTest
[ 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)