GeoServer

XML encoder in WFS 1.1 GetFeature leaks connection

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Fixed
  • Affects Version/s: None
  • Fix Version/s: 1.7.7, 2.0-RC2
  • Component/s: None
  • Labels:
    None
  • Number of attachments :
    0

Description

Sampo reported memory leak warning from GeoTools when running plain GetFeature 1.1 requests made by GeoEditor.

Instructed to add -Dgt2.jdbc.trace=true to the JVM he found this trace, reporting where the reader was grabbed from:

28 elo 13:35:55 WARN [geotools.jdb] - The unclosed reader originated on this stack trace
java.lang.Exception
	at org.geotools.jdbc.JDBCFeatureReader.init(JDBCFeatureReader.java:161)
	at org.geotools.jdbc.JDBCFeatureReader.<init>(JDBCFeatureReader.java:149)
	at org.geotools.jdbc.JDBCFeatureSource.getReaderInternal(JDBCFeatureSource.java:555)
	at org.geotools.jdbc.JDBCFeatureStore.getReaderInternal(JDBCFeatureStore.java:206)
	at org.geotools.data.store.ContentFeatureSource.getReader(ContentFeatureSource.java:508)
	at org.geotools.data.store.ContentFeatureCollection.iterator(ContentFeatureCollection.java:272)
	at org.geoserver.feature.RetypingFeatureCollection.iterator(RetypingFeatureCollection.java:47)
	at org.geoserver.feature.RetypingFeatureCollection.features(RetypingFeatureCollection.java:56)
	at org.geotools.data.crs.ReprojectFeatureResults.openIterator(ReprojectFeatureResults.java:108)
	at org.geotools.feature.collection.AbstractFeatureCollection.iterator(AbstractFeatureCollection.java:332)
	at org.geoserver.security.decorators.ReadOnlyFeatureCollection.iterator(ReadOnlyFeatureCollection.java:40)
	at org.geotools.xml.Encoder.encode(Encoder.java:984)
	at org.geotools.xml.Encoder.encode(Encoder.java:557)
	at org.geoserver.wfs.xml.GML3OutputFormat.write(GML3OutputFormat.java:134)
	at org.geoserver.wfs.WFSGetFeatureOutputFormat.write(WFSGetFeatureOutputFormat.java:137)
	at org.geoserver.ows.Dispatcher.response(Dispatcher.java:712)
	at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:216)
	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:875)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:809)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.vfny.geoserver.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:108)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:265)
	at org.acegisecurity.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:107)
	at org.acegisecurity.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:72)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
	at org.acegisecurity.ui.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:124)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
	at org.acegisecurity.providers.anonymous.AnonymousProcessingFilter.doFilter(AnonymousProcessingFilter.java:125)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
	at org.acegisecurity.ui.basicauth.BasicProcessingFilter.doFilter(BasicProcessingFilter.java:174)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
	at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249)
	at org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:275)
	at org.acegisecurity.util.FilterChainProxy.doFilter(FilterChainProxy.java:149)
	at org.acegisecurity.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:98)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.geoserver.filters.LoggingFilter.doFilter(LoggingFilter.java:73)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.geoserver.filters.ReverseProxyFilter.doFilter(ReverseProxyFilter.java:163)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at fi.tike.turvattuwfs.UrlAppenderFilter.doFilter(UrlAppenderFilter.java:44)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.geoserver.filters.GZIPFilter.doFilter(GZIPFilter.java:41)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
	at org.jstripe.tomcat.probe.Tomcat55AgentValve.invoke(Tomcat55AgentValve.java:20)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:849)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:454)
	at java.lang.Thread.run(Thread.java:619)

The code in fact grabs an iterator, but it's generic enough that it won't check for closing the iterator if it was originated by a feature collection. Very bad, a server under WFS 1.1 request load will end up the connections before the garbage collector can kick the finalizers and free them

Issue Links

depends upon

Bug - A problem which impairs or prevents the functions of the product. GEOT-2700 if exception occurs during encoding loop open iterators are not closed

  • Major - Major loss of function.
  • Closed - The issue is considered finished, the resolution is correct. Issues which are not closed can be reopened.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Andrea Aime added a comment -

Btw, it is possible the client it's cutting the request processing mid-air and thus makes the GML encoder bail out before time since the leak in question happens only on a very big layer.
Anyways, the code should make sure the resources are properly closed no matter how the clients behaves.

Show
Andrea Aime added a comment - Btw, it is possible the client it's cutting the request processing mid-air and thus makes the GML encoder bail out before time since the leak in question happens only on a very big layer. Anyways, the code should make sure the resources are properly closed no matter how the clients behaves.
Hide
Permalink
Andrea Aime added a comment -

Oh, btw, the client is our GeoEditor, displaying a WFS layer (big one).

Show
Andrea Aime added a comment - Oh, btw, the client is our GeoEditor, displaying a WFS layer (big one).
Hide
Permalink
Justin Deoliveira added a comment -

Hmmm... well the encoder does check for a feature collection and close the iterator. Is there an exception that is happening while encoding? In that case no it would not close it so that is an issue. Some more context please. Is there any way i can get hands on the dataset being used to try it out?

Show
Justin Deoliveira added a comment - Hmmm... well the encoder does check for a feature collection and close the iterator. Is there an exception that is happening while encoding? In that case no it would not close it so that is an issue. Some more context please. Is there any way i can get hands on the dataset being used to try it out?
Hide
Permalink
Andrea Aime added a comment -

The client is the GeoEditor, which is loading WFS data. The current HP is that the client is closing the connection in the xml encoder face if the user changes the zoom level or pans around whilst the data is loading. Which is consistent with Sampo observation that the leaks occurr only on the heaviest layer.
If the idea is correct, the all it takes is a long WFS request and drop the client mid-air when the encoding is going on. I can double check tomorrow on my PC with a sizeable dataaset.

Show
Andrea Aime added a comment - The client is the GeoEditor, which is loading WFS data. The current HP is that the client is closing the connection in the xml encoder face if the user changes the zoom level or pans around whilst the data is loading. Which is consistent with Sampo observation that the leaks occurr only on the heaviest layer. If the idea is correct, the all it takes is a long WFS request and drop the client mid-air when the encoding is going on. I can double check tomorrow on my PC with a sizeable dataaset.
Hide
Permalink
Andrea Aime added a comment - - edited

Just tried out with a sizable data set contained in postgis, making a plain jane request with curl:

http://localhost:8080/geoserver/wfs?service=WFS&version=1.1.0&request=GetFeature&typeName=topp:tiger_pg

and then killing curl whilst the request was still running (ctrl-c). After a couple of those requests the stack traces above start popping up (remember to add -Dgt2.jdbc.trace=true so that the stack trace will appear fully, otherwise you'll just get a single line warning).

If instead I make the requests stop by adding maxFeatures so that they are short:

curl "http://localhost:8080/geoserver/wfs?service=WFS&version=1.1.0&request=GetFeature&typeName=topp:tiger_pg&maxFeatures=1"

then nothing bad happens. Well, actually there is an annoying warning that keeps on popping up:

09 set 11:34:39 WARN [geotools.xml] - org.geotools.data.crs.ReprojectFeatureResults@18d3d6c (org.geotools.data.crs.ReprojectFeatureResults) is not of type [Lorg.opengis.feature.simple.SimpleFeature;

but it's not fatal

Oh, I've run this test on trunk, but Sampo found it on 1.7.x

Show
Andrea Aime added a comment - - edited Just tried out with a sizable data set contained in postgis, making a plain jane request with curl: http://localhost:8080/geoserver/wfs?service=WFS&version=1.1.0&request=GetFeature&typeName=topp:tiger_pg and then killing curl whilst the request was still running (ctrl-c). After a couple of those requests the stack traces above start popping up (remember to add -Dgt2.jdbc.trace=true so that the stack trace will appear fully, otherwise you'll just get a single line warning). If instead I make the requests stop by adding maxFeatures so that they are short: curl "http://localhost:8080/geoserver/wfs?service=WFS&version=1.1.0&request=GetFeature&typeName=topp:tiger_pg&maxFeatures=1" then nothing bad happens. Well, actually there is an annoying warning that keeps on popping up: 09 set 11:34:39 WARN [geotools.xml] - org.geotools.data.crs.ReprojectFeatureResults@18d3d6c (org.geotools.data.crs.ReprojectFeatureResults) is not of type [Lorg.opengis.feature.simple.SimpleFeature; but it's not fatal Oh, I've run this test on trunk, but Sampo found it on 1.7.x
Hide
Permalink
Justin Deoliveira added a comment -

Ok... i am still confused. Do you actually exhaust the database connections in the pool after a time? The above stack trace is just a trace of whenever a new iterator gets created... not an actual exception. Maybe I am wrong.

Anyways, i will patch the XML encoder to make sure that in the case of an exception during the encoding loop any open iterators are closed.

Show
Justin Deoliveira added a comment - Ok... i am still confused. Do you actually exhaust the database connections in the pool after a time? The above stack trace is just a trace of whenever a new iterator gets created... not an actual exception. Maybe I am wrong. Anyways, i will patch the XML encoder to make sure that in the case of an exception during the encoding loop any open iterators are closed.
Hide
Permalink
Andrea Aime added a comment -

It depends on the setup. If you have a very large heap garbage collection does not kick in often, and if the conneciton pool is not big (5-10 connections) you might well exhaust it before any garbage collection runs. By its nature you cannot trust GC, there is no guarantee about when it will be run.

Show
Andrea Aime added a comment - It depends on the setup. If you have a very large heap garbage collection does not kick in often, and if the conneciton pool is not big (5-10 connections) you might well exhaust it before any garbage collection runs. By its nature you cannot trust GC, there is no guarantee about when it will be run.
Hide
Permalink
Justin Deoliveira added a comment -

Sorry, my question was not hypothetical, I was asking if you and/or Sampo had physically reproduced exceptions resulting from an exhausted connection pool.

Show
Justin Deoliveira added a comment - Sorry, my question was not hypothetical, I was asking if you and/or Sampo had physically reproduced exceptions resulting from an exhausted connection pool.
Hide
Permalink
Justin Deoliveira added a comment -

Ok, so i have modified the encoder so that it will close any open iterators when an exception occurs during encoding. Did some tests with curl and watching the postgres processes on my machine and i don't see any leaking. Any chance one of you can verify?

Show
Justin Deoliveira added a comment - Ok, so i have modified the encoder so that it will close any open iterators when an exception occurs during encoding. Did some tests with curl and watching the postgres processes on my machine and i don't see any leaking. Any chance one of you can verify?
Hide
Permalink
Andrea Aime added a comment -

Checked myself, did not get leaks. I actually got an OOM at some point, but could not reproduce it at all in subsequent runs.
Will open a separate issue for it if I stumble into it again.

Show
Andrea Aime added a comment - Checked myself, did not get leaks. I actually got an OOM at some point, but could not reproduce it at all in subsequent runs. Will open a separate issue for it if I stumble into it again.

People

  • Assignee:
    Justin Deoliveira
    Reporter:
    Andrea Aime
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: