aerfalwl opened a new issue #13060:
URL: https://github.com/apache/pulsar/issues/13060
**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.<init>(MessageToken_v2.java:561)
~[?:1.8.0_271]
at
sun.security.jgss.krb5.MessageToken_v2.<init>(MessageToken_v2.java:194)
~[?:1.8.0_271]
at
sun.security.jgss.krb5.MessageToken_v2.<init>(MessageToken_v2.java:165)
~[?:1.8.0_271]
at sun.security.jgss.krb5.WrapToken_v2.<init>(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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
