strimzi-kafka-operator
strimzi-kafka-operator copied to clipboard
strimzi
Takes too long for KafkaUser to be ready
Describe the bug When creating Kafka users say 1-5 users it works just fine, KafkaUsers are in Ready status in no time. But when I try to create bulk KafkaUser - say 50 users at a time, some users can take almost 10 mins to be "Ready", so this means client cannot publish/consume messages using these KafkaUsers - wait can be very long as the number of KafkaUsers on a Kafka cluster increase.
To Reproduce Steps to reproduce the behavior:
-
To repro - you need 1. Kafka cluster, 1. topic already created.
-
Create 50 KafkaUsers on Strimzi Kafka cluster at the same time - via a script (I create it via K8 api)
-
Right away with in a minute trying to use all these users to publish/read from using these users and you will get Topic Authorization Failed, Group Authorization Failed errors, because users are not yet "Ready"
-
Create Custom Resource 'Kafka User' using the yaml below:
kind: KafkaUser
metadata:
name: cog-reader
labels:
strimzi.io/cluster: pod-kafka-cluster
spec:
authentication:
type: scram-sha-512
authorization:
type: simple
acls:
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Read
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Describe
- resource:
type: group
name: cog-group
patternType: literal
operation: Read
- Authorization simple, authentication SASL_SSL/SCRAM-SHA-512
- Apply 50 such users in parallel to Strimzi cluster.
- Check the logs of the user-operator and it is cluttered with TimeoutExceptions
2021-10-09 06:55:40 DEBUG KafkaAdminClient:815 - [AdminClient clientId=adminclient-1] Call(callName=describeAcls, deadlineMs=1633762539991, tries=1, nextAllowedTryMs=1633762540099) timed out at 1633762539999 after 1 attempt(s)
java.lang.Exception: TimeoutException: Timed out waiting to send the call. Call: describeAcls
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.failWithTimeout(KafkaAdminClient.java:816) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.fail(KafkaAdminClient.java:789) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$TimeoutProcessor.handleTimeouts(KafkaAdminClient.java:912) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.timeoutCallsToSend(KafkaAdminClient.java:993) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.processRequests(KafkaAdminClient.java:1301) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.run(KafkaAdminClient.java:1264) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2021-10-09 06:55:40 DEBUG KafkaAdminClient:815 - [AdminClient clientId=adminclient-1] Call(callName=alterUserScramCredentials, deadlineMs=1633762539992, tries=1, nextAllowedTryMs=1633762540099) timed out at 1633762539999 after 1 attempt(s)
java.lang.Exception: TimeoutException: Timed out waiting to send the call. Call: alterUserScramCredentials
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.failWithTimeout(KafkaAdminClient.java:816) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.fail(KafkaAdminClient.java:789) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$TimeoutProcessor.handleTimeouts(KafkaAdminClient.java:912) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.timeoutCallsToSend(KafkaAdminClient.java:993) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.processRequests(KafkaAdminClient.java:1301) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.run(KafkaAdminClient.java:1264) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
rg.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1633758992264, tries=1, nextAllowedTryMs=1633758992365) timed out at 1633758992265 after 1 attempt(s)
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeClientQuotas
2021-10-09 05:56:32 DEBUG StatusDiff:46 - Status differs: {"op":"add","path":"/conditions/0/reason","value":"TimeoutException"}
2021-10-09 05:56:32 DEBUG StatusDiff:48 - Desired Status path /conditions/0/reason has value "TimeoutException"
org.apache.kafka.common.errors.TimeoutException: Call(callName=describeClientQuotas, deadlineMs=1633758992264, tries=1, nextAllowedTryMs=1633758992365) timed out at 1633758992265 after 1 attempt(s)
Caused by: org.apache.kafka.common.errors.TimeoutException: Timed out waiting to send the call. Call: describeClientQuotas
java.lang.Exception: TimeoutException: Timed out waiting to send the call. Call: describeClientQuotas
java.lang.Exception: TimeoutException: Timed out waiting to send the call. Call: describeClientQuotas
java.lang.Exception: TimeoutException: Timed out waiting to send the call. Call: describeClientQuotas
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.failWithTimeout(KafkaAdminClient.java:816) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$Call.fail(KafkaAdminClient.java:789) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$TimeoutProcessor.handleTimeouts(KafkaAdminClient.java:912) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.timeoutCallsToSend(KafkaAdminClient.java:993) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.processRequests(KafkaAdminClient.java:1301) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.run(KafkaAdminClient.java:1264) [org.apache.kafka.kafka-clients-2.8.0.jar:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Expected behavior Creating Kafka user with ACL's should be a straightforward call and it should have deterministic output when 5 users are created or 50 users are created
Environment (please complete the following information):
-
Strimzi version: [e.g. main, 0.25.0]
-
Installation method:
- kubectl get ns kafka || kubectl create ns kafka
- helm repo add strimzi https://strimzi.io/charts/
- helm upgrade --install strimzi-kafka strimzi/strimzi-kafka-operator --version="0.25.0" -n kafka
-
Kubernetes cluster: EKS 1.18
-
Infrastructure: Amazon EKS
YAML files and logs Kafka -cluster yaml
apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
name: pod-kafka-cluster
namespace: kafka
spec:
kafka:
version: 2.8.0
replicas: 3
listeners:
- name: plain
port: 9092
tls: false
type: internal
- name: external
authentication:
type: scram-sha-512
port: 9094
tls: true
type: loadbalancer
authorization:
type: simple
config:
offsets.topic.replication.factor: 1
transaction.state.log.replication.factor: 1
transaction.state.log.min.isr: 1
log.message.format.version: "2.8"
storage:
type: persistent-claim
size: 50Gi
deleteClaim: true
zookeeper:
replicas: 3
storage:
type: persistent-claim
size: 50Gi
deleteClaim: true
entityOperator:
userOperator:
reconciliationIntervalSeconds: 157680000
logging:
type: inline
loggers:
rootLogger.level: DEBUG
topicOperator:
reconciliationIntervalSeconds: 157680000
logging:
type: inline
loggers:
rootLogger.level: DEBUG
Topic yaml
apiVersion: kafka.strimzi.io/v1beta2
kind: KafkaTopic
metadata:
name: pod-notifications
labels:
strimzi.io/cluster: pod-kafka-cluster
spec:
partitions: 1
replicas: 3
Publisher user (create multiple - this is just an example)
apiVersion: kafka.strimzi.io/v1beta2
kind: KafkaUser
metadata:
name: pod-agent-writer
labels:
strimzi.io/cluster: pod-kafka-cluster
spec:
authentication:
type: scram-sha-512
authorization:
type: simple
acls:
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Write
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Describe
Consumer - create multiple this is jus an example
apiVersion: kafka.strimzi.io/v1beta2
kind: KafkaUser
metadata:
name: cog-reader
labels:
strimzi.io/cluster: pod-kafka-cluster
spec:
authentication:
type: scram-sha-512
authorization:
type: simple
acls:
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Read
- resource:
type: topic
name: pod-notifications
patternType: literal
operation: Describe
- resource:
type: group
name: cog-group
patternType: literal
operation: Read
Additional context Use case: I have need to create Kafka. users/topics on demand, so I have a micro service that invokes K8's api that in-turn invoke Strimzi API's to create Kafka resources. topic operator works fine and topics are in ready status. KafkaUsers can take too long to be ready - and this causes some components that rely on this micro service to fail.
Earlier periodic reconciliation was causing too much issues, so I turned periodic reconciliation off. Now as the number of users have increased all those timeout errors are back. I don't know. if Kafka. Admin client is already busy and ignoring all the calls?
Any help here is appreciated. Any pointers,
I see the below exception in the broker logs
2021-10-09 18:23:06,696 INFO [ReplicaFetcher replicaId=1, leaderId=0, fetcherId=0] Error sending fetch request (sessionId=1689750346, epoch=70118) to node 0: (org.apache.kafka.clients.FetchSessionHandler) [ReplicaFetcherThread-0-0]
java.io.IOException: Client was shutdown before response was read
at org.apache.kafka.clients.NetworkClientUtils.sendAndReceive(NetworkClientUtils.java:109)
at kafka.server.ReplicaFetcherBlockingSend.sendRequest(ReplicaFetcherBlockingSend.scala:110)
at kafka.server.ReplicaFetcherThread.fetchFromLeader(ReplicaFetcherThread.scala:217)
at kafka.server.AbstractFetcherThread.processFetchRequest(AbstractFetcherThread.scala:317)
at kafka.server.AbstractFetcherThread.$anonfun$maybeFetch$3(AbstractFetcherThread.scala:141)
at kafka.server.AbstractFetcherThread.$anonfun$maybeFetch$3$adapted(AbstractFetcherThread.scala:140)
at scala.Option.foreach(Option.scala:437)
at kafka.server.AbstractFetcherThread.maybeFetch(AbstractFetcherThread.scala:140)
at kafka.server.AbstractFetcherThread.doWork(AbstractFetcherThread.scala:123)
at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:96)
is it possible the admin client in user-operator is timing out too soon before admin can actually respond?
I just tried with your configuration and the users were ready in range of seconds. I will do more testing to see if I can get the same error as you. // edit: With 500 Kafka Users I am getting these exceptions too.
I wonder if this has something to do with JVM memory footprint of the user-operator / or Kafka's memory foot print? I have used the default settings and have never changed it.
In my case it happens with very low number of users - which is a concern.
What is your version of Strimzi?
There are no default settings. You have to configure the memory and CPU requests in the Kafka CR for your use-case. Without that it might default either to some LimitRange settings or have no settings at all which means it has all and no resources depending on your cluster situation.
thanks @scholzj - (updating here for completeness) could you share the sample yaml example on how can I set CPU/MEM for Kafka cluster? I will try to play around with it. or if @sknot-rh could share what is his Kafka Configuration which works for 500 users within seconds, it will help me to fine tune my Kafka cluster settings.
https://github.com/strimzi/strimzi-kafka-operator/issues/4471 - I don't know if my issue is related to this - but I am following this thread - as I see my cluster also getting OOM killed now and then.
It is described in the docs => you just add the resources block with the appropriate settings to the YAML. This is my resource I use for development which should give you an idea:
apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
name: my-cluster
labels:
app: my-cluster
spec:
kafka:
replicas: 3
resources:
requests:
memory: 2Gi
cpu: 500m
limits:
memory: 2Gi
cpu: "1"
jvmOptions:
-Xms: 1024m
-Xmx: 1024m
listeners:
- name: plain
port: 9092
type: internal
tls: false
authentication:
type: scram-sha-512
- name: tls
port: 9093
type: internal
tls: true
authentication:
type: tls
authorization:
type: simple
config:
auto.create.topics.enable: "false"
offsets.topic.replication.factor: 3
transaction.state.log.replication.factor: 3
transaction.state.log.min.isr: 2
storage:
type: jbod
volumes:
- id: 0
type: persistent-claim
size: 100Gi
zookeeper:
replicas: 3
resources:
requests:
memory: 1Gi
cpu: "0.3"
limits:
memory: 1Gi
cpu: "0.5"
jvmOptions:
-Xms: 512m
-Xmx: 512m
storage:
type: persistent-claim
size: 100Gi
entityOperator:
topicOperator:
resources:
requests:
memory: 256Mi
cpu: "0.2"
limits:
memory: 256Mi
cpu: "0.5"
userOperator:
resources:
requests:
memory: 512Mi
cpu: "0.2"
limits:
memory: 512Mi
cpu: "0.5"
kafkaExporter:
resources:
requests:
memory: 256Mi
cpu: "0.1"
limits:
memory: 256Mi
cpu: "0.5"
You will need to adjust these for your use-cases.
@GarimaBathla I did further testing with 500 KafkaUsers. I did find out that each KafkaUser does require 5 AdminClient calls each reconciliation. That means high number of KUs is basically DDoSing the kafka brokers in the matter of AC requests. I did try to increase number of kafka brokers (3 -> 7) which improved the situation a bit, but there are still KUs which are not ready after long time. I think we should try to batch the requests to save some broker's load (@tombentley 's idea). What is your case for creating such a high number of KUs?
@sknot-rh -my use case for creating KU's on demand; my application supports multiple clients using same Kafka infrastructure. for each client, we need to setup topics/users with ACL's so each client can receive its own set of notifications based on its actions - say supporting multi-tenant DB applications.
Again in my use-case the load on brokers is pretty low - we send say 70 notifications/hr on a topic - and I might have 60 topics per cluster. but for each topic I have many consumers say 6 users - who consume from that topic per tenant.
My need is not 500, but say 300 total Kafka users, and I want to create 30 at a time.
@sknot-rh - I am surprised you only saw this problem with 500 KU's and not lower number. Could you share your Kafka cluster configuration - Like in above thread I think I have 2 problems - 1. I don't allocate enough resources to my kafka cluster - it has default Strimzi settings, 2 . I create on-demand resources that result in load on broker.
So I want to try your configuration/version as well. Thanks for your help.
I used the same configuration as you posted above. I think it is very flaky.
I think we should try to batch the requests to save some broker's load (@tombentley 's idea).
A good first step would be to explore avoid reconciling all the CRs at the same time (on the periodic reconciliation), instead spreading them evenly over the reconciliation interval. That would help with periodic reconciliations. It wouldn't help with the event-based reconciliations that happen when a whole bunch of CRs getting created, deleted or modified at the same time. For those we'd need batching.
I tried batching for quotas and I was able to get 340 ready KafkaUsers. For comparison, without batching I can get ~80 ready KafkaUsers.
@sknot-rh could you share more? How can I batch?
@tombentley for my usecase I have almost turned off periodic reconciliation all together - set it to 10 years time. But if batching works, I can test by turning it on.
I tested by increasing Kafka resources (CPU/Mem) from Strimzi default settings to 500m, 1G and also increase Strimzi user operators and topic operator to how much @scholzj has listed in the above example. None of these changes made any difference to the amount of time it takes to create custom resources;
I serialized creation of KU 1 user at a time and it turns out creation of a single KU takes 6 seconds - ( 6 seconds to get in ready status) , but if I create these users in parallel say 10 KU's at a time a single user can take around 25 seconds.
so this is not a resource issue, but indeed batching problem like it is listed above.
And if I turn on reconciliation, user-operator goes bonkers and is never able to get out of trouble, it is stuck in timeout exception loop.
@sknot-rh - could you please advice path forward? Would it be easy to do the batching of users and give me a new patch of strimzi?
truly appreciate all the help you all have provided.
here are the logs:
LOGS when creating single user at a time.
2021-10-13 00:43:49 INFO OperatorWatcher:38 - Reconciliation #2803(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): KafkaUser sys-ktest11-cogmanager-reader in namespace kafka was ADDED
2021-10-13 00:43:49 INFO AbstractOperator:219 - Reconciliation #2803(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): KafkaUser sys-ktest11-cogmanager-reader will be checked for creation or modification
2021-10-13 00:43:53 INFO OperatorWatcher:38 - Reconciliation #2804(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): KafkaUser sys-ktest11-cogmanager-reader in namespace kafka was MODIFIED
2021-10-13 00:43:53 INFO CrdOperator:113 - Reconciliation #2803(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): Status of KafkaUser sys-ktest11-cogmanager-reader in namespace kafka has been updated
2021-10-13 00:43:53 INFO AbstractOperator:466 - Reconciliation #2803(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): reconciled
2021-10-13 00:43:53 INFO AbstractOperator:219 - Reconciliation #2804(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): KafkaUser sys-ktest11-cogmanager-reader will be checked for creation or modification
2021-10-13 00:43:54 INFO OperatorWatcher:38 - Reconciliation #2805(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): KafkaUser sys-ktest11-pod-agent-writer in namespace kafka was ADDED
2021-10-13 00:43:54 INFO AbstractOperator:219 - Reconciliation #2805(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): KafkaUser sys-ktest11-pod-agent-writer will be checked for creation or modification
2021-10-13 00:43:57 INFO AbstractOperator:466 - Reconciliation #2804(watch) KafkaUser(kafka/sys-ktest11-cogmanager-reader): reconciled
2021-10-13 00:44:00 INFO OperatorWatcher:38 - Reconciliation #2806(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): KafkaUser sys-ktest11-pod-agent-writer in namespace kafka was MODIFIED
2021-10-13 00:44:00 INFO CrdOperator:113 - Reconciliation #2805(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): Status of KafkaUser sys-ktest11-pod-agent-writer in namespace kafka has been updated
2021-10-13 00:44:00 INFO AbstractOperator:466 - Reconciliation #2805(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): reconciled
2021-10-13 00:44:00 INFO AbstractOperator:219 - Reconciliation #2806(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): KafkaUser sys-ktest11-pod-agent-writer will be checked for creation or modification
2021-10-13 00:44:02 INFO OperatorWatcher:38 - Reconciliation #2807(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): KafkaUser acc-ktest11-password-rotation-writer in namespace kafka was ADDED
2021-10-13 00:44:02 INFO AbstractOperator:219 - Reconciliation #2807(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): KafkaUser acc-ktest11-password-rotation-writer will be checked for creation or modification
2021-10-13 00:44:04 INFO AbstractOperator:466 - Reconciliation #2806(watch) KafkaUser(kafka/sys-ktest11-pod-agent-writer): reconciled
2021-10-13 00:44:08 INFO OperatorWatcher:38 - Reconciliation #2808(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): KafkaUser acc-ktest11-password-rotation-writer in namespace kafka was MODIFIED
2021-10-13 00:44:08 INFO CrdOperator:113 - Reconciliation #2807(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): Status of KafkaUser acc-ktest11-password-rotation-writer in namespace kafka has been updated
2021-10-13 00:44:08 INFO AbstractOperator:466 - Reconciliation #2807(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): reconciled
2021-10-13 00:44:08 INFO AbstractOperator:219 - Reconciliation #2808(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): KafkaUser acc-ktest11-password-rotation-writer will be checked for creation or modification
2021-10-13 00:44:09 INFO OperatorWatcher:38 - Reconciliation #2809(watch) KafkaUser(kafka/sys-ktest11-password-reader): KafkaUser sys-ktest11-password-reader in namespace kafka was ADDED
2021-10-13 00:44:09 INFO AbstractOperator:219 - Reconciliation #2809(watch) KafkaUser(kafka/sys-ktest11-password-reader): KafkaUser sys-ktest11-password-reader will be checked for creation or modification
2021-10-13 00:44:12 INFO AbstractOperator:466 - Reconciliation #2808(watch) KafkaUser(kafka/acc-ktest11-password-rotation-writer): reconciled
2021-10-13 00:44:16 INFO OperatorWatcher:38 - Reconciliation #2810(watch) KafkaUser(kafka/sys-ktest11-password-reader): KafkaUser sys-ktest11-password-reader in namespace kafka was MODIFIED
2021-10-13 00:44:16 INFO CrdOperator:113 - Reconciliation #2809(watch) KafkaUser(kafka/sys-ktest11-password-reader): Status of KafkaUser sys-ktest11-password-reader in namespace kafka has been updated
2021-10-13 00:44:16 INFO AbstractOperator:466 - Reconciliation #2809(watch) KafkaUser(kafka/sys-ktest11-password-reader): reconciled
2021-10-13 00:44:16 INFO AbstractOperator:219 - Reconciliation #2810(watch) KafkaUser(kafka/sys-ktest11-password-reader): KafkaUser sys-ktest11-password-reader will be checked for creation or modification
2021-10-13 00:44:17 INFO OperatorWatcher:38 - Reconciliation #2811(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): KafkaUser sys-ktest12-cogmanager-reader in namespace kafka was ADDED
2021-10-13 00:44:17 INFO AbstractOperator:219 - Reconciliation #2811(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): KafkaUser sys-ktest12-cogmanager-reader will be checked for creation or modification
2021-10-13 00:44:19 INFO AbstractOperator:466 - Reconciliation #2810(watch) KafkaUser(kafka/sys-ktest11-password-reader): reconciled
2021-10-13 00:44:23 INFO OperatorWatcher:38 - Reconciliation #2812(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): KafkaUser sys-ktest12-cogmanager-reader in namespace kafka was MODIFIED
2021-10-13 00:44:23 INFO CrdOperator:113 - Reconciliation #2811(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): Status of KafkaUser sys-ktest12-cogmanager-reader in namespace kafka has been updated
2021-10-13 00:44:23 INFO AbstractOperator:466 - Reconciliation #2811(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): reconciled
2021-10-13 00:44:23 INFO AbstractOperator:219 - Reconciliation #2812(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): KafkaUser sys-ktest12-cogmanager-reader will be checked for creation or modification
2021-10-13 00:44:23 INFO OperatorWatcher:38 - Reconciliation #2813(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): KafkaUser sys-ktest12-pod-agent-writer in namespace kafka was ADDED
2021-10-13 00:44:23 INFO AbstractOperator:219 - Reconciliation #2813(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): KafkaUser sys-ktest12-pod-agent-writer will be checked for creation or modification
2021-10-13 00:44:26 INFO AbstractOperator:466 - Reconciliation #2812(watch) KafkaUser(kafka/sys-ktest12-cogmanager-reader): reconciled
2021-10-13 00:44:29 INFO CrdOperator:113 - Reconciliation #2813(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): Status of KafkaUser sys-ktest12-pod-agent-writer in namespace kafka has been updated
2021-10-13 00:44:29 INFO OperatorWatcher:38 - Reconciliation #2814(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): KafkaUser sys-ktest12-pod-agent-writer in namespace kafka was MODIFIED
2021-10-13 00:44:29 INFO AbstractOperator:466 - Reconciliation #2813(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): reconciled
2021-10-13 00:44:29 INFO AbstractOperator:219 - Reconciliation #2814(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): KafkaUser sys-ktest12-pod-agent-writer will be checked for creation or modification
2021-10-13 00:44:30 INFO OperatorWatcher:38 - Reconciliation #2815(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): KafkaUser acc-ktest12-password-rotation-writer in namespace kafka was ADDED
2021-10-13 00:44:30 INFO AbstractOperator:219 - Reconciliation #2815(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): KafkaUser acc-ktest12-password-rotation-writer will be checked for creation or modification
2021-10-13 00:44:35 INFO AbstractOperator:466 - Reconciliation #2814(watch) KafkaUser(kafka/sys-ktest12-pod-agent-writer): reconciled
2021-10-13 00:44:36 INFO OperatorWatcher:38 - Reconciliation #2816(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): KafkaUser acc-ktest12-password-rotation-writer in namespace kafka was MODIFIED
2021-10-13 00:44:36 INFO CrdOperator:113 - Reconciliation #2815(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): Status of KafkaUser acc-ktest12-password-rotation-writer in namespace kafka has been updated
2021-10-13 00:44:36 INFO AbstractOperator:466 - Reconciliation #2815(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): reconciled
2021-10-13 00:44:36 INFO AbstractOperator:219 - Reconciliation #2816(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): KafkaUser acc-ktest12-password-rotation-writer will be checked for creation or modification
2021-10-13 00:44:37 INFO OperatorWatcher:38 - Reconciliation #2817(watch) KafkaUser(kafka/sys-ktest12-password-reader): KafkaUser sys-ktest12-password-reader in namespace kafka was ADDED
2021-10-13 00:44:37 INFO AbstractOperator:219 - Reconciliation #2817(watch) KafkaUser(kafka/sys-ktest12-password-reader): KafkaUser sys-ktest12-password-reader will be checked for creation or modification
2021-10-13 00:44:39 INFO AbstractOperator:466 - Reconciliation #2816(watch) KafkaUser(kafka/acc-ktest12-password-rotation-writer): reconciled
2021-10-13 00:44:43 INFO OperatorWatcher:38 - Reconciliation #2818(watch) KafkaUser(kafka/sys-ktest12-password-reader): KafkaUser sys-ktest12-password-reader in namespace kafka was MODIFIED
2021-10-13 00:44:43 INFO CrdOperator:113 - Reconciliation #2817(watch) KafkaUser(kafka/sys-ktest12-password-reader): Status of KafkaUser sys-ktest12-password-reader in namespace kafka has been updated
2021-10-13 00:44:43 INFO AbstractOperator:466 - Reconciliation #2817(watch) KafkaUser(kafka/sys-ktest12-password-reader): reconciled
2021-10-13 00:44:43 INFO AbstractOperator:219 - Reconciliation #2818(watch) KafkaUser(kafka/sys-ktest12-password-reader): KafkaUser sys-ktest12-password-reader will be checked for creation or modification
2021-10-13 00:44:45 INFO OperatorWatcher:38 - Reconciliation #2819(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): KafkaUser sys-ktest13-cogmanager-reader in namespace kafka was ADDED
2021-10-13 00:44:45 INFO AbstractOperator:219 - Reconciliation #2819(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): KafkaUser sys-ktest13-cogmanager-reader will be checked for creation or modification
2021-10-13 00:44:50 INFO AbstractOperator:466 - Reconciliation #2818(watch) KafkaUser(kafka/sys-ktest12-password-reader): reconciled
2021-10-13 00:44:51 INFO OperatorWatcher:38 - Reconciliation #2820(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): KafkaUser sys-ktest13-cogmanager-reader in namespace kafka was MODIFIED
2021-10-13 00:44:51 INFO CrdOperator:113 - Reconciliation #2819(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): Status of KafkaUser sys-ktest13-cogmanager-reader in namespace kafka has been updated
2021-10-13 00:44:51 INFO AbstractOperator:466 - Reconciliation #2819(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): reconciled
2021-10-13 00:44:51 INFO AbstractOperator:219 - Reconciliation #2820(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): KafkaUser sys-ktest13-cogmanager-reader will be checked for creation or modification
2021-10-13 00:44:51 INFO OperatorWatcher:38 - Reconciliation #2821(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): KafkaUser sys-ktest13-pod-agent-writer in namespace kafka was ADDED
2021-10-13 00:44:51 INFO AbstractOperator:219 - Reconciliation #2821(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): KafkaUser sys-ktest13-pod-agent-writer will be checked for creation or modification
2021-10-13 00:44:56 INFO AbstractOperator:466 - Reconciliation #2820(watch) KafkaUser(kafka/sys-ktest13-cogmanager-reader): reconciled
2021-10-13 00:44:58 INFO OperatorWatcher:38 - Reconciliation #2822(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): KafkaUser sys-ktest13-pod-agent-writer in namespace kafka was MODIFIED
2021-10-13 00:44:58 INFO CrdOperator:113 - Reconciliation #2821(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): Status of KafkaUser sys-ktest13-pod-agent-writer in namespace kafka has been updated
2021-10-13 00:44:58 INFO AbstractOperator:466 - Reconciliation #2821(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): reconciled
2021-10-13 00:44:58 INFO AbstractOperator:219 - Reconciliation #2822(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): KafkaUser sys-ktest13-pod-agent-writer will be checked for creation or modification
2021-10-13 00:45:00 INFO OperatorWatcher:38 - Reconciliation #2823(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): KafkaUser acc-ktest13-password-rotation-writer in namespace kafka was ADDED
2021-10-13 00:45:00 INFO AbstractOperator:219 - Reconciliation #2823(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): KafkaUser acc-ktest13-password-rotation-writer will be checked for creation or modification
2021-10-13 00:45:01 INFO AbstractOperator:466 - Reconciliation #2822(watch) KafkaUser(kafka/sys-ktest13-pod-agent-writer): reconciled
2021-10-13 00:45:06 INFO OperatorWatcher:38 - Reconciliation #2824(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): KafkaUser acc-ktest13-password-rotation-writer in namespace kafka was MODIFIED
2021-10-13 00:45:06 INFO CrdOperator:113 - Reconciliation #2823(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): Status of KafkaUser acc-ktest13-password-rotation-writer in namespace kafka has been updated
2021-10-13 00:45:06 INFO AbstractOperator:466 - Reconciliation #2823(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): reconciled
2021-10-13 00:45:06 INFO AbstractOperator:219 - Reconciliation #2824(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): KafkaUser acc-ktest13-password-rotation-writer will be checked for creation or modification
2021-10-13 00:45:07 INFO OperatorWatcher:38 - Reconciliation #2825(watch) KafkaUser(kafka/sys-ktest13-password-reader): KafkaUser sys-ktest13-password-reader in namespace kafka was ADDED
2021-10-13 00:45:07 INFO AbstractOperator:219 - Reconciliation #2825(watch) KafkaUser(kafka/sys-ktest13-password-reader): KafkaUser sys-ktest13-password-reader will be checked for creation or modification
2021-10-13 00:45:10 INFO AbstractOperator:466 - Reconciliation #2824(watch) KafkaUser(kafka/acc-ktest13-password-rotation-writer): reconciled
2021-10-13 00:45:14 INFO OperatorWatcher:38 - Reconciliation #2826(watch) KafkaUser(kafka/sys-ktest13-password-reader): KafkaUser sys-ktest13-password-reader in namespace kafka was MODIFIED
2021-10-13 00:45:14 INFO CrdOperator:113 - Reconciliation #2825(watch) KafkaUser(kafka/sys-ktest13-password-reader): Status of KafkaUser sys-ktest13-password-reader in namespace kafka has been updated
2021-10-13 00:45:14 INFO AbstractOperator:466 - Reconciliation #2825(watch) KafkaUser(kafka/sys-ktest13-password-reader): reconciled
2021-10-13 00:45:14 INFO AbstractOperator:219 - Reconciliation #2826(watch) KafkaUser(kafka/sys-ktest13-password-reader): KafkaUser sys-ktest13-password-reader will be checked for creation or modification
2021-10-13 00:45:15 INFO OperatorWatcher:38 - Reconciliation #2827(watch) KafkaUser(kafka/sys-ktest14-cogmanager-reader): KafkaUser sys-ktest14-cogmanager-reader in namespace kafka was ADDED
2021-10-13 00:45:15 INFO AbstractOperator:219 - Reconciliation #2827(watch) KafkaUser(kafka/sys-ktest14-cogmanager-reader): KafkaUser sys-ktest14-cogmanager-reader will be checked for creation or modification
2021-10-13 00:45:18 INFO AbstractOperator:466 - Reconciliation #2826(watch) KafkaUser(kafka/sys-ktest13-password-reader): reconciled
I tested by increasing Kafka resources (CPU/Mem) from Strimzi default settings to 500m, 1G and also increase Strimzi user operators and topic operator to how much @scholzj has listed in the above example. None of these changes made any difference to the amount of time it takes to create custom resources;
Well, that was an example of how to configure the resources. As it was clearly sad there, you need to adjust the actual values. The exact resources there are used for development as mentioned there, so nowhere near 300 users. That said, I never had any issues with using it with a single digit number of users.
I created a PoC. The merging of reconciliation result for TLS and SCRAM user needs to be improved https://github.com/sknot-rh/strimzi/commit/8719e87d8987801295a0b091ae60feb28ed7aec1#diff-9c42d639637a67deb0200524f18b23daf141adeddc47f4d8d04145c76ed97995R61
@scholzj - thanks! yes I understood that was just a dev setting. I don't create 300 users at a time, I only create say 30 users at a time and I changed the way I create a user - forcing it to create a single Kafka User at a time instead of batching to create 30 users at a time and it takes 6 seconds per user to be ready - logs were attached. so 6 seconds on one user * 30 = 180 seconds ~ 3 mins. so I realized it is not a resource issue , it is batching issue, if we can create all 30 users with few seconds that would be ideal.
I have actually increased the memory of user-operator to
reconciliationIntervalSeconds: 157680000
resources:
limits:
cpu: "0.5"
memory: 1024Mi
requests:
cpu: "0.5"
memory: 1024Mi
but it was same results as when I used default settings.
@sknot-rh - thank you! how can I go about testing this fix in my env? I use helm to install strimzi - can this be shared as a patch via helm repo?
@sknot-rh - if a patch release is not possible, could you please share by when can this be fixed in strimzi?
To add a data point, I created 1100 users with 30 seconds sleep in between in a script and only 14 of them got into "Ready" status and the rest after an overnight wait still got stuck in "NotReady" status. "status": { "conditions": [ { "lastTransitionTime": "2021-11-10T00:45:53.514612Z", "message": "Call(callName=alterUserScramCredentials, deadlineMs=1636505138052, tries=1, nextAllowedTryMs=1636505138209) timed out at 1636505138109 after 1 attempt(s)", "reason": "TimeoutException", "status": "True", "type": "NotReady" } ],
The question is there seems to be a "TimeoutException" occurring. Is there a config parameter we can adjust to get the new users unstuck into "Ready" status?
there seems to be a limit of the number of users that can be created otherwise Broker will start reporting TimeoutException for the new users created. I think I am seeing issues starting from 200 or so users.
Thanks. @GarimaBathla @sknot-rh
Yeah, creating the users with some delays does not help IMO. The issue is, that AdminClient sends numberOfUsers*5 requests (200 users means 1000 requests) to brokers each reconciliation. So after there is a certain amount of users, the brokers are basically DDoS-ed and only a few of the users get reconciled and thus Ready in the status. With my patch above I was able to get 400 users ready however, we need to devise a better way how to batch users reconciliation.
Hi all, is any solution? I have same problem with 36 users only. What is going on? strimzi operator version: 0.25.0
@sknot-rh @scholzj -
I am still struggling with this problem, I have implemented some work-arounds in my code such that I don't do any parallelization and create one kafka user at a time, and even then I see there are times it can take 40-50 seconds sometimes for a kafka user to be in ready status.
I noticed today that for each kafka user user-operator is making few calls, and one of them is describe client quotas - in my case this is redundant call as I have not enabled any quotas at all.
Is it possible for user-operator to not make some calls all the time?
2022-02-19 13:06:37 DEBUG KafkaAdminClient:815 - [AdminClient clientId=adminclient-1] Call(callName=describeClientQuotas, deadlineMs=1645275997049, tries=2, nextAllowedTryMs=1645275997166) timed out at 1645275997066 after 2 attempt(s) java.lang.Exception: DisconnectException: Cancelled describeClientQuotas request with correlation id 5374 due to node 0 being disconnected at org.apache.kafka.clients.admin.KafkaAdminClient$Call.failWithTimeout(KafkaAdminClient.java:816) [org.apache.kafka.kafka-clients-2.8.0.jar:?] at org.apache.kafka.clients.admin.KafkaAdminClient$Call.fail(KafkaAdminClient.java:789) [org.apache.kafka.kafka-clients-2.8.0.jar:?] at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.handleResponses(KafkaAdminClient.java:1183) [org.apache.kafka.kafka-clients-2.8.0.jar:?] at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.processRequests(KafkaAdminClient.java:1341) [org.apache.kafka.kafka-clients-2.8.0.jar:?] at org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.run(KafkaAdminClient.java:1264) [org.apache.kafka.kafka-clients-2.8.0.jar:?] at java.lang.Thread.run(Thread.java:829) [?:?]
When your user has no quitas set, the operator has to make sure there are no quotas configured for it in Kafka either. So these calles are required.
well when operator is making sure no quotas are configured in kafka either, there is an assumption that changes are done to kafka without operator's knowledge. the Kafka-user Kubernetes custom resource should be enough for user-operator to find out if there is any quota or not and if it is configured only then make describeClientQuotas call
Does that not sound right?
I am impacted because in my case it is an unnecessary call being made and slowing down and having cascade effect on future kafka users.
there is an assumption that changes are done to kafka without operator's knowledge
Correct, that assumption is there and it is valid assumption. The operator has to ensure that it does not happen.
But it is not the only reason for this. The operator itself is stateless -> it depends on the state of the custom resources. So it does not know whether the user never used quotas or whether the quotas were just removed.
So no, it is not an unnecessary call.
I see - custom resource might have changed - current version vs previous version, so it is ensuring with the kafka.
I wish this bug would be resolved soon, is there any timeline you can share - it is really slowing down the system. my latest calls to create 2 kafka users took 2 mins.
@scholzj and. @sknot-rh @tombentley -
I am looking at the user-operator logs and the code and I see the below behavior -
there are 2 sets of duplicate calls being made to Kafka broker via admin-client when a Kafka user is added to the system.
KafkaUserOperator.CreateOrUpdate 1. describeClientQuotas - for both tlsUser and ScramUser - kafkaUserQuotasOperator.reconcile method is being invoked and these 2 executions check independently if the user has any quotas inside KafkaUserQuotasOperator.java exists method.
boolean exists(Reconciliation reconciliation, String username) throws Exception { return describeUserQuotas(reconciliation, username) != null; }
kafkaUserQuotasOperator.reconcile(reconciliation, KafkaUserModel.getTlsUserName(userName), finalTlsQuotas),
kafkaUserQuotasOperator.reconcile(reconciliation, KafkaUserModel.getScramUserName(userName),
finalScramOrNoneQuotas))),
2. describeAcls - describeAcls is invoked for both tlsUser and scramUser - though a user can be only TLS or Scram and not both. Inside SimpleAclOperator.reconcile method, both method executions invoke describeAcl -
And I think this adds up to the 4 calls
I don't know why AdminClient is not able to connect to the Kafka brokers and times out but if there are the same calls made with the exact same parameters, I think these can be merged.
@scholzj - is there a way for user-operator configuration to override this value
https://github.com/strimzi/strimzi-kafka-operator/blob/3b3a419dd17cac0458b2a96d3d2b6f9d47683ebe/operator-common/src/main/java/io/strimzi/operator/common/DefaultAdminClientProvider.java#L86
AdminClientConfig.REQUEST_TIMEOUT_MS_CONFIG - it is set to 10 seconds currently.
I don't think you can configure the Admin client. As for the calls for TLS / SCRAM users, this is needed to handle changes tot he authentication type.