pravega / pravega-benchmark

Performance benchmark tool for Pravega
Apache License 2.0
8 stars 22 forks source link

Segment-Store Error : SSLHandshakeException when TLS is enabled #105

Closed damienmas closed 4 years ago

damienmas commented 4 years ago

If TLS is anabled pravega-benchmark is not working

the client is able to communicate properly with the pravega-controller but then it fails to connect on the SS (segment-store).

2020-04-14 16:31:30:828 +0000 [main] INFO io.pravega.keycloak.client.PravegaKeycloakCredentials - Loaded Keycloak Credentials 2020-04-14 16:31:30:828 +0000 [main] INFO io.pravega.client.ClientConfig - Client credentials were extracted from environment variables. They weren't explicitly supplied as a Credentials object or system properties. 2020-04-14 16:31:30:829 +0000 [main] INFO io.pravega.client.stream.impl.ControllerImpl - Controller client connecting to server at pravega-controller.minikube.FQDN-OBFUSCATED:443 2020-04-14 16:31:30:930 +0000 [main] INFO io.pravega.client.admin.impl.StreamManagerImpl - Creating scope/stream: benchmark/benchmark1 with configuration: StreamConfiguration(scalingPolicy=ScalingPolicy(scaleType=FIXED_NUM_SEGMENTS, targetRate=0, scaleFactor=0, minNumSegments=1), retentionPolicy=null, timestampAggregationTimeout=0) 2020-04-14 16:31:30:956 +0000 [StreamManager-Controller-1] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=-6210969470396107479] Tagging client request (createStream-benchmark-benchmark1). 2020-04-14 16:31:31:058 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Attempting to refresh the controller server endpoints 2020-04-14 16:31:31:298 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Updating client with controllers: [[[pravega-controller.minikube.FQDN-OBFUSCATED/10.247.191.79:443]/{}]] 2020-04-14 16:31:31:431 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Rescheduling ControllerNameResolver task for after 120000 ms 2020-04-14 16:31:32:606 +0000 [grpc-default-executor-1] INFO io.pravega.client.stream.impl.ControllerImpl - [requestId=-6210969470396107479] Stream created successfully: benchmark1 2020-04-14 16:31:32:997 +0000 [main] INFO io.pravega.keycloak.client.PravegaKeycloakCredentials - Loaded Keycloak Credentials 2020-04-14 16:31:32:997 +0000 [main] INFO io.pravega.client.ClientConfig - Client credentials were extracted from environment variables. They weren't explicitly supplied as a Credentials object or system properties. 2020-04-14 16:31:33:035 +0000 [main] INFO io.pravega.client.stream.impl.ClientFactoryImpl - Creating writer: 0b375a0a-f9c9-4e70-9494-16f1799857fd for stream: benchmark1 with configuration: EventWriterConfig(initalBackoffMillis=1, maxBackoffMillis=20000, retryAttempts=10, backoffMultiple=10, enableConnectionPooling=true, transactionTimeoutTime=89999, automaticallyNoteTime=false) 2020-04-14 16:31:33:059 +0000 [main] INFO io.pravega.client.stream.impl.SegmentSelector - Refreshing segments for stream StreamImpl(scope=benchmark, streamName=benchmark1) 2020-04-14 16:31:33:065 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Attempting to refresh the controller server endpoints 2020-04-14 16:31:33:065 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Updating client with controllers: [[[pravega-controller.minikube.FQDN-OBFUSCATED/10.247.191.79:443]/{}]] 2020-04-14 16:31:33:068 +0000 [fetch-controllers-1] INFO io.pravega.client.stream.impl.ControllerResolverFactory - Rescheduling ControllerNameResolver task for after 120000 ms 2020-04-14 16:31:33:703 +0000 [clientInternal-2-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Fetching endpoint for segment benchmark/benchmark1/0.#epoch.0, writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e 2020-04-14 16:31:33:707 +0000 [ForkJoinPool-2-worker-1] INFO io.pravega.perf.WriterWorker - EventsWriter: Running 2020-04-14 16:31:33:802 +0000 [clientInternal-2-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Establishing connection to PravegaNodeUri(endpoint=nautilus-pravega-segmentstore-0.pravega.minikube.FQDN-OBFUSCATED, port=12345) for benchmark/benchmark1/0.#epoch.0, writerID: 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e 2020-04-14 16:31:33:812 +0000 [clientInternal-2-1] INFO io.pravega.client.netty.impl.ConnectionPoolImpl - Creating a new connection to PravegaNodeUri(endpoint=nautilus-pravega-segmentstore-0.pravega.minikube.FQDN-OBFUSCATED, port=12345) 2020-04-14 16:31:33:851 +0000 [clientInternal-2-1] INFO io.pravega.client.netty.impl.FlowHandler - Creating Flow 1 for endpoint nautilus-pravega-segmentstore-0.pravega.minikube.FQDN-OBFUSCATED. The current Channel is null. 2020-04-14 16:31:34:116 +0000 [epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection established with endpoint nautilus-pravega-segmentstore-0.pravega.minikube.FQDN-OBFUSCATED on channel [id: 0x7060461a] 2020-04-14 16:31:34:276 +0000 [epollEventLoopGroup-4-1] INFO io.pravega.client.netty.impl.FlowHandler - Connection drop observed with endpoint nautilus-pravega-segmentstore-0.pravega.minikube.FQDN-OBFUSCATED 2020-04-14 16:31:34:277 +0000 [epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Failing connection for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e with exception io.pravega.shared.protocol.netty.ConnectionFailedException: Connection dropped for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e 2020-04-14 16:31:34:278 +0000 [epollEventLoopGroup-4-1] INFO io.pravega.client.segment.impl.SegmentOutputStreamImpl - Handling exception io.pravega.shared.protocol.netty.ConnectionFailedException: Connection dropped for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e for connection io.pravega.client.netty.impl.ClientConnectionImpl@16c228b0 on writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e. SetupCompleted: false, Closed: false 2020-04-14 16:31:34:278 +0000 [epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - Connection for segment benchmark/benchmark1/0.#epoch.0 on writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e failed due to: Connection dropped for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e 2020-04-14 16:31:34:279 +0000 [epollEventLoopGroup-4-1] WARN io.pravega.client.segment.impl.SegmentOutputStreamImpl - 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e Failed to connect: java.util.concurrent.CompletionException: io.pravega.shared.protocol.netty.ConnectionFailedException: Connection dropped for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) at java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:888) at java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:866) at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.failConnection(SegmentOutputStreamImpl.java:222) at io.pravega.client.segment.impl.SegmentOutputStreamImpl$State.access$700(SegmentOutputStreamImpl.java:99) at io.pravega.client.segment.impl.SegmentOutputStreamImpl.failConnection(SegmentOutputStreamImpl.java:549) at io.pravega.client.segment.impl.SegmentOutputStreamImpl.access$500(SegmentOutputStreamImpl.java:70) at io.pravega.client.segment.impl.SegmentOutputStreamImpl$ResponseProcessor.connectionDropped(SegmentOutputStreamImpl.java:306) at io.pravega.client.netty.impl.FlowHandler.lambda$channelUnregistered$0(FlowHandler.java:221) at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597) at io.pravega.client.netty.impl.FlowHandler.channelUnregistered(FlowHandler.java:218) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160) at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160) at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160) at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:160) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1412) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) Caused by: io.pravega.shared.protocol.netty.ConnectionFailedException: Connection dropped for writer 3b8f2f2d-0aba-4a4d-8722-bbf4ccbc4a3e ... 30 more

See error below coming from the SS

2020-04-14 16:33:28,166 341326926 [epollEventLoopGroup-11-2] ERROR i.p.s.p.n.ExceptionLoggingHandler - Uncaught exception on connection /172.17.0.1:61466 io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: error:100000f7:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:472) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:421) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:321) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) Caused by: javax.net.ssl.SSLHandshakeException: error:100000f7:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.sslReadErrorResult(ReferenceCountedOpenSslEngine.java:1140) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1101) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1169) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1212) at io.netty.handler.ssl.SslHandler$SslEngineType$1.unwrap(SslHandler.java:216) at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1297) at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1211) at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1245) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) ... 14 common frames omitted 2020-04-14 16:33:28,166 341326926 [epollEventLoopGroup-11-2] ERROR i.p.s.s.h.h.ServerConnectionInboundHandler - Caught exception on connection: io.netty.handler.codec.DecoderException: javax.net.ssl.SSLHandshakeException: error:100000f7:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:472) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799) at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:421) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:321) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) Caused by: javax.net.ssl.SSLHandshakeException: error:100000f7:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.sslReadErrorResult(ReferenceCountedOpenSslEngine.java:1140) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1101) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1169) at io.netty.handler.ssl.ReferenceCountedOpenSslEngine.unwrap(ReferenceCountedOpenSslEngine.java:1212) at io.netty.handler.ssl.SslHandler$SslEngineType$1.unwrap(SslHandler.java:216) at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1297) at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1211) at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1245) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) ... 14 common frames omitted 2020-04-14 16:33:29,158 341327918 [CacheManager RUNNING] INFO i.p.s.server.CacheManager - CacheManager: Gen: 309331-309331; Clients: 334 (309330-301212); Cache: Stored = 10291, Used = 438272, Reserved = 385024, Allocated = 197132288, Max = 11811160064. 2020-04-14 16:33:30,160 341328920 [CacheManager RUNNING] INFO i.p.s.server.CacheManager - CacheManager: Gen: 309332-309332; Clients: 334 (309331-301212); Cache: Stored = 6579, Used = 434176, Reserved = 385024, Allocated = 197132288, Max = 11811160064. 2020-04-14 16:33:48,371 341347131 [epollEventLoopGroup-10-1] INFO i.n.handler.logging.LoggingHandler - [id: 0x589ba91a, L:/0.0.0.0:12345] READ: [id: 0xd11c03a6, L:/172.17.0.38:12345 - R:/172.17.0.1:61471]

I'm using Self-Signed Certificates generated with openssl command : openssl req -nodes -new -x509 -keyout /tmp/certs/tls.key -days 365 -out /tmp/certs/ca-certificates/tls.crt -subj "/C=CA/ST=Quebec/L=Montreal/O=DellEMC/OU=Nautilus/CN=${NAUTILUS_DNS_NAME}"

and the self-signed certificated is then loaded in the JVM during Docker Image Build RUN keytool -import -trustcacerts -noprompt -file /home/gradle/certs/tls.crt -alias nautilus_cert \ -storepass changeit -keystore /usr/local/openjdk-8/lib/security/cacerts