Aws-sdk-java-v2: closeEventLoopUninterruptibly Hanging on WebFlux Netty

Created on 4 Mar 2019  路  17Comments  路  Source: aws/aws-sdk-java-v2

When killing my Spring WebFlux on Netty app that uses S3AsyncClient the app hangs for 16 seconds.

Expected Behavior


Expect the server to be killed faster than 16 seconds.

Current Behavior





After timing out the following stack trace is given:

02:05:04.281 [Thread-19] ERROR s.a.a.h.n.n.NettyNioAsyncHttpClient - Unable to shutdown event loop
java.lang.RuntimeException: Shutting down Netty EventLoopGroup did not complete within 16 seconds
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.closeEventLoopUninterruptibly(NettyNioAsyncHttpClient.java:235)
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.lambda$close$2(NettyNioAsyncHttpClient.java:222)
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient$$Lambda$1600/736839034.run(Unknown Source)
    at software.amazon.awssdk.utils.FunctionalUtils.runAndLogError(FunctionalUtils.java:40)
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.close(NettyNioAsyncHttpClient.java:221)
    at software.amazon.awssdk.utils.IoUtils.closeQuietly(IoUtils.java:73)
    at software.amazon.awssdk.utils.IoUtils.closeIfCloseable(IoUtils.java:90)
    at software.amazon.awssdk.utils.AttributeMap.lambda$close$0(AttributeMap.java:86)
    at software.amazon.awssdk.utils.AttributeMap$$Lambda$1596/1964394254.accept(Unknown Source)
    at java.util.HashMap$Values.forEach(HashMap.java:972)
    at software.amazon.awssdk.utils.AttributeMap.close(AttributeMap.java:86)
    at software.amazon.awssdk.core.client.config.SdkClientConfiguration.close(SdkClientConfiguration.java:79)
    at software.amazon.awssdk.core.internal.http.HttpClientDependencies.close(HttpClientDependencies.java:88)
    at software.amazon.awssdk.core.internal.http.AmazonAsyncHttpClient.close(AmazonAsyncHttpClient.java:78)
    at software.amazon.awssdk.core.client.handler.BaseAsyncClientHandler.close(BaseAsyncClientHandler.java:138)
    at software.amazon.awssdk.services.s3.DefaultS3AsyncClient.close(DefaultS3AsyncClient.java:3942)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:337)
    at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:271)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:954)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:961)
    at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1041)
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1017)
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:937)

Steps to Reproduce (for bugs)



  • Deploy any Spring WebFlux 2.0.4.RELEASE app locally
  • Make a request that uses the S3AsyncClient to populate the response
  • Kill the server via control + c

Your Environment

  • AWS Java SDK version used: 2.5.1
  • JDK version used: 1.8.0_51
  • Operating System and version: MacOS High Sierra 10.13.6
  • Spring version: 2.0.4.RELEASE
bug investigating
Source
picture garrettbts
👍1

All 17 comments

Hi, could you provide a code snippet of how you create the s3 client? Are you using other SDK async clients in your application?

zoewangg picture zoewangg on 4 Mar 2019

@zoewangg Not using any other SDK async clients.

    @Bean
    S3AsyncClient s3AsyncClient(AwsCredentials awsConfiguration) {
        AwsBasicCredentials awsCreds = AwsBasicCredentials.create(
                  awsConfiguration.getAccessKeyId(),
                  awsConfiguration.getSecretAccessKey());

        return S3AsyncClient.builder().credentialsProvider(
                StaticCredentialsProvider.create(awsCreds)).
                build();
    }
garrettbts picture garrettbts on 4 Mar 2019

Hmm, that's odd. Does it happen every time you try to close the client or just occasionally?

zoewangg picture zoewangg on 4 Mar 2019

Every time.

garrettbts picture garrettbts on 4 Mar 2019

Could you share the code snippet of how you make the s3 request?
Is the client created per request or it's a singleton throughout the application?

zoewangg picture zoewangg on 4 Mar 2019

Client is singleton.

CompletableFuture<ResponseBytes<GetObjectResponse>> s3ResponseFuture = client.getObject(GetObjectRequest.builder()
.bucket(s3Configuration.getBucket()).key(key).build(), 
AsyncResponseTransformer.toBytes());

Mono<ResponseBytes<GetObjectResponse>> rtn = Mono.fromFuture(s3ResponseFuture);
garrettbts picture garrettbts on 4 Mar 2019

Thank you for the information! I was not able to reproduce the issue by making the same call and then closing the client.

I wonder if it's something related to Spring WebFlux. I will try to test with Spring WebFlux.

zoewangg picture zoewangg on 4 Mar 2019
👍1

Hi all, sorry for the long post but i'm trying to give as most relevant informations as i can.
I'm facing the same issue without importing the WebFlux of spring, my app is using PinpointAsyncClient and SnsAsyncClient.

_pom.xml_

    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.2.0.M1</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>software.amazon.awssdk</groupId>
                <artifactId>bom</artifactId>
                <version>2.5.11</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>

_AWS Config_

@Configuration
public class AWSConfig {

    private final AwsConfigurationProperties awsConfigurationProperties;

    @Autowired
    public AWSConfig(AwsConfigurationProperties awsConfigurationProperties) {
        this.awsConfigurationProperties = awsConfigurationProperties;
    }

    private AwsBasicCredentials awsCredentials() {
        return AwsBasicCredentials.create(awsConfigurationProperties.getAccessKey(), awsConfigurationProperties.getSecretKey());
    }

    @Bean
    public SnsAsyncClient amazonSNSClient() {
        return SnsAsyncClient.builder()
                .credentialsProvider(StaticCredentialsProvider.create(awsCredentials()))
                .region(Region.EU_WEST_1)
                .build();
    }


    @Bean
    public S3Client amazonS3Client() {
        return S3Client.builder()
                .credentialsProvider(StaticCredentialsProvider.create(awsCredentials()))
                .region(Region.EU_CENTRAL_1)
                .build();
    }

    @Bean
    public PinpointAsyncClient amazonPinpointClient() {
        return PinpointAsyncClient.builder()
                .credentialsProvider(StaticCredentialsProvider.create(awsCredentials()))
                .region(Region.US_EAST_1)
                .build();
    }

}

_Async Config_

@Configuration
@EnableAsync
public class ExecutorsConfig {
}

_Calls_

@Override
@Async
public void sendSMS() {
       snsAsyncClient.publish(request)
                .exceptionally(throwable -> {
                    LOGGER.error(new MessageNotSentException(throwable));
                    return null;
                });
    }

@Override
@Async
public void sendPush() {
       pinpointAsyncClient.sendUsersMessages(sendUsersMessagesRequest)
                .exceptionally(throwable -> {
                    LOGGER.error("Failed to deliver push notification ");
                    return null;
                });
    }

Current Behavior

  • When i use only a call from SnsAsyncClient and shutdown the server -> the error happens randomly
  • When i use only a call from PinpointAsyncClient and shutdown the server -> the error happens randomly
  • When i use only a call from PinpointAsyncClient and another from SnsAsyncClient then shutdown the server -> the error happens systemically

And here is the stacktrace : 

2019-03-20 11:41:20.967  INFO 69862 --- [      Thread-17] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2019-03-20 11:41:20.981  WARN 69862 --- [tyEventLoop-1-3] i.n.u.c.SingleThreadEventExecutor        : An event executor terminated with non-empty task queue (1)
2019-03-20 11:41:36.977 ERROR 69862 --- [      Thread-17] s.a.a.h.n.netty.NettyNioAsyncHttpClient  : Unable to shutdown event loop

java.lang.RuntimeException: Shutting down Netty EventLoopGroup did not complete within 16 seconds
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.closeEventLoopUninterruptibly(NettyNioAsyncHttpClient.java:240) [netty-nio-client-2.5.11.jar:na]
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.lambda$close$2(NettyNioAsyncHttpClient.java:227) [netty-nio-client-2.5.11.jar:na]
    at software.amazon.awssdk.utils.FunctionalUtils.runAndLogError(FunctionalUtils.java:40) ~[utils-2.5.11.jar:na]
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.close(NettyNioAsyncHttpClient.java:226) [netty-nio-client-2.5.11.jar:na]
    at software.amazon.awssdk.utils.IoUtils.closeQuietly(IoUtils.java:73) [utils-2.5.11.jar:na]
    at software.amazon.awssdk.utils.IoUtils.closeIfCloseable(IoUtils.java:90) [utils-2.5.11.jar:na]
    at software.amazon.awssdk.utils.AttributeMap.lambda$close$0(AttributeMap.java:86) [utils-2.5.11.jar:na]
    at java.util.HashMap$Values.forEach(HashMap.java:981) ~[na:1.8.0_191]
    at software.amazon.awssdk.utils.AttributeMap.close(AttributeMap.java:86) [utils-2.5.11.jar:na]
    at software.amazon.awssdk.core.client.config.SdkClientConfiguration.close(SdkClientConfiguration.java:79) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.HttpClientDependencies.close(HttpClientDependencies.java:88) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.AmazonAsyncHttpClient.close(AmazonAsyncHttpClient.java:78) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.client.handler.BaseAsyncClientHandler.close(BaseAsyncClientHandler.java:145) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.services.sns.DefaultSnsAsyncClient.close(DefaultSnsAsyncClient.java:2239) ~[sns-2.5.11.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_191]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_191]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_191]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_191]
    at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:337) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:271) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1055) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1062) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1057) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1026) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:945) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]

