search

GeoWebCache / geowebcache

GeoWebCache is a tile caching server implemented in Java that provides various tile caching services like WMS-C, TMS, WMTS, Google Maps, MS Bing and more
https://www.geowebcache.org
338 stars 281 forks source link

HTTP connections are not returned to the pool in GWC and it blocks subsequent requests.. #1308

Open vitalus opened 3 weeks ago

vitalus commented 3 weeks ago

GeoServer closes WMS service API with HTTP Basic authentication.

GWC sends internal request to WMS without credentials (if they are not configured) and also is not able to authenticate against WMS service..

WMSHttpHelper.connectAndCheckHeaders throws Service Exception (because WMS service responds with 401):

            if (responseCode != 200 && responseCode != 204) {
                tileRespRecv.setError();
                throw new ServiceException(
                        "Unexpected response code from backend: "
                                + responseCode
                                + " for "
                                + wmsBackendUrl.toString());
            }

So, in this workflow an allocated (from the pool) HTTP connection is never released back to the pool. By default 2 connections are per HTTP route (is is also questionable, shouldn't we allow more for internal GWC-WMS communication?)

So, connections are taken from the pool and never returned. All subsequent connections will wait pool without timeout.. (timeone is alos needed for internal connections).

AN easy fix is to put all content of connectAndCheckHeaders into try{}finally{}:

Something like this (tried quickly and locking problem is gone at least, regardless workflow connection is returned to the pool):

image

aaime commented 3 weeks ago

When you say "internal", are you talking about the GWC running inside GeoServer? If so, you're reporting on the wrong repository (no GWC code is involved), and there is no actual HTTP request involved, it's using a fake HTTP request: https://github.com/geoserver/geoserver/blob/main/src/gwc/src/main/java/org/geoserver/gwc/GWC.java#L1361

What you're pointing to seems to be the HTTP client used by the WMS Layers in a stand-alone GWC instead. Please make sure it's the last time you post a screenshot of code in a report, link to the actual code in the repository instead.

vitalus commented 3 weeks ago

GWC runs inside GeoServer (embedded) but works in usual way with just normal HTTP request.

So, the scenario is fully applicable also to standalone GWC.


"qtp1373072083-29" #29 prio=5 os_prio=0 cpu=2640.62ms elapsed=87.00s tid=0x00000260fa091d10 nid=15076 waiting on condition  [0x000000a533bfa000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@18.0.2/Native Method)
        - parking to wait for  <0x000000041af15ae8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(java.base@18.0.2/LockSupport.java:341)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@18.0.2/AbstractQueuedSynchronizer.java:506)
        at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@18.0.2/ForkJoinPool.java:3464)
        at java.util.concurrent.ForkJoinPool.managedBlock(java.base@18.0.2/ForkJoinPool.java:3435)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@18.0.2/AbstractQueuedSynchronizer.java:1623)
        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:391)
        at org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253)
        - locked <0x000000043221b438> (a org.apache.http.pool.AbstractConnPool$2)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:198)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:306)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
        at org.geowebcache.layer.wms.WMSHttpHelper.executeRequest(WMSHttpHelper.java:361)
        at org.geowebcache.layer.wms.WMSHttpHelper.connectAndCheckHeaders(WMSHttpHelper.java:179)
        at org.geowebcache.layer.wms.WMSHttpHelper.makeRequest(WMSHttpHelper.java:127)
        at org.geowebcache.layer.wms.WMSSourceHelper.makeRequest(WMSSourceHelper.java:53)
        at org.geowebcache.layer.wms.WMSLayer.getMetatilingReponse(WMSLayer.java:372)
        at org.geowebcache.layer.wms.WMSLayer.getTile(WMSLayer.java:283)
        at org.geowebcache.util.ResponseUtils.writeTile(ResponseUtils.java:101)
        at org.geowebcache.GeoWebCacheDispatcher.handleServiceRequest(GeoWebCacheDispatcher.java:436)
        at org.geowebcache.GeoWebCacheDispatcher.handleRequestInternal(GeoWebCacheDispatcher.java:288)
        at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:177)
        at org.geoserver.gwc.dispatch.GwcServiceProxy.dispatch(GwcServiceProxy.java:87)
        at java.lang.invoke.LambdaForm$DMH/0x000000080103c000.invokeVirtual(java.base@18.0.2/LambdaForm$DMH)
        at java.lang.invoke.LambdaForm$MH/0x0000000801aea400.invoke(java.base@18.0.2/LambdaForm$MH)
        at java.lang.invoke.LambdaForm$MH/0x0000000800c05400.invokeExact_MT(java.base@18.0.2/LambdaForm$MH)
        at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@18.0.2/DirectMethodHandleAccessor.java:156)
        at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@18.0.2/DirectMethodHandleAccessor.java:104)
        at java.lang.reflect.Method.invoke(java.base@18.0.2/Method.java:577)
        at org.geoserver.ows.Dispatcher.execute(Dispatcher.java:905)
        at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:269)
        at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:177)
        at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:51)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1072)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:965)
        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:503)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
        at org.eclipse.jetty.ee8.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1151)
        at org.eclipse.jetty.ee8.servlet.ServletHolder.handle(ServletHolder.java:640)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1374)
        at org.geoserver.filters.ThreadLocalsCleanupFilter.doFilter(ThreadLocalsCleanupFilter.java:28)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:73)
        at org.geoserver.ows.HTTPHeadersCollector.doFilter(HTTPHeadersCollector.java:48)
        at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:70)
        at org.geoserver.filters.HTTPMethodFilter.doFilter(HTTPMethodFilter.java:36)
        at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:70)
        at org.geoserver.filters.LoggingFilter.doFilter(LoggingFilter.java:194)
        at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:70)
        at org.geoserver.filters.SpringDelegatingFilter.doFilter(SpringDelegatingFilter.java:43)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.platform.AdvancedDispatchFilter.doFilter(AdvancedDispatchFilter.java:39)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:352)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:71)
        at org.springframework.security.web.access.intercept.AuthorizationFilter.doFilter(AuthorizationFilter.java:100)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:75)
        at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:361)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:71)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:126)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:120)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:75)
        at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:361)
        at org.geoserver.security.filter.GeoServerPreAuthenticationFilter.doFilter(GeoServerPreAuthenticationFilter.java:72)
        at org.geoserver.security.jwtheaders.filter.GeoServerJwtHeadersFilter.doFilter(GeoServerJwtHeadersFilter.java:145)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:361)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:71)
        at org.geoserver.security.filter.GeoServerSecurityContextPersistenceFilter$1.doFilterInternal(GeoServerSecurityContextPersistenceFilter.java:74)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
        at org.geoserver.security.filter.GeoServerCompositeFilter$NestedFilterChain.doFilter(GeoServerCompositeFilter.java:75)
        at org.geoserver.security.filter.GeoServerCompositeFilter.doFilter(GeoServerCompositeFilter.java:92)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:361)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:225)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:190)
        at org.geoserver.security.GeoServerSecurityFilterChainProxy.doFilter(GeoServerSecurityFilterChainProxy.java:141)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.filters.XFrameOptionsFilter.doFilter(XFrameOptionsFilter.java:116)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.filters.GZIPFilter.doFilter(GZIPFilter.java:48)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.filters.SessionDebugFilter.doFilter(SessionDebugFilter.java:49)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.geoserver.filters.FlushSafeFilter.doFilter(FlushSafeFilter.java:42)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.eclipse.jetty.ee8.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:302)
        at org.eclipse.jetty.ee8.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:270)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:171)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
        at org.eclipse.jetty.ee8.servlet.FilterHolder.doFilter(FilterHolder.java:177)
        at org.eclipse.jetty.ee8.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1348)
  .........

As written above, in case of ServiceException there is no reading attempt from input stream of response and normally working connection releasing code is omitted. Both 2 connections (that by default are allowed per route in HttpComponents) are leased and never returned to the pool, then all other subsequent requests are endlessly waiting...

Also if you check who calls GWC.dispatchOwsRequest - it seems only getFeatureInfo type of request. So, no "fake HTTP requests" for normal getMap of WMS from GWC to WMS..

I am not reporting to the wrong repo. Problem is debugged, dirty fix is applied myself (a simple one), but I would like , may be maintainers analyze the case and prefer to fix it by doing a bigger refactoring..

aaime commented 3 weeks ago

How in the world have you configured the GWC? It seems like you have setup a WMSLayer manually in gwc.xml rather than simply enabling tile caching in the GeoServer layer configuration, hence the usage of WMSLayer. A normal setup (tile caching tab in the GeoServer layer page) for embedded GWC would have make it use a GeoServerTileLayer instead.

Here is what the stack trace looks like in that case:

"qtp681639276-49" prio=5 Id=49 RUNNABLE (suspended)
    at org.geoserver.wms.GetMap.run(GetMap.java:108)
    at org.geoserver.wms.DefaultWebMapService.getMap(DefaultWebMapService.java:250)
    at java.lang.invoke.LambdaForm$DMH/0x0000707c8423a000.invokeInterface(
    at java.lang.invoke.LambdaForm$MH/0x0000707c842f0400.invoke(
    at java.lang.invoke.Invokers$Holder.invokeExact_MT(
    at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:154)
    at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
    at java.lang.reflect.Method.invoke(Method.java:580)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.geoserver.kml.WebMapServiceKmlInterceptor.invoke(WebMapServiceKmlInterceptor.java:38)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.geoserver.gwc.wms.CacheSeedingWebMapService.invoke(CacheSeedingWebMapService.java:57)
    at org.geoserver.gwc.wms.CacheSeedingWebMapService.invoke(CacheSeedingWebMapService.java:32)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.geoserver.gwc.wms.CachingWebMapService.invoke(CachingWebMapService.java:74)
    at org.geoserver.gwc.wms.CachingWebMapService.invoke(CachingWebMapService.java:43)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.geoserver.ows.util.RequestObjectLogger.invoke(RequestObjectLogger.java:29)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:241)
    at jdk.proxy3.$Proxy91.getMap(
    at java.lang.invoke.DirectMethodHandle$Holder.invokeSpecial(
    at java.lang.invoke.LambdaForm$MH/0x0000707c842f0400.invoke(
    at java.lang.invoke.Invokers$Holder.invokeExact_MT(
    at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:154)
    at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
    at java.lang.reflect.Method.invoke(Method.java:580)
    at org.geoserver.ows.Dispatcher.execute(Dispatcher.java:905)
    at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:269)
    at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:177)
    at org.geoserver.gwc.GWC.dispatchOwsRequest(GWC.java:1368)
    at org.geoserver.gwc.layer.GeoServerTileLayer.dispatchGetMap(GeoServerTileLayer.java:693)
    at org.geoserver.gwc.layer.GeoServerTileLayer.getMetatilingReponse(GeoServerTileLayer.java:613)
    at org.geoserver.gwc.layer.GeoServerTileLayer.getTile(GeoServerTileLayer.java:558)
    at org.geowebcache.util.ResponseUtils.writeTile(ResponseUtils.java:101)
    at org.geowebcache.GeoWebCacheDispatcher.handleServiceRequest(GeoWebCacheDispatcher.java:428)
    at org.geowebcache.GeoWebCacheDispatcher.handleRequestInternal(GeoWebCacheDispatcher.java:288)
    at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:177)
    at org.geoserver.gwc.dispatch.GwcServiceProxy.dispatch(GwcServiceProxy.java:87)
    at java.lang.invoke.LambdaForm$DMH/0x0000707c847a8000.invokeVirtual(
    at java.lang.invoke.LambdaForm$MH/0x0000707c84560c00.invoke(
    at java.lang.invoke.LambdaForm$MH/0x0000707c84002800.invokeExact_MT(
    at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:155)
    at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
    at java.lang.reflect.Method.invoke(Method.java:580)
    at org.geoserver.ows.Dispatcher.execute(Dispatcher.java:905)
    at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:269)

Using a HTTP connection for GeoServer to talk to itself was the first thing the developers integrating GWC with Geoserver tried to avoid, some 15-ish years ago.

vitalus commented 3 weeks ago

Answer: Using geowebcache.xml manual configuration within GeoServer.

But it is not related to the problem in general, because there is a standalone mode and behavior will be the same: deadlocking of all subsequent connections to GWC waiting a connection from pool where previous requests (failed with 401 from GeoServer) did not release connections..

vitalus commented 3 weeks ago

Standalone GWC is a production option, let's say (for me) in dev.env environment it's easier to test everything using GWC embedded. So , it allows creation of geowebcache.xml manually with all necessary tweaks in dev.env with GWC embedded (running as GeoServer from Eclipse in debug) and then use it for prod where GWC is standalone.

vitalus commented 3 weeks ago

https://github.com/GeoWebCache/geowebcache/issues/1194 is about the same problem. Reported in 2023.

It's critical defect with an easy fix in WMSHttpHelper ... (just dirty fix with the following general code improvement if necessary):


    private void connectAndCheckHeaders(
            TileResponseReceiver tileRespRecv,
            URL wmsBackendUrl,
            Map<String, String> wmsParams,
            MimeType requestMimeType,
            Integer backendTimeout,
            Resource target,
            WMSLayer.HttpRequestMode httpRequestMode)
            throws GeoWebCacheException {
....

        try{

...
        }finally {

            //Guarantees that connections are released to the pool
            if(method != null && method instanceof CloseableHttpResponse) {
                try {
                    ((CloseableHttpResponse)method).close();
                } catch (IOException e) {
                    e.printStackTrace();
                }
            }
        }
}