Net Client "Error" when upgrading from 3.2.1 -> 3.4.1

Sean Burns

unread,

Jun 9, 2017, 6:20:51 AM6/9/17

to vert.x

Hello,

I have a piece of code that works perfectly with vertx 3.2.1

@Override
public void start() throws Exception {
    log.info("Starting");
    vertx.createNetClient().connect(1500, "10.107.4.99", connectEvent -> {
        log.info("Connect Event");
        if (connectEvent.succeeded()) {
            log.info("Successful connect");
        } else {
            log.warn("Failed connect");
        }
    });
}

When I run that code with 3.2.1 this is the output

12:16:11.993 [vert.x-eventloop-thread-1] INFO com.thumbzup.service.payshield.MainVerticle - Starting
12:16:12.072 [vert.x-eventloop-thread-0] INFO io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer - Succeeded in deploying verticle
12:16:12.098 [vert.x-eventloop-thread-1] INFO com.thumbzup.service.payshield.MainVerticle - Connect Event
12:16:12.098 [vert.x-eventloop-thread-1] INFO com.thumbzup.service.payshield.MainVerticle - Successful connect

Now all I do is change vertx-core in my pom from 3.2.1 -> 3.4.1 and I get "Errors" and delayed connection.

12:18:50.860 [vert.x-eventloop-thread-0] INFO com.thumbzup.service.payshield.MainVerticle - Starting
12:18:53.773 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2917 ms, time limit is 2000
12:18:54.774 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3918 ms, time limit is 2000
12:18:55.777 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4921 ms, time limit is 2000
12:18:56.161 [vert.x-eventloop-thread-1] INFO io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer - Succeeded in deploying verticle
12:18:56.187 [vert.x-eventloop-thread-0] INFO com.thumbzup.service.payshield.MainVerticle - Connect Event
12:18:56.187 [vert.x-eventloop-thread-0] INFO com.thumbzup.service.payshield.MainVerticle - Successful connect

What has changed between version 3.2.1 and 3.3.0 (I tested with 3.3.0 as well)? What extra things do I need to do now?

Sean Burns

unread,

Jun 9, 2017, 7:43:31 AM6/9/17

to vert.x

Okay the issue is not with net client? I tried running the example from

https://github.com/vert-x3/vertx-examples/blob/master/core-examples/src/main/java/io/vertx/example/core/net/echo/Server.java

And get the same issue, here is my exact code (No logger, no anything extra)

Here is my full code

public class MainVerticle extends AbstractVerticle {



    @Override
    public void start() throws Exception {


        System.out.println("Start called");
        vertx.createNetServer().connectHandler(sock -> {
            Pump.pump(sock, sock).start();
        }).listen(1234);
        System.out.println("Echo server is now listening");
    }

    public static void main(String[] args) throws Exception {
        System.out.println("Main Start");
        Vertx v = Vertx.vertx();
        System.out.println("Main Deploying");
        v.deployVerticle(new MainVerticle());
    }
}

And this is the output in the console

Main Start
Main Deploying
Start called
Jun 09, 2017 1:42:00 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2920 ms, time limit is 2000
Jun 09, 2017 1:42:01 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3925 ms, time limit is 2000
Jun 09, 2017 1:42:02 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4930 ms, time limit is 2000
Echo server is now listening

I can't even imagine what the issue is, I am running jdk1.8.0_131.jdk on Mac OS X Sierra.

Sean Burns

unread,

Jun 9, 2017, 8:16:38 AM6/9/17

to vert.x

I enabled Trace level logging, I think the issue might be related to Netty, here is the log output with vertx 3.2.1

Main Deploying
Start called
14:10:32.250 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
14:10:32.250 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
14:10:32.250 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
14:10:32.251 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
14:10:32.275 [vert.x-eventloop-thread-1] DEBUG io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0xa7662b719ec62a51 (took 0 ms)
14:10:32.303 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
14:10:32.303 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
14:10:32.303 [vert.x-eventloop-thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
14:10:32.305 [vert.x-eventloop-thread-1] DEBUG io.netty.util.NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1)
14:10:32.306 [vert.x-eventloop-thread-1] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128 (non-existent)

Echo server is now listening

14:10:32.319 [vert.x-eventloop-thread-1] TRACE io.vertx.core.net.impl.NetServerImpl - Net server listening on 0.0.0.0:/0:0:0:0:0:0:0:0:1234

And here is the log with 3.4.1 (Netty seems to be blocking just before the "auto detect" stuff which is new)

Main Deploying
Start called
14:07:21.028 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
14:07:21.029 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
14:07:23.753 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2917 ms, time limit is 2000
14:07:24.756 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3921 ms, time limit is 2000
14:07:25.759 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4925 ms, time limit is 2000
14:07:26.086 [vert.x-eventloop-thread-0] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 22487 (auto-detected)
14:07:26.089 [vert.x-eventloop-thread-0] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 60:03:08:ff:fe:94:0b:78 (auto-detected)
14:07:26.091 [vert.x-eventloop-thread-0] DEBUG io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0x60d5ed67bd0f9952
14:07:26.110 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
14:07:26.111 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 65536
14:07:26.111 [vert.x-eventloop-thread-0] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384

Echo server is now listening

14:07:26.130 [vert.x-eventloop-thread-0] TRACE io.vertx.core.net.impl.NetServerBase - Net server listening on 0.0.0.0:/0:0:0:0:0:0:0:0:1234

Thomas SEGISMONT

unread,

Jun 9, 2017, 9:36:23 AM6/9/17

to ve...@googlegroups.com

Can you change the options so that the blocked thread warning shows the stacktrace? By default it's 5secs iirc and it seems it gets blocked for 4925ms on your machine :)

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+unsubscribe@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/b1eef4ec-2f94-4b91-983d-16ad04a0ab09%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

Sean Burns

unread,

Jun 9, 2017, 10:01:16 AM6/9/17

to vert.x

Thanks, I did not know about that option.

Here is the stack trace

