ERROR Failed to evaluate client token: javax.security.sasl.SaslException: Final handshake step failed
- Dominant language
- Java
- Stars
- 15.3k
- Forks
- 3.8k
- Avg merge
- 1d 14h
- Merged PRs (30d)
- 160
Description
**Describe the bug**
1. The version of puslar cluster is 2.7.0.
2. Cluster uses kerberos for authentication.
3. When use tools pulsar-admin to list topics under public/default, pulsar-admin shows the following exceptions:
```shell
org.apache.pulsar.client.impl.auth.PulsarSaslClient - Using JAAS/SASL/GSSAPI auth to connect to server Principal broker/host12,
null
Reason: java.util.concurrent.TimeoutException
```
and the broker shows the following exceptions:
```shell
20:47:18.326 [pulsar-web-42-1] ERROR org.apache.pulsar.broker.authentication.PulsarSaslServer - response: Failed to evaluate client token:
javax.security.sasl.SaslException: Final handshake step failed
at com.sun.security.sasl.gsskerb.GssKrb5Server.doHandshake2(GssKrb5Server.java:331) ~[?:1.8.0_271]
at com.sun.security.sasl.gsskerb.GssKrb5Server.evaluateResponse(GssKrb5Server.java:161) ~[?:1.8.0_271]
at org.apache.pulsar.broker.authentication.PulsarSaslServer.response(PulsarSaslServer.java:147) ~[org.apache.pulsar-pulsar-broker-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.broker.authentication.SaslAuthenticationDataSource.authenticate(SaslAuthenticationDataSource.java:45) ~[org.apache.pulsar-pulsar-broker-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.broker.authentication.SaslAuthenticationState.authenticate(SaslAuthenticationState.java:70) ~[org.apache.pulsar-pulsar-broker-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.broker.authentication.AuthenticationProviderSasl.authenticateHttpRequest(AuthenticationProviderSasl.java:264) ~[org.apache.pulsar-pulsar-broker-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.broker.web.AuthenticationFilter.doFilter(AuthenticationFilter.java:88) ~[org.apache.pulsar-pulsar-broker-common-2.7.0.jar:2.7.0]
at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) ~[org.eclipse.jetty-jetty-servlet-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1609) ~[org.eclipse.jetty-jetty-servlet-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:561) ~[org.eclipse.jetty-jetty-servlet-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1612) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[org.eclipse.jetty-jetty-servlet-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1582) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:179) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383) ~[org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:556) [org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375) [org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273) [org.eclipse.jetty-jetty-server-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [org.eclipse.jetty-jetty-io-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [org.eclipse.jetty-jetty-io-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [org.eclipse.jetty-jetty-io-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [org.eclipse.jetty-jetty-util-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [org.eclipse.jetty-jetty-util-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [org.eclipse.jetty-jetty-util-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [org.eclipse.jetty-jetty-util-9.4.33.v20201020.jar:9.4.33.v20201020]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375) [org.eclipse.jetty-jetty-util-9.4.33.v20201020.jar:9.4.33.v20201020]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_271]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_271]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.51.Final.jar:4.1.51.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_271]
Caused by: org.ietf.jgss.GSSException: Defective token detected (Mechanism level: Kerberos GSS-API Mechanism Token:Defective Token ID!)
at sun.security.jgss.krb5.MessageToken_v2$MessageTokenHeader.(MessageToken_v2.java:561) ~[?:1.8.0_271]
at sun.security.jgss.krb5.MessageToken_v2.(MessageToken_v2.java:194) ~[?:1.8.0_271]
at sun.security.jgss.krb5.MessageToken_v2.(MessageToken_v2.java:165) ~[?:1.8.0_271]
at sun.security.jgss.krb5.WrapToken_v2.(WrapToken_v2.java:71) ~[?:1.8.0_271]
at sun.security.jgss.krb5.Krb5Context.unwrap(Krb5Context.java:1058) ~[?:1.8.0_271]
at sun.security.jgss.GSSContextImpl.unwrap(GSSContextImpl.java:403) ~[?:1.8.0_271]
at com.sun.security.sasl.gsskerb.GssKrb5Server.doHandshake2(GssKrb5Server.java:254) ~[?:1.8.0_271]
... 40 more
20:47:18.333 [pulsar-web-42-1] WARN org.apache.pulsar.broker.web.AuthenticationFilter - [22.21.8.34] Failed to authenticate HTTP request: Final handshake step failed
20:47:18.334 [pulsar-web-42-1] INFO org.eclipse.jetty.server.RequestLog - 22.21.8.34 - - [29/Nov/2021:20:47:18 +0800] "GET /admin/v2/non-persistent/public/default/0x00000000_0x10000000 HTTP/1.1" 401 194 "-" "Jersey/2.31 (HttpUrlConnection 1.8.0_271)" 9
20:47:18.336 [jersey-client-async-executor-6] WARN org.apache.pulsar.client.impl.auth.AuthenticationSasl - Failed to perform http request
javax.ws.rs.ProcessingException: java.lang.NullPointerException
at org.glassfish.jersey.client.ClientRuntime.processFailure(ClientRuntime.java:247) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.processFailure(ClientRuntime.java:242) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.access$100(ClientRuntime.java:62) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime$2.lambda$failure$1(ClientRuntime.java:178) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:288) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime$2.failure(ClientRuntime.java:178) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.internal.HttpUrlConnector.apply(HttpUrlConnector.java:273) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.lambda$null$6(ClientRuntime.java:182) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:288) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.lambda$createRunnableForAsyncProcessing$7(ClientRuntime.java:156) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_271]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_271]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_271]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_271]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_271]
Caused by: java.lang.NullPointerException
at java.util.Base64$Decoder.decode(Base64.java:549) ~[?:1.8.0_271]
at org.apache.pulsar.client.impl.auth.AuthenticationSasl.newRequestHeader(AuthenticationSasl.java:269) ~[org.apache.pulsar-pulsar-client-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.client.impl.auth.AuthenticationSasl.newRequestBuilder(AuthenticationSasl.java:198) ~[org.apache.pulsar-pulsar-client-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.client.impl.auth.AuthenticationSasl.authenticationStage(AuthenticationSasl.java:307) ~[org.apache.pulsar-pulsar-client-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.client.impl.auth.AuthenticationSasl$1.completed(AuthenticationSasl.java:313) ~[org.apache.pulsar-pulsar-client-auth-sasl-2.7.0.jar:2.7.0]
at org.apache.pulsar.client.impl.auth.AuthenticationSasl$1.completed(AuthenticationSasl.java:308) ~[org.apache.pulsar-pulsar-client-auth-sasl-2.7.0.jar:2.7.0]
at org.glassfish.jersey.client.JerseyInvocation$1.completed(JerseyInvocation.java:814) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.processResponse(ClientRuntime.java:229) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime.access$200(ClientRuntime.java:62) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime$2.lambda$response$0(ClientRuntime.java:173) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:292) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:274) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:244) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:288) ~[org.glassfish.jersey.core-jersey-common-2.31.jar:?]
at org.glassfish.jersey.client.ClientRuntime$2.response(ClientRuntime.java:173) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
at org.glassfish.jersey.client.internal.HttpUrlConnector.apply(HttpUrlConnector.java:269) ~[org.glassfish.jersey.core-jersey-client-2.31.jar:?]
... 13 more
```
**To Reproduce**
Steps to reproduce the behavior:
1. execute the following command:
```shell
./bin/pulsar-admin topics list public/default
```
2. Wait for one hour (which is the token expired time hardcode in the broker), and execute the command in step 1 again.
**Expected behavior**
The command list all the topics without error.
**Possiable Reason**
1. When the client make a request to the server, there is a two-stage-handshake authentication, after which the server will generate a token to client, and then the client could commenicate with the server with given token.
2. When the token expired, the client need to do the two-stage-authentication again.
**Debug**
1. when use linux tools tcpdump to capture http message at port 8080. I find there is something unnornal at the second handshake stage of the authentication.
2. The following picture is captured from file "pulsar-client-auth-sasl\src\main\java\org\apache\pulsar\client\impl\auth\AuthenticationSasl.java"

3. From the picture, we can know that, when the token expired, it will redo the two-stage-handshake authentication, and re-assignment the authData. But the authData is not changed out of the functon(in the caller of the function). In the other word, the authData is correct in the first-stage-handshake, but incorrect in the second-stage-handshake.
Contributor guide
Assessment
This issue has not been assessed yet.