search

strimzi / strimzi-kafka-operator

Apache Kafka® running on Kubernetes
https://strimzi.io/
Apache License 2.0
4.8k stars 1.28k forks source link

[Bug]: Password in secret keeps updating every few minutes #8552

Closed kmcrawford closed 1 year ago

kmcrawford commented 1 year ago

Bug Description

When working with a topic the password in the secret created by a KafkaUser manifest is changing every few minutes.

Steps to reproduce

Create a KafkaUser manifest:

apiVersion: kafka.strimzi.io/v1beta2
kind: KafkaUser
metadata:
  name: my-user
  namespace: kafka
  labels:
    strimzi.io/cluster: my-kafka-cluster
spec:
  authentication:
    type: scram-sha-512
  authorization:
    type: simple
    acls:
      - resource:
          type: topic
          name: "my-topic"
          patternType: literal
        operations:
          - All
        host: "*"
      - resource:
          type: group
          name: "my-topic-consumer"
          patternType: literal
        operations:
          - All
        host: "*"

If I add the below to the authorization the password no longer self updates.

    password:
      valueFrom:
        secretKeyRef:
          name: my-user
          key: password

Expected behavior

I'm seeing the password be updated in the secret every few minutes.

I do see a bunch of errors in the logs for the user-operator:

2023-05-23 18:44:16 ERROR InformerUtils:29 - Caught exception in the Secret informer which is started
io.fabric8.kubernetes.client.WatcherException: Could not process websocket message
    at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onError(WatcherWebSocketListener.java:51) ~[io.fabric8.kubernetes-client-6.6.1.jar:?]
    at io.fabric8.kubernetes.client.jdkhttp.JdkWebSocketImpl$ListenerAdapter.onError(JdkWebSocketImpl.java:85) ~[io.fabric8.kubernetes-httpclient-jdk-6.6.1.jar:?]
    at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.processError(WebSocketImpl.java:508) ~[java.net.http:?]
    at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.run(WebSocketImpl.java:462) ~[java.net.http:?]
    at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
    at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
    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.net.SocketException: Connection reset

Strimzi version

strimzi-kafka-operator-0.35.0

Kubernetes version

Kubernetes 1.25

Installation method

helm strimzi-kafka-operator-0.35.0

Infrastructure

AKS

Configuration files and logs

apiVersion: kafka.strimzi.io/v1beta2
kind: Kafka
metadata:
  name: my-kafka-cluster
  namespace: kafka
spec:
  kafka:
    version: 3.4.0          
    replicas: 3
    logging: 
      type: inline
      loggers:
        kafka.root.logger.level: "WARN"
    resources: 
      requests:
        cpu: "2"
      limits:
        memory: 16Gi        
    readinessProbe: 
      initialDelaySeconds: 15
      timeoutSeconds: 5
    livenessProbe:
      initialDelaySeconds: 15
      timeoutSeconds: 5    
    jvmOptions: 
      -Xms: 12g
      -Xmx: 12g
    listeners: 
      - name: plain 
        port: 9092 
        type: internal 
        tls: false
        authentication: 
          type: scram-sha-512
      - name: external 
        port: 9094
        type: ingress
        tls: true
        authentication: 
          type: scram-sha-512
        configuration:
          class: kafka-internal
          bootstrap:
            host: kafka-crs-staging.myhost.com
          brokers:
          - broker: 0
            host: kafka-crs-staging-0.myhost.com
          - broker: 1
            host: kafka-crs-staging-1.myhost.com
          - broker: 2
            host: kafka-crs-staging-2.myhost.com
          brokerCertChainAndKey:
            secretName: ingress-gateway-tlscerts
            certificate: tls.crt
            key: tls.key            

    authorization:
      type: simple
      superUsers: 
        - my-super-user
    config: 
      auto.create.topics.enable: "false"
      offsets.topic.replication.factor: 3
      transaction.state.log.replication.factor: 3
      transaction.state.log.min.isr: 2
      default.replication.factor: 3
      min.insync.replicas: 2
      inter.broker.protocol.version: "3.4"
    storage: 
      type: persistent-claim 
      size: 100Gi 
      class: managed-premium-retain
    rack:
      topologyKey: topology.kubernetes.io/zone
  zookeeper:
    replicas: 3 
    logging: 
      type: inline
      loggers:
        zookeeper.root.logger: "WARN"
    resources:
      requests:
        memory: 1Gi
        cpu: "2"
      limits:
        memory: 2Gi        
    jvmOptions:
      -Xms: 756m
      -Xmx: 756m
    storage:
      type: persistent-claim
      size: 10Gi
      class: managed-premium-retain
  entityOperator:
    template:
      pod:
        tolerations:
        - effect: NoSchedule
          key: app
          operator: Equal
          value: redis  
    topicOperator:
      watchedNamespace: kafka
      reconciliationIntervalSeconds: 60
      logging: 
        type: inline
        loggers:
          rootLogger.level: "WARN"
      resources:
        requests:
          memory: 512Mi
          cpu: "1"
        limits:
          memory: 512Mi
          cpu: "1"
    userOperator:
      watchedNamespace: kafka
      reconciliationIntervalSeconds: 60
      logging: 
        type: inline
        loggers:
          rootLogger.level: "WARN"
      resources:
        requests:
          memory: 512Mi
          cpu: "1"
        limits:
          memory: 512Mi
          cpu: "1"
  kafkaExporter:
    groupRegex: ".*" 
    topicRegex: ".*" 
    resources: 
      requests:
        cpu: 200m
        memory: 64Mi
      limits:
        cpu: 500m
        memory: 128Mi
    logging: warn 
    enableSaramaLogging: true
    readinessProbe: 
      initialDelaySeconds: 15
      timeoutSeconds: 5
    livenessProbe: 
      initialDelaySeconds: 15
      timeoutSeconds: 5  
  cruiseControl: {}

Additional context

No response

scholzj commented 1 year ago

Please share the full log, ideally at a debug level. This is not happening in other clusters, so it is likely environment related.

scholzj commented 1 year ago

This error:

