Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
arisc097 opened this issue Sep 28, 2016 · 1 comment
Open

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

arisc097 opened this issue Sep 28, 2016 · 1 comment

Comments

@arisc097
Copy link

arisc097 commented Sep 28, 2016 •
edited
Loading

[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
Copy link
Owner

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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@cescoffier @arisc097