Also i'm not sure if this is related but all my calls from PinpointAsyncClient are failing systemically but all works with PinpointClient.
If it's not related may be i should open a separate bug.
Here is the global stacktrace a WARN followed by the effective ERROR : 

2019-03-20 11:41:05.449  INFO 69862 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 10 ms
2019-03-20 11:41:14.532  WARN 69862 --- [tyEventLoop-1-7] .a.h.n.n.i.UnusedChannelExceptionHandler : A non-I/O exception occurred on a channel (df1c7411) that was not in use. The channel has been closed to prevent any ongoing issues.

io.netty.handler.codec.DecoderException: javax.net.ssl.SSLException: Received fatal alert: handshake_failure
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:472) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-common-4.1.33.Final.jar:4.1.33.Final]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191]
Caused by: javax.net.ssl.SSLException: Received fatal alert: handshake_failure
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:208) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1647) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1615) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1781) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1070) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:896) ~[na:1.8.0_191]
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:766) ~[na:1.8.0_191]
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.8.0_191]
    at io.netty.handler.ssl.SslHandler$SslEngineType$3.unwrap(SslHandler.java:295) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1301) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1203) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1247) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    ... 15 common frames omitted

2019-03-20 11:41:14.978 ERROR 69862 --- [tyEventLoop-1-4] com.dabchy.api.service.PushService       : Failed to deliver push notification

java.util.concurrent.CompletionException: software.amazon.awssdk.core.exception.SdkClientException
    at software.amazon.awssdk.utils.CompletableFutureUtils.errorAsCompletionException(CompletableFutureUtils.java:61) ~[utils-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncExecutionFailureExceptionReportingStage.lambda$execute$0(AsyncExecutionFailureExceptionReportingStage.java:51) ~[sdk-core-2.5.11.jar:na]
    at java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:822) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:797) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_191]
    at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:75) ~[utils-2.5.11.jar:na]
    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_191]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.retryErrorIfNeeded(AsyncRetryableStage.java:173) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.retryIfNeeded(AsyncRetryableStage.java:124) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.lambda$execute$0(AsyncRetryableStage.java:105) ~[sdk-core-2.5.11.jar:na]
    at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_191]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_191]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage$ResponseHandler.onError(MakeAsyncHttpRequestStage.java:241) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor.handleFailure(NettyRequestExecutor.java:237) ~[netty-nio-client-2.5.11.jar:na]
    at software.amazon.awssdk.http.nio.netty.internal.NettyRequestExecutor.lambda$writeRequest$6(NettyRequestExecutor.java:191) ~[netty-nio-client-2.5.11.jar:na]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:485) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:834) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:797) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:778) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.flush(CombinedChannelDuplexHandler.java:533) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:358) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.ChannelDuplexHandler.flush(ChannelDuplexHandler.java:117) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:768) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:749) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.logging.LoggingHandler.flush(LoggingHandler.java:265) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:802) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at com.typesafe.netty.http.HttpStreamsHandler.completeBody(HttpStreamsHandler.java:298) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.http.HttpStreamsHandler.access$400(HttpStreamsHandler.java:14) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.http.HttpStreamsHandler$3$1.run(HttpStreamsHandler.java:276) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.http.HttpStreamsHandler.executeInEventLoop(HttpStreamsHandler.java:342) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.http.HttpStreamsHandler.access$300(HttpStreamsHandler.java:14) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.http.HttpStreamsHandler$3.complete(HttpStreamsHandler.java:273) ~[netty-reactive-streams-http-2.0.0.jar:na]
    at com.typesafe.netty.HandlerSubscriber$3.operationComplete(HandlerSubscriber.java:244) ~[netty-reactive-streams-2.0.0.jar:na]
    at com.typesafe.netty.HandlerSubscriber$3.operationComplete(HandlerSubscriber.java:241) ~[netty-reactive-streams-2.0.0.jar:na]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:485) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.internal.PromiseNotificationUtil.tryFailure(PromiseNotificationUtil.java:64) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:57) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DelegatingChannelPromiseNotifier.operationComplete(DelegatingChannelPromiseNotifier.java:31) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractCoalescingBufferQueue.releaseAndCompleteAll(AbstractCoalescingBufferQueue.java:340) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractCoalescingBufferQueue.releaseAndFailAll(AbstractCoalescingBufferQueue.java:207) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.releaseAndFailAll(SslHandler.java:1591) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.setHandshakeFailure(SslHandler.java:1585) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.handleUnwrapThrowable(SslHandler.java:1239) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1209) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1247) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278) ~[netty-codec-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) ~[netty-common-4.1.33.Final.jar:4.1.33.Final]
    at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_191]
Caused by: software.amazon.awssdk.core.exception.SdkClientException: null
    at software.amazon.awssdk.core.exception.SdkClientException$BuilderImpl.build(SdkClientException.java:97) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.util.ThrowableUtils.asSdkException(ThrowableUtils.java:98) ~[sdk-core-2.5.11.jar:na]
    at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryExecutor.retryIfNeeded(AsyncRetryableStage.java:123) ~[sdk-core-2.5.11.jar:na]
    ... 96 common frames omitted
Caused by: javax.net.ssl.SSLException: SSLEngine closed already
    at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
omahjoub picture omahjoub on 20 Mar 2019

@omahjoub
When you said shutdown the server, do you mean calling close() on the client?

varunnvs92 picture varunnvs92 on 22 Mar 2019

@varunnvs92 i mean closing the server from my IDE (Intellij)

omahjoub picture omahjoub on 24 Mar 2019

@omahjoub, @garrettbts I tried with sprint-boot and was able to reproduce, for just once though. After I changed to debug level, I haven't been able to reproduce it unfortunately :(

Could you turn on debug level for netty logging.level.io.netty.*=DEBUG and provide the logs? The netty logs after shutting down the server should be sufficient.

zoewangg picture zoewangg on 3 Apr 2019

Hi @zoewangg i activated the netty debug logs as well as the amazon sdk debug logs.
To reproduce you have to make at least one call from an async api (i took SnsAsyncClient) and then shut down the server.
Here are the logs :

2019-04-03 09:58:02.973  INFO 15726 --- [       Thread-3] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2019-04-03 09:58:02.981 DEBUG 15726 --- [nnection-reaper] s.a.a.h.a.i.conn.IdleConnectionReaper    : Reaper thread: 

java.lang.InterruptedException: sleep interrupted
    at java.lang.Thread.sleep(Native Method) [na:1.8.0_191]
    at software.amazon.awssdk.http.apache.internal.conn.IdleConnectionReaper$ReaperTask.run(IdleConnectionReaper.java:150) ~[apache-client-2.5.18.jar:na]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191]

2019-04-03 09:58:02.981 DEBUG 15726 --- [nnection-reaper] s.a.a.h.a.i.conn.IdleConnectionReaper    : Shutting down reaper thread.
2019-04-03 09:58:02.983 DEBUG 15726 --- [tyEventLoop-1-3] io.netty.buffer.PoolThreadCache          : Freed 18 thread-local buffer(s) from thread: aws-java-sdk-NettyEventLoop-1-3
2019-04-03 09:58:02.983  WARN 15726 --- [tyEventLoop-1-3] i.n.u.c.SingleThreadEventExecutor        : An event executor terminated with non-empty task queue (1)
2019-04-03 09:58:02.984 DEBUG 15726 --- [tyEventLoop-1-1] io.netty.buffer.PoolThreadCache          : Freed 13 thread-local buffer(s) from thread: aws-java-sdk-NettyEventLoop-1-1
2019-04-03 09:58:18.982 ERROR 15726 --- [       Thread-3] s.a.a.h.n.netty.NettyNioAsyncHttpClient  : Unable to shutdown event loop

java.lang.RuntimeException: Shutting down Netty EventLoopGroup did not complete within 16 seconds
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.closeEventLoopUninterruptibly(NettyNioAsyncHttpClient.java:252) [netty-nio-client-2.5.18.jar:na]
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.lambda$close$2(NettyNioAsyncHttpClient.java:239) [netty-nio-client-2.5.18.jar:na]
    at software.amazon.awssdk.utils.FunctionalUtils.runAndLogError(FunctionalUtils.java:40) ~[utils-2.5.18.jar:na]
    at software.amazon.awssdk.http.nio.netty.NettyNioAsyncHttpClient.close(NettyNioAsyncHttpClient.java:238) [netty-nio-client-2.5.18.jar:na]
    at software.amazon.awssdk.utils.IoUtils.closeQuietly(IoUtils.java:73) [utils-2.5.18.jar:na]
    at software.amazon.awssdk.utils.IoUtils.closeIfCloseable(IoUtils.java:90) [utils-2.5.18.jar:na]
    at software.amazon.awssdk.utils.AttributeMap.lambda$close$0(AttributeMap.java:86) [utils-2.5.18.jar:na]
    at java.util.HashMap$Values.forEach(HashMap.java:981) ~[na:1.8.0_191]
    at software.amazon.awssdk.utils.AttributeMap.close(AttributeMap.java:86) [utils-2.5.18.jar:na]
    at software.amazon.awssdk.core.client.config.SdkClientConfiguration.close(SdkClientConfiguration.java:79) ~[sdk-core-2.5.18.jar:na]
    at software.amazon.awssdk.core.internal.http.HttpClientDependencies.close(HttpClientDependencies.java:88) ~[sdk-core-2.5.18.jar:na]
    at software.amazon.awssdk.core.internal.http.AmazonAsyncHttpClient.close(AmazonAsyncHttpClient.java:78) ~[sdk-core-2.5.18.jar:na]
    at software.amazon.awssdk.core.client.handler.BaseAsyncClientHandler.close(BaseAsyncClientHandler.java:145) ~[sdk-core-2.5.18.jar:na]
    at software.amazon.awssdk.services.sns.DefaultSnsAsyncClient.close(DefaultSnsAsyncClient.java:2239) ~[sns-2.5.18.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_191]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_191]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_191]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_191]
    at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:337) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:271) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1055) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1062) ~[spring-beans-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1057) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1026) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:945) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE]

2019-04-03 09:58:18.989  INFO 15726 --- [       Thread-3] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2019-04-03 09:58:18.991  INFO 15726 --- [       Thread-3] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2019-04-03 09:58:18.998  INFO 15726 --- [       Thread-3] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

Process finished with exit code 130 (interrupted by signal 2: SIGINT)

Hope this helps.

omahjoub picture omahjoub on 3 Apr 2019

Thank you for providing the logs! I finally had a repro case.

I think this issue occurs when there is a task still in the eventloop queue during shutting down An event executor terminated with non-empty task queue (1) and this causes the future not completed.

I captured some thread dumps and found out globalEventExecutor was blocked on SimpleChannelPool.close, which is likely the same issue fixed in #1127 where the channel.close future never gets notified when the channel is already closed.

"globalEventExecutor-1-1" #62 prio=5 os_prio=31 tid=0x00007ff34abb8800 nid=0x8c0b in Object.wait() [0x0000700003023000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076b1b6a30> (a io.netty.channel.DefaultChannelPromise)
    at java.lang.Object.wait(Object.java:502)
    at io.netty.util.concurrent.DefaultPromise.awaitUninterruptibly(DefaultPromise.java:253)
    - locked <0x000000076b1b6a30> (a io.netty.channel.DefaultChannelPromise)
    at io.netty.channel.DefaultChannelPromise.awaitUninterruptibly(DefaultChannelPromise.java:137)
    at io.netty.channel.DefaultChannelPromise.awaitUninterruptibly(DefaultChannelPromise.java:30)
    at io.netty.channel.pool.SimpleChannelPool.close(SimpleChannelPool.java:398)
    at software.amazon.awssdk.http.nio.netty.internal.HonorCloseOnReleaseChannelPool.close(HonorCloseOnReleaseChannelPool.java:75)
    at software.amazon.awssdk.http.nio.netty.internal.utils.BetterFixedChannelPool$6.run(BetterFixedChannelPool.java:382)
    at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:248)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)

I have an idea of how to fix it and will discuss with the team.

zoewangg picture zoewangg on 3 Apr 2019

Did more research on this and the root cause is actually a race condition in Netty where the event loop gets terminated before channel is closed so globalEventExecutor will be stuck forever waiting for eventloop to notify the channel.close future. This is an known issue with Netty. https://github.com/netty/netty/issues/8398

zoewangg picture zoewangg on 9 Apr 2019
👍1

Fixed via #1200. Please try with latest version (2.5.31 as of now) and feel free to reopen if you continue to see the issue.

zoewangg picture zoewangg on 25 Apr 2019

Seeing this in v 2.7.25. Submit new issue or continue here? Happens when I start close multiple clients in the lifetime of the application. With only one client there's no problem.

frosforever picture frosforever on 30 Aug 2019

Open a new issue and provide repo code if possible.

varunnvs92 picture varunnvs92 on 30 Aug 2019
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

mscharp picture mscharp  路  5Comments
EthanStandel picture EthanStandel  路  3Comments
hmatland picture hmatland  路  3Comments
millems picture millems  路  6Comments
Jorgey7 picture Jorgey7  路  3Comments