2023-05-23 18:44:16 ERROR InformerUtils:29 - Caught exception in the Secret informer which is started
io.fabric8.kubernetes.client.WatcherException: Could not process websocket message
    at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onError(WatcherWebSocketListener.java:51) ~[io.fabric8.kubernetes-client-6.6.1.jar:?]
    at io.fabric8.kubernetes.client.jdkhttp.JdkWebSocketImpl$ListenerAdapter.onError(JdkWebSocketImpl.java:85) ~[io.fabric8.kubernetes-httpclient-jdk-6.6.1.jar:?]
    at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.processError(WebSocketImpl.java:508) ~[java.net.http:?]
    at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.run(WebSocketImpl.java:462) ~[java.net.http:?]
    at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
    at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
    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.net.SocketException: Connection reset

Suggests issues in communication with your API server. So that is possibly related to it. So you should also check the networking, your API server etc.

kmcrawford commented 1 year ago

This error:

2023-05-23 18:44:16 ERROR InformerUtils:29 - Caught exception in the Secret informer which is started
io.fabric8.kubernetes.client.WatcherException: Could not process websocket message
  at io.fabric8.kubernetes.client.dsl.internal.WatcherWebSocketListener.onError(WatcherWebSocketListener.java:51) ~[io.fabric8.kubernetes-client-6.6.1.jar:?]
  at io.fabric8.kubernetes.client.jdkhttp.JdkWebSocketImpl$ListenerAdapter.onError(JdkWebSocketImpl.java:85) ~[io.fabric8.kubernetes-httpclient-jdk-6.6.1.jar:?]
  at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.processError(WebSocketImpl.java:508) ~[java.net.http:?]
  at jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask.run(WebSocketImpl.java:462) ~[java.net.http:?]
  at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) ~[java.net.http:?]
  at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230) ~[java.net.http:?]
  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.net.SocketException: Connection reset

Suggests issues in communication with your API server. So that is possibly related to it. So you should also check the networking, your API server etc.

Thanks, this is managed AKS, I guess we can open a ticket with Microsoft.

kmcrawford commented 1 year ago

@scholzj I'll get debug turned on to see have more insight. I do think some error handling should be added to prevent an api or network issue from updating a password. This could cause catastrophic issues if this happened in a production environment.

kmcrawford commented 1 year ago

@scholzj DEBUG Logs: there is a lot of logs but I can see po-review-test-user password changing

2023-05-23 19:44:54 DEBUG KafkaUserOperator:475 - Reconciliation #14577(timer) KafkaUser(kafka/po-review-test-user): Secret po-review-test-user in namespace kafka already exists and cannot be created. It will be updated instead
2023-05-23 19:44:54 DEBUG AbstractBatchReconciler:92 - ScramShaCredentialsBatchReconciler: Processing batch of 3 records in the BatchReconciler
2023-05-23 19:44:54 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=alterUserScramCredentials, deadlineMs=1684871134752, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-23 19:44:54 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[62, -35, 86, 31, -30, -87, 18, -34, 127, -63, -98, 104, -30, 46, 70, 51, -118, -66, 15, 37, 112, -91, -26, 28, 8, 45, -67, -10, -91, 9, -28, -71, -61, -62, 8, 1, -84, 111, -120, 3, -57, -71, 8, -123, 105, 111, -33, -81, 65, 71, 26, 15, 84, 110, -36, -82, 4, -32, -97, -53, 3, 116, 105, 113]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=87967, timeoutMs=10000
2023-05-23 19:44:54 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending ALTER_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=87967, headerVersion=2) and timeout 10000 to node 2: AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[62, -35, 86, 31, -30, -87, 18, -34, 127, -63, -98, 104, -30, 46, 70, 51, -118, -66, 15, 37, 112, -91, -26, 28, 8, 45, -67, -10, -91, 9, -28, -71, -61, -62, 8, 1, -84, 111, -120, 3, -57, -71, 8, -123, 105, 111, -33, -81, 65, 71, 26, 15, 84, 110, -36, -82, 4, -32, -97, -53, 3, 116, 105, 113]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])])
2023-05-23 19:44:54 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received ALTER_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=87967, headerVersion=2): AlterUserScramCredentialsResponseData(throttleTimeMs=0, results=[AlterUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='')])
2023-05-23 19:44:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #14578(timer) KafkaUser(kafka/ui-user): SCRAM-SHA credentials reconciliation for user ui-user succeeded
2023-05-23 19:44:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #14577(timer) KafkaUser(kafka/po-review-test-user): SCRAM-SHA credentials reconciliation for user po-review-test-user succeeded
...
2023-05-23 19:46:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::po-review-test-user
2023-05-23 19:46:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::ui-user is not in use anymore and will be removed
kmcrawford commented 1 year ago

Here you can see this running every minute: 'Loading request password from Kubernetes Secret po-review-user'

image
scholzj commented 1 year ago

So, can you share the full log? So far, nothing in the screenshots or snippets you showed is unexpected apart from the connection issue on the websocket.

kmcrawford commented 1 year ago

During this time I didn't not see any Websocket errors, but the password did update: 

