Timed out waiting to send the call. Call: alterUserScramCredentials

[chary1112004]

Hi,

We are facing the issue message in argocd with below information

java.util.concurrent.CompletionException: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: alterUserScramCredentials

Configuration of server

apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
  labels:
    app.kubernetes.io/instance: kafka-dev-kafka-cluster
  name: kafka-cluster
  namespace: kafka-dev
spec:
  entityOperator:
    topicOperator: {}
    userOperator: {}
  kafka:
    authorization:
      type: simple
    config:
      auto.create.topics.enable: 'false'
      default.replication.factor: 1
      inter.broker.protocol.version: '3.4'
      min.insync.replicas: 1
      num.io.threads: 8
      num.network.threads: 5
      num.partitions: 1
      num.replica.fetchers: 1
      offsets.topic.replication.factor: 1
      replica.lag.time.max.ms: 30000
      socket.receive.buffer.bytes: 102400
      socket.request.max.bytes: 104857600
      socket.send.buffer.bytes: 102400
      transaction.state.log.min.isr: 1
      transaction.state.log.replication.factor: 1
      unclean.leader.election.enable: true
      zookeeper.session.timeout.ms: 18000
    listeners:
      - authentication:
          type: scram-sha-512
        name: tls
        port: 9093
        tls: true
        type: internal
    metricsConfig:
      type: jmxPrometheusExporter
      valueFrom:
        configMapKeyRef:
          key: kafka-metrics-config.yml
          name: kafka-metrics
    replicas: 1
    resources:
      requests:
        cpu: 200m
        memory: 2000Mi
    storage:
      type: jbod
      volumes:
        - class: kafka-dev-sc-gp2
          deleteClaim: false
          id: 0
          size: 30Gi
          type: persistent-claim
    version: 3.4.0
  kafkaExporter:
    groupRegex: .*
    resources:
      requests:
        cpu: 30m
        memory: 20Mi
    topicRegex: .*
  zookeeper:
    metricsConfig:
      type: jmxPrometheusExporter
      valueFrom:
        configMapKeyRef:
          key: zookeeper-metrics-config.yml
          name: kafka-metrics
    replicas: 1
    resources:
      requests:
        cpu: 25m
        memory: 400Mi
    storage:
      class: kafka-dev-sc-gp2
      deleteClaim: false
      size: 30Gi
      type: persistent-claim

Log:

2023-11-06 22:00:27 INFO  AdminMetadataManager:235 - [AdminClient clientId=adminclient-1] Metadata update failed
org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: fetchMetadata
2023-11-06 22:00:58 INFO  NetworkClient:819 - [AdminClient clientId=adminclient-1] Disconnecting from node 0 due to socket connection setup timeout. The timeout value is 35347 ms.
2023-11-06 22:00:58 INFO  AdminMetadataManager:235 - [AdminClient clientId=adminclient-1] Metadata update failed
org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: fetchMetadata
2023-11-06 22:00:58 WARN  AclCache:70 - Failed to load ACLs
java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: describeAcls
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.AclCache.loadCache(AclCache.java:54) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: describeAcls
2023-11-06 22:00:58 ERROR AbstractCache:149 - AclCache failed to update
java.lang.RuntimeException: Failed to load ACLs
	at io.strimzi.operator.user.operator.cache.AclCache.loadCache(AclCache.java:71) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: describeAcls
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.AclCache.loadCache(AclCache.java:54) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	... 7 more
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting for a node assignment. Call: describeAcls
2023-11-06 22:01:03 INFO  NetworkClient:797 - [AdminClient clientId=adminclient-1] Disconnecting from node 0 due to request timeout.
2023-11-06 22:01:03 INFO  NetworkClient:341 - [AdminClient clientId=adminclient-1] Cancelled in-flight DESCRIBE_CLIENT_QUOTAS request with correlation id 240179 due to node 0 being disconnected (elapsed time since creation: 464ms, elapsed time since send: 464ms, request timeout: 460ms)
2023-11-06 22:01:03 WARN  QuotasCache:62 - Failed to load Quotas
java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1699308063392, tries=1, nextAllowedTryMs=1699308063608) timed out at 1699308063508 after 1 attempt(s)
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.QuotasCache.loadCache(QuotasCache.java:51) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1699308063392, tries=1, nextAllowedTryMs=1699308063608) timed out at 1699308063508 after 1 attempt(s)
Caused by: org.apache.kafka.common.errors.DisconnectException: Cancelled describeClientQuotas request with correlation id 240179 due to node 0 being disconnected
2023-11-06 22:01:03 ERROR AbstractCache:149 - QuotasCache failed to update
java.lang.RuntimeException: Failed to load Quotas
	at io.strimzi.operator.user.operator.cache.QuotasCache.loadCache(QuotasCache.java:63) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1699308063392, tries=1, nextAllowedTryMs=1699308063608) timed out at 1699308063508 after 1 attempt(s)
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.QuotasCache.loadCache(QuotasCache.java:51) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	... 7 more
Caused by: org.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1699308063392, tries=1, nextAllowedTryMs=1699308063608) timed out at 1699308063508 after 1 attempt(s)
Caused by: org.apache.kafka.common.errors.DisconnectException: Cancelled describeClientQuotas request with correlation id 240179 due to node 0 being disconnected
2023-11-06 22:01:03 WARN  ScramShaCredentialsCache:54 - Failed to load SCRAM-SHA credentials
java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeUserScramCredentials
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.ScramShaCredentialsCache.loadCache(ScramShaCredentialsCache.java:49) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeUserScramCredentials
2023-11-06 22:01:03 ERROR AbstractCache:149 - ScramShaCredentialsCache failed to update
java.lang.RuntimeException: Failed to load SCRAM-SHA credentials
	at io.strimzi.operator.user.operator.cache.ScramShaCredentialsCache.loadCache(ScramShaCredentialsCache.java:55) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at io.strimzi.operator.user.operator.cache.AbstractCache.updateCache(AbstractCache.java:146) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.util.concurrent.ExecutionException: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeUserScramCredentials
	at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:396) ~[?:?]
	at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2096) ~[?:?]
	at org.apache.kafka.common.internals.KafkaFutureImpl.get(KafkaFutureImpl.java:180) ~[org.apache.kafka.kafka-clients-3.4.0.jar:?]
	at io.strimzi.operator.user.operator.cache.ScramShaCredentialsCache.loadCache(ScramShaCredentialsCache.java:49) ~[io.strimzi.user-operator-0.34.0.jar:0.34.0]
	... 7 more
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeUserScramCredentials

Any solution to resolve this issue would be very much appreciated! Thanks!

[scholzj]

I think your Kafka configuration is heavily underresourced - especially when it comes to CPU. So you should make sure all the components have sufficient CPU. E.g. not 25m CPU for ZooKeeper, 200m CPU for Kafka is also not much. You also do not have configured any resources for the User Operator. CPU starvation in any of the compoenents would definitely lead to the timeouts you are seeing.

[chary1112004]

Hi @scholzj,
the configuration is cpu/memory request (not cpu/memory limit) that is used when pod is located initially. I will try to test more and monitor to see if it lack of resource for kafka. Thanks!

[scholzj]

It is also the only thing that is guaranteed. So if that is all it gets, it will for sure have issues.