Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication #1062

jffp113 · 2023-07-20T19:55:33Z

Motivation

When using pulsar tls authentication with a broker that sets the authenticationRefreshCheckSeconds the connection was dropped for each authentication refresh check. After analyzing logs and tcpdumps I concluded that this error appears because the tls authentication is returning null, witch does not pass a validation in the broker.
After analyzing the tls auth implementation in Java (that works), I concluded that the GetData method should return empty byte array instead of nil.

2023-07-20 15:32:32 2023-07-20T14:32:32,225+0000 [pulsar-io-29-5] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:42304] Refreshing authentication credentials for originalPrincipal null and authRole pulsar-admin
2023-07-20 15:32:32 2023-07-20T14:32:32,225+0000 [pulsar-io-29-9] INFO  org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:42306] Refreshing authentication credentials for originalPrincipal null and authRole pulsar-admin
2023-07-20 15:32:32 2023-07-20T14:32:32,225+0000 [pulsar-io-29-6] INFO  org.apache.pulsar.broker.service.ServerCnx - [/172.18.0.1:33616] Refreshing authentication credentials for originalPrincipal null and authRole pulsar-admin
2023-07-20 15:32:32 2023-07-20T14:32:32,228+0000 [pulsar-io-29-6] WARN  org.apache.pulsar.broker.service.ServerCnx - [/172.18.0.1:33616] Got exception java.lang.IllegalArgumentException
2023-07-20 15:32:32     at com.google.common.base.Preconditions.checkArgument(Preconditions.java:131)
2023-07-20 15:32:32     at org.apache.pulsar.broker.service.ServerCnx.handleAuthResponse(ServerCnx.java:897)
2023-07-20 15:32:32     at org.apache.pulsar.common.protocol.PulsarDecoder.channelRead(PulsarDecoder.java:362)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-07-20 15:32:32     at io.netty.handler.flow.FlowControlHandler.dequeue(FlowControlHandler.java:200)
2023-07-20 15:32:32     at io.netty.handler.flow.FlowControlHandler.channelRead(FlowControlHandler.java:162)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-07-20 15:32:32     at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
2023-07-20 15:32:32     at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-07-20 15:32:32     at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373)
2023-07-20 15:32:32     at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1247)
2023-07-20 15:32:32     at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1287)
2023-07-20 15:32:32     at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
2023-07-20 15:32:32     at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
2023-07-20 15:32:32     at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-07-20 15:32:32     at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
2023-07-20 15:32:32     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-07-20 15:32:32     at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
2023-07-20 15:32:32     at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
2023-07-20 15:32:32     at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
2023-07-20 15:32:32     at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397)
2023-07-20 15:32:32     at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
2023-07-20 15:32:32     at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2023-07-20 15:32:32     at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2023-07-20 15:32:32     at java.base/java.lang.Thread.run(Thread.java:829)
2023-07-20 15:32:32

Modifications

Changed tls auth GetData to return empty byte array instead of nil.

Verifying this change

Make sure that the change passes the CI checks.

This change is a trivial rework / code cleanup without any test coverage.

Does this pull request potentially affect one of the following parts:

Dependencies (does it add or upgrade a dependency): no
The public API: no
The schema: no
The default values of configurations: no
The wire protocol: no

Documentation

Does this pull request introduce a new feature? no

RobertIndie · 2023-07-21T02:37:45Z

Hi, @jffp113. Thanks for your PR. :)
Could you add a test? Is there any reproducible code?

jffp113 · 2023-07-21T07:27:07Z

Hi @RobertIndie,
I have tested this fix locally with a producer and pulsar standalone.
How can I write a integration test to check for connection drops after a auth challenge?

jffp113 · 2023-07-24T15:12:01Z

This is the line of code that forces the connection to be reestablished: https://github.com/apache/pulsar/blob/b69f4efa6058c3f51885a61a2b3acb46f8b730f4/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/ServerCnx.java#L897

RobertIndie · 2023-07-25T10:24:22Z

Hi @jffp113 , Could you share your reproduce steps?

jffp113 · 2023-07-25T10:31:07Z

Hi @RobertIndie,

Yes.

You need to add authenticationRefreshCheckSeconds config into the broker configuration. You can set for example 30 seconds so that the client can crash fast. authenticationRefreshCheckSeconds forces authentication every x seconds. This is a good practice, for example, a certificate expiry date is only rechecked if there is a refresh authentication.

Then you configure simple golang pulsar producer that uses tls authentication.

You only need that two steps. I have tested this on pulsar 2.10.3 version.

If you need a more detail explanation I'm happy to provide.

jffp113 · 2023-07-25T10:56:09Z

Hi again,

I found the line of code in the java client that converts a null/empty auth data to a empty string:
https://github.com/apache/pulsar/blob/69d7a2bf14555f11a716a9545c5cf391d8179a27/pulsar-client-api/src/main/java/org/apache/pulsar/client/api/AuthenticationDataProvider.java#L161

RobertIndie · 2023-07-25T11:18:45Z

Unfortunately, I couldn't reproduce it. I used AuthenticationProviderTls and set authenticationRefreshCheckSeconds=5. But it didn't refresh the authentication check.

After checking the code, just found that AuthenticationProviderTls doesn't override newAuthState method so it is returning the OneStageAuthenticationState:https://github.com/apache/pulsar/blob/master/pulsar-broker-common/src/main/java/org/apache/pulsar/broker/authentication/AuthenticationProvider.java#L100-L105.
The OneStageAuthenticationState will never be expired. Therefore it seems that is should never pass this condition: https://github.com/apache/pulsar/blob/b69f4efa6058c3f51885a61a2b3acb46f8b730f4/pulsar-broker/src/main/java/org/apache/pulsar/broker/service/ServerCnx.java#L720-L722
So it won't trigger the refresh check. I'm not sure what I didn't set up correctly.

Anyway, I'm +1 for your PR. But I'm trying to reproduce the issue to investigate it further.

jffp113 · 2023-07-25T11:40:38Z

I noticed that we have a custom authentication plugin that does not always return false in AuthenticationState::isExpired:
https://github.com/apache/pulsar/blob/69d7a2bf14555f11a716a9545c5cf391d8179a27/pulsar-broker-common/src/main/java/org/apache/pulsar/broker/authentication/AuthenticationState.java#L107C28-L107C28

Sorry for the confusion.

RobertIndie · 2023-07-26T10:22:38Z

@jffp113 Thanks for your explanation. But it doesn't seem to make sense to refresh the tls auth. And it always returns the empty auth data.

RobertIndie

I approve your PR because this issue may happen when using the custom authentication provider. And it also makes the behavior consistent with the Java client.

jffp113 · 2023-07-26T10:25:46Z

@RobertIndie If want to check if the certificate is still valid we must refresh tls (e.g check the CRL, check expires at field, etc)

jffp113 · 2023-07-26T10:30:30Z

We could make this change generic, and if any provider returns nil we change to []byte{}.
I did this in the cpp client:
apache/pulsar-client-cpp#304

RobertIndie · 2023-07-26T10:46:12Z

If want to check if the certificate is still valid we must refresh tls (e.g check the CRL, check expires at field, etc)

This would only happen when we reconnect the client connection. But refreshing the authentication won't check the tls certificate.

We could make this change generic, and if any provider returns nil we change to []byte{}.

I'm +1 for this.

…using tls authentication (apache#1062) ### Motivation When using pulsar tls authentication with a broker that sets the authenticationRefreshCheckSeconds the connection was dropped for each authentication refresh check. After analyzing logs and tcpdumps I concluded that this error appears because the tls authentication is returning null, witch does not pass a validation in the broker. After analyzing the tls auth implementation in Java (that works), I concluded that the GetData method should return empty byte array instead of nil. ### Modifications Changed tls auth GetData to return empty byte array instead of nil. --------- Co-authored-by: Jorge Pereira <jorge.pereira@cross-join.com>

…using tls authentication (#1062) ### Motivation When using pulsar tls authentication with a broker that sets the authenticationRefreshCheckSeconds the connection was dropped for each authentication refresh check. After analyzing logs and tcpdumps I concluded that this error appears because the tls authentication is returning null, witch does not pass a validation in the broker. After analyzing the tls auth implementation in Java (that works), I concluded that the GetData method should return empty byte array instead of nil. ### Modifications Changed tls auth GetData to return empty byte array instead of nil. --------- Co-authored-by: Jorge Pereira <jorge.pereira@cross-join.com> (cherry picked from commit 16a0299)

fix: client reconnected every authenticationRefreshCheckSeconds

59456c4

jffp113 changed the title ~~Fix: client reconnected every authenticationRefreshCheckSeconds~~ Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication Jul 20, 2023

RobertIndie assigned jffp113 Jul 21, 2023

RobertIndie added type/bug area/security labels Jul 21, 2023

RobertIndie added this to the v0.12.0 milestone Jul 21, 2023

jffp113 mentioned this pull request Jul 25, 2023

Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication apache/pulsar-client-cpp#304

Merged

1 task

RobertIndie approved these changes Jul 26, 2023

View reviewed changes

Jorge Pereira added 2 commits July 26, 2023 11:54

fix: client reconnected every authenticationRefreshCheckSeconds

8bc1cd5

fix: client reconnected every authenticationRefreshCheckSeconds

bcef09a

RobertIndie approved these changes Jul 26, 2023

View reviewed changes

RobertIndie merged commit 16a0299 into apache:master Jul 27, 2023
6 checks passed

RobertIndie added release/0.11.1 cherry-picked/branch-0.11.0 labels Sep 7, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication #1062

Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication #1062

jffp113 commented Jul 20, 2023 •

edited by RobertIndie

Loading

RobertIndie commented Jul 21, 2023

jffp113 commented Jul 21, 2023 •

edited

Loading

jffp113 commented Jul 24, 2023

RobertIndie commented Jul 25, 2023

jffp113 commented Jul 25, 2023 •

edited

Loading

jffp113 commented Jul 25, 2023

RobertIndie commented Jul 25, 2023

jffp113 commented Jul 25, 2023 •

edited

Loading

RobertIndie commented Jul 26, 2023

RobertIndie left a comment

jffp113 commented Jul 26, 2023

jffp113 commented Jul 26, 2023 •

edited

Loading

RobertIndie commented Jul 26, 2023

Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication #1062

Fix: client reconnected every authenticationRefreshCheckSeconds when using tls authentication #1062

Conversation

jffp113 commented Jul 20, 2023 • edited by RobertIndie Loading

Motivation

Modifications

Verifying this change

Does this pull request potentially affect one of the following parts:

Documentation

RobertIndie commented Jul 21, 2023

jffp113 commented Jul 21, 2023 • edited Loading

jffp113 commented Jul 24, 2023

RobertIndie commented Jul 25, 2023

jffp113 commented Jul 25, 2023 • edited Loading

jffp113 commented Jul 25, 2023

RobertIndie commented Jul 25, 2023

jffp113 commented Jul 25, 2023 • edited Loading

RobertIndie commented Jul 26, 2023

RobertIndie left a comment

Choose a reason for hiding this comment

jffp113 commented Jul 26, 2023

jffp113 commented Jul 26, 2023 • edited Loading

RobertIndie commented Jul 26, 2023

jffp113 commented Jul 20, 2023 •

edited by RobertIndie

Loading

jffp113 commented Jul 21, 2023 •

edited

Loading

jffp113 commented Jul 25, 2023 •

edited

Loading

jffp113 commented Jul 25, 2023 •

edited

Loading

jffp113 commented Jul 26, 2023 •

edited

Loading