2023-05-24 14:09:53 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937433606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104895, timeoutMs=10000
2023-05-24 14:09:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104895, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:09:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104895, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:09:53 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:09:53 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937433669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104896, timeoutMs=10000
2023-05-24 14:09:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104896, headerVersion=2) and timeout 10000 to node 2: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:09:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104896, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:09:53 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:09:53 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937433685, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104897, timeoutMs=10000
2023-05-24 14:09:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104897, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:09:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104897, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:09:53 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:09:53 DEBUG DefaultSharedIndexInformer:232 - Checking for resync at interval for kafka.strimzi.io/v1beta2/namespaces/kafka/kafkausers
2023-05-24 14:09:53 DEBUG DefaultSharedIndexInformer:232 - Checking for resync at interval for v1/namespaces/kafka/secrets
2023-05-24 14:09:53 DEBUG DefaultSharedIndexInformer:235 - Resync running for v1/namespaces/kafka/secrets
2023-05-24 14:09:53 INFO  UserController:135 - Secret test-user in namespace kafka was MODIFIED
2023-05-24 14:09:53 DEBUG ControllerQueue:53 - Enqueueing KafkaUser test-user in namespace kafka
2023-05-24 14:09:53 INFO  UserController:135 - Secret ui-user in namespace kafka was MODIFIED
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::test-user
2023-05-24 14:09:53 DEBUG ControllerQueue:53 - Enqueueing KafkaUser ui-user in namespace kafka
2023-05-24 14:09:53 INFO  UserControllerLoop:99 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): KafkaUser will be reconciled
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::ui-user
2023-05-24 14:09:53 INFO  UserControllerLoop:99 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): KafkaUser will be reconciled
2023-05-24 14:09:53 DEBUG KafkaUserOperator:218 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): Deleting User test-user from namespace kafka
2023-05-24 14:09:53 DEBUG KafkaUserOperator:248 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Updating User ui-user in namespace kafka
2023-05-24 14:09:53 DEBUG KafkaUserModel:370 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Re-using password which already exists
2023-05-24 14:09:53 DEBUG SimpleAclOperator:78 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:53 DEBUG ScramCredentialsOperator:83 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Upserting SCRAM-SHA credentials for user ui-user
2023-05-24 14:09:53 DEBUG SimpleAclOperator:78 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:53 DEBUG QuotasOperator:71 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:53 DEBUG QuotasOperator:71 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:53 DEBUG QuotasOperator:71 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:53 DEBUG QuotasOperator:71 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:53 DEBUG SimpleAclOperator:78 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:53 DEBUG SimpleAclOperator:89 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): 3 expected Acl rules and 3 existing Acl rules -> Reconciling rules
2023-05-24 14:09:53 DEBUG SimpleAclOperator:188 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Requesting update of ACLs for user ui-user
2023-05-24 14:09:53 DEBUG ResourceDiff:57 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/creationTimestamp"}
2023-05-24 14:09:53 DEBUG ResourceDiff:57 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/managedFields"}
2023-05-24 14:09:53 DEBUG ResourceDiff:57 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/resourceVersion"}
2023-05-24 14:09:53 DEBUG ResourceDiff:57 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/uid"}
2023-05-24 14:09:53 DEBUG KafkaUserOperator:431 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Secret kafka/ui-user exist, and is identical
2023-05-24 14:09:53 INFO  UserControllerLoop:120 - Reconciliation #18607(watch) KafkaUser(kafka/test-user): reconciled
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::test-user
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::test-user is not in use anymore and will be removed
2023-05-24 14:09:53 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-2: Waiting for next event from work queue
2023-05-24 14:09:53 DEBUG AbstractBatchReconciler:92 - ScramShaCredentialsBatchReconciler: Processing batch of 1 records in the BatchReconciler
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=alterUserScramCredentials, deadlineMs=1684937433756, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:09:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64])]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104898, timeoutMs=10000
2023-05-24 14:09:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending ALTER_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104898, headerVersion=2) and timeout 10000 to node 2: AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64])])
2023-05-24 14:09:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received ALTER_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104898, headerVersion=2): AlterUserScramCredentialsResponseData(throttleTimeMs=0, results=[AlterUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='')])
2023-05-24 14:09:53 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): SCRAM-SHA credentials reconciliation for user ui-user succeeded
2023-05-24 14:09:53 DEBUG ScramCredentialsOperator:110 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): Updated SCRAM credentials for user ui-user
2023-05-24 14:09:53 INFO  UserControllerLoop:120 - Reconciliation #18608(watch) KafkaUser(kafka/ui-user): reconciled
2023-05-24 14:09:53 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:09:53.774444390Z"}
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::ui-user
2023-05-24 14:09:53 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::ui-user is not in use anymore and will be removed
2023-05-24 14:09:53 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-40: Waiting for next event from work queue
2023-05-24 14:09:54 INFO  UserController:258 - Triggering periodic reconciliation of KafkaUser resources for namespace kafka
2023-05-24 14:09:54 DEBUG QuotasOperator:207 - Searching for Users with any quotas
2023-05-24 14:09:54 DEBUG SimpleAclOperator:312 - Searching for Users with any ACL rules
2023-05-24 14:09:54 DEBUG SimpleAclOperator:329 - Adding user po-review-test-user to Set of users with ACLs
2023-05-24 14:09:54 DEBUG SimpleAclOperator:329 - Adding user ui-user to Set of users with ACLs
2023-05-24 14:09:54 DEBUG SimpleAclOperator:329 - Adding user po-review-user to Set of users with ACLs
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:169 - Listing all users with SCRAM credentials
2023-05-24 14:09:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:09:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser po-review-user in namespace kafka
2023-05-24 14:09:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser po-review-test-user in namespace kafka
2023-05-24 14:09:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser ui-user in namespace kafka
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::po-review-user
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::po-review-test-user
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::ui-user
2023-05-24 14:09:54 INFO  UserControllerLoop:99 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): KafkaUser will be reconciled
2023-05-24 14:09:54 INFO  UserControllerLoop:99 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): KafkaUser will be reconciled
2023-05-24 14:09:54 INFO  UserControllerLoop:99 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): KafkaUser will be reconciled
2023-05-24 14:09:54 DEBUG KafkaUserOperator:248 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Updating User po-review-user in namespace kafka
2023-05-24 14:09:54 DEBUG KafkaUserOperator:248 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Updating User ui-user in namespace kafka
2023-05-24 14:09:54 DEBUG KafkaUserOperator:248 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Updating User po-review-test-user in namespace kafka
2023-05-24 14:09:54 DEBUG KafkaUserModel:370 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Re-using password which already exists
2023-05-24 14:09:54 DEBUG KafkaUserModel:376 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Generating user password
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Upserting SCRAM-SHA credentials for user ui-user
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Upserting SCRAM-SHA credentials for user po-review-test-user
2023-05-24 14:09:54 DEBUG SimpleAclOperator:78 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:89 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): 3 expected Acl rules and 3 existing Acl rules -> Reconciling rules
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:188 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Requesting update of ACLs for user ui-user
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:78 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:89 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): 1 expected Acl rules and 1 existing Acl rules -> Reconciling rules
2023-05-24 14:09:54 DEBUG KafkaUserOperator:442 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Secret kafka/po-review-test-user does not exist, creating it
2023-05-24 14:09:54 DEBUG SimpleAclOperator:188 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Requesting update of ACLs for user po-review-test-user
2023-05-24 14:09:54 DEBUG ResourceDiff:57 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/creationTimestamp"}
2023-05-24 14:09:54 DEBUG ResourceDiff:57 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/managedFields"}
2023-05-24 14:09:54 DEBUG ResourceDiff:57 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/resourceVersion"}
2023-05-24 14:09:54 DEBUG ResourceDiff:57 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/uid"}
2023-05-24 14:09:54 DEBUG KafkaUserOperator:431 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Secret kafka/ui-user exist, and is identical
2023-05-24 14:09:54 DEBUG KafkaUserModel:363 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Loading request password from Kubernetes Secret po-review-user
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Upserting SCRAM-SHA credentials for user po-review-user
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG QuotasOperator:71 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:78 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:09:54 DEBUG SimpleAclOperator:89 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): 2 expected Acl rules and 2 existing Acl rules -> Reconciling rules
2023-05-24 14:09:54 DEBUG KafkaUserOperator:442 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Secret kafka/po-review-user does not exist, creating it
2023-05-24 14:09:54 DEBUG SimpleAclOperator:188 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Requesting update of ACLs for user po-review-user
2023-05-24 14:09:54 DEBUG KafkaUserOperator:475 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Secret po-review-test-user in namespace kafka already exists and cannot be created. It will be updated instead
2023-05-24 14:09:54 DEBUG KafkaUserOperator:475 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Secret po-review-user in namespace kafka already exists and cannot be created. It will be updated instead
2023-05-24 14:09:54 DEBUG Config:651 - Trying to configure client from Kubernetes config...
2023-05-24 14:09:54 DEBUG Config:657 - Did not find Kubernetes config at: [/home/strimzi/.kube/config]. Ignoring.
2023-05-24 14:09:54 DEBUG Config:528 - Trying to configure client from service account...
2023-05-24 14:09:54 DEBUG Config:536 - Found service account host and port: 10.3.0.1:443
2023-05-24 14:09:54 DEBUG Config:542 - Found service account ca cert at: [/var/run/secrets/kubernetes.io/serviceaccount/ca.crt}].
2023-05-24 14:09:54 DEBUG Config:553 - Found service account token at: [/var/run/secrets/kubernetes.io/serviceaccount/token].
2023-05-24 14:09:54 DEBUG Config:651 - Trying to configure client from Kubernetes config...
2023-05-24 14:09:54 DEBUG Config:878 - Trying to configure client namespace from Kubernetes service account namespace path...
2023-05-24 14:09:54 DEBUG Config:657 - Did not find Kubernetes config at: [/home/strimzi/.kube/config]. Ignoring.
2023-05-24 14:09:54 DEBUG Config:883 - Found service account namespace at: [/var/run/secrets/kubernetes.io/serviceaccount/namespace].
2023-05-24 14:09:54 DEBUG Config:528 - Trying to configure client from service account...
2023-05-24 14:09:54 DEBUG Config:536 - Found service account host and port: 10.3.0.1:443
2023-05-24 14:09:54 DEBUG Config:542 - Found service account ca cert at: [/var/run/secrets/kubernetes.io/serviceaccount/ca.crt}].
2023-05-24 14:09:54 DEBUG Config:553 - Found service account token at: [/var/run/secrets/kubernetes.io/serviceaccount/token].
2023-05-24 14:09:54 DEBUG Config:878 - Trying to configure client namespace from Kubernetes service account namespace path...
2023-05-24 14:09:54 DEBUG Config:883 - Found service account namespace at: [/var/run/secrets/kubernetes.io/serviceaccount/namespace].
2023-05-24 14:09:54 DEBUG AbstractBatchReconciler:92 - ScramShaCredentialsBatchReconciler: Processing batch of 3 records in the BatchReconciler
2023-05-24 14:09:54 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=alterUserScramCredentials, deadlineMs=1684937434766, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:09:54 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[62, -99, -15, -87, -96, 104, 26, 87, 5, -97, 47, 85, 39, -5, 127, 115, -111, -80, -85, 104, 21, -6, 7, 33, 85, -82, 47, 70, 13, 31, 41, -13, -55, -103, -117, -70, 26, -31, -20, 34, -3, -63, 3, 39, -96, -35, 80, 31, -73, -128, -84, 107, 34, 6, -23, -127, 115, 115, -98, 107, -76, 102, -95, 31]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104899, timeoutMs=10000
2023-05-24 14:09:54 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending ALTER_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104899, headerVersion=2) and timeout 10000 to node 2: AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[62, -99, -15, -87, -96, 104, 26, 87, 5, -97, 47, 85, 39, -5, 127, 115, -111, -80, -85, 104, 21, -6, 7, 33, 85, -82, 47, 70, 13, 31, 41, -13, -55, -103, -117, -70, 26, -31, -20, 34, -3, -63, 3, 39, -96, -35, 80, 31, -73, -128, -84, 107, 34, 6, -23, -127, 115, 115, -98, 107, -76, 102, -95, 31]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])])
2023-05-24 14:09:54 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received ALTER_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104899, headerVersion=2): AlterUserScramCredentialsResponseData(throttleTimeMs=0, results=[AlterUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='')])
2023-05-24 14:09:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): SCRAM-SHA credentials reconciliation for user ui-user succeeded
2023-05-24 14:09:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): SCRAM-SHA credentials reconciliation for user po-review-test-user succeeded
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): Updated SCRAM credentials for user ui-user
2023-05-24 14:09:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): SCRAM-SHA credentials reconciliation for user po-review-user succeeded
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): Updated SCRAM credentials for user po-review-user
2023-05-24 14:09:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): Updated SCRAM credentials for user po-review-test-user
2023-05-24 14:09:54 INFO  UserControllerLoop:120 - Reconciliation #18609(timer) KafkaUser(kafka/po-review-user): reconciled
2023-05-24 14:09:54 INFO  UserControllerLoop:120 - Reconciliation #18611(timer) KafkaUser(kafka/ui-user): reconciled
2023-05-24 14:09:54 INFO  UserControllerLoop:120 - Reconciliation #18610(timer) KafkaUser(kafka/po-review-test-user): reconciled
2023-05-24 14:09:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:09:54.822803724Z"}
2023-05-24 14:09:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:09:54.822885326Z"}
2023-05-24 14:09:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:09:54.822929528Z"}
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::ui-user
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::po-review-user
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::ui-user is not in use anymore and will be removed
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::po-review-test-user
2023-05-24 14:09:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-4: Waiting for next event from work queue
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::po-review-user is not in use anymore and will be removed
2023-05-24 14:09:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::po-review-test-user is not in use anymore and will be removed
2023-05-24 14:09:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-26: Waiting for next event from work queue
2023-05-24 14:09:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-15: Waiting for next event from work queue
2023-05-24 14:10:08 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937448606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104900, timeoutMs=10000
2023-05-24 14:10:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104900, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:10:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104900, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:10:08 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:10:08 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937448669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104901, timeoutMs=10000
2023-05-24 14:10:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104901, headerVersion=2) and timeout 10000 to node 0: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:10:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104901, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:10:08 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:10:08 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937448684, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104902, timeoutMs=10000
2023-05-24 14:10:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104902, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:10:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104902, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:10:08 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:10:09 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104903, timeoutMs=10000
2023-05-24 14:10:09 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending METADATA request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104903, headerVersion=2) and timeout 10000 to node 2: MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false)
2023-05-24 14:10:09 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received METADATA response from node 2 for request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104903, headerVersion=2): MetadataResponseData(throttleTimeMs=0, brokers=[MetadataResponseBroker(nodeId=0, host='crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=2, host='crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=1, host='crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0')], clusterId='eAf3EAbiRv2OMKLkjHxsWA', controllerId=2, topics=[], clusterAuthorizedOperations=-2147483648)
2023-05-24 14:10:09 DEBUG AdminMetadataManager:247 - [AdminClient clientId=adminclient-1] Updating cluster metadata to Cluster(id = eAf3EAbiRv2OMKLkjHxsWA, nodes = [crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0), crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0), crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 1 rack: 0)], partitions = [], controller = crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0))
2023-05-24 14:10:12 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:10:12 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:10:23 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937463606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104904, timeoutMs=10000
2023-05-24 14:10:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104904, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:10:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104904, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:10:23 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:10:23 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937463669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104905, timeoutMs=10000
2023-05-24 14:10:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104905, headerVersion=2) and timeout 10000 to node 0: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:10:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104905, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:10:23 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:10:23 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937463685, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104906, timeoutMs=10000
2023-05-24 14:10:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104906, headerVersion=2) and timeout 10000 to node 0: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:10:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104906, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:10:23 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:10:32 DEBUG WatchConnectionManager:60 - Closing websocket io.fabric8.kubernetes.client.jdkhttp.JdkWebSocketImpl@716fc47c
2023-05-24 14:10:32 DEBUG WatcherWebSocketListener:71 - WebSocket close received. code: 1000, reason:
2023-05-24 14:10:32 DEBUG AbstractWatchManager:200 - Scheduling reconnect task in 1000 ms
2023-05-24 14:10:33 DEBUG AbstractWatchManager:283 - Watching https://10.3.0.1:443/apis/kafka.strimzi.io/v1beta2/namespaces/kafka/kafkausers?labelSelector=strimzi.io%2Fcluster%3Dcrs-kafka-cluster&resourceVersion=201566371&timeoutSeconds=600&allowWatchBookmarks=true&watch=true...
2023-05-24 14:10:33 DEBUG WatcherWebSocketListener:41 - WebSocket successfully opened
2023-05-24 14:10:38 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937478606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104907, timeoutMs=10000
2023-05-24 14:10:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104907, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:10:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104907, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:10:38 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:10:38 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937478669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104908, timeoutMs=10000
2023-05-24 14:10:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104908, headerVersion=2) and timeout 10000 to node 0: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:10:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104908, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:10:38 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:10:38 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937478685, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104909, timeoutMs=10000
2023-05-24 14:10:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104909, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:10:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104909, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:10:38 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:10:39 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104910, timeoutMs=10000
2023-05-24 14:10:39 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending METADATA request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104910, headerVersion=2) and timeout 10000 to node 0: MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false)
2023-05-24 14:10:39 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received METADATA response from node 0 for request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104910, headerVersion=2): MetadataResponseData(throttleTimeMs=0, brokers=[MetadataResponseBroker(nodeId=0, host='crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=2, host='crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=1, host='crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0')], clusterId='eAf3EAbiRv2OMKLkjHxsWA', controllerId=2, topics=[], clusterAuthorizedOperations=-2147483648)
2023-05-24 14:10:39 DEBUG AdminMetadataManager:247 - [AdminClient clientId=adminclient-1] Updating cluster metadata to Cluster(id = eAf3EAbiRv2OMKLkjHxsWA, nodes = [crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0), crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 1 rack: 0), crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0)], partitions = [], controller = crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0))
2023-05-24 14:10:53 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937493606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104911, timeoutMs=10000
2023-05-24 14:10:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104911, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:10:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104911, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:10:53 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:10:53 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937493669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104912, timeoutMs=10000
2023-05-24 14:10:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104912, headerVersion=2) and timeout 10000 to node 2: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:10:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104912, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:10:53 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:10:53 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937493684, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:53 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104913, timeoutMs=10000
2023-05-24 14:10:53 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104913, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:10:53 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104913, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:10:53 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:10:54 INFO  UserController:258 - Triggering periodic reconciliation of KafkaUser resources for namespace kafka
2023-05-24 14:10:54 DEBUG QuotasOperator:207 - Searching for Users with any quotas
2023-05-24 14:10:54 DEBUG SimpleAclOperator:312 - Searching for Users with any ACL rules
2023-05-24 14:10:54 DEBUG SimpleAclOperator:329 - Adding user po-review-test-user to Set of users with ACLs
2023-05-24 14:10:54 DEBUG SimpleAclOperator:329 - Adding user ui-user to Set of users with ACLs
2023-05-24 14:10:54 DEBUG SimpleAclOperator:329 - Adding user po-review-user to Set of users with ACLs
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:169 - Listing all users with SCRAM credentials
2023-05-24 14:10:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG CustomResource:165 - Calling CustomResource#setApiVersion doesn't do anything because the API version is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG CustomResource:176 - Calling CustomResource#setKind doesn't do anything because the Kind is computed and shouldn't be changed
2023-05-24 14:10:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser po-review-user in namespace kafka
2023-05-24 14:10:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser po-review-test-user in namespace kafka
2023-05-24 14:10:54 DEBUG ControllerQueue:53 - Enqueueing KafkaUser ui-user in namespace kafka
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::po-review-user
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::ui-user
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:42 - Trying to obtain lock KafkaUser::kafka::po-review-test-user
2023-05-24 14:10:54 INFO  UserControllerLoop:99 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): KafkaUser will be reconciled
2023-05-24 14:10:54 INFO  UserControllerLoop:99 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): KafkaUser will be reconciled
2023-05-24 14:10:54 INFO  UserControllerLoop:99 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): KafkaUser will be reconciled
2023-05-24 14:10:54 DEBUG KafkaUserOperator:248 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Updating User ui-user in namespace kafka
2023-05-24 14:10:54 DEBUG KafkaUserOperator:248 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Updating User po-review-user in namespace kafka
2023-05-24 14:10:54 DEBUG KafkaUserModel:370 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Re-using password which already exists
2023-05-24 14:10:54 DEBUG KafkaUserOperator:248 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Updating User po-review-test-user in namespace kafka
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Upserting SCRAM-SHA credentials for user ui-user
2023-05-24 14:10:54 DEBUG KafkaUserModel:376 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Generating user password
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:78 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Upserting SCRAM-SHA credentials for user po-review-test-user
2023-05-24 14:10:54 DEBUG SimpleAclOperator:89 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): 3 expected Acl rules and 3 existing Acl rules -> Reconciling rules
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:188 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Requesting update of ACLs for user ui-user
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:78 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:89 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): 1 expected Acl rules and 1 existing Acl rules -> Reconciling rules
2023-05-24 14:10:54 DEBUG SimpleAclOperator:188 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Requesting update of ACLs for user po-review-test-user
2023-05-24 14:10:54 DEBUG KafkaUserOperator:442 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Secret kafka/po-review-test-user does not exist, creating it
2023-05-24 14:10:54 DEBUG ResourceDiff:57 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/creationTimestamp"}
2023-05-24 14:10:54 DEBUG ResourceDiff:57 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/managedFields"}
2023-05-24 14:10:54 DEBUG ResourceDiff:57 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/resourceVersion"}
2023-05-24 14:10:54 DEBUG ResourceDiff:57 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Ignoring Secret ui-user diff {"op":"remove","path":"/metadata/uid"}
2023-05-24 14:10:54 DEBUG KafkaUserOperator:431 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Secret kafka/ui-user exist, and is identical
2023-05-24 14:10:54 DEBUG KafkaUserModel:363 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Loading request password from Kubernetes Secret po-review-user
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:83 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Upserting SCRAM-SHA credentials for user po-review-user
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG QuotasOperator:71 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): No expected quotas and no existing quotas -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:78 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): No expected Acl rules and no existing Acl rules -> NoOp
2023-05-24 14:10:54 DEBUG SimpleAclOperator:89 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): 2 expected Acl rules and 2 existing Acl rules -> Reconciling rules
2023-05-24 14:10:54 DEBUG KafkaUserOperator:442 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Secret kafka/po-review-user does not exist, creating it
2023-05-24 14:10:54 DEBUG SimpleAclOperator:188 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Requesting update of ACLs for user po-review-user
2023-05-24 14:10:54 DEBUG KafkaUserOperator:475 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Secret po-review-test-user in namespace kafka already exists and cannot be created. It will be updated instead
2023-05-24 14:10:54 DEBUG KafkaUserOperator:475 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Secret po-review-user in namespace kafka already exists and cannot be created. It will be updated instead
2023-05-24 14:10:54 DEBUG Config:651 - Trying to configure client from Kubernetes config...
2023-05-24 14:10:54 DEBUG Config:657 - Did not find Kubernetes config at: [/home/strimzi/.kube/config]. Ignoring.
2023-05-24 14:10:54 DEBUG Config:528 - Trying to configure client from service account...
2023-05-24 14:10:54 DEBUG Config:536 - Found service account host and port: 10.3.0.1:443
2023-05-24 14:10:54 DEBUG Config:542 - Found service account ca cert at: [/var/run/secrets/kubernetes.io/serviceaccount/ca.crt}].
2023-05-24 14:10:54 DEBUG Config:553 - Found service account token at: [/var/run/secrets/kubernetes.io/serviceaccount/token].
2023-05-24 14:10:54 DEBUG Config:878 - Trying to configure client namespace from Kubernetes service account namespace path...
2023-05-24 14:10:54 DEBUG Config:883 - Found service account namespace at: [/var/run/secrets/kubernetes.io/serviceaccount/namespace].
2023-05-24 14:10:54 DEBUG Config:651 - Trying to configure client from Kubernetes config...
2023-05-24 14:10:54 DEBUG Config:657 - Did not find Kubernetes config at: [/home/strimzi/.kube/config]. Ignoring.
2023-05-24 14:10:54 DEBUG Config:528 - Trying to configure client from service account...
2023-05-24 14:10:54 DEBUG Config:536 - Found service account host and port: 10.3.0.1:443
2023-05-24 14:10:54 DEBUG Config:542 - Found service account ca cert at: [/var/run/secrets/kubernetes.io/serviceaccount/ca.crt}].
2023-05-24 14:10:54 DEBUG Config:553 - Found service account token at: [/var/run/secrets/kubernetes.io/serviceaccount/token].
2023-05-24 14:10:54 DEBUG Config:878 - Trying to configure client namespace from Kubernetes service account namespace path...
2023-05-24 14:10:54 DEBUG Config:883 - Found service account namespace at: [/var/run/secrets/kubernetes.io/serviceaccount/namespace].
2023-05-24 14:10:54 DEBUG AbstractBatchReconciler:92 - ScramShaCredentialsBatchReconciler: Processing batch of 3 records in the BatchReconciler
2023-05-24 14:10:54 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=alterUserScramCredentials, deadlineMs=1684937494740, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:10:54 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-59, -73, -73, -34, -35, 78, 62, -87, 110, -18, 59, -105, -65, 42, 11, -29, -122, 126, 64, -113, -107, 101, 13, 34, 92, -50, 40, -4, 88, 47, 29, 30, -99, 61, 44, 50, 35, 76, -10, -102, 127, -74, 7, -127, 92, 38, 0, 102, -126, 120, 76, -117, 121, -122, -39, -65, 44, 81, 92, -78, 36, -37, -51, 35]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104914, timeoutMs=10000
2023-05-24 14:10:54 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending ALTER_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104914, headerVersion=2) and timeout 10000 to node 2: AlterUserScramCredentialsRequestData(deletions=[], upsertions=[ScramCredentialUpsertion(name='ui-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-84, 76, 33, 22, -9, -101, 26, 16, 32, 11, -115, -22, -89, -12, -106, 2, 73, 24, 63, 79, 124, -15, 73, -115, -41, -71, -71, 10, 78, -121, 99, 66, 117, 41, 99, 77, -128, -86, -69, 55, 16, 80, -59, 109, 2, 33, -107, 125, -31, -89, -14, -15, 8, 62, 13, -110, 79, 101, 101, -25, 115, -122, -63, 64]), ScramCredentialUpsertion(name='po-review-test-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[-59, -73, -73, -34, -35, 78, 62, -87, 110, -18, 59, -105, -65, 42, 11, -29, -122, 126, 64, -113, -107, 101, 13, 34, 92, -50, 40, -4, 88, 47, 29, 30, -99, 61, 44, 50, 35, 76, -10, -102, 127, -74, 7, -127, 92, 38, 0, 102, -126, 120, 76, -117, 121, -122, -39, -65, 44, 81, 92, -78, 36, -37, -51, 35]), ScramCredentialUpsertion(name='po-review-user', mechanism=2, iterations=4096, salt=[101, 121, 48, 108, 111, 111, 119, 114, 109, 100, 54, 107, 111, 52, 48, 48, 110, 117, 50, 49, 101, 116, 48, 99, 118], saltedPassword=[103, -50, -118, -4, 63, 15, -39, -39, -102, 3, 60, 13, -33, 3, -108, -3, 31, -117, -4, 71, 3, 80, -42, -55, 117, -114, 2, 97, 85, 39, 113, 39, -12, -44, 90, -118, 105, 38, 127, -127, 117, -35, 109, 32, -76, 123, -83, -19, -100, 23, 80, 66, 89, -120, 83, 57, 42, 44, 62, 8, 119, -89, 87, -97])])
2023-05-24 14:10:54 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received ALTER_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=ALTER_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104914, headerVersion=2): AlterUserScramCredentialsResponseData(throttleTimeMs=0, results=[AlterUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage=''), AlterUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='')])
2023-05-24 14:10:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): SCRAM-SHA credentials reconciliation for user ui-user succeeded
2023-05-24 14:10:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): SCRAM-SHA credentials reconciliation for user po-review-test-user succeeded
2023-05-24 14:10:54 DEBUG ScramShaCredentialsBatchReconciler:88 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): SCRAM-SHA credentials reconciliation for user po-review-user succeeded
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): Updated SCRAM credentials for user ui-user
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): Updated SCRAM credentials for user po-review-test-user
2023-05-24 14:10:54 DEBUG ScramCredentialsOperator:110 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): Updated SCRAM credentials for user po-review-user
2023-05-24 14:10:54 INFO  UserControllerLoop:120 - Reconciliation #18614(timer) KafkaUser(kafka/po-review-test-user): reconciled
2023-05-24 14:10:54 INFO  UserControllerLoop:120 - Reconciliation #18613(timer) KafkaUser(kafka/ui-user): reconciled
2023-05-24 14:10:54 INFO  UserControllerLoop:120 - Reconciliation #18612(timer) KafkaUser(kafka/po-review-user): reconciled
2023-05-24 14:10:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:10:54.784816169Z"}
2023-05-24 14:10:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:10:54.784754667Z"}
2023-05-24 14:10:54 DEBUG StatusDiff:42 - Ignoring Status diff {"op":"replace","path":"/conditions/0/lastTransitionTime","value":"2023-05-24T14:10:54.784753767Z"}
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::po-review-user
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::po-review-user is not in use anymore and will be removed
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::po-review-test-user
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:59 - Trying to release lock KafkaUser::kafka::ui-user
2023-05-24 14:10:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-14: Waiting for next event from work queue
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::po-review-test-user is not in use anymore and will be removed
2023-05-24 14:10:54 DEBUG ReconciliationLockManager:62 - Lock KafkaUser::kafka::ui-user is not in use anymore and will be removed
2023-05-24 14:10:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-10: Waiting for next event from work queue
2023-05-24 14:10:54 DEBUG AbstractControllerLoop:181 - KafkaUser-ControllerLoop-18: Waiting for next event from work queue
2023-05-24 14:11:08 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937508606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104915, timeoutMs=10000
2023-05-24 14:11:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104915, headerVersion=2) and timeout 10000 to node 0: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:11:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 0 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104915, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:11:08 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:11:08 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937508669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104916, timeoutMs=10000
2023-05-24 14:11:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104916, headerVersion=2) and timeout 10000 to node 2: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:11:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104916, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:11:08 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:11:08 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937508684, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:08 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104917, timeoutMs=10000
2023-05-24 14:11:08 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104917, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:11:08 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104917, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:11:08 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:11:09 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0). correlationId=104918, timeoutMs=10000
2023-05-24 14:11:09 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending METADATA request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104918, headerVersion=2) and timeout 10000 to node 0: MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false)
2023-05-24 14:11:09 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received METADATA response from node 0 for request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104918, headerVersion=2): MetadataResponseData(throttleTimeMs=0, brokers=[MetadataResponseBroker(nodeId=0, host='crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=2, host='crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=1, host='crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0')], clusterId='eAf3EAbiRv2OMKLkjHxsWA', controllerId=2, topics=[], clusterAuthorizedOperations=-2147483648)
2023-05-24 14:11:09 DEBUG AdminMetadataManager:247 - [AdminClient clientId=adminclient-1] Updating cluster metadata to Cluster(id = eAf3EAbiRv2OMKLkjHxsWA, nodes = [crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0), crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0), crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 1 rack: 0)], partitions = [], controller = crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0))
2023-05-24 14:11:23 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937523606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104919, timeoutMs=10000
2023-05-24 14:11:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104919, headerVersion=2) and timeout 10000 to node 2: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:11:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104919, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:11:23 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:11:23 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937523669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104920, timeoutMs=10000
2023-05-24 14:11:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104920, headerVersion=2) and timeout 10000 to node 2: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:11:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104920, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:11:23 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:11:23 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937523685, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:23 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104921, timeoutMs=10000
2023-05-24 14:11:23 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104921, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:11:23 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104921, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:11:23 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:11:38 DEBUG AbstractCache:145 - Starting update of QuotasCache
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeClientQuotas, deadlineMs=1684937538606, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeClientQuotasRequestData(components=[], strict=false) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104922, timeoutMs=10000
2023-05-24 14:11:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_CLIENT_QUOTAS request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104922, headerVersion=2) and timeout 10000 to node 2: DescribeClientQuotasRequestData(components=[], strict=false)
2023-05-24 14:11:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_CLIENT_QUOTAS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_CLIENT_QUOTAS, apiVersion=1, clientId=adminclient-1, correlationId=104922, headerVersion=2): DescribeClientQuotasResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', entries=[])
2023-05-24 14:11:38 DEBUG AbstractCache:147 - QuotasCache updated
2023-05-24 14:11:38 DEBUG AbstractCache:145 - Starting update of AclCache
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeAcls, deadlineMs=1684937538669, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104923, timeoutMs=10000
2023-05-24 14:11:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_ACLS request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104923, headerVersion=2) and timeout 10000 to node 2: DescribeAclsRequestData(resourceTypeFilter=1, resourceNameFilter=null, patternTypeFilter=1, principalFilter=null, hostFilter=null, operation=1, permissionType=1)
2023-05-24 14:11:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_ACLS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_ACLS, apiVersion=3, clientId=adminclient-1, correlationId=104923, headerVersion=2): DescribeAclsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', resources=[DescribeAclsResource(resourceType=2, resourceName='po-review-changes', patternType=3, acls=[AclDescription(principal='User:po-review-test-user', host='*', operation=2, permissionType=3), AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=2, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='po-review-consumer', patternType=3, acls=[AclDescription(principal='User:po-review-user', host='*', operation=2, permissionType=3)]), DescribeAclsResource(resourceType=4, resourceName='kafka-cluster', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=8, permissionType=3)]), DescribeAclsResource(resourceType=3, resourceName='*', patternType=3, acls=[AclDescription(principal='User:ui-user', host='*', operation=2, permissionType=3)])])
2023-05-24 14:11:38 DEBUG AbstractCache:147 - AclCache updated
2023-05-24 14:11:38 DEBUG AbstractCache:145 - Starting update of ScramShaCredentialsCache
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1443 - [AdminClient clientId=adminclient-1] Queueing Call(callName=describeUserScramCredentials, deadlineMs=1684937538685, tries=0, nextAllowedTryMs=0) with a timeout 10000 ms from now.
2023-05-24 14:11:38 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending DescribeUserScramCredentialsRequestData(users=[]) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104924, timeoutMs=10000
2023-05-24 14:11:38 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending DESCRIBE_USER_SCRAM_CREDENTIALS request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104924, headerVersion=2) and timeout 10000 to node 2: DescribeUserScramCredentialsRequestData(users=[])
2023-05-24 14:11:38 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received DESCRIBE_USER_SCRAM_CREDENTIALS response from node 2 for request with header RequestHeader(apiKey=DESCRIBE_USER_SCRAM_CREDENTIALS, apiVersion=0, clientId=adminclient-1, correlationId=104924, headerVersion=2): DescribeUserScramCredentialsResponseData(throttleTimeMs=0, errorCode=0, errorMessage='', results=[DescribeUserScramCredentialsResult(user='po-review-test-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='po-review-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)]), DescribeUserScramCredentialsResult(user='ui-user', errorCode=0, errorMessage='', credentialInfos=[CredentialInfo(mechanism=2, iterations=4096)])])
2023-05-24 14:11:38 DEBUG AbstractCache:147 - ScramShaCredentialsCache updated
2023-05-24 14:11:39 DEBUG KafkaAdminClient:1186 - [AdminClient clientId=adminclient-1] Sending MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false) to crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0). correlationId=104925, timeoutMs=10000
2023-05-24 14:11:39 DEBUG NetworkClient:521 - [AdminClient clientId=adminclient-1] Sending METADATA request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104925, headerVersion=2) and timeout 10000 to node 2: MetadataRequestData(topics=[], allowAutoTopicCreation=true, includeClusterAuthorizedOperations=false, includeTopicAuthorizedOperations=false)
2023-05-24 14:11:39 DEBUG NetworkClient:879 - [AdminClient clientId=adminclient-1] Received METADATA response from node 2 for request with header RequestHeader(apiKey=METADATA, apiVersion=12, clientId=adminclient-1, correlationId=104925, headerVersion=2): MetadataResponseData(throttleTimeMs=0, brokers=[MetadataResponseBroker(nodeId=0, host='crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=2, host='crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0'), MetadataResponseBroker(nodeId=1, host='crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc', port=9091, rack='0')], clusterId='eAf3EAbiRv2OMKLkjHxsWA', controllerId=2, topics=[], clusterAuthorizedOperations=-2147483648)
2023-05-24 14:11:39 DEBUG AdminMetadataManager:247 - [AdminClient clientId=adminclient-1] Updating cluster metadata to Cluster(id = eAf3EAbiRv2OMKLkjHxsWA, nodes = [crs-kafka-cluster-kafka-1.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 1 rack: 0), crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0), crs-kafka-cluster-kafka-0.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 0 rack: 0)], partitions = [], controller = crs-kafka-cluster-kafka-2.crs-kafka-cluster-kafka-brokers.kafka.svc:9091 (id: 2 rack: 0))
scholzj commented 1 year ago

