Cache is not alive (STATUS_SHUTDOWN)

已查看 1,153 次
跳至第一个未读帖子

kossavot

未读,
2020年11月29日 04:59:192020/11/29
收件人 onebusaway-developers

Hi guys,
I'm sometimes seeing the following exception in the tds log which happens occasionally when the bundle is hot swapped. Maybe it's not strictly related to this exception but I've noticed that when this occurs, after the bundle swap has completed, it seems that web-api can't fetch results from the federation-webapp (I'm sorry for the description if it's not accurate).
Any idea on what's going on ?

Thank you

2020-11-26 17:22:56,471 INFO  [AbstractApplicationContext.java:984] : Closing WebApplicationContext for namespace 'remoting-servlet': startup date [Wed Nov 25 18:45:41 CET 2020]; parent: Root WebApplicationContext
2020-11-26 17:22:56,473 INFO  [AbstractApplicationContext.java:984] : Closing Root WebApplicationContext: startup date [Wed Nov 25 18:44:57 CET 2020]; root of context hierarchy
2020-11-26 17:22:56,474 INFO  [ExecutorConfigurationSupport.java:202] : Shutting down ExecutorService 'taskScheduler'
2020-11-26 17:22:56,474 INFO  [ExecutorConfigurationSupport.java:202] : Shutting down ExecutorService 'scheduledExecutorService'
2020-11-26 17:22:56,474 INFO  [ServiceAlertsServiceImpl.java:83] : Stopping ServiceAlertsService
2020-11-26 17:22:56,475 INFO  [MBeanExporter.java:449] : Unregistering JMX-exposed beans on shutdown
2020-11-26 17:22:56,475 INFO  [MBeanRegistrationSupport.java:241] : Unregistering JMX-exposed beans
2020-11-26 17:22:56,476 INFO  [EhCacheManagerFactoryBean.java:112] : Shutting down EHCache CacheManager
2020-11-26 17:22:56,486 WARN  [GtfsRealtimeSource.java:1124] : Error updating from GTFS-realtime data sources
java.lang.IllegalStateException: The org.onebusaway.transit_data_federation.impl.ExtendedCalendarServiceImpl.serviceDateRangeCache Cache is not alive (STATUS_SHUTDOWN)
       at net.sf.ehcache.Cache$CacheStatus.checkAlive(Cache.java:4104)
       at net.sf.ehcache.Cache.checkStatus(Cache.java:2795)
       at net.sf.ehcache.Cache.get(Cache.java:1744)
       at org.onebusaway.transit_data_federation.impl.ExtendedCalendarServiceImpl.getServiceDatesWithinRange(ExtendedCalendarServiceImpl.java:179)
       at sun.reflect.GeneratedMethodAccessor63.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
       at java.lang.reflect.Method.invoke(Method.java:498)
       at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
       at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
       at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
       at com.sun.proxy.$Proxy58.getServiceDatesWithinRange(Unknown Source)
       at org.onebusaway.transit_data_federation.impl.blocks.BlockCalendarServiceImpl.handleBlockIndex(BlockCalendarServiceImpl.java:297)
       at org.onebusaway.transit_data_federation.impl.blocks.BlockCalendarServiceImpl.getActiveBlocksInTimeRange(BlockCalendarServiceImpl.java:286)
       at org.onebusaway.transit_data_federation.impl.blocks.BlockCalendarServiceImpl.getActiveBlocksInTimeRange(BlockCalendarServiceImpl.java:254)
       at org.onebusaway.transit_data_federation.impl.blocks.BlockCalendarServiceImpl.getActiveBlocks(BlockCalendarServiceImpl.java:111)
       at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
       at java.lang.reflect.Method.invoke(Method.java:498)
       at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
       at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
       at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
       at com.sun.proxy.$Proxy60.getActiveBlocks(Unknown Source)
       at org.onebusaway.transit_data_federation.impl.realtime.BlockLocationServiceImpl.getBestBlockForRecord(BlockLocationServiceImpl.java:472)
       at org.onebusaway.transit_data_federation.impl.realtime.BlockLocationServiceImpl.getVehicleLocationRecordAsBlockInstance(BlockLocationServiceImpl.java:460)
       at org.onebusaway.transit_data_federation.impl.realtime.BlockLocationServiceImpl.handleVehicleLocationRecord(BlockLocationServiceImpl.java:311)
       at org.onebusaway.transit_data_federation.impl.realtime.VehicleStatusServiceImpl.handleVehicleLocationRecord(VehicleStatusServiceImpl.java:100)
       at org.onebusaway.transit_data_federation.impl.realtime.gtfs_realtime.GtfsRealtimeSource.handleCombinedUpdates(GtfsRealtimeSource.java:533)
       at org.onebusaway.transit_data_federation.impl.realtime.gtfs_realtime.GtfsRealtimeSource.handleUpdates(GtfsRealtimeSource.java:475)
       at org.onebusaway.transit_data_federation.impl.realtime.gtfs_realtime.GtfsRealtimeSource.refresh(GtfsRealtimeSource.java:434)
       at org.onebusaway.transit_data_federation.impl.realtime.gtfs_realtime.GtfsRealtimeSource$RefreshTask.run(GtfsRealtimeSource.java:1121)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
       at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       at java.lang.Thread.run(Thread.java:748)
2020-11-26 17:23:05,025 INFO  [ContextLoader.java:304] : Root WebApplicationContext: initialization started


Sheldon A. Brown

未读,
2020年11月29日 09:18:282020/11/29
收件人 onebusaway...@googlegroups.com
From the look of that log, Tomcat is actually shutting down /
restarting the container. The spring context would not normally
shutdown during typical execution.

Is there any indication why Tomcat would have restarted?

Sheldon
> --
> You received this message because you are subscribed to the Google Groups "onebusaway-developers" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to onebusaway-devel...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/onebusaway-developers/f41363c5-1438-484e-8b5a-66aff3c7e0e3n%40googlegroups.com.

kossavot

未读,
2020年11月29日 12:20:322020/11/29
收件人 onebusaway-developers
Hi Sheldon,
here's the log I can get from catalina.out around the time when this exception happened.

Just before the exception I can see repated log lines of the type:

26-Nov-2020 17:22:56.009 WARNING [main] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [gtfs-v1] is still processing a request that has yet to finish. This is very likely to create a memory leak. You can cont
rol the time allowed for requests to finish by using the unloadDelay attribute of the standard Context implementation. Stack trace of request processing thread:[
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
java.net.SocketInputStream.read(SocketInputStream.java:171)
java.net.SocketInputStream.read(SocketInputStream.java:141)
java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
java.io.BufferedInputStream.read(BufferedInputStream.java:345)
sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)
sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678)
sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1593)
sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498)
java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
com.caucho.hessian.client.HessianURLConnection.sendRequest(HessianURLConnection.java:112)
com.caucho.hessian.client.HessianProxy.sendRequest(HessianProxy.java:296)
com.caucho.hessian.client.HessianProxy.invoke(HessianProxy.java:171)
com.sun.proxy.$Proxy104.getStopsForRoute(Unknown Source)
sun.reflect.GeneratedMethodAccessor339.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.springframework.remoting.caucho.HessianClientInterceptor.invoke(HessianClientInterceptor.java:248)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
com.sun.proxy.$Proxy105.getStopsForRoute(Unknown Source)
org.onebusaway.api.actions.api.where.StopsForRouteAction.show(StopsForRouteAction.java:97)

.....................................................................................................................................................................
.....................................................................................................................................................................
.....................................................................................................................................................................

then there's a repeated sequence which goes like:

