[Geoserver-users] There is code leaving feature readers/iterators open

Stefano_Iacovella1 · April 29, 2010, 8:31am

Dear all

I’m founfing a lot of WARN and ERROR as the one I attached to this email in the geoserv log.
Geoserver is 1.7.7 with Oracle NG datastore deployed on Tomcat 6.0.20 with SUN JDK 1.6.0_11 on Windows 2003 server. Oracle version is 10.2.0.4

I did a rapid search for "There is code leaving feature readers/iterators open, this is leaking statements and connections! " string in the list and
jira.
I notice this issue:

http://jira.codehaus.org/browse/GEOT-2039

Could it be related?

I’ve restarted the jvm hosting the tomcat with -Dgt2.jdbc.trace=true as Aime suggested for a similar question on the list to see if logs can help more.

Best regards

2010-04-28 13:24:54,366 WARN [geotools.jdb] - There is code leaving feature readers/iterators open, this is leaking statements and connections!
2010-04-28 13:24:54,366 WARN [geotools.jdbc] - Error occurred closing statement
2010-04-28 13:24:54,381 WARN [geotools.jdbc] - Error occurred closing connection
2010-04-28 13:24:54,381 WARN [geotools.jdbc] - Error occurred closing connection
2010-04-28 13:24:54,381 ERROR [geotools.rendering] - java.io.IOException
java.lang.RuntimeException: java.io.IOException
at org.geotools.data.store.ContentFeatureCollection.iterator(ContentFeatureCollection.java:275)
at org.geoserver.security.decorators.ReadOnlyFeatureCollection.iterator(ReadOnlyFeatureCollection.java:41)
at org.geotools.renderer.lite.StreamingRenderer.drawOptimized(StreamingRenderer.java:1793)
at org.geotools.renderer.lite.StreamingRenderer.processStylers(StreamingRenderer.java:1727)
at org.geotools.renderer.lite.StreamingRenderer.paint(StreamingRenderer.java:675)
at org.geotools.renderer.shape.ShapefileRenderer.renderWithStreamingRenderer(ShapefileRenderer.java:1509)
at org.geotools.renderer.shape.ShapefileRenderer.paint(ShapefileRenderer.java:1358)
at org.geotools.renderer.shape.ShapefileRenderer.paint(ShapefileRenderer.java:269)
at org.vfny.geoserver.wms.responses.DefaultRasterMapProducer.produceMap(DefaultRasterMapProducer.java:395)
at org.vfny.geoserver.wms.responses.GetMapResponse.execute(GetMapResponse.java:416)
at org.geoserver.ows.adapters.ResponseAdapter.getMimeType(ResponseAdapter.java:48)
at org.geoserver.ows.Dispatcher.response(Dispatcher.java:699)
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.doGet(FrameworkServlet.java:501)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
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 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.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.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:769)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:698)
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:891)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException
at org.geotools.jdbc.JDBCFeatureSource.getReaderInternal(JDBCFeatureSource.java:568)
at org.geotools.jdbc.JDBCFeatureStore.getReaderInternal(JDBCFeatureStore.java:207)
at org.geotools.data.store.ContentFeatureSource.getReader(ContentFeatureSource.java:510)
at org.geotools.data.store.ContentFeatureCollection.iterator(ContentFeatureCollection.java:272)
… 63 more
Caused by: java.sql.SQLException: Io exception: Software caused connection abort: recv failed
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146)
at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:255)
at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:977)
at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1060)
at oracle.jdbc.driver.T4CPreparedStatement.executeMaybeDescribe(T4CPreparedStatement.java:839)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1132)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3316)
at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3361)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
at org.geotools.jdbc.JDBCFeatureReader.(JDBCFeatureReader.java:154)
at org.geotools.jdbc.JDBCFeatureSource.getReaderInternal(JDBCFeatureSource.java:556)
… 66 more

Andrea_Aime3 · April 29, 2010, 9:10am

Stefano Iacovella ha scritto:

Dear all

I'm founfing a lot of WARN and ERROR as the one I attached to this email in the geoserv log.
Geoserver is 1.7.7 with Oracle NG datastore deployed on Tomcat 6.0.20 with SUN JDK 1.6.0_11 on Windows 2003 server. Oracle version is 10.2.0.4

I did a rapid search for "There is code leaving feature readers/iterators open, this is leaking statements and connections! " string in the list and
jira.
I notice this issue:

http://jira.codehaus.org/browse/GEOT-2039

Could it be related?

I don't see how? It's just about code duplication, has nothing to do
with proper resource management (connections in this case).

I've restarted the jvm hosting the tomcat with -Dgt2.jdbc.trace=true as Aime suggested for a similar question on the list to see if logs can help more.

The logs you have down there indicate there has been a problem connecting to Oracle. Possibly a network failure, or Oracle does not
like our pooled connection and shuts them down forcefully.
In the latter case it helps to turn on connection validation (there
should be an option), it will issue a test query before giving the
connection back to the code.
Of course this comes with a little overhead, but if Oracle is not
playing fair or the network is not reliable
the code has to defend against it.

However, I'm not sure that is also the cause of the error
about leaking iterators. Keep it going with the above option
and let's see where the problem really occurs

Cheers
Andrea

--
Andrea Aime
OpenGeo - http://opengeo.org
Expert service straight from the developers.

