Another invalid_token error

[maxemontio]

Hi everyone!

I have kafka 3.6.0 on two separate VMs: controller (kraft) and broker. There is ssl everywhere. When i try to setup an authentication using strimzi (0.14.0), i get {"status":"invalid_token"} error.

Here is my controller config:

process.roles=controller
node.id=1
cluster.id=UHc1bld0VWdXSGlJR0p0OQ==

controller.quorum.voters=1@10.51.5.147:9095

listeners=CONTROLLER://10.51.5.147:9095
controller.listener.names=CONTROLLER
listener.security.protocol.map=CONTROLLER:SSL

log.dirs=/mnt/kraft-controller-logs

ssl.keystore.location=/etc/kafka/certs/keystore.pem
ssl.keystore.type=PEM
ssl.truststore.location=/etc/kafka/certs/ca.crt
ssl.truststore.type=PEM

And here is my broker config:

process.roles=broker
node.id=10
controller.quorum.voters=1@10.51.5.147:9095

cluster.id=UHc1bld0VWdXSGlJR0p0OQ==

listeners=CLIENT://10.51.4.226:9094,INTER_BROKER://10.51.4.226:9443
inter.broker.listener.name=INTER_BROKER
advertised.listeners=CLIENT://10.51.4.226:9094,INTER_BROKER://10.51.4.226:9443
controller.listener.names=CONTROLLERS
listener.security.protocol.map=CLIENT:SASL_SSL,CONTROLLERS:SSL,INTER_BROKER:SSL

log.dirs=/mnt/kraft-broker-logs

# to controllers
listener.name.controllers.ssl.keystore.location=/etc/kafka/certs/keystore.pem
listener.name.controllers.ssl.keystore.type=PEM
listener.name.controllers.ssl.truststore.location=/etc/kafka/certs/ca.crt
listener.name.controllers.ssl.truststore.type=PEM

# to clients
listener.name.client.ssl.keystore.location=/etc/kafka/certs/keystore.pem
listener.name.client.ssl.keystore.type=PEM
listener.name.client.ssl.truststore.location=/etc/kafka/certs/ca.crt
listener.name.client.ssl.truststore.type=PEM

# between brokers
listener.name.inter_broker.ssl.keystore.location=/etc/kafka/certs/keystore.pem
listener.name.inter_broker.ssl.keystore.type=PEM
listener.name.inter_broker.ssl.truststore.location=/etc/kafka/certs/ca.crt
listener.name.inter_broker.ssl.truststore.type=PEM

oauth.ssl.truststore.certificates=/etc/kafka/certs/keystore.pem
oauth.ssl.truststore.type=PEM
oauth.ssl.truststore.location=/etc/kafka/certs/ca.crt

principal.builder.class=io.strimzi.kafka.oauth.server.OAuthKafkaPrincipalBuilder
listener.name.client.sasl.enabled.mechanisms=OAUTHBEARER
listener.name.client.oauthbearer.sasl.jaas.config=org.apache.kafka.common.security.oauthbearer.OAuthBearerLoginModule required \
  oauth.jwks.endpoint.uri="https://auth.dev/auth/realms/kafka-new/protocol/openid-connect/certs" \
  oauth.valid.issuer.uri="https://auth.dev/auth/realms/kafka-new" \
  oauth.token.endpoint.uri="https://auth.dev/auth/realms/kafka-new/protocol/openid-connect/token" \
  oauth.username.claim="preferred_username" \
  oauth.check.audience="true" \
  oauth.client.id="kafka" \
  oauth.client.secret="kbAhxknkuuA2GByAK15lFOPpbm" \
  unsecuredLoginStringClaim_sub="unused" ;

super.users="User:admin"

It starts without any errors, but when i try to make a user request using this client.properties file... :

security.protocol=SASL_SSL
sasl.mechanism=OAUTHBEARER
sasl.jaas.config=org.apache.kafka.common.security.oauthbearer.OAuthBearerLoginModule required \
  oauth.client.id="team-one" \
  oauth.client.secret="pwMAIWlgkN9EbDiJ6hs4n" \
  oauth.username.claim="preferred_username" \
  oauth.token.endpoint.uri="https://auth.dev/auth/realms/kafka-new/protocol/openid-connect/token" ;
sasl.login.callback.handler.class=io.strimzi.kafka.oauth.client.JaasClientOauthLoginCallbackHandler

ssl.truststore.location=/Users/maxemontio/certs/ca.crt
ssl.truststore.type=PEM

... i get this response:

./kafka-topics.sh --bootstrap-server broker-1.sandbox:9094 --list  --command-config=/Users/maxemontio/KAFKA/client.properties
[2023-11-06 15:09:53,204] ERROR [AdminClient clientId=adminclient-1] Connection to node -1 (broker-1.sandbox/10.51.4.226:9094) failed authentication due to: {"status":"invalid_token"} (org.apache.kafka.clients.NetworkClient)
[2023-11-06 15:09:53,206] WARN [AdminClient clientId=adminclient-1] Metadata update failed due to authentication error (org.apache.kafka.clients.admin.internals.AdminMetadataManager)
org.apache.kafka.common.errors.SaslAuthenticationException: {"status":"invalid_token"}
Error while executing topic command : {"status":"invalid_token"}
[2023-11-06 15:09:53,213] ERROR org.apache.kafka.common.errors.SaslAuthenticationException: {"status":"invalid_token"}
 (kafka.admin.TopicCommand$)

Broker says the same:

Nov 06 11:09:53 broker-1 kafka-server-start.sh[1777753]: [2023-11-06 11:09:53,114] INFO [SocketServer listenerType=BROKER, nodeId=10] Failed authentication with /172.27.47.191 (channelId=10.51.4.226:9094-172.27.47.191:55786-0) ({"status":"invalid_token"}) (org.apache.kafka.common.network.Selector)

I am sure that all of the client.id and client.secret entries are correct, so i believe that there may be some sort of misconfiguration.

Could someone please help me out and highlight what i am doing wrong?

[mstruk]

Try to configure logging on your broker with io.strimzi logger set to DEBUG level. That should give you more information about the exact cause.

[maxemontio]

@mstruk I put log4j.logger.io.strimzi=DEBUG to my log4j.properties, but it gave no new logs with DEBUG level. I even decided to substitute contents of my log4j.properties with these, but it had the same result. Then i turned on debug logging globally, it gave this:

Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,330] DEBUG [SslTransportLayer channelId=10.51.4.226:9094-172.27.47.191:61803-0 key=channel=java.nio.channels.SocketChannel[connected local=/10.51.4.226:9094 remote=/172.27.47.191:61803], selector=sun.nio.ch.EPollSelectorImpl@31a6af6, interestOps=1, readyOps=0] SSL peer is not authenticated, returning ANONYMOUS instead (org.apache.kafka.common.network.SslTransportLayer)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,330] DEBUG [SslTransportLayer channelId=10.51.4.226:9094-172.27.47.191:61803-0 key=channel=java.nio.channels.SocketChannel[connected local=/10.51.4.226:9094 remote=/172.27.47.191:61803], selector=sun.nio.ch.EPollSelectorImpl@31a6af6, interestOps=1, readyOps=0] SSL handshake completed successfully with peerHost '172.27.47.191' peerPort 61803 peerPrincipal 'User:ANONYMOUS' protocol 'TLSv1.2' cipherSuite 'TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384' (org.apache.kafka.common.network.SslTransportLayer)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,553] DEBUG Set SASL server state to HANDSHAKE_OR_VERSIONS_REQUEST during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,553] DEBUG Handling Kafka request API_VERSIONS during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,554] DEBUG Set SASL server state to HANDSHAKE_REQUEST during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,722] DEBUG Handling Kafka request SASL_HANDSHAKE during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,722] DEBUG Using SASL mechanism 'OAUTHBEARER' provided by client (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,725] DEBUG Set SASL server state to AUTHENTICATE during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:42 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:42,873] DEBUG {"status":"invalid_token"} (org.apache.kafka.common.security.oauthbearer.internals.OAuthBearerSaslServer)
Nov 06 13:49:43 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:43,019] DEBUG Received %x01 response from client after it received our error (org.apache.kafka.common.security.oauthbearer.internals.OAuthBearerSaslServer)
Nov 06 13:49:43 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:43,019] DEBUG Set SASL server state to FAILED during authentication (org.apache.kafka.common.security.authenticator.SaslServerAuthenticator)
Nov 06 13:49:43 broker-1 kafka-server-start.sh[1803038]: [2023-11-06 13:49:43,020] INFO [SocketServer listenerType=BROKER, nodeId=10] Failed authentication with /172.27.47.191 (channelId=10.51.4.226:9094-172.27.47.191:61803-0) ({"status":"invalid_token"}) (org.apache.kafka.common.network.Selector)