26-Nov-2020 17:22:56.393 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [gtfs-v1] created a ThreadLocal with key of type [org.springframework.core.NamedThreadLocal] (value [LocaleContext])
and a value of type [org.springframework.context.i18n.SimpleLocaleContext] (value [en]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
26-Nov-2020 17:22:56.394 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [gtfs-v1] created a ThreadLocal with key of type [org.springframework.core.NamedThreadLocal] (value [Request attribut
es]) and a value of type [org.springframework.web.context.request.ServletRequestAttributes] (value [org.apache.catalina.connector.RequestFacade@3a0abab4]) but failed to remove it when the web application was stopped. Threads are going to be renewed over
time to try and avoid a probable memory leak.

.....................................................................................................................................................................
.....................................................................................................................................................................
.....................................................................................................................................................................

and then:

26-Nov-2020 17:22:56.493 WARNING [main] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [onebusaway-transit-data-federation-webapp] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it w
hen the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
26-Nov-2020 17:22:56.499 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-127.0.0.1-8080"]
2020-11-26 17:22:57
Full thread dump OpenJDK 64-Bit Server VM (25.275-b01 mixed mode):

.....................................................................................................................................................................
.....................................................................................................................................................................
.....................................................................................................................................................................


G.

Sheldon A. Brown

未读,
2020年11月29日 19:30:402020/11/29
收件人 onebusaway...@googlegroups.com
Sorry, not much there I can see, just typical messages when Tomcat restarts. See if you can find and messages as to why Tomcat restarted. 

Sheldon 

kossavot

未读,
2020年11月30日 14:48:232020/11/30
收件人 onebusaway-developers
thanks, but I'm afraid I haven't found anything meaningful in the log.
The only sure thing is that it happens after the bundle switches so my best guess is that it's a problems caused by memory running out although I haven't found any jvm errors.

kossavot

未读,
2020年12月2日 08:05:242020/12/2
收件人 onebusaway-developers
similar behaviour in the sense that the oba api seems to stop working led to the following api log this morning. No weird log in tds.log which seems to work fine.
Again this happened after the bundle switch.

2020-12-02 12:35:05,248 INFO  [CommonsLogger.java:46] : Executed action [//api/where/arrivals-and-departures-for-stop!show!json!200] took 36463 ms (execution: 36459 ms, result: 4 ms)
2020-12-02 12:35:05,291 ERROR [CommonsLogger.java:42] : Exception processing the result.
org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
       at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:351)
       at org.apache.catalina.connector.OutputBuffer.appendByteArray(OutputBuffer.java:746)
       at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:675)
       at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:386)
       at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:364)
       at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96)
       at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:89)
       at org.apache.struts2.rest.DefaultContentTypeHandlerManager.handleResult(DefaultContentTypeHandlerManager.java:199)
       at org.apache.struts2.rest.RestActionInvocation.executeResult(RestActionInvocation.java:232)
       at org.apache.struts2.rest.RestActionInvocation.processResult(RestActionInvocation.java:197)
       at org.apache.struts2.rest.RestActionInvocation.invoke(RestActionInvocation.java:145)
       at com.opensymphony.xwork2.DefaultActionProxy.execute(DefaultActionProxy.java:147)
       at org.apache.struts2.dispatcher.Dispatcher.serviceAction(Dispatcher.java:575)
       at org.apache.struts2.dispatcher.ng.ExecuteOperations.executeAction(ExecuteOperations.java:81)
       at org.apache.struts2.dispatcher.ng.filter.StrutsPrepareAndExecuteFilter.doFilter(StrutsPrepareAndExecuteFilter.java:99)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
       at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176)
       at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
       at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
       at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:381)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
       at org.apache.catalina.filters.CorsFilter.handleNonCORS(CorsFilter.java:352)
       at org.apache.catalina.filters.CorsFilter.doFilter(CorsFilter.java:171)
       at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
       at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
       at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
       at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
       at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526)
       at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
       at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
       at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:678)
       at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
       at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
       at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)
       at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
       at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860)
       at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1591)
       at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
       at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.IOException: Broken pipe
       at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
       at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
       at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
       at sun.nio.ch.IOUtil.write(IOUtil.java:65)
       at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:470)
       at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:138)
       at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101)
       at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:152)
       at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1257)
       at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:814)
       at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:584)
       at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:522)
       at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:538)
       at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:73)
       at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:190)
       at org.apache.coyote.Response.doWrite(Response.java:601)
       at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:339)


any idea ?
回复全部
回复作者
转发
0 个新帖子