We have created a sample CorDapp and deployed it in a distributed network on AWS. Our aim is to verify whether the application can store 1 million transactions or not. However the application is crashing with SSL handshake timed out exception followed by java heap space error, when a single flow is executed multiple times for different inputs.
[INFO ] 2018-02-06T16:51:58,146Z [Node thread] connections.access.getIsolatedConnection - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@13ddad19] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
[INFO ] 2018-02-06T16:52:13,643Z [Node thread] persistence.HibernateConfiguration.makeSessionFactoryForSchemas - Created session factory for schemas: [InvoiceSchemaV1(name=com.org1.app.invoice.InvoiceSchema, version=1)]
[INFO ] 2018-02-06T16:58:18,791Z [Node thread] persistence.HibernateConfiguration.makeSessionFactoryForSchemas - Creating session factory for schemas: [InvoiceSchemaV1(name=com.org1.app.invoice.InvoiceSchema, version=1)]
[ERROR] 2018-02-06T16:57:55,388Z [main] messaging.NodeMessagingClient.deliver - Caught exception whilst executing message handler for platform.session.0
java.util.concurrent.ExecutionException: java.util.concurrent.ExecutionException: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 45]
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_161]
at net.corda.node.utilities.AffinityExecutor$DefaultImpls.fetchFrom(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor.fetchFrom(AffinityExecutor.kt:56) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.deliver(NodeMessagingClient.kt:420) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.processMessage(NodeMessagingClient.kt:310) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.runPostNetworkMap(NodeMessagingClient.kt:352) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.run(NodeMessagingClient.kt:368) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.Node.run(Node.kt:358) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.startNode(NodeStartup.kt:115) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.run(NodeStartup.kt:74) [corda-node-2.0.0.jar:?]
at net.corda.node.Corda.main(Corda.kt:11) [corda-node-2.0.0.jar:?]
Caused by: java.util.concurrent.ExecutionException: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 45]
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_161]
at net.corda.node.utilities.AffinityExecutor$DefaultImpls.fetchFrom(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor.fetchFrom(AffinityExecutor.kt:56) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.send(NodeMessagingClient.kt:484) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager.sendSessionMessage(StateMachineManager.kt:655) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager.sendSessionMessage$default(StateMachineManager.kt:629) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager.onSessionInit(StateMachineManager.kt:404) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager.onSessionMessage(StateMachineManager.kt:297) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager.access$onSessionMessage(StateMachineManager.kt:78) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager$resumeRestoredFibers$2.invoke(StateMachineManager.kt:263) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.statemachine.StateMachineManager$resumeRestoredFibers$2.invoke(StateMachineManager.kt:78) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.callHandlers(NodeMessagingClient.kt:444) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.access$callHandlers(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$deliver$1$1.invoke(NodeMessagingClient.kt:429) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$deliver$1$1.invoke(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.CordaPersistence.inTopLevelTransaction(CordaPersistence.kt:84) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.CordaPersistence.transaction(CordaPersistence.kt:75) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.CordaPersistence.transaction(CordaPersistence.kt:65) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$deliver$1.invoke(NodeMessagingClient.kt:421) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$deliver$1.invoke(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$fetchFrom$1.get(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) ~[?:1.8.0_161]
.....
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor$1$thread$1.run(AffinityExecutor.kt:69) ~[corda-node-2.0.0.jar:?]
Caused by: org.apache.activemq.artemis.api.core.ActiveMQConnectionTimedOutException: AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 45
at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:401) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:319) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.protocol.core.impl.ActiveMQSessionContext.queueQuery(ActiveMQSessionContext.java:271) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ClientSessionImpl.queueQuery(ClientSessionImpl.java:625) ~[artemis-core-client-2.1.0.jar:2.1.0]
at net.corda.node.services.messaging.NodeMessagingClient.createQueueIfAbsent(NodeMessagingClient.kt:572) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.getMQAddress(NodeMessagingClient.kt:564) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.access$getMQAddress(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$send$1.invoke(NodeMessagingClient.kt:486) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$send$1.invoke(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$fetchFrom$1.get(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) ~[?:1.8.0_161]
.....
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor$1$thread$1.run(AffinityExecutor.kt:69) ~[corda-node-2.0.0.jar:?]
[INFO ] 2018-02-06T16:58:50,543Z [Node thread] internal.ConnectionProviderInitiator.initiateService - HHH000130: Instantiating explicit connection provider: net.corda.node.services.persistence.HibernateConfiguration$NodeDatabaseConnectionProvider
[INFO ] 2018-02-06T16:58:50,550Z [Node thread] dialect.Dialect.<init> - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
[WARN ] 2018-02-06T16:58:50,551Z [Thread-30 (ActiveMQ-client-global-threads)] core.client.fail - AMQ212037: Connection failure has been detected: AMQ119011: Did not receive data from server for org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnection@3cc278a8[local= /172.43.2.182:45734, remote=172.43.2.94/172.43.2.94:10002] [code=CONNECTION_TIMEDOUT]
[INFO ] 2018-02-06T16:58:50,565Z [Node thread] type.BasicTypeRegistry.register - HHH000270: Type registration [materialized_blob] overrides previous : org.hibernate.type.MaterializedBlobType@31142d58
[WARN ] 2018-02-06T16:58:58,531Z [Thread-31 (ActiveMQ-client-global-threads)] core.client.fail - AMQ212037: Connection failure has been detected: AMQ119011: Did not receive data from server for org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnection@39a48023[local= /172.43.2.182:41766, remote=172.43.2.120/172.43.2.120:10005] [code=CONNECTION_TIMEDOUT]
[INFO ] 2018-02-06T16:59:29,775Z [Node thread] connections.access.getIsolatedConnection - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@a1bcdf7] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode.
[INFO ] 2018-02-06T16:59:53,062Z [Node thread] persistence.HibernateConfiguration.makeSessionFactoryForSchemas - Created session factory for schemas: [InvoiceSchemaV1(name=com.org1.app.invoice.InvoiceSchema, version=1)]
[ERROR] 2018-02-06T17:00:32,534Z [Thread-251 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$3@6b2e9db2)] core.client.createConnection - AMQ214016: Failed to create netty connection
javax.net.ssl.SSLException: handshake timed out
at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
[WARN ] 2018-02-06T17:00:55,826Z [Thread-32 (ActiveMQ-client-global-threads)] messaging.RPCServer.bindingRemovalArtemisMessageHandler - Detected RPC client disconnect on address rpc.client.SystemUsers/Node.3952268792838798166, scheduling for reaping
[ERROR] 2018-02-06T17:04:18,493Z [Thread-258 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$3@6b2e9db2)] core.client.createConnection - AMQ214016: Failed to create netty connection
javax.net.ssl.SSLException: handshake timed out
at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
[INFO ] 2018-02-06T17:04:26,310Z [Node thread] persistence.HibernateConfiguration.makeSessionFactoryForSchemas - Creating session factory for schemas: [InvoiceSchemaV1(name=com.org1.app.invoice.InvoiceSchema, version=1)]
[WARN ] 2018-02-06T17:04:26,311Z [Thread-259 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$3@6b2e9db2)] core.client.fail - AMQ212037: Connection failure has been detected: AMQ119014: Did not receive data from /172.43.2.182:52884 within the 60,000ms connection TTL. The connection will now be closed. [code=CONNECTION_TIMEDOUT]
[INFO ] 2018-02-06T17:04:41,883Z [Node thread] internal.ConnectionProviderInitiator.initiateService - HHH000130: Instantiating explicit connection provider: net.corda.node.services.persistence.HibernateConfiguration$NodeDatabaseConnectionProvider
[INFO ] 2018-02-06T17:04:41,884Z [Node thread] dialect.Dialect.<init> - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
[INFO ] 2018-02-06T17:04:50,056Z [Node thread] type.BasicTypeRegistry.register - HHH000270: Type registration [materialized_blob] overrides previous : org.hibernate.type.MaterializedBlobType@31142d58
............
[ERROR] 2018-02-06T19:24:09,447Z [Thread-453 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$3@6b2e9db2)] core.client.createConnection - AMQ214016: Failed to create netty connection
javax.net.ssl.SSLException: handshake timed out
at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
[ERROR] 2018-02-06T19:25:11,537Z [main] messaging.NodeMessagingClient.deliver - Caught exception whilst executing message handler for platform.session.0
java.util.concurrent.ExecutionException: java.util.concurrent.ExecutionException: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 71]
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_161]
at net.corda.node.utilities.AffinityExecutor$DefaultImpls.fetchFrom(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor.fetchFrom(AffinityExecutor.kt:56) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.deliver(NodeMessagingClient.kt:420) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.processMessage(NodeMessagingClient.kt:310) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.runPostNetworkMap(NodeMessagingClient.kt:352) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.run(NodeMessagingClient.kt:368) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.Node.run(Node.kt:358) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.startNode(NodeStartup.kt:115) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.run(NodeStartup.kt:74) [corda-node-2.0.0.jar:?]
at net.corda.node.Corda.main(Corda.kt:11) [corda-node-2.0.0.jar:?]
............
Caused by: org.apache.activemq.artemis.api.core.ActiveMQConnectionTimedOutException: AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 71
at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:401) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:319) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.protocol.core.impl.ActiveMQSessionContext.sendFullMessage(ActiveMQSessionContext.java:439) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ClientProducerImpl.sendRegularMessage(ClientProducerImpl.java:292) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ClientProducerImpl.doSend(ClientProducerImpl.java:264) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:126) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ClientProducerImpl.send(ClientProducerImpl.java:131) ~[artemis-core-client-2.1.0.jar:2.1.0]
at net.corda.node.services.messaging.NodeMessagingClient$send$1.invoke(NodeMessagingClient.kt:506) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient$send$1.invoke(NodeMessagingClient.kt:76) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$fetchFrom$1.get(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590) ~[?:1.8.0_161]
....
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor$1$thread$1.run(AffinityExecutor.kt:69) ~[corda-node-2.0.0.jar:?]
[ERROR] 2018-02-06T19:30:30,052Z [main] messaging.NodeMessagingClient.deliver - Caught exception whilst executing message handler for platform.session.0
java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:357) ~[?:1.8.0_161]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1895) ~[?:1.8.0_161]
at net.corda.node.utilities.AffinityExecutor$DefaultImpls.fetchFrom(AffinityExecutor.kt:44) ~[corda-node-2.0.0.jar:?]
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor.fetchFrom(AffinityExecutor.kt:56) ~[corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.deliver(NodeMessagingClient.kt:420) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.processMessage(NodeMessagingClient.kt:310) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.runPostNetworkMap(NodeMessagingClient.kt:352) [corda-node-2.0.0.jar:?]
at net.corda.node.services.messaging.NodeMessagingClient.run(NodeMessagingClient.kt:368) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.Node.run(Node.kt:358) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.startNode(NodeStartup.kt:115) [corda-node-2.0.0.jar:?]
at net.corda.node.internal.NodeStartup.run(NodeStartup.kt:74) [corda-node-2.0.0.jar:?]
at net.corda.node.Corda.main(Corda.kt:11) [corda-node-2.0.0.jar:?]
Caused by: java.lang.OutOfMemoryError: Java heap space
[WARN ] 2018-02-06T19:30:53,316Z [Thread-0 (activemq-netty-threads)] channel.DefaultChannelPipeline.warn - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
java.lang.OutOfMemoryError: Java heap space
[WARN ] 2018-02-06T19:30:53,317Z [Finalizer] core.client.finalize - AMQ212008: I am closing a core ClientSessionFactory you left open. Please make sure you close all ClientSessionFactories explicitly before letting them go out of scope! 1,984,930,856
java.lang.Exception: null
at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.<init>(ClientSessionFactoryImpl.java:168) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:680) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.reconnectOnOriginalNode(BridgeImpl.java:832) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.createSessionFactory(BridgeImpl.java:800) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.connect(BridgeImpl.java:860) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl$ConnectRunnable.run(BridgeImpl.java:1045) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:101) ~[artemis-commons-2.1.0.jar:2.1.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_161]
[WARN ] 2018-02-06T19:31:24,925Z [Finalizer] core.client.finalize - AMQ212008: I am closing a core ClientSessionFactory you left open. Please make sure you close all ClientSessionFactories explicitly before letting them go out of scope! 474,648,234
java.lang.Exception: null
at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.<init>(ClientSessionFactoryImpl.java:168) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:680) ~[artemis-core-client-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.reconnectOnOriginalNode(BridgeImpl.java:832) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.createSessionFactory(BridgeImpl.java:800) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl.connect(BridgeImpl.java:860) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.core.server.cluster.impl.BridgeImpl$ConnectRunnable.run(BridgeImpl.java:1045) ~[artemis-server-2.1.0.jar:2.1.0]
at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:101) ~[artemis-commons-2.1.0.jar:2.1.0]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_161]
[WARN ] 2018-02-06T19:44:36,116Z [Thread-0 (activemq-netty-threads)] epoll.EpollEventLoop.warn - Unexpected exception in the selector loop.
io.netty.util.IllegalReferenceCountException: refCnt: 0, decrement: 1
at io.netty.buffer.AbstractReferenceCountedByteBuf.release0(AbstractReferenceCountedByteBuf.java:101) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.buffer.AbstractReferenceCountedByteBuf.release(AbstractReferenceCountedByteBuf.java:89) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.handleReadException(AbstractEpollStreamChannel.java:811) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:1043) ~[netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:394) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:299) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
[WARN ] 2018-02-06T19:59:44,192Z [Thread-2 (activemq-netty-threads)] concurrent.AbstractEventExecutor.warn - A task raised an exception. Task: io.netty.channel.AbstractChannel$AbstractUnsafe$1@51a2d13d
java.lang.OutOfMemoryError: Java heap space
[WARN ] 2018-02-06T19:59:51,967Z [Thread-0 (activemq-netty-threads)] channel.AbstractChannelHandlerContext.warn - An exception 'java.lang.OutOfMemoryError: Java heap space' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
java.lang.OutOfMemoryError: Java heap space
[WARN ] 2018-02-06T19:59:44,193Z [Thread-4 (activemq-netty-threads)] channel.AbstractChannelHandlerContext.warn - An exception 'java.lang.OutOfMemoryError: Java heap space' [enable DEBUG level for full stacktrace] was thrown by a user handler's exceptionCaught() method while handling the following exception:
io.netty.channel.ChannelPipelineException: org.apache.activemq.artemis.core.remoting.impl.netty.NettyAcceptor$3.handlerAdded() has thrown an exception; removed.
at io.netty.channel.DefaultChannelPipeline.callHandlerAdded0(DefaultChannelPipeline.java:617) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.DefaultChannelPipeline.access$000(DefaultChannelPipeline.java:44) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.DefaultChannelPipeline$PendingHandlerAddedTask.execute(DefaultChannelPipeline.java:1387) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.DefaultChannelPipeline.callHandlerAddedForAllHandlers(DefaultChannelPipeline.java:1122) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.DefaultChannelPipeline.invokeHandlerAddedIfNeeded(DefaultChannelPipeline.java:647) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.register0(AbstractChannel.java:506) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe.access$200(AbstractChannel.java:419) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.AbstractChannel$AbstractUnsafe$1.run(AbstractChannel.java:478) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.9.Final.jar:4.1.9.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]
Caused by: java.lang.OutOfMemoryError: Java heap space
[WARN ] 2018-02-06T20:00:07,519Z [Thread-3 (activemq-netty-threads)] bootstrap.ServerBootstrap.warn - Failed to register an accepted channel: [id: 0x917cc14d, L:/172.43.2.182:10008 ! R:/172.43.2.94:35734]
java.lang.OutOfMemoryError: Java heap space
What could be the possible reason for this crash/exception?
About the CorDapp:
The application defines a flow which creates an invoice between the parties. The create transaction is signed by A and B node. The create transaction request is always sent to Party A. It signs the transaction after validation. Party A then forwards the request to Part B for signing. Once both parties have signed the transaction is sent to finality flow for commit. Party C simply commits the transaction. There is no signing by Party C. The state and ledger is stored on all three nodes.
The application has
- 3 party nodes (A, B, C)
- 2 notary nodes (1 simple, 1 validating)
- 1 oracle service node
- 1 Controller node
Condition:
We started executing the create flow using JMeter (25 threads running in loop, max one request per second). Initially, the application responded well with response time at around 2~4 transactions per second. However as the number of committed transactions increased, the performance started deterioting. At around 200K transactions, the application crashed with with Java heap space error. We have set the max heap size for java Corda process at 4GB.
Our observations:
- It is always the B node which crashes. Within our Corda flow, responsibility of this node is to sign the transaction and later on commit it to database in FinalityFlow.
- Using netstat command on B node, it shows multiple connection in CLOSE_WAIT1 state and few in FIN_WAIT1 state.
- From the log it seems that, at first there is SSLException stating SSL handshake timed out for executing flows. After multiple such exceptions, there is Java heap space error.
- The B node stops communicating with other nodes after certain time/condition, which in turn leads to all these exceptions. However the reason why this is happening is unknown to us.