Stefano_Iacovella1 · April 29, 2010, 9:23am

2010/4/29 Andrea Aime <aaime@anonymised.com>

Stefano Iacovella ha scritto:

Dear all

I’m founfing a lot of WARN and ERROR as the one I attached to this email
in the geoserv log.
Geoserver is 1.7.7 with Oracle NG datastore deployed on Tomcat 6.0.20
with SUN JDK 1.6.0_11 on Windows 2003 server. Oracle version is 10.2.0.4

I did a rapid search for "There is code leaving feature
readers/iterators open, this is leaking statements and connections! "
string in the list and
jira.
I notice this issue:

http://jira.codehaus.org/browse/GEOT-2039

Could it be related?

I don’t see how? It’s just about code duplication, has nothing to do
with proper resource management (connections in this case).

I’ve restarted the jvm hosting the tomcat with -Dgt2.jdbc.trace=true as
Aime suggested for a similar question on the list to see if logs can
help more.

The logs you have down there indicate there has been a problem
connecting to Oracle. Possibly a network failure, or Oracle does not
like our pooled connection and shuts them down forcefully.
In the latter case it helps to turn on connection validation (there
should be an option), it will issue a test query before giving the
connection back to the code.

Ok, I double checked to be sure. The four Datastores configured was all with the validate connection flag set to true.

Of course this comes with a little overhead, but if Oracle is not
playing fair or the network is not reliable
the code has to defend against it.

We are fighting against a lot of error of this type:

ORA-12571: TNs packet failure writer

This problem is not affecting only the geoserver but is much more frequent on the server hosting the geoserver.
Of course we are investigating all the network devices, not to mention other software installed on the servers, but at the moment we have no clue about some devices in fault or something similar. There are no firewall between the geoserver and the ORacle instance.

However, I’m not sure that is also the cause of the error
about leaking iterators. Keep it going with the above option
and let’s see where the problem really occurs

Thanks a lot

stefano

Cheers
Andrea

–
Andrea Aime
OpenGeo - http://opengeo.org
Expert service straight from the developers.

Geoserver-users mailing list
Geoserver-users@anonymised.comsts.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/geoserver-users

Stefano_Iacovella1 · April 29, 2010, 10:29am

2010/4/29 Andrea Aime <aaime@anonymised.com>

Stefano Iacovella ha scritto:

Dear all

I’m founfing a lot of WARN and ERROR as the one I attached to this email
in the geoserv log.
Geoserver is 1.7.7 with Oracle NG datastore deployed on Tomcat 6.0.20
with SUN JDK 1.6.0_11 on Windows 2003 server. Oracle version is 10.2.0.4

I did a rapid search for "There is code leaving feature
readers/iterators open, this is leaking statements and connections! "
string in the list and
jira.
I notice this issue:

http://jira.codehaus.org/browse/GEOT-2039

Could it be related?

I don’t see how? It’s just about code duplication, has nothing to do
with proper resource management (connections in this case).

May I ask you about the relation between this period in jira?

“If any of the subclasses happened to use the other iterator for any reason, the result would be an unclosed reader.”

and the WARN in the log:
“There is code leaving feature readers/iterators open”

I found a similar WARN here:

http://svn.geotools.org/trunk/modules/unsupported/jdbc-ng/jdbc-core/src/main/java/org/geotools/jdbc/JDBCFeatureReader.java

It seemed to me the same point throwing the exception in my log

at org.geotools.jdbc.JDBCFeatureReader.(JDBCFeatureReader.java:154)

thanks a lot and forgive me if I’m totally missing something

Stefano

Andrea_Aime3 · April 29, 2010, 10:38am

Stefano Iacovella ha scritto:

     >
     > http://jira.codehaus.org/browse/GEOT-2039
     >
     > Could it be related?

    I don't see how? It's just about code duplication, has nothing to do
    with proper resource management (connections in this case).

May I ask you about the relation between this period in jira?

"If any of the subclasses happened to use the other iterator for any reason, the result would be an unclosed reader."

and the WARN in the log:
"There is code leaving feature readers/iterators open"

I found a similar WARN here:

http://svn.geotools.org/trunk/modules/unsupported/jdbc-ng/jdbc-core/src/main/java/org/geotools/jdbc/JDBCFeatureReader.java

It seemed to me the same point throwing the exception in my log

at org.geotools.jdbc.JDBCFeatureReader.<init>(JDBCFeatureReader.java:154)

thanks a lot and forgive me if I'm totally missing something

Ah no, you're right, a connection is possible, but only in theory.
In practice it's not a problem since there is nothing in JDBC-NG
using DataFeatureCollection and nothing in GeoServer using
plain iterators, we stick to FeatureIterator that has an
explict close() method.

My guess is that in some corner case we fail to close the iterator,
maybe related to the fact your connections are unreliable.
So, if my theory is correct, we have somewhere an iterator.close()
that is inside the try {...} block instead of being inside a
finally {...} block.

Mind that when those error messages the connection is actually
closed (it's a finalizer that does that). However, since garbage
collection and finalization are unreliable, you cannot rely
on them to perform the cleanup quickly.

Cheers
Andrea

--
Andrea Aime
OpenGeo - http://opengeo.org
Expert service straight from the developers.