15:59:44.806 [vertx-blocked-thread-checker] WARN  io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2914 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
 at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method) ~[?:1.8.0_131]
 at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928) ~[?:1.8.0_131]
 at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323) ~[?:1.8.0_131]
 at java.net.InetAddress.getLocalHost(InetAddress.java:1500) ~[?:1.8.0_131]
 at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140) ~[?:1.8.0_131]
 at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59) ~[?:1.8.0_131]
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_131]
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_131]
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_131]
 at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_131]
 at io.netty.channel.DefaultChannelId.defaultProcessId(DefaultChannelId.java:121) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.DefaultChannelId.<clinit>(DefaultChannelId.java:78) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.AbstractChannel.newId(AbstractChannel.java:107) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.AbstractChannel.<init>(AbstractChannel.java:79) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.nio.AbstractNioChannel.<init>(AbstractNioChannel.java:84) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.nio.AbstractNioMessageChannel.<init>(AbstractNioMessageChannel.java:42) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.socket.nio.NioDatagramChannel.<init>(NioDatagramChannel.java:147) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.socket.nio.NioDatagramChannel.<init>(NioDatagramChannel.java:115) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:1.8.0_131]
 at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:1.8.0_131]
 at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.8.0_131]
 at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:1.8.0_131]
 at java.lang.Class.newInstance(Class.java:442) ~[?:1.8.0_131]
 at io.netty.channel.ReflectiveChannelFactory.newChannel(ReflectiveChannelFactory.java:38) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.bootstrap.AbstractBootstrap.initAndRegister(AbstractBootstrap.java:321) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.bootstrap.AbstractBootstrap.register(AbstractBootstrap.java:235) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.resolver.dns.DnsNameResolver.<init>(DnsNameResolver.java:249) ~[netty-resolver-dns-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.resolver.dns.DnsNameResolverBuilder.build(DnsNameResolverBuilder.java:347) ~[netty-resolver-dns-4.1.8.Final.jar:4.1.8.Final]
 at io.vertx.core.impl.resolver.DnsResolverProvider$1$1.newNameResolver(DnsResolverProvider.java:153) ~[vertx-core-3.4.1.jar:?]
 at io.netty.resolver.dns.DnsAddressResolverGroup.newResolver(DnsAddressResolverGroup.java:84) ~[netty-resolver-dns-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.resolver.dns.DnsAddressResolverGroup.newResolver(DnsAddressResolverGroup.java:73) ~[netty-resolver-dns-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.resolver.AddressResolverGroup.getResolver(AddressResolverGroup.java:67) ~[netty-resolver-4.1.8.Final.jar:4.1.8.Final]
 at io.vertx.core.impl.resolver.DnsResolverProvider$1.newResolver(DnsResolverProvider.java:157) ~[vertx-core-3.4.1.jar:?]
 at io.netty.resolver.AddressResolverGroup.getResolver(AddressResolverGroup.java:67) ~[netty-resolver-4.1.8.Final.jar:4.1.8.Final]
 at io.vertx.core.impl.AddressResolver.resolveHostname(AddressResolver.java:83) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.impl.VertxImpl.resolveAddress(VertxImpl.java:711) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.net.impl.AsyncResolveConnectHelper.doBind(AsyncResolveConnectHelper.java:74) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.net.impl.NetServerBase.listen(NetServerBase.java:154) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.net.impl.NetServerImpl.listen(NetServerImpl.java:129) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.net.impl.NetServerImpl.listen(NetServerImpl.java:108) ~[vertx-core-3.4.1.jar:?]
 at com.thumbzup.service.payshield.MainVerticle.start(MainVerticle.java:23) ~[classes/:?]
 at io.vertx.core.AbstractVerticle.start(AbstractVerticle.java:111) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.impl.DeploymentManager$$Lambda$6/501187768.handle(Unknown Source) ~[?:?]
 at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337) ~[vertx-core-3.4.1.jar:?]
 at io.vertx.core.impl.ContextImpl$$Lambda$7/1822971466.run(Unknown Source) ~[?:?]
 at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403) ~[netty-common-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445) ~[netty-transport-4.1.8.Final.jar:4.1.8.Final]
 at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) ~[netty-common-4.1.8.Final.jar:4.1.8.Final]
 at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_131]

To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.

Visit this group at https://groups.google.com/group/vertx.

Thomas SEGISMONT

unread,

Jun 9, 2017, 10:08:35 AM6/9/17

to ve...@googlegroups.com

Looks like the processId gen needs localhost resolution. You might falling into this: https://stackoverflow.com/questions/39636792/jvm-takes-a-long-time-to-resolve-ip-address-for-localhost

Add the info in hosts file and your problem should go away

To unsubscribe from this group and stop receiving emails from it, send an email to vertx+unsubscribe@googlegroups.com.

Visit this group at https://groups.google.com/group/vertx.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/343018d7-db28-4326-956b-12bbdac7eda9%40googlegroups.com.

Julien Viet

unread,

Jun 9, 2017, 10:08:52 AM6/9/17

to ve...@googlegroups.com

what’s your OS ?

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/343018d7-db28-4326-956b-12bbdac7eda9%40googlegroups.com.

Sean Burns

unread,

Jun 9, 2017, 10:11:00 AM6/9/17

to vert.x

I am running jdk1.8.0_131.jdk on Mac OS X Sierra.

Sean Burns

unread,

Jun 9, 2017, 10:16:20 AM6/9/17

to vert.x

Thanks... adding my pc name

::1 localhost Seans-MacBook-Pro.local

Fixed the issue.

Reply all

Reply to author

Forward