search

AsyncHttpClient / async-http-client

Asynchronous Http and WebSocket Client library for Java
Other
6.28k stars 1.59k forks source link

make http request via version 2.1.0-RC1 timeout all the time, but ok with version 2.0.37 #1487

Closed spccold closed 6 years ago

spccold commented 6 years ago

http url in java code come from requestb.in

maven dependency:

<dependency>
    <groupId>org.asynchttpclient</groupId>
    <artifactId>async-http-client</artifactId>
    <version>2.1.0-RC1</version>
</dependency>

java code:

import static org.asynchttpclient.Dsl.asyncHttpClient;

import java.io.IOException;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.Future;

import org.asynchttpclient.AsyncHttpClient;
import org.asynchttpclient.Response;

public class App {
    public static void main(String[] args) {
        AsyncHttpClient asyncHttpClient = asyncHttpClient();
        // please generate a new url from https://requestb.in
        Future<Response> whenResponse = asyncHttpClient.prepareGet("https://requestb.in/1bds3ri1")
                .setRequestTimeout(5000).execute();
        try {
            System.out.println(whenResponse.get().getStatusCode());
        } catch (InterruptedException | ExecutionException e) {
            e.printStackTrace();
        } finally {
            try {
                asyncHttpClient.close();
            } catch (IOException e) {
                e.printStackTrace();
            }
        }
    }
}

exception:

20:55:48.147 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
20:55:48.153 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
20:55:48.155 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
20:55:48.181 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: MacOS
20:55:48.183 [main] DEBUG i.n.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
20:55:48.183 [main] DEBUG i.n.util.internal.PlatformDependent0 - Java version: 8
20:55:48.185 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
20:55:48.185 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
20:55:48.186 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
20:55:48.186 [main] DEBUG i.n.util.internal.PlatformDependent0 - direct buffer constructor: available
20:55:48.187 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
20:55:48.187 [main] DEBUG i.n.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
20:55:48.187 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
20:55:48.187 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
20:55:48.188 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/h6/nq57z4r96sn883csp6lx17gc0000gn/T (java.io.tmpdir)
20:55:48.188 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
20:55:48.189 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
20:55:48.189 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 1908932608 bytes
20:55:48.189 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
20:55:48.190 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
20:55:48.190 [main] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1593948d
20:55:48.198 [main] DEBUG i.n.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
20:55:48.467 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
20:55:48.467 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA]
20:55:48.499 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
20:55:48.510 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
20:55:48.511 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
20:55:48.534 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
20:55:48.534 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
20:55:48.563 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
20:55:48.564 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
20:55:48.564 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
20:55:48.564 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
20:55:48.573 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
20:55:48.573 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
20:55:48.573 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
20:55:53.711 [pool-1-thread-1] DEBUG o.a.netty.timeout.TimeoutTimerTask - Request timeout to requestb.in:443 after 5000 ms for NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@77625859,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@7e0b259a,
    future=java.util.concurrent.CompletableFuture@1a3f5d33[Not completed],
    uri=https://requestb.in/1bds3ri1,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@7738258b,
    inAuth=0,
    statusReceived=0,
    touch=1512996948637} after 5079 ms
20:55:53.712 [pool-1-thread-1] DEBUG o.a.netty.request.NettyRequestSender - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@77625859,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@7e0b259a,
    future=java.util.concurrent.CompletableFuture@1a3f5d33[Not completed],
    uri=https://requestb.in/1bds3ri1,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@7738258b,
    inAuth=0,
    statusReceived=0,
    touch=1512996948637}

20:55:53.716 [pool-1-thread-1] DEBUG o.a.netty.request.NettyRequestSender - Request timeout to requestb.in:443 after 5000 ms
java.util.concurrent.TimeoutException: Request timeout to requestb.in:443 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44) [async-http-client-2.1.0-RC1.jar:na]
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51) [async-http-client-2.1.0-RC1.jar:na]
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]
20:55:53.717 [pool-1-thread-1] DEBUG o.a.AsyncCompletionHandler - Request timeout to requestb.in:443 after 5000 ms
java.util.concurrent.TimeoutException: Request timeout to requestb.in:443 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44) [async-http-client-2.1.0-RC1.jar:na]
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51) [async-http-client-2.1.0-RC1.jar:na]
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]
20:55:53.997 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 87644 (auto-detected)
20:55:54.001 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
20:55:54.001 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
20:55:54.002 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1)
20:55:54.003 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
20:55:54.007 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 4c:32:75:ff:fe:99:9f:c1 (auto-detected)
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Request timeout to requestb.in:443 after 5000 ms
    at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
    at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
    at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:213)
    at com.wacai.middleware.demo.App.main(App.java:18)
Caused by: java.util.concurrent.TimeoutException: Request timeout to requestb.in:443 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44)
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663)
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738)
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466)
    at java.lang.Thread.run(Thread.java:745)
20:55:54.055 [AsyncHttpClient-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true
20:55:54.055 [AsyncHttpClient-2-1] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@616645a6
20:55:54.146 [AsyncHttpClient-2-4] DEBUG o.a.n.channel.NettyConnectListener - Trying to recover from failing to connect channel [id: 0xf7057535] with a retry value of true 
20:55:54.160 [AsyncHttpClient-2-4] DEBUG o.a.n.channel.NettyConnectListener - Failed to recover from connect exception: java.lang.IllegalStateException: executor not accepting a task with channel [id: 0xf7057535]

change maven dependency to:

<dependency>
    <groupId>org.asynchttpclient</groupId>
    <artifactId>async-http-client</artifactId>
    <version>2.0.37</version>
</dependency>

result(with some java code):

20:58:34.143 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
20:58:34.149 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
20:58:34.151 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.maxRecords: 4
20:58:34.151 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.maxSampledRecords: 40
20:58:34.175 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: MacOS
20:58:34.176 [main] DEBUG i.n.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
20:58:34.177 [main] DEBUG i.n.util.internal.PlatformDependent0 - Java version: 8
20:58:34.179 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
20:58:34.180 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
20:58:34.181 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
20:58:34.181 [main] DEBUG i.n.util.internal.PlatformDependent0 - direct buffer constructor: available
20:58:34.182 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
20:58:34.182 [main] DEBUG i.n.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
20:58:34.182 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
20:58:34.182 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
20:58:34.183 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/h6/nq57z4r96sn883csp6lx17gc0000gn/T (java.io.tmpdir)
20:58:34.183 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
20:58:34.184 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
20:58:34.185 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 1908932608 bytes
20:58:34.185 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
20:58:34.185 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
20:58:34.186 [main] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@548a9f61
20:58:34.194 [main] DEBUG i.n.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
20:58:34.468 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
20:58:34.469 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA]
20:58:34.498 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
20:58:34.509 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
20:58:34.509 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
20:58:34.537 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
20:58:34.537 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
20:58:34.549 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
20:58:34.550 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
20:58:34.551 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
20:58:34.685 [AsyncHttpClient-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true
20:58:34.685 [AsyncHttpClient-2-1] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@2534182b
20:58:35.026 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacity.default: 32768
20:58:35.026 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
20:58:35.026 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
20:58:35.026 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
20:58:35.807 [AsyncHttpClient-2-1] DEBUG o.a.n.channel.NettyConnectListener - Using new Channel '[id: 0xb9644e00, L:/172.16.133.139:53391 - R:requestb.in/104.31.86.204:443]' for 'GET' to '/1bds3ri1'
20:58:35.814 [AsyncHttpClient-2-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xb9644e00, L:/172.16.133.139:53391 - R:requestb.in/104.31.86.204:443] HANDSHAKEN: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
20:58:36.236 [AsyncHttpClient-2-1] DEBUG o.a.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
GET /1bds3ri1 HTTP/1.1
Host: requestb.in
Accept: */*
User-Agent: AHC/2.0

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Date: Mon, 11 Dec 2017 12:57:27 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Set-Cookie: __cfduid=dc43f3aca5494c36492bfac4445e1e1861512997047; expires=Tue, 11-Dec-18 12:57:27 GMT; path=/; domain=.requestb.in; HttpOnly
Sponsored-By: https://www.runscope.com
Via: 1.1 vegur
Strict-Transport-Security: max-age=15552000
X-Content-Type-Options: nosniff
Server: cloudflare-nginx
CF-RAY: 3cb89c1c295951ac-SJC

20:58:36.241 [AsyncHttpClient-2-1] DEBUG o.a.netty.channel.ChannelManager - Adding key: https://requestb.in:443 for channel [id: 0xb9644e00, L:/172.16.133.139:53391 - R:requestb.in/104.31.86.204:443]
200
slandelle commented 6 years ago

Works just fine for me:

2017-12-11 14:07:00,979 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
2017-12-11 14:07:00,985 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
2017-12-11 14:07:00,986 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
2017-12-11 14:07:01,009 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: MacOS
2017-12-11 14:07:01,011 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
2017-12-11 14:07:01,011 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8
2017-12-11 14:07:01,012 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
2017-12-11 14:07:01,013 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
2017-12-11 14:07:01,013 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
2017-12-11 14:07:01,014 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: available
2017-12-11 14:07:01,014 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
2017-12-11 14:07:01,014 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
2017-12-11 14:07:01,014 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
2017-12-11 14:07:01,015 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
2017-12-11 14:07:01,015 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/3m/b2yp9rr56s30thdsxrq7hy200000gn/T (java.io.tmpdir)
2017-12-11 14:07:01,015 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2017-12-11 14:07:01,016 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
2017-12-11 14:07:01,017 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 3817865216 bytes
2017-12-11 14:07:01,017 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2017-12-11 14:07:01,017 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
2017-12-11 14:07:01,017 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@46d56d67
2017-12-11 14:07:01,027 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2017-12-11 14:07:01,257 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
2017-12-11 14:07:01,257 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA]
2017-12-11 14:07:01,283 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
2017-12-11 14:07:01,292 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
2017-12-11 14:07:01,292 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
2017-12-11 14:07:01,313 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2017-12-11 14:07:01,313 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2017-12-11 14:07:01,324 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
2017-12-11 14:07:01,325 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
2017-12-11 14:07:01,333 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
2017-12-11 14:07:01,333 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
2017-12-11 14:07:01,333 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
2017-12-11 14:07:01,417 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 25600 (auto-detected)
2017-12-11 14:07:01,419 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
2017-12-11 14:07:01,419 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
2017-12-11 14:07:01,420 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2017-12-11 14:07:01,421 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2017-12-11 14:07:01,423 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: a8:20:66:ff:fe:1b:e6:1c (auto-detected)
2017-12-11 14:07:01,469 [AsyncHttpClient-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true
2017-12-11 14:07:01,469 [AsyncHttpClient-2-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@313b97ac
2017-12-11 14:07:01,526 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 32768
2017-12-11 14:07:01,526 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
2017-12-11 14:07:01,526 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
2017-12-11 14:07:01,526 [AsyncHttpClient-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
2017-12-11 14:07:01,667 [AsyncHttpClient-2-1] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Using new Channel '[id: 0x11832c81, L:/192.168.10.229:63047 - R:requestb.in/104.31.86.204:443]' for 'GET' to '/1bds3ri1'
2017-12-11 14:07:01,685 [AsyncHttpClient-2-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0x11832c81, L:/192.168.10.229:63047 - R:requestb.in/104.31.86.204:443] HANDSHAKEN: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
2017-12-11 14:07:01,914 [AsyncHttpClient-2-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
GET /1bds3ri1 HTTP/1.1
host: requestb.in
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
Date: Mon, 11 Dec 2017 13:07:01 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Set-Cookie: __cfduid=d1950394a29c3062270b60a6bb55f32041512997621; expires=Tue, 11-Dec-18 13:07:01 GMT; path=/; domain=.requestb.in; HttpOnly
Sponsored-By: https://www.runscope.com
Via: 1.1 vegur
Strict-Transport-Security: max-age=15552000
X-Content-Type-Options: nosniff
Server: cloudflare-nginx
CF-RAY: 3cb8aa1fb8869bff-AMS

2017-12-11 14:07:01,920 [AsyncHttpClient-2-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Adding key: https://requestb.in:443 for channel [id: 0x11832c81, L:/192.168.10.229:63047 - R:requestb.in/104.31.86.204:443]
200

Are you sure you didn't experience a temporary server failure/slow down?

slandelle commented 6 years ago

Most likely either DNS resolution or TLS handshake (hence an issue on your side). As you seem to be in China, my usual suspect is your great firewall... Try getting a thread dump before the timeout.

spccold commented 6 years ago

i get this issue first from local area network http request, use url from requestb.in just for show the issue, i boot tomcat in my laptop and make a request to http://localhost:8080, but get the same exception

21:27:33.558 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
21:27:33.564 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
21:27:33.566 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
21:27:33.592 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: MacOS
21:27:33.594 [main] DEBUG i.n.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
21:27:33.594 [main] DEBUG i.n.util.internal.PlatformDependent0 - Java version: 8
21:27:33.596 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
21:27:33.597 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
21:27:33.597 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
21:27:33.598 [main] DEBUG i.n.util.internal.PlatformDependent0 - direct buffer constructor: available
21:27:33.599 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
21:27:33.599 [main] DEBUG i.n.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
21:27:33.599 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
21:27:33.599 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
21:27:33.600 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/h6/nq57z4r96sn883csp6lx17gc0000gn/T (java.io.tmpdir)
21:27:33.600 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
21:27:33.601 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
21:27:33.601 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 1908932608 bytes
21:27:33.602 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
21:27:33.602 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
21:27:33.602 [main] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1593948d
21:27:33.612 [main] DEBUG i.n.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
21:27:33.899 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
21:27:33.900 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA]
21:27:33.927 [main] DEBUG i.n.c.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 8
21:27:33.938 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
21:27:33.938 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
21:27:33.966 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
21:27:33.966 [main] DEBUG i.n.u.i.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
21:27:33.994 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8
21:27:33.995 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
21:27:33.996 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
21:27:33.997 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
21:27:33.997 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
21:27:33.997 [main] DEBUG i.n.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
21:27:34.007 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
21:27:34.007 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
21:27:34.007 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
21:27:39.124 [pool-1-thread-1] DEBUG o.a.netty.timeout.TimeoutTimerTask - Request timeout to localhost:8080 after 5000 ms for NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@266a9ff8,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@153871b,
    future=java.util.concurrent.CompletableFuture@a6faaa8[Not completed],
    uri=http://localhost:8080,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@44bbcbc,
    inAuth=0,
    statusReceived=0,
    touch=1512998854079} after 5048 ms
21:27:39.125 [pool-1-thread-1] DEBUG o.a.netty.request.NettyRequestSender - Aborting Future NettyResponseFuture{currentRetry=0,
    isDone=0,
    isCancelled=0,
    asyncHandler=org.asynchttpclient.AsyncCompletionHandlerBase@266a9ff8,
    nettyRequest=org.asynchttpclient.netty.request.NettyRequest@153871b,
    future=java.util.concurrent.CompletableFuture@a6faaa8[Not completed],
    uri=http://localhost:8080,
    keepAlive=true,
    redirectCount=0,
    timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@44bbcbc,
    inAuth=0,
    statusReceived=0,
    touch=1512998854079}

21:27:39.129 [pool-1-thread-1] DEBUG o.a.netty.request.NettyRequestSender - Request timeout to localhost:8080 after 5000 ms
java.util.concurrent.TimeoutException: Request timeout to localhost:8080 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44) [async-http-client-2.1.0-RC1.jar:na]
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51) [async-http-client-2.1.0-RC1.jar:na]
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]
21:27:39.130 [pool-1-thread-1] DEBUG o.a.AsyncCompletionHandler - Request timeout to localhost:8080 after 5000 ms
java.util.concurrent.TimeoutException: Request timeout to localhost:8080 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44) [async-http-client-2.1.0-RC1.jar:na]
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51) [async-http-client-2.1.0-RC1.jar:na]
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466) [netty-common-4.1.17.Final.jar:4.1.17.Final]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]
21:27:39.134 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 88191 (auto-detected)
21:27:39.137 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
21:27:39.137 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
21:27:39.138 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1)
21:27:39.139 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
21:27:39.141 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 4c:32:75:ff:fe:99:9f:c1 (auto-detected)
java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Request timeout to localhost:8080 after 5000 ms
    at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357)
    at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895)
    at org.asynchttpclient.netty.NettyResponseFuture.get(NettyResponseFuture.java:213)
    at com.wacai.middleware.demo.App.main(App.java:18)
Caused by: java.util.concurrent.TimeoutException: Request timeout to localhost:8080 after 5000 ms
    at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:44)
    at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:51)
    at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:663)
    at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:738)
    at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:466)
    at java.lang.Thread.run(Thread.java:745)
21:27:39.187 [AsyncHttpClient-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true
21:27:39.188 [AsyncHttpClient-2-1] DEBUG i.n.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@13133d01
21:27:39.278 [AsyncHttpClient-2-2] DEBUG o.a.n.channel.NettyConnectListener - Trying to recover from failing to connect channel [id: 0xeae5045c] with a retry value of true 
21:27:39.291 [AsyncHttpClient-2-2] DEBUG o.a.n.channel.NettyConnectListener - Failed to recover from connect exception: java.lang.IllegalStateException: executor not accepting a task with channel [id: 0xeae5045c]
spccold commented 6 years ago

but when i change version to 2.0.37, it's get ok right now

slandelle commented 6 years ago

See above, I have no problem running your sample on my side. If I can't reproduce, I can't investigate.

spccold commented 6 years ago

ok, i attempt to find more evidence

spccold commented 6 years ago

all time consumed in DefaultChannelId.defaultProcessId() invoke , jdk version jdk1.8.0_121, may be i should report this issue to netty

private static int defaultProcessId() {
        ClassLoader loader = null;
        String value;
        try {
            loader = PlatformDependent.getClassLoader(DefaultChannelId.class);
            // Invoke java.lang.management.ManagementFactory.getRuntimeMXBean().getName()
            Class<?> mgmtFactoryType = Class.forName("java.lang.management.ManagementFactory", true, loader);
            Class<?> runtimeMxBeanType = Class.forName("java.lang.management.RuntimeMXBean", true, loader);

            Method getRuntimeMXBean = mgmtFactoryType.getMethod("getRuntimeMXBean", EmptyArrays.EMPTY_CLASSES);
            Object bean = getRuntimeMXBean.invoke(null, EmptyArrays.EMPTY_OBJECTS);
            Method getName = runtimeMxBeanType.getMethod("getName", EmptyArrays.EMPTY_CLASSES);
            // very slowly at here
            value = (String) getName.invoke(bean, EmptyArrays.EMPTY_OBJECTS);
        } catch (Throwable t) {
            logger.debug("Could not invoke ManagementFactory.getRuntimeMXBean().getName(); Android?", t);
            try {
                // Invoke android.os.Process.myPid()
                Class<?> processType = Class.forName("android.os.Process", true, loader);
                Method myPid = processType.getMethod("myPid", EmptyArrays.EMPTY_CLASSES);
                value = myPid.invoke(null, EmptyArrays.EMPTY_OBJECTS).toString();
            } catch (Throwable t2) {
                logger.debug("Could not invoke Process.myPid(); not Android?", t2);
                value = "";
            }
        }

        int atIndex = value.indexOf('@');
        if (atIndex >= 0) {
            value = value.substring(0, atIndex);
        }

        int pid;
        try {
            pid = Integer.parseInt(value);
        } catch (NumberFormatException e) {
            // value did not contain an integer.
            pid = -1;
        }

        if (pid < 0) {
            pid = PlatformDependent.threadLocalRandom().nextInt();
            logger.warn("Failed to find the current process ID from '{}'; using a random value: {}",  value, pid);
        }

        return pid;
    }
slandelle commented 6 years ago

Interesting! Yes, please report a bug against Netty. Don't forget to mention:

cc @normanmaurer

normanmaurer commented 6 years ago

@spccold yes please open an issue in netty with all the infos and log. I will investigate.

@slandelle thanks for pinging.

spccold commented 6 years ago

ok, i will open an issue in netty later.

normanmaurer commented 6 years ago

@spccold thanks a lot... also it would be helpful to take a thread-dump or provide a profiler snapshot to understand where exactly in this method the time is spend.

spccold commented 6 years ago

yes. you right

java code(extract from DefaultChannelId#defaultProcessId):

import java.lang.reflect.Method;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import io.netty.channel.DefaultChannelId;
import io.netty.util.internal.EmptyArrays;
import io.netty.util.internal.PlatformDependent;

public class Issue {

    private static final Logger logger = LoggerFactory.getLogger(Issue.class);

    public static void main(String[] args) {
        defaultProcessId();
    }

    private static int defaultProcessId() {
        ClassLoader loader = null;
        String value;
        try {
            loader = PlatformDependent.getClassLoader(DefaultChannelId.class);
            // Invoke java.lang.management.ManagementFactory.getRuntimeMXBean().getName()
            Class<?> mgmtFactoryType = Class.forName("java.lang.management.ManagementFactory", true, loader);
            Class<?> runtimeMxBeanType = Class.forName("java.lang.management.RuntimeMXBean", true, loader);

            Method getRuntimeMXBean = mgmtFactoryType.getMethod("getRuntimeMXBean", EmptyArrays.EMPTY_CLASSES);
            Object bean = getRuntimeMXBean.invoke(null, EmptyArrays.EMPTY_OBJECTS);
            Method getName = runtimeMxBeanType.getMethod("getName", EmptyArrays.EMPTY_CLASSES);
            // add for test
            long start = System.currentTimeMillis();
            System.out.println("begin to invoke");
            value = (String) getName.invoke(bean, EmptyArrays.EMPTY_OBJECTS);
            // add for test
            long end = System.currentTimeMillis();
            // add for test
            logger.info("consume {} ms", (end - start));
        } catch (Throwable t) {
            logger.debug("Could not invoke ManagementFactory.getRuntimeMXBean().getName(); Android?", t);
            try {
                // Invoke android.os.Process.myPid()
                Class<?> processType = Class.forName("android.os.Process", true, loader);
                Method myPid = processType.getMethod("myPid", EmptyArrays.EMPTY_CLASSES);
                value = myPid.invoke(null, EmptyArrays.EMPTY_OBJECTS).toString();
            } catch (Throwable t2) {
                logger.debug("Could not invoke Process.myPid(); not Android?", t2);
                value = "";
            }
        }

        int atIndex = value.indexOf('@');
        if (atIndex >= 0) {
            value = value.substring(0, atIndex);
        }

        int pid;
        try {
            pid = Integer.parseInt(value);
        } catch (NumberFormatException e) {
            // value did not contain an integer.
            pid = -1;
        }

        if (pid < 0) {
            pid = PlatformDependent.threadLocalRandom().nextInt();
            logger.warn("Failed to find the current process ID from '{}'; using a random value: {}", value, pid);
        }

        return pid;
    }

}

result:

16:54:17.438 [main] DEBUG i.n.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework
16:54:17.443 [main] DEBUG i.n.util.internal.PlatformDependent - Platform: MacOS
16:54:17.446 [main] DEBUG i.n.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
16:54:17.449 [main] DEBUG i.n.util.internal.PlatformDependent0 - Java version: 8
16:54:17.451 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
16:54:17.456 [main] DEBUG i.n.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
16:54:17.460 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
16:54:17.462 [main] DEBUG i.n.util.internal.PlatformDependent0 - direct buffer constructor: available
16:54:17.464 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
16:54:17.464 [main] DEBUG i.n.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
16:54:17.464 [main] DEBUG i.n.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
16:54:17.464 [main] DEBUG i.n.util.internal.PlatformDependent - sun.misc.Unsafe: available
16:54:17.464 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/h6/nq57z4r96sn883csp6lx17gc0000gn/T (java.io.tmpdir)
16:54:17.465 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
16:54:17.466 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
16:54:17.467 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 1908932608 bytes
16:54:17.467 [main] DEBUG i.n.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
16:54:17.468 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
begin to invoke
16:54:22.479 [main] INFO  com.spccold.issue.Issue - consume 5003 ms

jstack( i take three thread dumps in a short time):

"main" #1 prio=5 os_prio=31 tid=0x00007fea1f802000 nid=0x1c03 runnable [0x00007000019a1000]
   java.lang.Thread.State: RUNNABLE
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
    at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
    - locked <0x0000000795b01548> (a java.lang.Object)
    at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140)
    at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59)
    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:498)
    at com.spccold.issue.Issue.defaultProcessId(Issue.java:35)
    at com.spccold.issue.Issue.main(Issue.java:17)

"main" #1 prio=5 os_prio=31 tid=0x00007fea1f802000 nid=0x1c03 runnable [0x00007000019a1000]
   java.lang.Thread.State: RUNNABLE
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
    at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
    - locked <0x0000000795b01548> (a java.lang.Object)
    at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140)
    at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59)
    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:498)
    at com.spccold.issue.Issue.defaultProcessId(Issue.java:35)
    at com.spccold.issue.Issue.main(Issue.java:17)

"main" #1 prio=5 os_prio=31 tid=0x00007fea1f802000 nid=0x1c03 runnable [0x00007000019a1000]
   java.lang.Thread.State: RUNNABLE
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
    at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
    at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
    - locked <0x0000000795b01548> (a java.lang.Object)
    at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140)
    at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59)
    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:498)
    at com.spccold.issue.Issue.defaultProcessId(Issue.java:35)
    at com.spccold.issue.Issue.main(Issue.java:17)
spccold commented 6 years ago

https://thoeni.io/post/macos-sierra-java/ resolve my problem

just add 127.0.0.1 xxxxMacBook-Pro.local to /etc/hosts

slandelle commented 6 years ago

It never crossed my mind that intra-JVM JMX needs to resolve localhost address o_0

Yep, I was about to point to those threads. Internet seem to be full of people complaining of a regression introduced in MacOS Sierra. Some people seem to believe this is related to reverse DNS look up failures, Sharing enabled, or System Integrity Protection: https://stackoverflow.com/questions/39636792/jvm-takes-a-long-time-to-resolve-ip-address-for-localhost/39698914

As most Netty core committers work for Apple, they might have a better idea about what happens.

I'm closing here as I can't do anything on the AHC side.

spccold commented 6 years ago

@slandelle thanks a lot

slandelle commented 6 years ago

@spccold You're welcome. Note that one of my coworker runs on latest Sierra (not High Sierra) and couldn't reproduce, even without hostname declared in /etc/hosts). You might want to upgrade MacOS version.