Have you tried to restart the user operator?

kmcrawford commented 1 year ago

@scholzj I just restarted it and no secrets changed since since. I wonder if these operators should panic when it can't reach the api server. Like how cert-manager, argo, and etc do to prevent updating things incorrectly.

scholzj commented 1 year ago

I'm not sure what you mean by panic. From the log and from the fact that the restart helped, it looks like a duplicate of #8528 where the Kubernetes Informer gets stuck for some reason - it's just that in your case it is the Secrets informer which is stuck and not the Pod Informer. The operator thinks the secret does not exist because the informer says so. We are trying to figure out with the Kubernetes client what the exact issue might be.

scholzj commented 1 year ago

BTW: Would you mind sharing your Kube distribution and version on which this happened?

kmcrawford commented 1 year ago

I'm not sure what you mean by panic. From the log and from the fact that the restart helped, it looks like a duplicate of #8528 where the Kubernetes Informer gets stuck for some reason - it's just that in your case it is the Secrets informer which is stuck and not the Pod Informer. The operator thinks the secret does not exist because the informer says so. We are trying to figure out with the Kubernetes client what the exact issue might be.

By panic I mean cause the pod to restart. We see this all the time when our master is in process of being upgraded.

kmcrawford commented 1 year ago

BTW: Would you mind sharing your Kube distribution and version on which this happened?

This is Azure AKS Kubernetes 1.25

Server Version: version.Info{Major:"1", Minor:"25", GitVersion:"v1.25.5", GitCommit:"fd6aae27a28fca7e8b996d7201b0da6fbf6f732a", GitTreeState:"clean", BuildDate:"2023-04-08T13:27:20Z", GoVersion:"go1.19.4", Compiler:"gc", Platform:"linux/amd64"}
kmcrawford commented 1 year ago

@scholzj I had the same issue again this morning. restarting fixed it again.

scholzj commented 1 year ago

Triaged on 1.6.2023: Duplicate of #8528 which should be kept for tracking.