search

hashgraph / hedera-mirror-node

Hedera Mirror Node archives data from consensus nodes and serves it via an API
Apache License 2.0
147 stars 112 forks source link

HCS GRPC Server throwing ArithmeticException: long overflow errors #521

Closed Nana-EC closed 4 years ago

Nana-EC commented 4 years ago

Over the weekend during normal and non-peak operations of the tesnet the GRPC module triggered an alert that was caused by an ArithmeticException: long overflow.

This occurred about 3 times https://hedera.pagerduty.com/incidents/P0VGW2Z

The error seems to come from the InstantToLongConverter.convert() which takes an Instant and converts it to a Long. This happens when the startTime and endTime of a TopicMessageFilter object are converted to longs when creation the DB whereClause Criteria object in TopicMessageRepositoryCustomImpl.findByFilter()

The code base has tests that confirm this logic and as such it's by design. Will confirm that no action needs to be taken and there's no unintended impact.

At the least if this is expected we shouldn't alert on it.

error encountered

Feb 01 19:32:13 mirrornode-testnet-grpc-1 java[816]: 2020-02-01 19:32:13,952 INFO  [grpc-default-executor-725] c.h.m.g.s.TopicMessageServiceImpl Topic 0.159463 listen complete with 9 messages in 23.18 s
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at java.lang.Thread.run(Thread.java:834) [?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) [grpc-core-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) [grpc-core-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:814) [grpc-core-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:331) [grpc-core-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35) [grpc-api-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:172) [grpc-stub-1.25.0.jar!/:1.25.0]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.api.proto.ReactorConsensusServiceGrpc$MethodHandlers.invoke(ReactorConsensusServiceGrpc.java:116) [hedera-mirror-protobuf-0.5.1.jar!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.salesforce.reactorgrpc.stub.ServerCalls.oneToMany(ServerCalls.java:67) [reactor-grpc-stub-1.0.0.jar!/:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.Flux.subscribeWith(Flux.java:8307) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.Flux.subscribe(Flux.java:8143) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:90) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onSubscribe(MonoFlatMapMany.java:134) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:162) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2186) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:121) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:156) [reactor-core-3.3.1.RELEASE.jar!/:3.3.1.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.grpc.service.TopicMessageServiceImpl$$EnhancerBySpringCGLIB$$18960421.subscribeTopic(<generated>) ~[classes!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.validation.beanvalidation.MethodValidationInterceptor.invoke(MethodValidationInterceptor.java:120) ~[spring-context-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.grpc.service.TopicMessageServiceImpl$$FastClassBySpringCGLIB$$40d0042f.invoke(<generated>) ~[classes!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.grpc.service.TopicMessageServiceImpl.subscribeTopic(TopicMessageServiceImpl.java:52) ~[classes!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.sun.proxy.$Proxy97.findByFilter(Unknown Source) ~[?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:605) ~[spring-data-commons-2.2.3
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:621) ~[spring-data-commons-2.2
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.2.RELEASE.jar!/:5.2.2.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:657) ~[spring-data-com
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:204) ~[spring-data-commons-2.2.3.RELEASE.jar!/:2.2.3.RELEASE]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:371) ~[spring-data-commons-2.2.3.RELEASE.jar!/:2.
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at jdk.internal.reflect.GeneratedMethodAccessor39.invoke(Unknown Source) ~[?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.grpc.repository.TopicMessageRepositoryCustomImpl.findByFilter(TopicMessageRepositoryCustomImpl.java:48) ~[classes!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at com.hedera.mirror.grpc.converter.InstantToLongConverter.convert(InstantToLongConverter.java:40) ~[classes!/:0.5.1]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]:         at java.lang.Math.multiplyExact(Math.java:946) ~[?:?]
Feb 01 19:32:03 mirrornode-testnet-grpc-1 java[816]: java.lang.ArithmeticException: long overflow
Nana-EC commented 4 years ago

Seems to be a result of a user using a data time outside what we expected

Feb 1 19:32:03 mirrornode-testnet-grpc-1 java[816]: 2020-02-01 19:32:03,897 INFO [grpc-default-executor-724] c.h.m.g.s.TopicMessageServiceImpl Subscribing to topic: TopicMessageFilter(endTime=null, limit=0, realmNum=0, startTime=0001-01-01T00:00:00Z, topicNum=159463)

Though the overflow is expected it disturbs the flows and produces unnecessary unhandled exceptions.

2 solutions were considered 1) Scope it in so any overflows for startTime are set to EPOCH, and any overflows for endTime result in no endTime getting set. Documentation would need to be updated to reflect this expectation. 2) Return an empty stream, or a single terminating element in the stream to the client with the error noting there was an issue with the startTime or endTime. It should be an error that doesn't trigger alerts on single occurences though.

After some deliberation and noting that most developers might prescribe the following, we decided to go with #1 MirrorConsensusTopicQuery.setStartTime(Instant.MIN).setEndTime(Instant.MAX) -> would cause overflow everytime