OIDC Authentication troubleshooting issue: unable to view log details

On a fresh 1.4.0-1 install, I’ve setup oidc authentication against our keycloak server. Here’s the configuration

    ---
    _meta:
      type: "config"
      config_version: 2
    config:
      dynamic:
        authc:
          openid_auth_domain:
            http_enabled: true
            transport_enabled: true
            order: 0
            http_authenticator:
              type: openid
              challenge: false
              config:
                subject_key: preferred_username
                roles_key: roles
                openid_connect_url: https://keycloak/auth/realms/cloud/.well-known/openid-configuration
            authentication_backend:
              type: noop
          basic_internal_auth_domain:
            description: "Authenticate via HTTP Basic against internal users database"
            http_enabled: true
            transport_enabled: true
            order: 1
            http_authenticator:
              type: "basic"
              challenge: true
            authentication_backend:
              type: "intern"

I’ve also add the following line in /etc/elasticsearch/log4j2.properties

logger.opendistro_security.name = com.amazon.opendistroforelasticsearch.security
logger.opendistro_security.level = trace
logger.opendistro_security.appenderRef.rolling.ref = rolling
logger.opendistro_security.appenderRef.rolling_old.ref = rolling_old
logger.opendistro_security.additivity = false

logger.opendistro_security.name = com.amazon.dlic.auth.http.jwt
logger.opendistro_security.level = trace

I’m trying to connect with a valid token

curl --location --request GET 'https://rdfoelk01:9200/' --header 'Authorization: Bearer eyJhbGciOi...yiiuyevCjVzia9rL3G0'

I get a 401 and here are the only log I have

[2020-05-15T12:07:10,933][INFO ][c.a.d.a.h.j.k.JwtVerifier] [rdfoelk01] Escaped Key ID from JWT Token
[2020-05-15T12:07:10,934][DEBUG][c.a.d.a.h.j.k.SelfRefreshingKeySet] [rdfoelk01] performRefresh(FJ86GcF3jTbNLOco4NvZkUCIUmfYCqoqtOQeMfbhNlE)
[2020-05-15T12:07:10,934][INFO ][c.a.d.a.h.j.k.SelfRefreshingKeySet] [rdfoelk01] Performing refresh 1
[2020-05-15T12:07:11,353][INFO ][c.a.d.a.h.j.k.SelfRefreshingKeySet] [rdfoelk01] KeySetProvider finished
[2020-05-15T12:07:11,359][WARN ][c.a.o.s.h.HTTPBasicAuthenticator] [rdfoelk01] No 'Basic Authorization' header, send 401 and 'WWW-Authenticate Basic'

So it looks like the keycloak configuration is quite good as elasticsearch is able to retrieve the key.
But there is no more information in logs to explain the 401.

Anyone has a idea on how to get more logging information ?

I’ve finally found that the logger configuration was incorrect as I had two entries “logger.opendistro_security.name”. I’ve removed the second and now I have much more logs.

[2020-05-25T10:01:50,354][TRACE][c.a.o.s.h.XFFResolver    ] [rdfoelk01] no xff done (enabled or no netty request) false,class org.elasticsearch.rest.RestRequest,{},{}
[2020-05-25T10:01:50,354][TRACE][c.a.o.s.a.BackendRegistry] [rdfoelk01] Rest authentication request from 10.255.56.154:1282 [original: /10.255.56.154:1282]
[2020-05-25T10:01:50,354][DEBUG][c.a.o.s.a.BackendRegistry] [rdfoelk01] Check authdomain for rest noop/0 or 2 in total
[2020-05-25T10:01:50,354][TRACE][c.a.o.s.a.BackendRegistry] [rdfoelk01] Try to extract auth creds from jwt-key-by-oidc http authenticator
[2020-05-25T10:01:50,356][INFO ][c.a.d.a.h.j.k.JwtVerifier] [rdfoelk01] Escaped Key ID from JWT Token
[2020-05-25T10:01:50,356][INFO ][c.a.d.a.h.j.k.SelfRefreshingKeySet] [rdfoelk01] Performing refresh 1
[2020-05-25T10:01:50,448][INFO ][c.a.d.a.h.j.k.SelfRefreshingKeySet] [rdfoelk01] KeySetProvider finished
[2020-05-25T10:01:50,449][DEBUG][c.a.o.s.a.BackendRegistry] [rdfoelk01] 'org.apache.cxf.rs.security.jose.jws.JwsException: INVALID_KEY' extracting credentials from jwt-key-by-oidc http authenticator
org.apache.cxf.rs.security.jose.jws.JwsException: INVALID_KEY
        at org.apache.cxf.rs.security.jose.jws.JwsUtils.checkSignatureKeySize(JwsUtils.java:521) ~[cxf-rt-rs-security-jose-3.2.2.jar:3.2.2]
        at org.apache.cxf.rs.security.jose.jws.PublicKeyJwsSignatureVerifier.<init>(PublicKeyJwsSignatureVerifier.java:47) ~[cxf-rt-rs-security-jose-3.2.2.jar:3.2.2]
        at org.apache.cxf.rs.security.jose.jws.PublicKeyJwsSignatureVerifier.<init>(PublicKeyJwsSignatureVerifier.java:41) ~[cxf-rt-rs-security-jose-3.2.2.jar:3.2.2]
        at org.apache.cxf.rs.security.jose.jws.JwsUtils.getPublicKeySignatureVerifier(JwsUtils.java:181) ~[cxf-rt-rs-security-jose-3.2.2.jar:3.2.2]
        at org.apache.cxf.rs.security.jose.jws.JwsUtils.getSignatureVerifier(JwsUtils.java:146) ~[cxf-rt-rs-security-jose-3.2.2.jar:3.2.2]
        at com.amazon.dlic.auth.http.jwt.keybyoidc.JwtVerifier.getInitializedSignatureVerifier(JwtVerifier.java:107) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.dlic.auth.http.jwt.keybyoidc.JwtVerifier.getVerifiedJwtToken(JwtVerifier.java:66) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.dlic.auth.http.jwt.AbstractHTTPJwtAuthenticator.extractCredentials0(AbstractHTTPJwtAuthenticator.java:103) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.dlic.auth.http.jwt.AbstractHTTPJwtAuthenticator.access$000(AbstractHTTPJwtAuthenticator.java:45) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.dlic.auth.http.jwt.AbstractHTTPJwtAuthenticator$1.run(AbstractHTTPJwtAuthenticator.java:85) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.dlic.auth.http.jwt.AbstractHTTPJwtAuthenticator$1.run(AbstractHTTPJwtAuthenticator.java:82) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at java.security.AccessController.doPrivileged(AccessController.java:312) ~[?:?]
        at com.amazon.dlic.auth.http.jwt.AbstractHTTPJwtAuthenticator.extractCredentials(AbstractHTTPJwtAuthenticator.java:82) ~[opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.opendistroforelasticsearch.security.auth.BackendRegistry.authenticate(BackendRegistry.java:412) [opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.opendistroforelasticsearch.security.filter.OpenDistroSecurityRestFilter.checkAndAuthenticateRequest(OpenDistroSecurityRestFilter.java:146) [opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.opendistroforelasticsearch.security.filter.OpenDistroSecurityRestFilter.access$000(OpenDistroSecurityRestFilter.java:63) [opendistro_security-1.4.0.0.jar:1.4.0.0]
        at com.amazon.opendistroforelasticsearch.security.filter.OpenDistroSecurityRestFilter$1.handleRequest(OpenDistroSecurityRestFilter.java:93) [opendistro_security-1.4.0.0.jar:1.4.0.0]
        at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:222) [elasticsearch-7.4.2.jar:7.4.2]
        at org.elasticsearch.rest.RestController.tryAllHandlers(RestController.java:295) [elasticsearch-7.4.2.jar:7.4.2]
        at org.elasticsearch.rest.RestController.dispatchRequest(RestController.java:166) [elasticsearch-7.4.2.jar:7.4.2]
        at com.amazon.opendistroforelasticsearch.security.ssl.http.netty.ValidatingDispatcher.dispatchRequest(ValidatingDispatcher.java:63) [opendistro_security-1.4.0.0.jar:1.4.0.0]
        at org.elasticsearch.http.AbstractHttpServerTransport.dispatchRequest(AbstractHttpServerTransport.java:322) [elasticsearch-7.4.2.jar:7.4.2]
        at org.elasticsearch.http.AbstractHttpServerTransport.handleIncomingRequest(AbstractHttpServerTransport.java:372) [elasticsearch-7.4.2.jar:7.4.2]
        at org.elasticsearch.http.AbstractHttpServerTransport.incomingRequest(AbstractHttpServerTransport.java:301) [elasticsearch-7.4.2.jar:7.4.2]
        at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:69) [transport-netty4-client-7.4.2.jar:7.4.2]
        at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:31) [transport-netty4-client-7.4.2.jar:7.4.2]
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at org.elasticsearch.http.netty4.Netty4HttpPipeliningHandler.channelRead(Netty4HttpPipeliningHandler.java:58) [transport-netty4-client-7.4.2.jar:7.4.2]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:328) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:302) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:287) [netty-handler-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475) [netty-handler-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1224) [netty-handler-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1271) [netty-handler-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283) [netty-codec-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1421) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:597) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:551) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511) [netty-transport-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918) [netty-common-4.1.38.Final.jar:4.1.38.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.38.Final.jar:4.1.38.Final]
        at java.lang.Thread.run(Thread.java:830) [?:?]
