Skip to content
This repository has been archived by the owner on Jan 24, 2024. It is now read-only.

[BUG] Should support delaying response to failed client authentication #668

Closed
Demogorgon314 opened this issue Aug 20, 2021 · 2 comments · Fixed by #709
Closed

[BUG] Should support delaying response to failed client authentication #668

Demogorgon314 opened this issue Aug 20, 2021 · 2 comments · Fixed by #709
Assignees
Labels

Comments

@Demogorgon314
Copy link
Member

Demogorgon314 commented Aug 20, 2021

Describe the bug
When KoP enable authentication, if kafka client not config with authentication, the broker error logs is too many. We don't need the authentication error stack trace.
In ShutdownableThread Shutting down,Shutdown completed should be debug level logs.
In KafkaRequestHandler when channel close, should be debug level log too.

Important : We need implement KIP-306 to prevent potential DoS.

16:31:33.582 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.KafkaCommandDecoder - close channel [id: 0x0a847838, L:/127.0.0.1:9092 - R:/127.0.0.1:54413] with 1 pending responses
16:31:33.582 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-produce] Shutting down
16:31:33.582 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-produce] Shutdown completed
16:31:33.582 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-fetch] Shutting down
16:31:33.582 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-fetch] Shutdown completed
16:31:33.583 [pulsar-io-29-21] INFO  io.streamnative.pulsar.handlers.kop.KafkaRequestHandler - channel inactive [id: 0x0a847838, L:/127.0.0.1:9092 ! R:/127.0.0.1:54413]
16:31:33.686 [ExpirationReaper-produce] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-produce] Starting
16:31:33.686 [ExpirationReaper-fetch] INFO  io.streamnative.pulsar.handlers.kop.utils.ShutdownableThread - [ExpirationReaper-fetch] Starting
16:31:33.686 [pulsar-io-29-23] INFO  io.streamnative.pulsar.handlers.kop.KafkaRequestHandler - channel active: [id: 0x2ae3dd41, L:/127.0.0.1:9092 - R:/127.0.0.1:54414]
16:31:33.687 [pulsar-io-29-23] ERROR io.streamnative.pulsar.handlers.kop.KafkaCommandDecoder - unexpected error in authenticate:
javax.naming.AuthenticationException: Unexpected Kafka request of type METADATA during SASL handshake
	at io.streamnative.pulsar.handlers.kop.security.SaslAuthenticator.handleKafkaRequest(SaslAuthenticator.java:233) ~[8hFx6yeFnnzVem5ezdmT4g/:?]
	at io.streamnative.pulsar.handlers.kop.security.SaslAuthenticator.authenticate(SaslAuthenticator.java:118) ~[8hFx6yeFnnzVem5ezdmT4g/:?]
	at io.streamnative.pulsar.handlers.kop.KafkaRequestHandler.authenticate(KafkaRequestHandler.java:344) ~[8hFx6yeFnnzVem5ezdmT4g/:?]
	at io.streamnative.pulsar.handlers.kop.KafkaCommandDecoder.channelRead(KafkaCommandDecoder.java:210) [8hFx6yeFnnzVem5ezdmT4g/:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) [io.netty-netty-codec-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) [io.netty-netty-codec-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [io.netty-netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [io.netty-netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [io.netty-netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.66.Final.jar:4.1.66.Final]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_292]

Expected behavior
Just like kafka broker

[2021-08-20 16:05:28,747] INFO [SocketServer brokerId=0] Failed authentication with /127.0.0.1 (Unexpected Kafka request of type METADATA during SASL handshake.) (org.apache.kafka.common.network.Selector)
[2021-08-20 16:05:29,158] INFO [SocketServer brokerId=0] Failed authentication with /127.0.0.1 (Unexpected Kafka request of type METADATA during SASL handshake.) (org.apache.kafka.common.network.Selector)
[2021-08-20 16:05:29,568] INFO [SocketServer brokerId=0] Failed authentication with /127.0.0.1 (Unexpected Kafka request of type METADATA during SASL handshake.) (org.apache.kafka.common.network.Selector)
@Demogorgon314
Copy link
Member Author

I also noticed that when we use kafka broker, the error retry interval it's about 400ms, in KoP the retry interval it's about 100ms.

@Demogorgon314
Copy link
Member Author

Demogorgon314 commented Aug 20, 2021

I also noticed that when we use kafka broker, the error retry interval it's about 400ms, in KoP the retry interval it's about 100ms.

We may need implement the KIP-306 to resolve this problem (https://cwiki.apache.org/confluence/display/KAFKA/KIP-306%3A+Configuration+for+Delaying+Response+to+Failed+Client+Authentication).

@Demogorgon314 Demogorgon314 changed the title [BUG] When KoP enable authentication, if kafka client not config with authentication, the broker error logs is too many. [BUG] Should support delaying response to failed client authentication Sep 6, 2021
BewareMyPower pushed a commit that referenced this issue Sep 7, 2021
Fix #668

## Motivation
Performing authentication is one of the most expensive operation performed in the network thread, so much so that it could end up saturating them, preventing from getting any useful work from being done.

## Modifications
* Support delay close on authentication failed.
* Change logs level.
BewareMyPower pushed a commit that referenced this issue Sep 8, 2021
Fix #668

## Motivation
Performing authentication is one of the most expensive operation performed in the network thread, so much so that it could end up saturating them, preventing from getting any useful work from being done.

## Modifications
* Support delay close on authentication failed.
* Change logs level.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant