Matthias J. Sax created KAFKA-7921:
--------------------------------------
Summary: Instable KafkaStreamsTest
Key: KAFKA-7921
URL: https://issues.apache.org/jira/browse/KAFKA-7921
Project: Kafka
Issue Type: Bug
Components: streams, unit tests
Reporter: Matthias J. Sax
{{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)
