arangodb/arangodb-java-driver

java.io.IOException: Reached the end of the stream.

bobaikato opened this issue · 6 comments

What's the cause of this issue? DB stopped responding and then started throwing this error. I am running ArangoDB on Azure VM for the testing we are performing.

com.arangodb.ArangoDBException: java.util.concurrent.ExecutionException: com.arangodb.ArangoDBException: java.io.IOException: Reached the end of the stream.
	at com.arangodb.internal.velocystream.internal.VstConnectionSync.write(VstConnectionSync.java:100)
	at com.arangodb.internal.velocystream.VstCommunicationSync.send(VstCommunicationSync.java:148)
	at com.arangodb.internal.velocystream.VstCommunicationSync.execute(VstCommunicationSync.java:128)
	at com.arangodb.internal.velocystream.VstCommunicationSync.execute(VstCommunicationSync.java:44)
	at com.arangodb.internal.velocystream.VstCommunication.execute(VstCommunication.java:142)
	at com.arangodb.internal.velocystream.VstProtocol.execute(VstProtocol.java:46)
	at com.arangodb.internal.ArangoExecutorSync.execute(ArangoExecutorSync.java:71)
	at com.arangodb.internal.ArangoExecutorSync.execute(ArangoExecutorSync.java:57)
	at com.arangodb.internal.ArangoExecutorSync.execute(ArangoExecutorSync.java:53)
	at com.arangodb.internal.ArangoDatabaseImpl.createCollection(ArangoDatabaseImpl.java:95)
	at com.arangodb.internal.ArangoCollectionImpl.create(ArangoCollectionImpl.java:343)
	at com.arangodb.springframework.core.template.ArangoTemplate.lambda$_collection$1(ArangoTemplate.java:192)
	at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1708)
	at com.arangodb.springframework.core.template.ArangoTemplate._collection(ArangoTemplate.java:188)
	at com.arangodb.springframework.core.template.ArangoTemplate._collection(ArangoTemplate.java:169)
	at com.arangodb.springframework.core.template.ArangoTemplate.collection(ArangoTemplate.java:834)
org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
	at com.publicgives.user.account.service.config.AspectLogging.profileAllMethods(AspectLogging.java:68)
	at com.publicgives.user.account.service.config.AspectLogging.serviceLayer(AspectLogging.java:51)
	at jdk.internal.reflect.GeneratedMethodAccessor154.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
	at com.publicgives.user.account.service.service.impl.HealthService$$EnhancerBySpringCGLIB$$e9bf62ee.ping(<generated>)
	at com.publicgives.user.account.service.controller.HealthApi.ping(HealthApi.java:62)
	at com.publicgives.user.account.service.controller.HealthApi$$FastClassBySpringCGLIB$$2bb0a287.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
	at com.publicgives.user.account.service.controller.HealthApi$$EnhancerBySpringCGLIB$$8e3bbc6.ping(<generated>)
	at jdk.internal.reflect.GeneratedMethodAccessor152.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:111)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122)
	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at com.publicgives.user.account.service.security.auth.AuthenticationFilter.doFilterInternal(AuthenticationFilter.java:116)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:91)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
	at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336)
	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:769)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:359)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:889)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1735)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.util.concurrent.ExecutionException: com.arangodb.ArangoDBException: java.io.IOException: Reached the end of the stream.
	at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
	at com.arangodb.internal.velocystream.internal.VstConnectionSync.write(VstConnectionSync.java:98)
	... 155 more
Caused by: com.arangodb.ArangoDBException: java.io.IOException: Reached the end of the stream.
	at com.arangodb.internal.velocystream.internal.MessageStore.get(MessageStore.java:71)
	at com.arangodb.internal.velocystream.internal.VstConnectionSync.lambda$write$0(VstConnectionSync.java:94)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at com.arangodb.internal.velocystream.internal.MessageStore.clear(MessageStore.java:94)
	at com.arangodb.internal.velocystream.internal.VstConnection.lambda$open$0(VstConnection.java:221)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	... 1 more
Caused by: java.io.IOException: Reached the end of the stream.
	at com.arangodb.internal.velocystream.internal.VstConnection.readBytesIntoBuffer(VstConnection.java:348)
	at com.arangodb.internal.velocystream.internal.VstConnection.readBytes(VstConnection.java:340)
	at com.arangodb.internal.velocystream.internal.VstConnection.readChunk(VstConnection.java:315)
	at com.arangodb.internal.velocystream.internal.VstConnection.lambda$open$0(VstConnection.java:212)
	... 4 more

It means that the connection has been closed from the server side. Maybe because it remained idle too long.
To understand why you can enable the finer log levels on the coordinators (--log.level requests=trace --log.level communication=trace ).

To avoid it you can configure VST keep-alive: https://www.arangodb.com/docs/stable/drivers/java-reference-setup.html#vst-keep-alive

I will have to enable the logs because the connection wasn't closed.

We notice we get the issue if we use the customer @Query("AQL"), but it works fine if we call method ArangoRepository also, this issue is intermittent annoying and challenging to figure out the cause of the problem.

I will consider the VST configurations and see if it makes a difference.

  1. How can I configure it the same the configurations are here [1]
    I have reviewed this [2], but we are using Springboot and prefer the [1] config method. Please guide.

  2. We have multiple Springboot Microservices connecting the same host but different DB. Do we have to put the same VST on all the Microservice?

  3. Whats the right way to enable the logs on the Springboot properties

[1] https://github.com/arangodb/spring-data-demo/blob/master/src/main/resources/application.properties
[2] https://www.arangodb.com/docs/stable/drivers/spring-data-getting-started.html

Currently VST keep-alive is not exposed as Spring Boot property, to use it you need to programmatically provide ArangoConfiguration, see https://www.arangodb.com/docs/stable/drivers/spring-data-getting-started.html#configuration

As alternative, you can use HTTP communication protocol by setting arangodb.spring.data.protocol=http_vpack. Note that this requires you to include org.apache.httpcomponents:httpclient as additional dependency.

To see ArangoDB driver debug logs you can set: logging.level.com.arangodb=debug.

Not clear about what the HTTP communication protocol is for.
Is that an alternative to enabling VST keep-alive?

Also, you didn't answer the second question above

ArangoDB supports 2 communication protocols: VST and HTTP, for reference see: https://www.arangodb.com/docs/stable/http/general.html#protocol

VST is stateful so the connection must be kept alive and reused. ArangoDB (or intermediate proxies) could close stale connections after some time of inactivity. To prevent this the client should periodically ping the server by sending the above mentioned VST keep-alive probes. This is not required when using HTTP, since the protocol is stateless.

Not sure if I understand your second question correctly, can you please elaborate on that?

Okay, that's helpful and did answer the other questions too. I prefer this solution. Thanks a million