Uploaded image for project: 'GeoServer'
  1. GEOS-7128

OWS Dispatcher does not handle exceptions in fireFinishedCallback()

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Medium
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.6.5, 2.7.3, 2.8-beta
    • Component/s: WCS, WFS, WMS, WPS
    • Labels:
      None
    • Environment:

      GeoServer WAR running on Tomcat 7 (Windows 7, Ubuntu 14)

      Description

      Update: The root cause of the issue is actually caused by exceptions thrown from Dispatcher.fireFinishedCallback(). Any exception thrown from this method will be silenty handled by higher level Dispatcher classes, and will not be logged by GeoServer. This can cause failures to cleanup request resources, and premature EOF errors when reading the OWS response message.

      Previous Title: WPS Thread pool recycling not clearing ThreadLocals

      This issue does not effect core geoserver - it only seems to crop up when using certain downstream GeoServer extensions that mess with thread pooling.

      Sometimes, when running a WPS request, I get an error response:

      <ows:ExceptionReport xmlns:xs="http://www.w3.org/2001/XMLSchema" xmlns:ows="http
      ://www.opengis.net/ows/1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance
      " version="1.1.0" xsi:schemaLocation="http://www.opengis.net/ows/1.1 http://loca
      lhost:8080/geoserver/schemas/ows/1.1.0/owsAll.xsd">
        <ows:Exception exceptionCode="NoApplicableCode">
          <ows:ExceptionText>Cannot switch process status from FAILED to QUEUED</ows:E
      xceptionText>
        </ows:Exception>
      </ows:ExceptionReport>
      curl: (18) transfer closed with outstanding read data remaining
      

      geoserver.log:

      2015-07-24 11:00:35,817 ERROR [geoserver.ows] - 
      org.geoserver.wps.WPSException: Cannot switch process status from SUCCEEDED to QUEUED
      	at org.geoserver.wps.MemoryProcessStatusStore.save(MemoryProcessStatusStore.java:53)
      	at org.geoserver.wps.executor.ProcessStatusTracker.submitted(ProcessStatusTracker.java:59)
      	at org.geoserver.wps.executor.ProcessListenerNotifier.fireProcessSubmitted(ProcessListenerNotifier.java:54)
      	at org.geoserver.wps.executor.ProcessListenerNotifier.<init>(ProcessListenerNotifier.java:47)
      	at org.geoserver.wps.executor.WPSExecutionManager$Executor.<init>(WPSExecutionManager.java:326)
      	at org.geoserver.wps.executor.WPSExecutionManager$Executor.<init>(WPSExecutionManager.java:293)
      	at org.geoserver.wps.executor.WPSExecutionManager.submit(WPSExecutionManager.java:177)
      	at org.geoserver.wps.Execute.run(Execute.java:66)
      	at org.geoserver.wps.DefaultWebProcessingService.execute(DefaultWebProcessingService.java:82)
      	at sun.reflect.GeneratedMethodAccessor137.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      	at java.lang.reflect.Method.invoke(Unknown Source)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
      	at com.boundlessgeo.suite.geoserver.intruments.OWSServiceInstrument.invoke(OWSServiceInstrument.java:69)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
      	at org.geoserver.ows.util.RequestObjectLogger.invoke(RequestObjectLogger.java:55)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      	at com.sun.proxy.$Proxy86.execute(Unknown Source)
      	at sun.reflect.GeneratedMethodAccessor136.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
      	at java.lang.reflect.Method.invoke(Unknown Source)
      	at org.geoserver.ows.Dispatcher.execute(Dispatcher.java:841)
      	at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:275)
      	at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
      	at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
      	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
      	at com.boundlessgeo.geoserver.AppDispatcher.doDispatch(AppDispatcher.java:67)
      	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
      	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
      	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:650)
      	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.ThreadLocalsCleanupFilter.doFilter(ThreadLocalsCleanupFilter.java:28)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:75)
      	at org.geoserver.wms.animate.AnimatorFilter.doFilter(AnimatorFilter.java:71)
      	at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:71)
      	at com.boundlessgeo.geoserver.AppAuthFilter.doFilter(AppAuthFilter.java:111)
      	at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:71)
      	at org.geoserver.filters.SpringDelegatingFilter.doFilter(SpringDelegatingFilter.java:46)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.platform.AdvancedDispatchFilter.doFilter(AdvancedDispatchFilter.java:50)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:69)
      	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
      	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:73)
      	at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:69)
      	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:73)
      	at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
      	at org.geoserver.security.filter.GeoServerAnonymousAuthenticationFilter.doFilter(GeoServerAnonymousAuthenticationFilter.java:54)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:69)
      	at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:73)
      	at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
      	at org.geoserver.security.filter.GeoServerBasicAuthenticationFilter.doFilter(GeoServerBasicAuthenticationFilter.java:83)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:69)
      	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
      	at org.geoserver.security.filter.GeoServerSecurityContextPersistenceFilter$1.doFilter(GeoServerSecurityContextPersistenceFilter.java:53)
      	at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:73)
      	at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
      	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
      	at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
      	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
      	at org.geoserver.security.GeoServerSecurityFilterChainProxy.doFilter(GeoServerSecurityFilterChainProxy.java:135)
      	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
      	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.LoggingFilter.doFilter(LoggingFilter.java:87)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.GZIPFilter.doFilter(GZIPFilter.java:48)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.SessionDebugFilter.doFilter(SessionDebugFilter.java:48)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.geoserver.filters.FlushSafeFilter.doFilter(FlushSafeFilter.java:44)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.vfny.geoserver.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:109)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
      	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
      	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:957)
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)
      	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)
      	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:620)
      	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      	at java.lang.Thread.run(Unknown Source)
      

      If I run a number of request in succession, this error gradually becomes more common, until it is the only response I see (restarting geoserver fixes this temporarily).

      When I stop GeoServer, I also see the following error:

      SEVERE: The web application [/geoserver] created a ThreadLocal with key of type
      [java.lang.InheritableThreadLocal] (value [java.lang.InheritableThreadLocal@215d
      90]) and a value of type [org.geoserver.ows.Request] (value [WPS 1.0.0 Execute])
       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.
      Jul 24, 2015 11:09:11 AM org.apache.catalina.loader.WebappClassLoader checkThrea
      dLocalMapForLeaks
      

      I have traced the issue through GeoServer, and have ascertained that WPSResourceManager is using a ThreadLocal to store the unique excecution id for the WPS process. Tomcat is reusing these threads, and when one of these threads gets reused by a different WPS process, the old excecution id is still stored in the ThreadLocal. Then, when the WPSExecutionManager tries to submit the new request, it grabs the ExcecutionStatus from the old request, tries to subit it as a new request, and gets the error "Cannot switch process status from FAILED [old request] to QUEUED [new request]"

      Even though this does not seem to affect core GeoServer, WPS should really be doing proper cleanup of its ThreadLocal variables.

        Attachments

          Activity

            People

            • Assignee:
              tbarsballe Torben Barsballe
              Reporter:
              tbarsballe Torben Barsballe
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: