GeoTools

EPSG HSQL factories cannot recover from connection corruption

Details

  • Type: Bug Bug
  • Status: Resolved Resolved
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: 2.7.3
  • Fix Version/s: 2.7.5, 8.0-RC2
  • Component/s: referencing
  • Labels:
    None
  • Environment:
    Ubuntu Server, Sun JDK 1.6, x86_64

Description

Hi,

This is a bug that occures in GeoServer, but I suppose it's more related to GeoTools than to GeoServer.
The following exception is thrown when GeoServer needs to reproject some vector data: 

Error occurred decoding the espg code urn:x-ogc:def:crs:EPSG:4326
Database failure while creating a 'CoordinateReferenceSystem' object for code "EPSG:4326".
Connection is closed
Details:
org.geoserver.platform.ServiceException: Error occurred decoding the espg code urn:x-ogc:def:crs:EPSG:4326
        at org.geoserver.wms.map.GetMapKvpRequestReader.read(GetMapKvpRequestReader.java:181)
        at org.geoserver.wms.map.GetMapKvpRequestReader.read(GetMapKvpRequestReader.java:74)
        at org.geoserver.ows.Dispatcher.parseRequestKVP(Dispatcher.java:1157)
        at org.geoserver.ows.Dispatcher.dispatch(Dispatcher.java:488)
        at org.geoserver.ows.Dispatcher.handleRequestInternal(Dispatcher.java:231)
        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.geoserver.filters.ThreadLocalsCleanupFilter.doFilter(ThreadLocalsCleanupFilter.java:23)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.geoserver.filters.SpringDelegatingFilter$Chain.doFilter(SpringDelegatingFilter.java:74)
        at org.geoserver.filters.SpringDelegatingFilter.doFilter(SpringDelegatingFilter.java:45)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.geoserver.platform.AdvancedDispatchFilter.doFilter(AdvancedDispatchFilter.java:49)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.vfny.geoserver.filters.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:109)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:394)
        at org.springframework.security.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
        at org.springframework.security.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:406)
        at org.springframework.security.ui.ExceptionTranslationFilter.doFilterHttp(ExceptionTranslationFilter.java:101)
        at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:406)
        at org.springframework.security.providers.anonymous.AnonymousProcessingFilter.doFilterHttp(AnonymousProcessingFilter.java:105)
        at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:406)
        at org.springframework.security.ui.basicauth.BasicProcessingFilter.doFilterHttp(BasicProcessingFilter.java:174)
        at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:406)
        at org.springframework.security.context.HttpSessionContextIntegrationFilter.doFilterHttp(HttpSessionContextIntegrationFilter.java:235)
        at org.springframework.security.ui.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:53)
        at org.springframework.security.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:406)
        at org.springframework.security.util.FilterChainProxy.doFilter(FilterChainProxy.java:185)
        at org.springframework.security.util.FilterToBeanProxy.doFilter(FilterToBeanProxy.java:99)
        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:71)
        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:183)
        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.geoserver.filters.SessionDebugFilter.doFilter(SessionDebugFilter.java:46)
        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:127)
        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:298)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
        at java.lang.Thread.run(Thread.java:662)
Caused by: org.opengis.referencing.FactoryException: Database failure while creating a 'CoordinateReferenceSystem' object for code "EPSG:4326".
        at org.geotools.referencing.factory.epsg.DirectEpsgFactory.databaseFailure(DirectEpsgFactory.java:2986)
        at org.geotools.referencing.factory.epsg.DirectEpsgFactory.createCoordinateReferenceSystem(DirectEpsgFactory.java:2038)
        at org.geotools.referencing.factory.BufferedAuthorityFactory.createCoordinateReferenceSystem(BufferedAuthorityFactory.java:782)
        at org.geotools.referencing.factory.AuthorityFactoryAdapter.createCoordinateReferenceSystem(AuthorityFactoryAdapter.java:799)
        at org.geotools.referencing.factory.FallbackAuthorityFactory.createCoordinateReferenceSystem(FallbackAuthorityFactory.java:639)
        at org.geotools.referencing.factory.FallbackAuthorityFactory.createCoordinateReferenceSystem(FallbackAuthorityFactory.java:643)
        at org.geotools.referencing.factory.AuthorityFactoryAdapter.createCoordinateReferenceSystem(AuthorityFactoryAdapter.java:799)
        at org.geotools.referencing.factory.AuthorityFactoryAdapter.createCoordinateReferenceSystem(AuthorityFactoryAdapter.java:799)
        at org.geotools.referencing.factory.AuthorityFactoryAdapter.createCoordinateReferenceSystem(AuthorityFactoryAdapter.java:799)
        at org.geotools.referencing.factory.ThreadedAuthorityFactory.createCoordinateReferenceSystem(ThreadedAuthorityFactory.java:730)
        at org.geotools.referencing.DefaultAuthorityFactory.createCoordinateReferenceSystem(DefaultAuthorityFactory.java:179)
        at org.geotools.referencing.CRS.decode(CRS.java:488)
        at org.geotools.referencing.CRS.decode(CRS.java:416)
        at org.geoserver.wms.map.GetMapKvpRequestReader.read(GetMapKvpRequestReader.java:176)
        ... 69 more