[2020-05-25T10:01:50,451][DEBUG][c.a.o.s.a.BackendRegistry] [rdfoelk01] Check authdomain for rest internal/1 or 2 in total
[2020-05-25T10:01:50,452][TRACE][c.a.o.s.a.BackendRegistry] [rdfoelk01] Try to extract auth creds from basic http authenticator
[2020-05-25T10:01:50,452][WARN ][c.a.o.s.h.HTTPBasicAuthenticator] [rdfoelk01] No 'Basic Authorization' header, send 401 and 'WWW-Authenticate Basic'
[2020-05-25T10:01:50,452][TRACE][c.a.o.s.a.i.AuditLogImpl ] [rdfoelk01] Check for REST category:FAILED_LOGIN, effectiveUser:<NONE>, request:/

I still do no understand what’s wrong because the kid provided in my jwt is good. I’m using the same with other applications.
Here is the header of the JWT token:

{
  "alg": "RS256",
  "typ": "JWT",
  "kid": "FJ86GcF3jTbNLOco4NvZkUCIUmfYCqoqtOQeMfbhNlE"
}

and here’s the result from https://<KEYCLOAK_URL>/auth/realms/cloud/protocol/openid-connect/certs

{"keys":[{"kid":"FJ86GcF3jTbNLOco4NvZkUCIUmfYCqoqtOQeMfbhNlE","kty":"RSA","alg":"RS256","use":"sig","n":"q1awrk7QK24Gmcy9Yb4dMbS-ZnO6NDaj1Z2F5C74HMIgtwYyxsNbRhBqCWlw7kmkZZaG5udyQYY8d91Db_uc_1DBuJMrQVsYXjVSpy-hoKpTWmzGhXzyzwhfJAICp7Iu_TTKPp-ip0mPGHlJnnP6dr4ztjY7EgFXFhEDFYSd9S8","e":"AQAB","x5c":["MIIBsDCCARkCBgFxQFtmCTANBgkqhkiG9w0BAQsFADAeMRwwGgYDVQQDDBNjbG91ZDIwMjAwNDAzMTYwNDIxMB4XDTIwMDQwMzE0MDI0M1oXDTMwMDQwMzE0MDQyM1owHjEcMBoGA1UEAwwTY2xvdWQyMDIwMDQwMzE2MDQyMTCBnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEAq1awrk7QK24Gmcy9Yb4dMbS+ZnO6NDaj1Z2F5C74HMIgtwYyxsNbRhBqCWlw7kmkZZaG5udyQYY8d91Db/uc/1DBuJMrQVsYXjVSpy+hoKpTWmzGhXzyzwhfJAICp7Iu/TTKPp+ip0mPGHlJnnP6dr4ztjY7EgFXFhEDFYSd9S8CAwEAATANBgkqhkiG9w0BAQsFAAOBgQBDK0FKXzLPCgK18zR2shExWNI1LjAsqqua7OsIjyz2Xf9Nlhg4POEjSG63moR3yuFpbzsYwbb5iLTzEHFGPm/kHdtouUOfOpdlQWHw4HZT/rfYu7xcu4xBs4rJdtbw0ZFyN/c4Ynnrhz0EF0wW4FU5Jk+Wj5xaA834VUI0AmQg/w=="],"x5t":"GpyvqP8Vw8KQN7amQLp5wthp7tU","x5t#S256":"J9EOXp3v8E9UXRSIatm34z9CtgkW9wHHuBzdUUdqduA"}]}

Any help will be appreciated

The message is not very clear “INVALID_KEY” but as it has been raised by checkSignatureKeySize, I’ve been able to find that the minimum key length authorized is 2048 ( see code https://github.com/apache/cxf/blob/master/rt/rs/security/jose-parent/jose/src/main/java/org/apache/cxf/rs/security/jose/jws/JwsUtils.java ).
So we have to change the rsa key of our keycloak server which is a 1024 bit length.

I got stuck with the exact same issue for days! thank you very much @dfournout for leaving the solution here. I got it worked finally!

here is how to regenerate the rsa key
https://www.keycloak.org/docs/6.0/server_admin/#adding-a-generated-keypair

then disable and set the old one to active:off!