Questions on stability of NIS running as SuperNode

Thies1965 · December 30, 2017, 11:33am

Hi,
in the last days I noticed that one of my supernodes is running into issues where tests fail due to no responses.
The node (NEM_Cloud_2) is running on the latest nis level 0.6.95 on CentOS (4GB).

I was walking through the log files to find any hints when and what is going wrong. I am still in the process of analysing. But I found some entries, I could not interpret. Maybe someone from the nis team could shed some light on this:

After running a couple of hours without any such warning, this appears repeatedly:
WARNUNG your balance hasn’t vested yet, harvesting does not make sense
To which account does “your balance” refer to ? Is it the account running the super node?

2017-12-30 04:00:23.140 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-30 04:00:23.142 WARNUNG your balance hasn’t vested yet, harvesting does not make sense (org.nem.nis.state.AccountImportance t)
2017-12-30 04:00:24.143 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-30 04:00:24.146 WARNUNG your balance hasn’t vested yet, harvesting does not make sense (org.nem.nis.state.AccountImportance t)
2017-12-30 04:00:25.146 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-30 04:00:25.149 WARNUNG your balance hasn’t vested yet, harvesting does not make sense (org.nem.nis.state.AccountImportance t)
2017-12-30 04:00:25.168 INFORMATION synchronizing with Node [Hi, I am Alice6 ] @ [108.61.168.86] (org.nem.peer.services.NodeSynchronizer b)
2017-12-30 04:00:25.904 INFORMATION synchronizing with Node [Hi, I am Alice6 ] @ [108.61.168.86] finished (org.nem.peer.services.NodeSynchronizer b)
2017-12-30 04:00:26.150 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-30 04:00:26.152 WARNUNG your balance hasn’t vested yet, harvesting does not make sense (org.nem.nis.state.AccountImportance t)
2017-12-30 04:00:27.153 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-30 04:00:27.156 WARNUNG your balance hasn’t vested yet, harvesting does not make sense (org.nem.nis.state.AccountImportance t)

2) Exception due to HTTP status 500 on Timer BROADCAST
This exception occurs only on Timer BROADCAST, not clear which peer does not respond, but this repeats every hour.
Does this have an impact on time synchronization of my own node?

2017-12-30 01:04:47.742 WARNUNG Timer BROADCAST raised exception: org.nem.core.connect.FatalPeerException: Peer returned 500 with error: <�Internal Server Error7Request cannot be executed; I/O reactor status: STOPPED-�/>
java.util.concurrent.CompletionException: org.nem.core.connect.FatalPeerException: Peer returned 500 with error: <�Internal Server Error7Request cannot be executed; I/O reactor status: STOPPED-�/>
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:604)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.nem.core.connect.HttpMethodClient$HttpMethodClientFutureCallback.completed(HttpMethodClient.java:196)
	at org.nem.core.connect.HttpMethodClient$HttpMethodClientFutureCallback.completed(HttpMethodClient.java:186)
	at org.apache.http.concurrent.BasicFuture.completed(BasicFuture.java:119)
	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:181)
	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:437)
	at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:327)
	at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:265)
	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
	at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
	at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
	at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
	at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
	at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
	at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:588)
	at java.lang.Thread.run(Thread.java:745)
Caused by: org.nem.core.connect.FatalPeerException: Peer returned 500 with error: <�Internal Server Error7Request cannot be executed; I/O reactor status: STOPPED-�/>
	at org.nem.core.connect.HttpDeserializerResponseStrategy.coerce(HttpDeserializerResponseStrategy.java:29)
	at org.nem.core.connect.HttpDeserializerResponseStrategy.coerce(HttpDeserializerResponseStrategy.java:14)
	at org.nem.core.connect.HttpMethodClient.lambda$sendRequest$1(HttpMethodClient.java:121)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
	... 20 more
 (org.nem.core.async.NemAsyncTimerVisitor notifyOperationCompleteExceptionally)

3) NIS_ILLEGAL_STATE_LOADING_CHAIN when starting nis
The log shows entries stating NIS_ILLEGAL_STATE_LOADING_CHAIN.
What does this actually mean? Why do those entries not show-up on another supernode?

2017-12-29 22:44:40.248 INFORMATION entering /time-sync/network-time [24.51.60.23] (org.nem.nis.controller.interceptors.AuditInterceptor preHandle)
2017-12-29 22:44:40.249 WARNUNG Can't perform any actions until db is fully loaded; currently at height 6600 (org.nem.nis.controller.te.ibx preHandle)
2017-12-29 22:44:40.258 INFORMATION entering /account/harvests [24.51.60.23] (org.nem.nis.controller.interceptors.AuditInterceptor preHandle)
2017-12-29 22:44:40.259 WARNUNG Can't perform any actions until db is fully loaded; currently at height 6600 (org.nem.nis.controller.te.ibx preHandle)
2017-12-29 22:44:40.259 WARNUNG Can't perform any actions until db is fully loaded; currently at height 6600 (org.nem.nis.controller.te.ibx preHandle)
2017-12-29 22:44:40.260 SCHWERWIEGEND Http Status Code 503: NIS_ILLEGAL_STATE_LOADING_CHAIN (org.nem.core.connect.ErrorResponse <init>)
2017-12-29 22:44:40.260 SCHWERWIEGEND Http Status Code 503: NIS_ILLEGAL_STATE_LOADING_CHAIN (org.nem.core.connect.ErrorResponse <init>)
2017-12-29 22:44:40.261 SCHWERWIEGEND Http Status Code 503: NIS_ILLEGAL_STATE_LOADING_CHAIN (org.nem.core.connect.ErrorResponse <init>)
2017-12-29 22:44:40.266 INFORMATION loadBlocks (from height 6602 to height 6701) needed 66ms (org.nem.nis.dao.BlockDaoImpl d)

Sorry for bothering with this, but I try to solve the root-cause for the instability of my supernode.
The weird thing is that this node was running very stable over the years.

Thank you, Markus.

BloodyRookie · December 30, 2017, 2:57pm

Hi Markus,

means that some guy let his account remote harvest on your server, then moved the balance of the account and is not eligible for harvesting any more.
means that a remote node has problems and cannot accept the broadcasted entity.
means that your NIS is loading the chain when starting, just wait for it to complete.

None of the above should let your node fail a test.
Looking at
https://supernodes.nem.io/details/59
i am wondering if you have started NIS with only 1GB heap. Did you adjust the startup param to give java more heap? Since it is a 4GB node, you can give 2800M to the java process.

Thies1965 · December 31, 2017, 11:32am

Hi BR,

thank you for your explanations.
Indeed, I started the NIS with the default heap settings.

This morning, the supernode failed again the height tests.
Looking into the log files, I found again some exceptions which just occur before the block height did not increase on the supernode.

May I ask you to have a quick judging look into them?
My impression is that after those exceptions the server does not process any push transactions anymore (IMHO).

Http Status Code 500: java.util.concurrent.CancellationException

2017-12-31 00:01:58.649 WARNUNG forcibly aborting request to http://69.232.158.87:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:01:58.650 SCHWERWIEGEND Http Status Code 500: java.util.concurrent.CancellationException (org.nem.core.connect.ErrorResponse <init>)
2017-12-31 00:01:58.650 SCHWERWIEGEND Failed to invoke @ExceptionHandler method: public org.springframework.http.ResponseEntity<org.nem.core.connect.ErrorResponse> org.nem.nis.controller.cot.c(java.lang.Exception)
java.lang.IllegalStateException: WRITER
	at org.eclipse.jetty.server.Response.getOutputStream(Response.java:896)
	at org.springframework.http.server.ServletServerHttpResponse.getBody(ServletServerHttpResponse.java:84)
	at org.nem.deploy.SerializableEntityHttpMessageConverter.a(SerializableEntityHttpMessageConverter.java:49)
	at org.nem.deploy.SerializableEntityHttpMessageConverter.writeInternal(SerializableEntityHttpMessageConverter.java:13)
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:208)
	at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:161)
	at org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor.handleReturnValue(HttpEntityMethodProcessor.java:146)
	at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:71)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:126)
	at org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver.doResolveHandlerMethodException(ExceptionHandlerExceptionResolver.java:362)
	at org.springframework.web.servlet.handler.AbstractHandlerMethodExceptionResolver.doResolveException(AbstractHandlerMethodExceptionResolver.java:60)
	at org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver.resolveException(AbstractHandlerExceptionResolver.java:138)
	at org.springframework.web.servlet.handler.HandlerExceptionResolverComposite.resolveException(HandlerExceptionResolverComposite.java:74)
	at org.springframework.web.servlet.DispatcherServlet.processHandlerException(DispatcherServlet.java:1183)
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1020)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:971)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:868)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
	at org.nem.deploy.server.AbstractNemServletContextListener$1.doFilter(AbstractNemServletContextListener.java:124)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:83)
	at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:300)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlets.DoSFilter.doFilterChain(DoSFilter.java:470)
	at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:322)
	at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:292)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)
 (org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver doResolveHandlerMethodException)
2017-12-31 00:01:58.650 INFORMATION exiting /node/sign-of-life [69.232.158.87] (org.nem.nis.controller.interceptors.AuditInterceptor afterCompletion)
2017-12-31 00:01:59.122 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:00.125 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:01.129 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:02.132 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:03.135 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:04.139 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:05.142 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:06.145 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:07.149 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:08.152 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:09.156 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:10.159 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:11.162 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:12.167 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:13.170 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:13.500 WARNUNG forcibly aborting request to http://153.122.86.245:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:02:13.500 SCHWERWIEGEND Http Status Code 500: java.util.concurrent.CancellationException (org.nem.core.connect.ErrorResponse <init>)
2017-12-31 00:02:13.501 SCHWERWIEGEND Failed to invoke @ExceptionHandler method: public org.springframework.http.ResponseEntity<org.nem.core.connect.ErrorResponse> org.nem.nis.controller.cot.c(java.lang.Exception)
java.lang.IllegalStateException: WRITER
	at org.eclipse.jetty.server.Response.getOutputStream(Response.java:896)
	at org.springframework.http.server.ServletServerHttpResponse.getBody(ServletServerHttpResponse.java:84)
	at org.nem.deploy.SerializableEntityHttpMessageConverter.a(SerializableEntityHttpMessageConverter.java:49)
	at org.nem.deploy.SerializableEntityHttpMessageConverter.writeInternal(SerializableEntityHttpMessageConverter.java:13)
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:208)
	at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:161)
	at org.springframework.web.servlet.mvc.method.annotation.HttpEntityMethodProcessor.handleReturnValue(HttpEntityMethodProcessor.java:146)
	at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:71)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:126)
	at org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver.doResolveHandlerMethodException(ExceptionHandlerExceptionResolver.java:362)
	at org.springframework.web.servlet.handler.AbstractHandlerMethodExceptionResolver.doResolveException(AbstractHandlerMethodExceptionResolver.java:60)
	at org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver.resolveException(AbstractHandlerExceptionResolver.java:138)
	at org.springframework.web.servlet.handler.HandlerExceptionResolverComposite.resolveException(HandlerExceptionResolverComposite.java:74)
	at org.springframework.web.servlet.DispatcherServlet.processHandlerException(DispatcherServlet.java:1183)
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1020)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:971)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:966)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:868)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:842)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)
	at org.nem.deploy.server.AbstractNemServletContextListener$1.doFilter(AbstractNemServletContextListener.java:124)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlets.UserAgentFilter.doFilter(UserAgentFilter.java:83)
	at org.eclipse.jetty.servlets.GzipFilter.doFilter(GzipFilter.java:300)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlets.DoSFilter.doFilterChain(DoSFilter.java:470)
	at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:322)
	at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:292)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:110)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:499)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
	at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
	at java.lang.Thread.run(Thread.java:745)
 (org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver doResolveHandlerMethodException)
2017-12-31 00:02:13.501 INFORMATION exiting /node/sign-of-life [153.122.86.245] (org.nem.nis.controller.interceptors.AuditInterceptor afterCompletion)
2017-12-31 00:02:14.173 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)

2 /chain/last-block height:1438086, the height which did not increase over time (reason for failing test)

2017-12-31 00:02:43.277 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:44.281 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:45.285 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:46.288 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:47.292 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:02:47.637 INFORMATION /chain/last-block height:1438086 signer:NBRMGZKWJU2Y3VWSZLRZZMT7NXOBBIU2JS63Y6IO (org.nem.nis.controller.zwd bP)
2017-12-31 00:02:48.296 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)

3 FAILURE_ENTITY_UNUSABLE_OUT_OF_SYNC

2017-12-31 00:04:02.560 WARNUNG forcibly aborting request to http://62.75.171.41:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:04:02.561 WARNUNG Timer BROADCAST BUFFERED ENTITIES raised exception: java.util.concurrent.CancellationException
java.util.concurrent.CompletionException: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2265)
	at org.nem.core.connect.HttpMethodClient$HttpMethodClientFutureCallback.cancelled(HttpMethodClient.java:216)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:157)
	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.executionCancelled(DefaultClientExchangeHandlerImpl.java:116)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.connectionRequestCancelled(AbstractClientExchangeHandler.java:357)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.access$200(AbstractClientExchangeHandler.java:62)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler$1.cancelled(AbstractClientExchangeHandler.java:397)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$1.cancelled(PoolingNHttpClientConnectionManager.java:295)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$2.cancel(PoolingNHttpClientConnectionManager.java:304)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.cancel(AbstractClientExchangeHandler.java:443)
	at org.apache.http.client.methods.AbstractExecutionAwareRequest.abort(AbstractExecutionAwareRequest.java:90)
	at org.nem.core.connect.HttpMethodClient.lambda$sendRequest$2(HttpMethodClient.java:129)
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.nem.core.async.SleepFuture$1.run(SleepFuture.java:24)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
Caused by: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2263)
	... 21 more
 (org.nem.core.async.NemAsyncTimerVisitor notifyOperationCompleteExceptionally)
2017-12-31 00:04:02.582 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:04:03.585 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:04:04.589 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:04:05.116 INFORMATION entering /push/block [185.122.56.35] (org.nem.nis.controller.interceptors.AuditInterceptor preHandle)
2017-12-31 00:04:05.118 INFORMATION    block height: 1438441 (org.nem.nis.service.PushService m)
2017-12-31 00:04:05.118 INFORMATION isLastBlockParent? false; last block height: 1438086; hash: 99ac8208c57096c18a1bd28132e50c81540a8ec49ffa356a684d0dba063a7df6 (org.nem.nis.BlockChain a)
2017-12-31 00:04:05.118 INFORMATION Warning: ValidationResult=FAILURE_ENTITY_UNUSABLE_OUT_OF_SYNC (org.nem.nis.service.PushService a)
2017-12-31 00:04:05.118 INFORMATION exiting /push/block [185.122.56.35] (org.nem.nis.controller.interceptors.AuditInterceptor afterCompletion)

4 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [itechly-1 ] @ [47.91.72.121]>

2017-12-31 00:05:14.718 WARNUNG forcibly aborting request to http://82.196.9.221:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:05:14.719 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [hokkaido <NCGMPRP5FUGCH6UGGRR6WP7UORPHEB7XPVF2P23C>] @ [82.196.9.221]>: java.util.concurrent.CompletionException: java.util.concurrent.CancellationException (org.nem.peer.services.NodeRefresher a)
2017-12-31 00:05:14.719 INFORMATION Updating "Node [hokkaido <NCGMPRP5FUGCH6UGGRR6WP7UORPHEB7XPVF2P23C>] @ [82.196.9.221]" -> FAILURE (org.nem.peer.services.NodeRefresher update)
2017-12-31 00:05:14.719 WARNUNG forcibly aborting request to http://45.63.98.203:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:05:14.719 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [lithium <NAUAREJN44KECNCYKTEWQRORJS3DE6QHEKJX34VD>] @ [45.63.98.203]>: java.util.concurrent.CompletionException: java.util.concurrent.CancellationException (org.nem.peer.services.NodeRefresher a)
2017-12-31 00:05:14.719 INFORMATION Updating "Node [lithium <NAUAREJN44KECNCYKTEWQRORJS3DE6QHEKJX34VD>] @ [45.63.98.203]" -> FAILURE (org.nem.peer.services.NodeRefresher update)
2017-12-31 00:05:14.719 WARNUNG forcibly aborting request to http://153.122.86.59:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:05:14.719 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [nkzsn2 <NCP2VTFST6DBEOHSORLVO5NNQ2ONMDXY3Y2H5WET>] @ [153.122.86.59]>: java.util.concurrent.CompletionException: java.util.concurrent.CancellationException (org.nem.peer.services.NodeRefresher a)
2017-12-31 00:05:14.719 INFORMATION Updating "Node [nkzsn2 <NCP2VTFST6DBEOHSORLVO5NNQ2ONMDXY3Y2H5WET>] @ [153.122.86.59]" -> FAILURE (org.nem.peer.services.NodeRefresher update)
2017-12-31 00:05:14.719 WARNUNG forcibly aborting request to http://47.91.72.121:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:05:14.719 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [itechly-1 <NALPVL3OYNFZISK64LCKC5K5G3BRPEX7MINAMMEP>] @ [47.91.72.121]>: java.util.concurrent.CompletionException: java.util.concurrent.CancellationException (org.nem.peer.services.NodeRefresher a)
2017-12-31 00:05:14.719 INFORMATION Updating "Node [itechly-1 <NALPVL3OYNFZISK64LCKC5K5G3BRPEX7MINAMMEP>] @ [47.91.72.121]" -> FAILURE (org.nem.peer.services.NodeRefresher update)
2017-12-31 00:05:14.719 WARNUNG forcibly aborting request to http://153.122.13.92:7890/node/info (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:05:14.720 SCHWERWIEGEND DIRECT fatal error encountered while communicating with <Node [ho <NC6L2S6ZH7K7C5KUOP332SW7CNYYVFOCD7UTL5FM>] @ [153.122.13.92]>: java.util.concurrent.CompletionException: java.util.concurrent.CancellationException (org.nem.peer.services.NodeRefresher a)
2017-12-31 00:05:14.720 INFORMATION Updating "Node [ho <NC6L2S6ZH7K7C5KUOP332SW7CNYYVFOCD7UTL5FM>] @ [153.122.13.92]" -> FAILURE (org.nem.peer.services.NodeRefresher update)
2017-12-31 00:05:14.720 INFORMATION calculating trust values (org.nem.peer.trust.CachedTrustProvider a)

Thies1965 · December 31, 2017, 11:33am

5 Timer BROADCAST BUFFERED ENTITIES raised exception: java.util.concurrent.CancellationException

2017-12-31 00:06:59.196 WARNUNG forcibly aborting request to http://86.7.199.116:7890/chain/score (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:06:59.197 WARNUNG Timer SYNC raised exception: java.util.concurrent.CancellationException
java.util.concurrent.CompletionException: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2265)
	at org.nem.core.connect.HttpMethodClient$HttpMethodClientFutureCallback.cancelled(HttpMethodClient.java:216)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:157)
	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.executionCancelled(DefaultClientExchangeHandlerImpl.java:116)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.connectionRequestCancelled(AbstractClientExchangeHandler.java:357)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.access$200(AbstractClientExchangeHandler.java:62)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler$1.cancelled(AbstractClientExchangeHandler.java:397)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$1.cancelled(PoolingNHttpClientConnectionManager.java:295)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$2.cancel(PoolingNHttpClientConnectionManager.java:304)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.cancel(AbstractClientExchangeHandler.java:443)
	at org.apache.http.client.methods.AbstractExecutionAwareRequest.abort(AbstractExecutionAwareRequest.java:90)
	at org.nem.core.connect.HttpMethodClient.lambda$sendRequest$2(HttpMethodClient.java:129)
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.nem.core.async.SleepFuture$1.run(SleepFuture.java:24)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
Caused by: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2263)
	... 21 more
 (org.nem.core.async.NemAsyncTimerVisitor notifyOperationCompleteExceptionally)