Caused by: java.sql.SQLException: Connection is closed
        at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
        at org.hsqldb.jdbc.Util.sqlException(Unknown Source)
        at org.hsqldb.jdbc.jdbcConnection.checkClosed(Unknown Source)
        at org.hsqldb.jdbc.jdbcConnection.prepareStatement(Unknown Source)
        at org.geotools.referencing.factory.epsg.DirectEpsgFactory.prepareStatement(DirectEpsgFactory.java:716)
        at org.geotools.referencing.factory.epsg.DirectEpsgFactory.createCoordinateReferenceSystem(DirectEpsgFactory.java:1879)
        ... 81 more
  1. Text File
    GEOT-4061.patch
    07/May/12 10:36 PM
    5 kB
    Ian Schneider
  2. Text File
    GEOT-4061-aa.patch
    12/May/12 3:17 PM
    10 kB
    Andrea Aime

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Andrea Aime added a comment - - edited
Yep known problem, unknown cause (the HSQL connection should never be dropped, it's a embedded database), the likely solution is to rewrite the way the current code handles connections and prepared statements so that it uses a proper connection pool. Not a small task unfortunately, not I can guarantee 100% it will solve the problem since I could never reproduce the problem locally with a debugger handy.
Show
Andrea Aime added a comment - - edited Yep known problem, unknown cause (the HSQL connection should never be dropped, it's a embedded database), the likely solution is to rewrite the way the current code handles connections and prepared statements so that it uses a proper connection pool. Not a small task unfortunately, not I can guarantee 100% it will solve the problem since I could never reproduce the problem locally with a debugger handy.
Hide
Permalink
Gabriel Roldan added a comment - - edited
Last time I checked GeoToolkit (in its GeoTools fork) already changed the way that works (can't assure it fixed this specific issue, but looks like).

Looking at the AuthorityCodes and related classes, this seems overlay complication to me: implementing a Set that backs its iterator by a _cached_ prepared statement, and on each call sets it to null and when the garbage collector reclaims the iterator it restores the prepared statement back to its outer class, all using a single database connection. Just because you might need to pull like up to 4000 epsg codes out of a table? and... just so that the calling code ends up adding all of the elements of this crazy set to a plain LinkedHashSet most of the time ( I think).

GeoToolkit's version of AuthorityCodes is a bit different:

GeoTools':
{code}
    /**
     * Returns all codes.
     */
    private ResultSet getAll() throws SQLException {
        assert Thread.holdsLock(this);
        if (queryAll != null && factory.isConnectionValid(queryAll.getConnection())) {
            try {
                return queryAll.executeQuery();
            } catch (SQLException ignore) {
                /*
                 * Failed to reuse an existing statement. This problem occurs in some occasions
                 * with the JDBC-ODBC bridge in Java 6 (the error message is "Invalid handle").
                 * I'm not sure where the bug come from (didn't noticed it when using HSQL). We
                 * will try again with a new statement created in the code after this 'catch'
                 * clause. Note that we set 'queryAll' to null first in case of failure during
                 * the 'prepareStatement(...)' execution.
                 */
                queryAll.close();
                queryAll = null;
                recoverableException("getAll", ignore);
            }
        }
        queryAll = factory.getConnection().prepareStatement(sqlAll);
        return queryAll.executeQuery();
    }
{code}

GeoToolkit's:
{code}
      /**
    * Returns all codes.
    */
   private ResultSet getAll() throws SQLException {
       assert Thread.holdsLock(this);
       if (queryAll != null) {
           try {
               return queryAll.executeQuery();
           } catch (SQLException ignore) {
               /*
                * Failed to reuse an existing statement. This problem occurs in some occasions
                * with the JDBC-ODBC bridge in Java 6 (the error message is "Invalid handle").
                * I'm not sure where the bug come from (didn't noticed it when using HSQL). We
                * will try again with a new statement created in the code after this 'catch'
                * clause. Note that we set 'queryAll' to null first in case of failure during
                * the 'prepareStatement(...)' execution.
                */
               queryAll.close();
               queryAll = null;
               recoverableException("getAll", ignore);
           }
       }
       queryAll = connection.prepareStatement(sqlAll);
       return queryAll.executeQuery();
   }
{code}

See the difference? yes, their AuthorityCodes instances get a handle to a connection directly and hold it as an instance variable. I bet they're pooled too. But didn't get deeper into GeoToolkit's source code and I'm sure I didn't even get the GeoTools one figured out well either.

hmmm.. so no, I don't have a solution right now. This is too scary as to come up with a magical one-liner fix out of the air.

In any case AuthorityCodes.java line 190:
{{queryAll = factory.getConnection().prepareStatement(sqlAll);}}

So factory.getConnection() did return the connection, previously checking it was valid by executing some check alive sentence, and it looks like somewhere between that and Connection.prepareStatement the connection got closed.
Also, not sure if this would solve anything, but since this cached "queryAll" PreparedStatement (that's set to null at Set.iterator() and restablished at Iterator.finalize() ) is so important, I think it wouldn't hurt declaring it with the volatile keyword, so that all threads see the same reference at any given time.

(btw, caching 4000 EPSG codes as a plain HashSet<String> would consume about 40K of heap... is it worth the complexity to have a pool of this AuthorityCodes class that in the end share a jdbc connection?)
Show
Gabriel Roldan added a comment - - edited Last time I checked GeoToolkit (in its GeoTools fork) already changed the way that works (can't assure it fixed this specific issue, but looks like). Looking at the AuthorityCodes and related classes, this seems overlay complication to me: implementing a Set that backs its iterator by a _cached_ prepared statement, and on each call sets it to null and when the garbage collector reclaims the iterator it restores the prepared statement back to its outer class, all using a single database connection. Just because you might need to pull like up to 4000 epsg codes out of a table? and... just so that the calling code ends up adding all of the elements of this crazy set to a plain LinkedHashSet most of the time ( I think). GeoToolkit's version of AuthorityCodes is a bit different: GeoTools': {code}     /**      * Returns all codes.      */     private ResultSet getAll() throws SQLException {         assert Thread.holdsLock(this);         if (queryAll != null && factory.isConnectionValid(queryAll.getConnection())) {             try {                 return queryAll.executeQuery();             } catch (SQLException ignore) {                 /*                  * Failed to reuse an existing statement. This problem occurs in some occasions                  * with the JDBC-ODBC bridge in Java 6 (the error message is "Invalid handle").                  * I'm not sure where the bug come from (didn't noticed it when using HSQL). We                  * will try again with a new statement created in the code after this 'catch'                  * clause. Note that we set 'queryAll' to null first in case of failure during                  * the 'prepareStatement(...)' execution.                  */                 queryAll.close();                 queryAll = null;                 recoverableException("getAll", ignore);             }         }         queryAll = factory.getConnection().prepareStatement(sqlAll);         return queryAll.executeQuery();     } {code} GeoToolkit's: {code}       /**     * Returns all codes.     */    private ResultSet getAll() throws SQLException {        assert Thread.holdsLock(this);        if (queryAll != null) {            try {                return queryAll.executeQuery();            } catch (SQLException ignore) {                /*                 * Failed to reuse an existing statement. This problem occurs in some occasions                 * with the JDBC-ODBC bridge in Java 6 (the error message is "Invalid handle").                 * I'm not sure where the bug come from (didn't noticed it when using HSQL). We                 * will try again with a new statement created in the code after this 'catch'                 * clause. Note that we set 'queryAll' to null first in case of failure during                 * the 'prepareStatement(...)' execution.                 */                queryAll.close();                queryAll = null;                recoverableException("getAll", ignore);            }        }        queryAll = connection.prepareStatement(sqlAll);        return queryAll.executeQuery();    } {code} See the difference? yes, their AuthorityCodes instances get a handle to a connection directly and hold it as an instance variable. I bet they're pooled too. But didn't get deeper into GeoToolkit's source code and I'm sure I didn't even get the GeoTools one figured out well either. hmmm.. so no, I don't have a solution right now. This is too scary as to come up with a magical one-liner fix out of the air. In any case AuthorityCodes.java line 190: {{queryAll = factory.getConnection().prepareStatement(sqlAll);}} So factory.getConnection() did return the connection, previously checking it was valid by executing some check alive sentence, and it looks like somewhere between that and Connection.prepareStatement the connection got closed. Also, not sure if this would solve anything, but since this cached "queryAll" PreparedStatement (that's set to null at Set.iterator() and restablished at Iterator.finalize() ) is so important, I think it wouldn't hurt declaring it with the volatile keyword, so that all threads see the same reference at any given time. (btw, caching 4000 EPSG codes as a plain HashSet<String> would consume about 40K of heap... is it worth the complexity to have a pool of this AuthorityCodes class that in the end share a jdbc connection?)
Hide
Permalink
Andrea Aime added a comment -
Gabriel, gathering the codes is not the only thing that the factory does, it also computes on the fly the best transformatio between two codes based on instructions found in the database, which normally contains a list of possible methods, in order of accuracy.
Do you want to also keep 5000*4999/2 transformations in memory? How much memory and time it would take to keep them around? (the codes today are almost 5000)
Show
Andrea Aime added a comment - Gabriel, gathering the codes is not the only thing that the factory does, it also computes on the fly the best transformatio between two codes based on instructions found in the database, which normally contains a list of possible methods, in order of accuracy. Do you want to also keep 5000*4999/2 transformations in memory? How much memory and time it would take to keep them around? (the codes today are almost 5000)
Hide
Permalink
Ian Schneider added a comment -
This area of geotools is a complete mystery to me but it is killing my project since I'm having to restart geoserver every day or so.

As Andrea notes, one major issue is the connection pooling and the fact that a connection should _not_ ever get closed - but it does... somewhere. I cannot duplicate this except via a unit test.

Part of the issue is the SingleConnectionDataSource which doesn't allow for reopening the connection if inadvertently closed.

The attached patch makes the ThreadedHsqlEpsgFactory use a DataSource and attempts to fix various connection checking and re-opening code. The test changes ensure that the connection is closed prior to running each test case hopefully ensuring coverage of the various failure points.

Frankly, if nobody understands this (I don't), this whole referencing codebase needs to be redone - major blocker to uptime for anyone dealing w/ CRS.

I'll be applying this patch and running with it, because as it stands, there is no good way to detect this state and, windows-style, reboot.

On a separate note, I ran all the tests - could only get them passing using maven-2 (not sure why).
Show
Ian Schneider added a comment - This area of geotools is a complete mystery to me but it is killing my project since I'm having to restart geoserver every day or so. As Andrea notes, one major issue is the connection pooling and the fact that a connection should _not_ ever get closed - but it does... somewhere. I cannot duplicate this except via a unit test. Part of the issue is the SingleConnectionDataSource which doesn't allow for reopening the connection if inadvertently closed. The attached patch makes the ThreadedHsqlEpsgFactory use a DataSource and attempts to fix various connection checking and re-opening code. The test changes ensure that the connection is closed prior to running each test case hopefully ensuring coverage of the various failure points. Frankly, if nobody understands this (I don't), this whole referencing codebase needs to be redone - major blocker to uptime for anyone dealing w/ CRS. I'll be applying this patch and running with it, because as it stands, there is no good way to detect this state and, windows-style, reboot. On a separate note, I ran all the tests - could only get them passing using maven-2 (not sure why).
Hide
Permalink
Andrea Aime added a comment -
Ian, I'll be looking into this one, however, one comment on the statement " if nobody understands this (I don't), this whole referencing codebase needs to be redone - major blocker to uptime for anyone dealing w/ CRS. "
It is true that few people understand how this works, but the blocker here so far has been inability to find time to fix it. If I had any of my customers with support contracts hitting this issue I would have had working hours to address it, and it would have been solved a long time ago.
But I don't, this issue about connection getting lost seems to be happening only under peculiar conditions.

I'll have a look at the patch as soon as possible, there is quite a bit of them waiting me to spend Saturday/Sunday reviewing them.
Show
Andrea Aime added a comment - Ian, I'll be looking into this one, however, one comment on the statement " if nobody understands this (I don't), this whole referencing codebase needs to be redone - major blocker to uptime for anyone dealing w/ CRS. " It is true that few people understand how this works, but the blocker here so far has been inability to find time to fix it. If I had any of my customers with support contracts hitting this issue I would have had working hours to address it, and it would have been solved a long time ago. But I don't, this issue about connection getting lost seems to be happening only under peculiar conditions. I'll have a look at the patch as soon as possible, there is quite a bit of them waiting me to spend Saturday/Sunday reviewing them.
Hide
Permalink
Andrea Aime added a comment -
Hi Ian, looked at the patch, it's good but I've still found ways to get GeoServer in trouble by deleting the EPSG database under its feet.

Modified the patch a little, so that also AuthorityCodes validates the prepared statements, and voilà, now you can literally remove the /tmp/GeoTools directory holding the EPSG database and GeoServer won't break a sweat, and will re-create the database instead without throwing any error.

Good enough?
Show
Andrea Aime added a comment - Hi Ian, looked at the patch, it's good but I've still found ways to get GeoServer in trouble by deleting the EPSG database under its feet. Modified the patch a little, so that also AuthorityCodes validates the prepared statements, and voilà, now you can literally remove the /tmp/GeoTools directory holding the EPSG database and GeoServer won't break a sweat, and will re-create the database instead without throwing any error. Good enough?
Hide
Permalink
Andrea Aime added a comment -
Patch applied on 2.7.x and trunk
Show
Andrea Aime added a comment - Patch applied on 2.7.x and trunk
Hide
Permalink
Ian Schneider added a comment -
Andrea,
Apologies for missing the comments on this (guess I forgot to watch it?) and thanks for taking the time to go the extra step.
As for my comment, I understand and it was made out of frustration.
Show
Ian Schneider added a comment - Andrea, Apologies for missing the comments on this (guess I forgot to watch it?) and thanks for taking the time to go the extra step. As for my comment, I understand and it was made out of frustration.

People

  • Assignee:
    Andrea Aime
    Reporter:
    Wouter Schaubroeck
Vote (0)
Watch (3)

Dates

  • Created:
    Updated:
    Resolved: