search

cescoffier / vertx-microservices-workshop

Vert.x Microservices Hand's on lab
http://escoffier.me/vertx-hol/
Apache License 2.0
330 stars 196 forks source link

audit-service fails to load after the other components are up. #11

Open arisc097 opened 7 years ago

arisc097 commented 7 years ago

[INFO] Reactor Summary: [INFO] [INFO] vertx-microservice-workshop ........................ SUCCESS [ 2.208 s] [INFO] vertx-workshop-common .............................. SUCCESS [ 4.765 s] [INFO] quote-generator .................................... SUCCESS [ 10.839 s] [INFO] portfolio-service .................................. SUCCESS [ 7.528 s] [INFO] audit-service ...................................... SUCCESS [ 3.877 s] [INFO] compulsive-traders ................................. SUCCESS [ 3.506 s] [INFO] trader-dashboard ................................... SUCCESS [ 4.402 s] [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 37.704 s [INFO] Finished at: 2016-09-27T19:11:51-07:00 [INFO] Final Memory: 62M/305M [INFO] ------------------------------------------------------------------------

| => java -jar target/quote-generator-1.0-SNAPSHOT-fat.jar Members [1] { Member [127.0.0.1]:5701 this }

Sep 27, 2016 7:12:18 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5701 [dev] [3.6.3] Address[127.0.0.1]:5701 is STARTED Sep 27, 2016 7:12:18 PM com.hazelcast.partition.InternalPartitionService INFO: [127.0.0.1]:5701 [dev] [3.6.3] Initializing cluster partition table arrangement... Reading config file: /Users/arisco97/workspace/vertx-microservices-workshop/quote-generator/src/conf/config.json Sep 27, 2016 7:12:19 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer INFO: Succeeded in deploying verticle Market-Data service published : true Quotes (Rest endpoint) service published : true Server started

| => java -jar target/trader-dashboard-1.0-SNAPSHOT-fat.jar Members [2] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 this }

Sep 27, 2016 7:13:13 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5702 [dev] [3.6.3] Address[127.0.0.1]:5702 is STARTED Config file not found /Users/arisco97/workspace/vertx-microservices-workshop/trader-dashboard/src/conf/config.json Sep 27, 2016 7:13:14 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer INFO: Succeeded in deploying verticle

| => java -jar target/portfolio-service-1.0-SNAPSHOT-fat.jar Members [3] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 this }

Sep 27, 2016 7:13:44 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5703 [dev] [3.6.3] Address[127.0.0.1]:5703 is STARTED Config file not found /Users/arisco97/workspace/vertx-microservices-workshop/portfolio-service/src/conf/config.json Portfolio service published : true Sep 27, 2016 7:13:45 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer INFO: Succeeded in deploying verticle Portfolio Events service published : true

| => java -jar target/compulsive-traders-1.0-SNAPSHOT-fat.jar Members [4] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 Member [127.0.0.1]:5704 this }

Sep 27, 2016 7:14:16 PM com.hazelcast.map.impl.query.MapQueryEngineImpl INFO: [127.0.0.1]:5704 [dev] [3.6.3] Partition assignments changed while executing query: TruePredicate{} Sep 27, 2016 7:14:17 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5704 [dev] [3.6.3] Address[127.0.0.1]:5704 is STARTED Config file not found /Users/arisco97/workspace/vertx-microservices-workshop/compulsive-traders/src/conf/config.json Java compulsive trader configured for company Divinator and shares: 4 Sep 27, 2016 7:14:18 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer INFO: Succeeded in deploying verticle

| => java -jar target/audit-service-1.0-SNAPSHOT-fat.jar Members [5] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 Member [127.0.0.1]:5704 Member [127.0.0.1]:5705 this }

Sep 27, 2016 7:14:50 PM com.hazelcast.nio.tcp.SocketAcceptorThread INFO: [127.0.0.1]:5705 [dev] [3.6.3] Accepting socket connection from /127.0.0.1:52757 Sep 27, 2016 7:14:50 PM com.hazelcast.nio.tcp.TcpIpConnectionManager INFO: [127.0.0.1]:5705 [dev] [3.6.3] Established socket connection between /127.0.0.1:5705 and /127.0.0.1:52757 Sep 27, 2016 7:14:50 PM com.hazelcast.nio.tcp.InitConnectionTask INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connecting to /127.0.0.1:5704, timeout: 0, bind-any: true Sep 27, 2016 7:14:50 PM com.hazelcast.nio.tcp.TcpIpConnectionManager INFO: [127.0.0.1]:5705 [dev] [3.6.3] Established socket connection between /127.0.0.1:52758 and /127.0.0.1:5704 Sep 27, 2016 7:14:52 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5705 [dev] [3.6.3] Address[127.0.0.1]:5705 is STARTED Reading config file: /Users/arisco97/workspace/vertx-microservices-workshop/audit-service/src/conf/config.json Sep 27, 2016 7:14:53 PM com.mchange.v2.log.MLog INFO: MLog clients using java 1.4+ standard logging. Sep 27, 2016 7:14:53 PM com.mchange.v2.c3p0.C3P0Registry INFO: Initializing c3p0-0.9.5.2 [built 08-December-2015 22:06:04 -0800; debug? true; trace: 10] Sep 27, 2016 7:14:53 PM com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource INFO: Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge16l9juohgt41la3sag|6b2b20a6, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> null, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge16l9juohgt41la3sag|6b2b20a6, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:hsqldb:file:audit-db;shutdown=true, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ] java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:414) at sun.nio.ch.Net.bind(Net.java:406) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214) at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:127) at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:554) at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1258) at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:511) at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:496) at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:980) at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:250) at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:363) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:394) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:369) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:433) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) at java.lang.Thread.run(Thread.java:745) Sep 27, 2016 7:14:53 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer SEVERE: Failed in deploying verticle java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:414) at sun.nio.ch.Net.bind(Net.java:406) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214) at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:127) at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:554) at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1258) at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:511) at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:496) at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:980) at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:250) at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:363) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:394) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:369) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:433) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) at java.lang.Thread.run(Thread.java:745)

java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:414) at sun.nio.ch.Net.bind(Net.java:406) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:214) at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:127) at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:554) at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1258) at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:511) at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:496) at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:980) at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:250) at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:363) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:394) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:369) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:433) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) at java.lang.Thread.run(Thread.java:745) Sep 27, 2016 7:14:53 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5705 [dev] [3.6.3] Address[127.0.0.1]:5705 is SHUTTING_DOWN Sep 27, 2016 7:14:53 PM com.hazelcast.instance.Node INFO: [127.0.0.1]:5705 [dev] [3.6.3] Shutting down connection manager... Sep 27, 2016 7:14:53 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connection [Address[127.0.0.1]:5701] lost. Reason: Socket explicitly closed Sep 27, 2016 7:14:53 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connection [Address[127.0.0.1]:5702] lost. Reason: Socket explicitly closed Sep 27, 2016 7:14:53 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connection [Address[127.0.0.1]:5703] lost. Reason: Socket explicitly closed Sep 27, 2016 7:14:53 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connection [Address[127.0.0.1]:5704] lost. Reason: Socket explicitly closed Sep 27, 2016 7:14:53 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5705 [dev] [3.6.3] Connection [Address[127.0.0.1]:5704] lost. Reason: Socket explicitly closed Sep 27, 2016 7:14:53 PM com.hazelcast.instance.Node INFO: [127.0.0.1]:5705 [dev] [3.6.3] Shutting down node engine... Sep 27, 2016 7:14:54 PM com.hazelcast.instance.NodeExtension INFO: [127.0.0.1]:5705 [dev] [3.6.3] Destroying node NodeExtension. Sep 27, 2016 7:14:54 PM com.hazelcast.instance.Node INFO: [127.0.0.1]:5705 [dev] [3.6.3] Hazelcast Shutdown is completed in 233 ms. Sep 27, 2016 7:14:54 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5705 [dev] [3.6.3] Address[127.0.0.1]:5705 is SHUTDOWN

What am i missing?

I also tried launching trader-dashboard as the last verticle. In this case the audit-service launched properly, but the trader-dashboard failed.

| => java -jar target/audit-service-1.0-SNAPSHOT-fat.jar Members [4] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 Member [127.0.0.1]:5704 this }

Sep 27, 2016 7:25:57 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5704 [dev] [3.6.3] Address[127.0.0.1]:5704 is STARTED . . . . Sep 27, 2016 7:26:09 PM com.hazelcast.cluster.ClusterService INFO: [127.0.0.1]:5704 [dev] [3.6.3]

Members [5] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 Member [127.0.0.1]:5704 this Member [127.0.0.1]:5705 //trader-dashboard was introduced into cluster. }

Sep 27, 2016 7:26:09 PM com.hazelcast.nio.tcp.InitConnectionTask INFO: [127.0.0.1]:5704 [dev] [3.6.3] Connecting to /127.0.0.1:5705, timeout: 0, bind-any: true Sep 27, 2016 7:26:09 PM com.hazelcast.nio.tcp.TcpIpConnectionManager INFO: [127.0.0.1]:5704 [dev] [3.6.3] Established socket connection between /127.0.0.1:52895 and /127.0.0.1:5705 Sep 27, 2016 7:26:12 PM com.hazelcast.nio.tcp.TcpIpConnection INFO: [127.0.0.1]:5704 [dev] [3.6.3] Connection [Address[127.0.0.1]:5705] lost. Reason: Socket explicitly closed //connection to trader-dashboard lost.

| => java -jar target/trader-dashboard-1.0-SNAPSHOT-fat.jar Members [5] { Member [127.0.0.1]:5701 Member [127.0.0.1]:5702 Member [127.0.0.1]:5703 Member [127.0.0.1]:5704 Member [127.0.0.1]:5705 this }

Sep 27, 2016 7:26:09 PM com.hazelcast.nio.tcp.SocketAcceptorThread INFO: [127.0.0.1]:5705 [dev] [3.6.3] Accepting socket connection from /127.0.0.1:52895 Sep 27, 2016 7:26:09 PM com.hazelcast.nio.tcp.TcpIpConnectionManager INFO: [127.0.0.1]:5705 [dev] [3.6.3] Established socket connection between /127.0.0.1:5705 and /127.0.0.1:52895 Sep 27, 2016 7:26:11 PM com.hazelcast.core.LifecycleService INFO: [127.0.0.1]:5705 [dev] [3.6.3] Address[127.0.0.1]:5705 is STARTED Config file not found /Users/arisco97/workspace/vertx-microservices-workshop/trader-dashboard/src/conf/config.json java.net.BindException: Address already in use

cescoffier commented 7 years ago

Can you check on which port the RestQuoteAPIVerticle is using ?

In addition, in the AuditVerticle you need to start another HTTP server. The solution start it on the port 0 to avoid conflict (and as the discovery is used to retrieve the endpoint we don't need to know the port).