Topic operator sends CREATE_TOPICS requests every reconciliation

[arnitolog]

after the upgrade from 0.19.0 to 0.21.1 I noticed that there a lot of CREATE_TOPICS sends to Kafka Cluster. For every such request, the Kafka cluster responds with TOPIC_ALREADY_EXISTS.
I enabled Debug log level on Topic Operator and see that it definitely sends CREATE_TOPICS for every existing topic every reconciliation. Please find the attached log. What is also interesting that TO tries to create these topics with numPartitions=1, replicationFactor=1 regardless of the real values (in my case all topics have numPartitions=12, replicationFactor=3 )
TO1.txt
seems it doesn't cause any issues so far, but probably it makes sense to re-view this behavior to reduce the load on the cluster.
The attached log is for a brand new cluster and brand new topics

[scholzj]

@tombentley @sknot-rh Any ideas?

[sknot-rh]

Hm, that is strange. The line below is suspicious

2021-03-26 08:52:44,92750 DEBUG [vert.x-eventloop-thread-1] K8sTopicWatcher:72 - 5|initial kafka test-topic3: Concurrent modification in kube: new version 27281

however on the line 72 of K8sTopicWatcher is no logging. I also tried to run TO and create few topics and I am not getting the messages in the log that you do. Are you sure you do use the image with right version? (sorry for dumb question, but it is really weird)

[arnitolog]

here is a values.yaml for the Kafka operator chart. Everything pretty standard except that we use a private docker registry

[arnitolog]

values.yaml
values.yaml.txt

[arnitolog]

also, here is my Kafka resource and Topics:
topics.yaml.txt
kafka.txt

[sknot-rh]

Ok, logging comes from LogContext class, sorry. @tombentley do you think this is something that could be added by

strimzi-kafka-operator/topic-operator/src/main/java/io/strimzi/operator/topic/KafkaImpl.java

Line 70 in cdd5ad4

public Future<Boolean> topicExists(TopicName topicName) {

?

[oleksandr-balyshyn]

Something that can be related to this discussion:
I have fresh instalation of TO (image: quay.io/strimzi/operator:0.22.0) and i observe a similar behaviour. that Topic operator sends CREATE_TOPICS requests every reconciliation

TO tries to create these topics with numPartitions=1, replicationFactor=1 regardless of the real values (in my case all topics have numPartitions=12, replicationFactor=3 )

In my case the default ones should be following numPartitions=6, replicationFactor=1

TO

2021-08-25 10:55:24 INFO  TopicOperator:537 - 181|periodic kafka __consumer_offsets|106371: Reconciling topic __consumer_offsets, k8sTopic:nonnull, kafkaTopic:nonnull, privateTopic:nonnull
2021-08-25 10:55:24 DEBUG TopicOperator:597 - 181|periodic kafka __consumer_offsets|106371: 3 way diff
2021-08-25 10:55:24 DEBUG TopicOperator:688 - 181|periodic kafka __consumer_offsets|106371: topicStore->kafkaTopic: TopicDiff{differences={}}
2021-08-25 10:55:24 DEBUG TopicOperator:690 - 181|periodic kafka __consumer_offsets|106371: topicStore->k8sTopic: TopicDiff{differences={}}
2021-08-25 10:55:24 DEBUG TopicOperator:699 - 181|periodic kafka __consumer_offsets|106371: Diffs do not conflict, merged diff: TopicDiff{differences={}}
2021-08-25 10:55:24 INFO  TopicOperator:701 - 181|periodic kafka __consumer_offsets|106371: All three topics are identical
2021-08-25 10:55:24 INFO  TopicOperator:1417 - Success reconciling KafkaTopic default/consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a
2021-08-25 10:55:24 DEBUG TopicOperator:1353 - __consumer_offsets reconcile success -> succeeded
2021-08-25 10:55:24 DEBUG TopicOperator:474 - 181|periodic kafka __consumer_offsets|106371: Executing handler for action reconcile-from-kafka on topic __consumer_offsets
2021-08-25 10:55:24 DEBUG TopicOperator:1006 - 181|periodic kafka __consumer_offsets|106371: There is a KafkaTopic to set status on, rv=106371, generation=1
2021-08-25 10:55:24 DEBUG StatusDiff:43 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2021-08-25T10:55:24.575120Z"}
2021-08-25 10:55:24 DEBUG TopicOperator:491 - 181|periodic kafka __consumer_offsets|106371: Lock released
2021-08-25 10:55:24 DEBUG TopicOperator:448 - 181|periodic kafka __consumer_offsets|106371: Removing last waiter reconcile-from-kafka
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG CustomResource:157 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2021-08-25 10:55:24 DEBUG K8sTopicWatcher:72 - 182|periodic kube consumer-offsets---84e7a678d08f4bd226872e5cdd4eb527fadc1c6a: Concurrent modification in kube: new version 10637
2021-08-25 10:55:24 DEBUG KafkaAdminClient:1094 - [AdminClient clientId=adminclient-1] Sending CreateTopicsRequestData(topics=[CreatableTopic(name='__consumer_offsets', numPartitions=1, replicationFactor=1, assignments=[], configs=[])], timeoutMs=30000, validateOnly=true) to 192.168.0.138:9092 (id: 1001 rack: null). correlationId=259
2021-08-25 10:55:24 DEBUG NetworkClient:522 - [AdminClient clientId=adminclient-1] Sending CREATE_TOPICS request with header RequestHeader(apiKey=CREATE_TOPICS, apiVersion=2, clientId=adminclient-1, correlationId=259) and timeout 30000 to node 1001: {topics=[{name=__consumer_offsets,num_partitions=1,replication_factor=1,assignments=[],configs=[]}],timeout_ms=30000,validate_only=true}

Logs from Kafka server

[2021-08-25 10:55:24,474] INFO [Admin Manager on Broker 1001]: Error processing create topic request for topic __consumer_offsets with arguments (numPartitions=1, replicationFactor=1, replicasAssignments={}, configs={}) (kafka.server.AdminManager)
org.apache.kafka.common.errors.TopicExistsException: Topic '__consumer_offsets' already exists

[scholzj]

In my case the default ones should be following numPartitions=6, replicationFactor=1

What do you mean with default ones? The operator will be following most probably the KafkaTopic resource, so it matters what is written there.

[oleksandr-balyshyn]

Topics were created manually before

In my case the default ones should be following numPartitions=6, replicationFactor=1

What do you mean with default ones? The operator will be following most probably the KafkaTopic resource, so it matters what is written there.

[scholzj]

I also guess that the validateOnly=true means that this does not really create anything. @tombentley or @sknot-rh might know why does it make this call. But I guess the comment in the source code explains it as just a more reliable way to find out if the topic already exists:

strimzi-kafka-operator/topic-operator/src/main/java/io/strimzi/operator/topic/KafkaImpl.java

Line 70 in 3b3a419

public Future<Boolean> topicExists(Reconciliation reconciliation, TopicName topicName) {

[oleksandr-balyshyn]

I also guess that the validateOnly=true means that this does not really create anything. @tombentley or @sknot-rh might know why does it make this call. But I guess the comment in the source code explains it as just a more reliable way to find out if the topic already exists:

strimzi-kafka-operator/topic-operator/src/main/java/io/strimzi/operator/topic/KafkaImpl.java

Line 70 in 3b3a419

public Future<Boolean> topicExists(Reconciliation reconciliation, TopicName topicName) {

thanks