Maybe i am turning the io.strimzi logger on in a wrong way?

[mstruk]

@maxemontio You should see much more logging. You can try by setting root logger level to DEBUG and then grep for io.strimzi just to make sure logging changes took effect. Maybe a different logging configuration file is in effect for your container.

[maxemontio]

@mstruk The point is that i am deliberately not using containers here, i take regular kafka, put there built jars and thats it. I set root logger level to DEBUG, it definitely took effect because it resulted in a lot of output but it didn't give me anything connected with the problem. io.strimzi appears only in one line in KafkaConfig values, where it shows me that principal.builder.class = class io.strimzi.kafka.oauth.server.OAuthKafkaPrincipalBuilder applied. Is it possible that i may have lost some jars/scripts/etc in my installation? As i see, copying jars is everything i need.

[mstruk]

When listeners are initialised on the broker, the custom validation callback handlers get installed and they output the effective configuration using DEBUG log level. This occurs during broker initialization. Thus you should see more than one io.strimzi line in the log.

Taking a second look at your configuration it appears to be missing an important item:

listener.name.client.oauthbearer.sasl.server.callback.handler.class=io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler

That would certainly be a reason for not seeing more io.strimzi logs.

[maxemontio]

@mstruk Yes, you are right, after adding this option i got way more sensible logs:

# cat server.log | grep io.strimzi
[2023-11-07 14:33:11,999] INFO JWKS keys change detected. Keys updated. (io.strimzi.kafka.oauth.validator.JWTSignatureValidator)
    includeAcceptHeader: true (io.strimzi.kafka.oauth.validator.JWTSignatureValidator)
    principal.builder.class = class io.strimzi.kafka.oauth.server.OAuthKafkaPrincipalBuilder
[2023-11-07 14:33:27,109] DEBUG Token: {"exp":1699371205,"iat":1699367605,"jti":"b90cb0cc-dfa8-4c94-ab9a-d791c10ee5c0","iss":"https://auth.dev/auth/realms/kafka-new","aud":"account","sub":"d33cee2f-916a-4c72-af10-229bfea681b6","typ":"Bearer","azp":"team-one","acr":"1","realm_access":{"roles":["team-one-rrole","offline_access"]},"resource_access":{"account":{"roles":["manage-account","manage-account-links","view-profile"]}},"scope":"profile email","email_verified":false,"clientHost":"172.27.47.226","clientId":"team-one","preferred_username":"service-account-team-one","clientAddress":"172.27.47.226"} (io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler)
[2023-11-07 14:33:27,146] DEBUG Access token expires at (UTC): 2023-11-07T15:33:25 (io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler)
[2023-11-07 14:33:27,152] DEBUG Token validation failed for token: eyJh**Bjrg (ErrId: c8488a56) (io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler)
io.strimzi.kafka.oauth.validator.TokenValidationException: Token validation failed: Expected audience not available in the token
    at io.strimzi.kafka.oauth.validator.JWTSignatureValidator.validateTokenPayload(JWTSignatureValidator.java:503)
    at io.strimzi.kafka.oauth.validator.JWTSignatureValidator.validate(JWTSignatureValidator.java:431)
    at io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler.validateToken(JaasServerOauthValidatorCallbackHandler.java:668)
    at io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler.handleCallback(JaasServerOauthValidatorCallbackHandler.java:610)
    at io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler.delegatedHandle(JaasServerOauthValidatorCallbackHandler.java:593)
    at io.strimzi.kafka.oauth.server.JaasServerOauthValidatorCallbackHandler.handle(JaasServerOauthValidatorCallbackHandler.java:572)

Managed to fix this by setting oauth.check.audience="false"

But i was not adding callback.handler intentionally, in the Enabling the custom callbacks section of the documentation it is said: If the listener is not used for inter-broker communication, then you don't have to configure the login callback. My client listener is not used for inter-broker communication - i have separated inter_broker listener for that. Do i understand this wrong or it can be some sort of inaccuracy in the documentation?

[mstruk]

The login callback is the SASL client configuration rather than the server configuration (as opposed to the server callback, which is the SASL server configuration. For your problem here it doesn't matter if you set login callback or not. Your problem was that you didn't set the server callback, which for the listener always has to be set to properly enable OAuth support on the listener.

If you think the documentation is unclear feel free to propose an improvement.

[maxemontio]

Got it. That solved my problem.

Thanks for your help, @mstruk!