Uploaded image for project: 'Kafka'
  1. Kafka
  2. KAFKA-7921

Instable KafkaStreamsTest

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Critical
    • Resolution: Fixed
    • 2.3.0
    • 2.4.0
    • streams, unit tests

    Description

      KafkaStreamsTest failed multiple times, eg,

      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)

      or

      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)

       
      The preserved logs are as follows:

      [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)

       
      Note, that the instance goes from

      [2019-02-12 07:02:17,199] INFO stream-client [clientId] State transition from CREATED to REBALANCING (org.apache.kafka.streams.KafkaStreams:263)

      to

      [2019-02-12 07:02:17,200] INFO stream-client [clientId] State transition from REBALANCING to PENDING_SHUTDOWN (org.apache.kafka.streams.KafkaStreams:263)

      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):

      ...[truncated 1593438 chars]...

      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).

      Attachments

        Issue Links

          links to

          Web Link GitHub Pull Request #6262

          Activity

            People

              Unassigned Unassigned
              mjsax Matthias J. Sax
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: