[Bug]: Finalizing JUnit 5 test case with Kafka Streams and Spring Boot takes several minutes #8948
-
ModuleKafka Testcontainers version1.19.8 Using the latest Testcontainers version?Yes Host OSMacOS, Linux, Windows Host ArchARM, x86 Docker versionThis is my local setup with Podman. In the pipeline we use Docker and other colleagues use Docker Desktop where the issue also happens.
Client: Docker Engine - Community
Version: 27.0.3
API version: 1.41 (downgraded from 1.46)
Go version: go1.22.4
Git commit: 7d4bcd863a
Built: Fri Jun 28 14:56:30 2024
OS/Arch: darwin/arm64
Context: default
Server: linux/arm64/fedora-40
Podman Engine:
Version: 5.0.3
APIVersion: 5.0.3
Arch: arm64
BuildTime: 2024-05-10T02:00:00+02:00
Experimental: false
GitCommit:
GoVersion: go1.22.2
KernelVersion: 6.8.8-300.fc40.aarch64
MinAPIVersion: 4.0.0
Os: linux
Conmon:
Version: conmon version 2.1.10, commit:
Package: conmon-2.1.10-1.fc40.aarch64
OCI Runtime (crun):
Version: crun version 1.14.4
commit: a220ca661ce078f2c37b38c92e66cf66c012d9c1
rundir: /run/crun
spec: 1.0.0
+SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +LIBKRUN +WASM:wasmedge +YAJL
Package: crun-1.14.4-1.fc40.aarch64
Engine:
Version: 5.0.3
API version: 1.41 (minimum version 1.24)
Go version: go1.22.2
Git commit:
Built: Fri May 10 02:00:00 2024
OS/Arch: linux/arm64
Experimental: false What happened?We're running a Spring Boot project with Kafka Streams. We have one integration test (using It seems like the Kafka container is stopped before the Spring context is shutdown. And the Spring Context is waiting for Kafka to become available before shutting down. Relevant log output### The following 20 lines are printed repeatedly for several minutes
[11:00:35.147] [INFO] [org.apache.kafka.clients.NetworkClient] - [Consumer clientId=<our-consumer-group>-StreamThread-1-consumer, groupId=streams.notification-report-selector.notification-repartitioner] Node 1 disconnected.
[11:00:35.147] [WARN] [org.apache.kafka.clients.NetworkClient] - [Consumer clientId=<our-consumer-group>-StreamThread-1-consumer, groupId=streams.notification-report-selector.notification-repartitioner] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:35.218] [INFO] [org.apache.kafka.clients.NetworkClient] - [AdminClient clientId=<our-consumer-group>-admin] Node 1 disconnected.
[11:00:35.218] [WARN] [org.apache.kafka.clients.NetworkClient] - [AdminClient clientId=<our-consumer-group>-admin] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:35.350] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-3] Node 1 disconnected.
[11:00:35.350] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-3] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:35.591] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=<our-consumer-group>-StreamThread-1-producer] Node 1 disconnected.
[11:00:35.591] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=<our-consumer-group>-StreamThread-1-producer] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:35.782] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-1] Node 1 disconnected.
[11:00:35.782] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-1] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.072] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-2] Node 1 disconnected.
[11:00:36.072] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-2] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.148] [INFO] [org.apache.kafka.clients.NetworkClient] - [Consumer clientId=<our-consumer-group>-StreamThread-1-consumer, groupId=[<our-consumer-group>]] Node 1 disconnected.
[11:00:36.148] [WARN] [org.apache.kafka.clients.NetworkClient] - [Consumer clientId=<our-consumer-group>-StreamThread-1-consumer, groupId=[<our-consumer-group>]] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.221] [INFO] [org.apache.kafka.clients.NetworkClient] - [AdminClient clientId=<our-consumer-group>-admin] Node 1 disconnected.
[11:00:36.221] [WARN] [org.apache.kafka.clients.NetworkClient] - [AdminClient clientId=<our-consumer-group>-admin] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.370] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-3] Node 1 disconnected.
[11:00:36.371] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-3] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.544] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=<our-consumer-group>-StreamThread-1-producer] Node 1 disconnected.
[11:00:36.544] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=<our-consumer-group>-StreamThread-1-producer] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.731] [INFO] [org.apache.kafka.clients.admin.internals.AdminMetadataManager] - [AdminClient clientId=<our-consumer-group>-admin] Metadata update failed
org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: fetchMetadata
[11:00:36.804] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-1] Node 1 disconnected.
[11:00:36.804] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-1] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
[11:00:36.925] [INFO] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-2] Node 1 disconnected.
[11:00:36.925] [WARN] [org.apache.kafka.clients.NetworkClient] - [Producer clientId=producer-2] Connection to node 1 (localhost/127.0.0.1:32772) could not be established. Node may not be available.
### The following log lines are only printed once at when the tests are finalized
Error: 1:00:36.961] [ERROR] [org.apache.kafka.streams.processor.internals.TaskExecutor] - stream-thread [<our-consumer-group>-StreamThread-1] Committing task(s) 0_1 failed.
org.apache.kafka.common.errors.TimeoutException: Timeout of 60000ms expired before successfully committing offsets {notification.managed-1=OffsetAndMetadata{offset=5, leaderEpoch=null, metadata='AgAAAZCWstBN'}}
Error: 1:00:36.961] [ERROR] [org.apache.kafka.streams.processor.internals.TaskManager] - stream-thread [<our-consumer-group>-StreamThread-1] Exception caught while committing tasks [TaskId: 0_1
ProcessorTopology:
Notifications:
topics: [notification.managed]
children: [Event-Type-Filter]
Event-Type-Filter:
children: [Key-Selector]
Key-Selector:
children: [Notifications-By-Id]
Notifications-By-Id:
topic: StaticTopicNameExtractor(notification.by-id)
Partitions [notification.managed-1]
]
org.apache.kafka.common.errors.TimeoutException: Timeout of 60000ms expired before successfully committing offsets {notification.managed-1=OffsetAndMetadata{offset=5, leaderEpoch=null, metadata='AgAAAZCWstBN'}}
[11:00:36.961] [INFO] [org.apache.kafka.streams.processor.internals.StreamTask] - stream-thread [<our-consumer-group>-StreamThread-1] task [0_0] Suspended from RUNNING
[11:00:36.962] [INFO] [org.apache.kafka.streams.processor.internals.RecordCollectorImpl] - stream-thread [<our-consumer-group>-StreamThread-1] stream-task [0_0] Closing record collector dirty
[11:00:36.962] [INFO] [org.apache.kafka.streams.processor.internals.StreamTask] - stream-thread [<our-consumer-group>-StreamThread-1] task [0_0] Closed dirty
[11:00:36.962] [INFO] [org.apache.kafka.streams.processor.internals.StreamTask] - stream-thread [<our-consumer-group>-StreamThread-1] task [0_1] Suspended from RUNNING
[11:00:36.963] [INFO] [org.apache.kafka.streams.processor.internals.RecordCollectorImpl] - stream-thread [<our-consumer-group>-StreamThread-1] stream-task [0_1] Closing record collector dirty
[11:00:36.963] [INFO] [org.apache.kafka.streams.processor.internals.StreamTask] - stream-thread [<our-consumer-group>-StreamThread-1] task [0_1] Closed dirty
[11:00:36.963] [INFO] [org.apache.kafka.clients.producer.KafkaProducer] - [Producer clientId=<our-consumer-group>-StreamThread-1-producer] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
[11:00:36.966] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics scheduler closed
[11:00:36.966] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.metrics.JmxReporter
[11:00:36.966] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.telemetry.internals.ClientTelemetryReporter
[11:00:36.966] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics reporters closed
[11:00:36.967] [INFO] [org.apache.kafka.common.utils.AppInfoParser] - App info kafka.producer for <our-consumer-group>-StreamThread-1-producer unregistered
Error: 1:00:36.967] [ERROR] [org.apache.kafka.streams.processor.internals.StreamThread] - stream-thread [<our-consumer-group>-StreamThread-1] Failed to close task manager due to the following error:
org.apache.kafka.common.errors.TimeoutException: Timeout of 60000ms expired before successfully committing offsets {notification.managed-1=OffsetAndMetadata{offset=5, leaderEpoch=null, metadata='AgAAAZCWstBN'}}
[11:00:36.967] [INFO] [org.apache.kafka.clients.consumer.internals.LegacyKafkaConsumer] - [Consumer clientId=<our-consumer-group>-StreamThread-1-restore-consumer, groupId=null] Unsubscribed all topics or patterns and assigned partitions
[11:00:36.967] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics scheduler closed
[11:00:36.967] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.metrics.JmxReporter
[11:00:36.967] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.telemetry.internals.ClientTelemetryReporter
[11:00:36.967] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics reporters closed
[11:00:36.970] [INFO] [org.apache.kafka.common.utils.AppInfoParser] - App info kafka.consumer for <our-consumer-group>-StreamThread-1-consumer unregistered
[11:00:36.970] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics scheduler closed
[11:00:36.970] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.metrics.JmxReporter
[11:00:36.970] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.telemetry.internals.ClientTelemetryReporter
[11:00:36.970] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics reporters closed
[11:00:36.972] [INFO] [org.apache.kafka.common.utils.AppInfoParser] - App info kafka.consumer for <our-consumer-group>-StreamThread-1-restore-consumer unregistered
[11:00:36.973] [INFO] [org.apache.kafka.streams.processor.internals.StreamThread] - stream-thread [<our-consumer-group>-StreamThread-1] State transition from PENDING_SHUTDOWN to DEAD
[11:00:36.973] [INFO] [org.apache.kafka.streams.processor.internals.StreamThread] - stream-thread [<our-consumer-group>-StreamThread-1] Shutdown complete
[11:00:36.973] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Shutdown 1 stream threads complete
[11:00:36.973] [INFO] [org.apache.kafka.common.utils.AppInfoParser] - App info kafka.admin.client for <our-consumer-group>-admin unregistered
[11:00:36.973] [INFO] [org.apache.kafka.clients.admin.internals.AdminMetadataManager] - [AdminClient clientId=<our-consumer-group>-admin] Metadata update failed
org.apache.kafka.common.errors.TimeoutException: The AdminClient thread has exited. Call: fetchMetadata
[11:00:36.973] [INFO] [org.apache.kafka.clients.admin.KafkaAdminClient] - [AdminClient clientId=<our-consumer-group>-admin] Timed out 1 remaining operation(s) during close.
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics scheduler closed
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.metrics.JmxReporter
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics reporters closed
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics scheduler closed
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Closing reporter org.apache.kafka.common.metrics.JmxReporter
[11:00:36.984] [INFO] [org.apache.kafka.common.metrics.Metrics] - Metrics reporters closed
[11:00:36.985] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] State transition from PENDING_SHUTDOWN to NOT_RUNNING
[11:00:36.985] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client stopped completely
[11:00:37.006] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal NOT_RUNNING state, all resources are closed and the client has stopped.
[11:00:37.007] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal NOT_RUNNING state, all resources are closed and the client has stopped.
[11:00:37.007] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal NOT_RUNNING state, all resources are closed and the client has stopped.
[11:00:37.007] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal NOT_RUNNING state, all resources are closed and the client has stopped.
[11:00:37.011] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.011] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.011] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.011] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.016] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.016] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.016] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.016] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.028] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.028] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.029] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.029] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.044] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.044] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.044] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped.
[11:00:37.044] [INFO] [org.apache.kafka.streams.KafkaStreams] - stream-client [<our-consumer-group>] Streams client is already in the terminal ERROR state, all resources are closed and the client has stopped. Additional InformationThe issue seems to be mitigated to some extend (we wait < 10 seconds for the test to finalize) if we start the container manually in the |
Beta Was this translation helpful? Give feedback.
Replies: 8 comments 4 replies
-
Does anyone have a clue why this can happen? Or how I can investigate further? |
Beta Was this translation helpful? Give feedback.
-
Hi, do you have a project to reproduce it? |
Beta Was this translation helpful? Give feedback.
-
I'll try to provide you with a minimal example today. |
Beta Was this translation helpful? Give feedback.
-
Sorry for the slow response. Here is the example repo: https://github.com/MarvinVaillant/demo-long-kafka-streams-teardown/tree/main |
Beta Was this translation helpful? Give feedback.
-
Here you'll also find a short video that shows the issue: |
Beta Was this translation helpful? Give feedback.
-
@MarvinVaillant thanks for providing the example but I am not able to run the project. It fails because of |
Beta Was this translation helpful? Give feedback.
-
i'm really sorry. I was fiddeling around with the code to get some more insights. Could you please pull the latest commits? |
Beta Was this translation helpful? Give feedback.
-
Thanks for updating it. I'm moving this to a discussion because It is not an issue itself. Testcontainers is creating, running the container and killing it. However, in order to close the context you should call |
Beta Was this translation helpful? Give feedback.
I was digging a little bit more on this and I ended up doing this
AfterAllCallback
implementationKafkaStreamsCallback
at test class level@ExtendWith(DemoLongKafkaStreamsTeardownApplicationTests.KafkaStreamsCallback.class)