2017-12-31 00:06:59.216 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:00.220 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:00.510 INFORMATION entering /node/cysm [128.199.223.15] (org.nem.nis.controller.interceptors.AuditInterceptor preHandle)
2017-12-31 00:07:00.511 INFORMATION exiting /node/cysm [128.199.223.15] (org.nem.nis.controller.interceptors.AuditInterceptor afterCompletion)
2017-12-31 00:07:01.223 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:02.197 INFORMATION synchronizing with Node [tango.nemspace.com <NBML2TVUVNYCXTIVTPARYRYJUBSMKBUCLH7W7N43>] @ [159.203.24.250] (org.nem.peer.services.NodeSynchronizer b)
2017-12-31 00:07:02.237 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:03.241 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:03.561 WARNUNG forcibly aborting request to http://217.182.66.112:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.561 WARNUNG forcibly aborting request to http://27.134.244.125:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.562 WARNUNG forcibly aborting request to http://104.238.161.61:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.562 WARNUNG forcibly aborting request to http://108.61.182.27:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.562 WARNUNG forcibly aborting request to http://209.126.98.204:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.562 WARNUNG forcibly aborting request to http://go.nem.ninja:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.562 WARNUNG forcibly aborting request to http://hachi.nem.ninja:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://jusan.nem.ninja:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://178.63.18.3:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://62.75.171.41:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://163.44.165.27:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://108.61.168.86:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://nijuichi.nem.ninja:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://san.nem.ninja:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://78.46.208.207:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://62.75.163.236:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.563 WARNUNG forcibly aborting request to http://62.75.251.134:7890/push/transactions (org.nem.core.connect.HttpMethodClient lambda$sendRequest$2)
2017-12-31 00:07:03.564 WARNUNG Timer BROADCAST BUFFERED ENTITIES raised exception: java.util.concurrent.CancellationException
java.util.concurrent.CompletionException: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593)
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2265)
	at org.nem.core.connect.HttpMethodClient$HttpMethodClientFutureCallback.cancelled(HttpMethodClient.java:216)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:157)
	at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.executionCancelled(DefaultClientExchangeHandlerImpl.java:116)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.connectionRequestCancelled(AbstractClientExchangeHandler.java:357)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.access$200(AbstractClientExchangeHandler.java:62)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler$1.cancelled(AbstractClientExchangeHandler.java:397)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$1.cancelled(PoolingNHttpClientConnectionManager.java:295)
	at org.apache.http.concurrent.BasicFuture.cancel(BasicFuture.java:150)
	at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager$2.cancel(PoolingNHttpClientConnectionManager.java:304)
	at org.apache.http.impl.nio.client.AbstractClientExchangeHandler.cancel(AbstractClientExchangeHandler.java:443)
	at org.apache.http.client.methods.AbstractExecutionAwareRequest.abort(AbstractExecutionAwareRequest.java:90)
	at org.nem.core.connect.HttpMethodClient.lambda$sendRequest$2(HttpMethodClient.java:129)
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.nem.core.async.SleepFuture$1.run(SleepFuture.java:24)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
Caused by: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2263)
	... 21 more
 (org.nem.core.async.NemAsyncTimerVisitor notifyOperationCompleteExceptionally)
2017-12-31 00:07:04.244 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:05.249 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)
2017-12-31 00:07:06.252 INFORMATION 4 harvesters are attempting to harvest a new block. (org.nem.nis.ld.gah cH)

BloodyRookie · December 31, 2017, 1:04pm

Your NIS deaded ^^
Restart NIS. Are you sure it is given enough heap now?

Thies1965 · December 31, 2017, 5:39pm

Seems so. Did not see any OOM exception but maybe I just increase the heap