Cursor State not Valid error

[lgorlin]

SmartClient Version: v10.0p_2015-07-30/PowerEdition Deployment (built 2015-07-30)
Isomorphic SmartClient/SmartGWT Framework (v10.0p_2015-07-30/PowerEdition Deployment 2015-07-30)

Browser: Chrome

This is a server side issue

We have a customer who is regularly failing during database access with a “Cursor state not valid” error. In most cases, SmartGWT is able to do a retry and the process completes. However, often the process will end in error during the attempt to retry, sending an error dialog back to the user.

The failing error is happening when com.isomorphic.sql.SQLConnectionManager attempts to free the connection in preparation for the next attempt.

The "Cursor state not valid" error always seems to folow this debug message:
DEBUG SQLTransform - [builtinApplication.fetchWithPackReconciliation] isBeforeFirst()/isAfterLast() throwing exceptions - attempting workaround

I’m including two examples of the server log, one that fails and another that appears to recover. For clarity, I’ve isolated only the log messages from the thread that’s experiencing the error. If you need more, please let me know.

Though the "Cursor state not valid error" is a concern, the biggest worry is when the recovery results in an error that is working its way back to the user. Based on the log, it appears that query eventually goes through, though I can’t tell for certain.

Thanks.

From server.properties

sql.iptsfil.database.type: db2iSeries
sql.iptsfil.interface.type: driverManager
sql.iptsfil.driver: com.ibm.as400.access.AS400JDBCDriver
sql.iptsfil.driver.url: jdbc:as400://host;naming=system;prompt=false;user=XXXXXX;password=XXXXXX;libraries=LIBRARY1,LIBRARY2,LIBRARY3;translate binary=true
sql.iptsfil.autoJoinTransactions: false
sql.iptsfil.defaultDateType: date
sql.iptsfil.trimTextFields: true
sql.iptsfil.naming: system

This is an example that fails, leading to an error message sent to the user.

  === 2016-03-29 11:15:13,442 [c-10] INFO  IpIDACall - Processing DataSource ShippingTerms
  === 2016-03-29 11:15:13,443 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] Performing fetch operation with
      criteria: {}    values: {}
  === 2016-03-29 11:15:13,444 [c-10] INFO  SQLWhereClause - [builtinApplication.ShippingTerms_fetch] empty condition
  === 2016-03-29 11:15:13,444 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] derived query: SELECT $defaultSelectClause FROM
                  ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
               WHERE $defaultWhereClause
  === 2016-03-29 11:15:13,444 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] 2468: Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,        
                                  9
 
                 AS inUse,        
                                  9
 
               AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                  ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
               WHERE ('1'='1')
  === 2016-03-29 11:15:13,444 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Borrowed connection '1588800931'
  === 2016-03-29 11:15:13,444 [c-10] DEBUG SQLDriver - [builtinApplication.ShippingTerms_fetch] About to execute SQL query in 'iptsfil' using connection '1588800931'
  === 2016-03-29 11:15:13,444 [c-10] INFO  SQLDriver - [builtinApplication.ShippingTerms_fetch] Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,        
                                  9
 
                 AS inUse,        
                                  9
 
               AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                  ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
               WHERE ('1'='1')
  === 2016-03-29 11:15:13,509 [c-10] DEBUG SQLTransform - [builtinApplication.ShippingTerms_fetch] isBeforeFirst()/isAfterLast() throwing exceptions - attempting workaround
  === 2016-03-29 11:15:13,509 [c-10] INFO  SQLDriver - [builtinApplication.ShippingTerms_fetch] Execute of select: SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,        
                                  9
 
                 AS inUse,        
                                  9
 
               AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                  ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
               WHERE ('1'='1') on db: iptsfil threw exception: java.sql.SQLException: Cursor state not valid. - assuming stale connection and retrying query.
  === 2016-03-29 11:15:13,509 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] About to close connection with hashcode "1588800931"
  === 2016-03-29 11:15:13,533 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Really closing and invalidating PoolableConnection with hashcode "1588800931"
  === 2016-03-29 11:15:13,598 [c-10] ERROR SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Error attempting to commit and close a connection
  java.lang.NullPointerException
      at com.isomorphic.sql.SQLConnectionManager.free(SQLConnectionManager.java:313)
      at com.isomorphic.sql.SQLDriver.getTransformedResults(SQLDriver.java:688)
      at com.isomorphic.sql.SQLDriver.executeQuery(SQLDriver.java:1013)
      at com.isomorphic.sql.SQLDataSource.executeNativeQuery(SQLDataSource.java:559)
      at com.isomorphic.sql.SQLDataSource.executeNativeQuery(SQLDataSource.java:553)
      at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1927)
      at com.isomorphic.sql.SQLDataSource.processRequest(SQLDataSource.java:444)
      at com.isomorphic.sql.SQLDataSource.executeFetch(SQLDataSource.java:389)
      at com.islandpacific.gui.server.customDataSource.ShippingTermsDS.executeFetch(ShippingTermsDS.java:37)
      at com.isomorphic.datasource.DataSource.execute(DataSource.java:1922)
      at com.islandpacific.gui.server.customDataSource.IpDataSource.getResponse(IpDataSource.java:375)
      at com.islandpacific.gui.server.customDataSource.IpDataSource.execute(IpDataSource.java:151)
      at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:726)
      at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658)
      at com.isomorphic.application.AppBase.execute(AppBase.java:491)
      at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:2548)
      at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:220)
      at com.islandpacific.gui.server.customDataSource.IpIDACall.handleDSRequest(IpIDACall.java:117)
      at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:185)
      at com.islandpacific.gui.server.customDataSource.IpIDACall.processRPCTransaction(IpIDACall.java:67)
      at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:152)
      at com.isomorphic.servlet.IDACall._processRequest(IDACall.java:117)
      at com.isomorphic.servlet.IDACall.doPost(IDACall.java:76)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
      at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:156)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:343)
      at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
      at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:97)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:100)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:35)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:188)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at com.islandpacific.gui.security.IpConcurrentSessionFilter.doFilter(IpConcurrentSessionFilter.java:55)
      at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
      at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:149)
      at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
      at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      at com.isomorphic.servlet.CompressionFilter._doFilter(CompressionFilter.java:260)
      at com.isomorphic.servlet.BaseFilter.doFilter(BaseFilter.java:83)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
      at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
      at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
      at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
      at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
      at java.lang.Thread.run(Unknown Source)
  === 2016-03-29 11:15:13,619 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.ShippingTerms_fetch] makeObject() created a pooled Connection '1588800931'
  === 2016-03-29 11:15:13,640 [c-10] INFO  DSResponse - [builtinApplication.ShippingTerms_fetch] DSResponse: List with 1 items
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 138375065
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "138375065"
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1101562616
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "1101562616"
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1588800931
  === 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "1588800931"
  === 2016-03-29 11:15:13,644 [c-10] INFO  Compression - /ipgui/ipgui/sc/IDACall: 16077 -> 2935 bytes

Here's an example that appears to recover without an error being sent to the user:

  === 2016-03-29 11:19:49,931 [ec-8] INFO  SQLDataSource - [builtinApplication.fetchWithPackReconciliation] Performing fetch operation with
      criteria: {parentId:"40"}    values: {parentId:"40"}
  === 2016-03-29 11:19:49,932 [ec-8] INFO  SQLDataSource - [builtinApplication.fetchWithPackReconciliation] derived query: SELECT
               ProductionLineVariant.*,ProductionLineVariant.color as itemColor,
               ProductionLineVariant.size AS itemSize, IFNULL(i.ISKU, 0) as itemSku,  
               (CURDATE()-IFNULL(i.ixdi,CURDATE())) as daysSinceItemCreated  
            FROM
             ProductionLineVariant
               INNER JOIN productionline l
                 ON ProductionLineVariant.parentid=l.id
               LEFT JOIN ipithdr i
                 ON i.isty = l.itemStyle
                   AND i.icls = l.itemClass
                   AND i.iven = l.itemVendor
                   AND i.iclr = ProductionLineVariant.color
                   AND i.isiz = ProductionLineVariant.size
            WHERE $defaultWhereClause ORDER BY itemColor, itemSize
  === 2016-03-29 11:19:49,932 [ec-8] INFO  SQLDataSource - [builtinApplication.fetchWithPackReconciliation] 3586: Executing SQL query on 'iptsfil': SELECT
               ProductionLineVariant.*,ProductionLineVariant.color as itemColor,
               ProductionLineVariant.size AS itemSize, IFNULL(i.ISKU, 0) as itemSku,  
               (CURDATE()-IFNULL(i.ixdi,CURDATE())) as daysSinceItemCreated  
            FROM
             ProductionLineVariant
               INNER JOIN productionline l
                 ON ProductionLineVariant.parentid=l.id
               LEFT JOIN ipithdr i
                 ON i.isty = l.itemStyle
                   AND i.icls = l.itemClass
                   AND i.iven = l.itemVendor
                   AND i.iclr = ProductionLineVariant.color
                   AND i.isiz = ProductionLineVariant.size
            WHERE (ProductionLineVariant.parentId=40) ORDER BY itemColor, itemSize
  === 2016-03-29 11:19:49,932 [ec-8] DEBUG SQLConnectionManager - [builtinApplication.fetchWithPackReconciliation] Borrowed connection '1101562616'
  === 2016-03-29 11:19:49,932 [ec-8] DEBUG SQLDriver - [builtinApplication.fetchWithPackReconciliation] About to execute SQL query in 'iptsfil' using connection '1101562616'
  === 2016-03-29 11:19:49,932 [ec-8] INFO  SQLDriver - [builtinApplication.fetchWithPackReconciliation] Executing SQL query on 'iptsfil': SELECT
               ProductionLineVariant.*,ProductionLineVariant.color as itemColor,
               ProductionLineVariant.size AS itemSize, IFNULL(i.ISKU, 0) as itemSku,  
               (CURDATE()-IFNULL(i.ixdi,CURDATE())) as daysSinceItemCreated  
            FROM
             ProductionLineVariant
               INNER JOIN productionline l
                 ON ProductionLineVariant.parentid=l.id
               LEFT JOIN ipithdr i
                 ON i.isty = l.itemStyle
                   AND i.icls = l.itemClass
                   AND i.iven = l.itemVendor
                   AND i.iclr = ProductionLineVariant.color
                   AND i.isiz = ProductionLineVariant.size
            WHERE (ProductionLineVariant.parentId=40) ORDER BY itemColor, itemSize
  === 2016-03-29 11:19:50,017 [ec-8] DEBUG SQLTransform - [builtinApplication.fetchWithPackReconciliation] isBeforeFirst()/isAfterLast() throwing exceptions - attempting workaround
  === 2016-03-29 11:19:50,017 [ec-8] INFO  SQLDriver - [builtinApplication.fetchWithPackReconciliation] Execute of select: SELECT
               ProductionLineVariant.*,ProductionLineVariant.color as itemColor,
               ProductionLineVariant.size AS itemSize, IFNULL(i.ISKU, 0) as itemSku,  
               (CURDATE()-IFNULL(i.ixdi,CURDATE())) as daysSinceItemCreated  
            FROM
             ProductionLineVariant
               INNER JOIN productionline l
                 ON ProductionLineVariant.parentid=l.id
               LEFT JOIN ipithdr i
                 ON i.isty = l.itemStyle
                   AND i.icls = l.itemClass
                   AND i.iven = l.itemVendor
                   AND i.iclr = ProductionLineVariant.color
                   AND i.isiz = ProductionLineVariant.size
            WHERE (ProductionLineVariant.parentId=40) ORDER BY itemColor, itemSize on db: iptsfil threw exception: java.sql.SQLException: Cursor state not valid. - assuming stale connection and retrying query.
  === 2016-03-29 11:19:50,017 [ec-8] DEBUG SQLConnectionManager - [builtinApplication.fetchWithPackReconciliation] Connection 1101562616 was already closed when we came to free it
  === 2016-03-29 11:19:50,293 [ec-8] DEBUG PoolableSQLConnectionFactory - [builtinApplication.fetchWithPackReconciliation] makeObject() created a pooled Connection '1773990153'
  === 2016-03-29 11:19:50,365 [ec-8] INFO  DSResponse - [builtinApplication.fetchWithPackReconciliation] DSResponse: List with 20 items
  === 2016-03-29 11:19:50,366 [ec-8] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1773990153
  === 2016-03-29 11:19:50,366 [ec-8] DEBUG SQLConnectionManager - About to close connection with hashcode "1773990153"

[lgorlin]

Reviewing this internally, we’re now feeling that it may have to do with multiple threads using the same connection simultaneously. So I’m regretting having isolated the log entries from a single thread in my original post.

In the following log snippet, you can see the same connection (hashcode "1588800931") being used in two threads, [ec-4] and [c-10]. There's no indication that the connection was released in the one thread before its re-use in the other.

It appears that thread ec-4 is closing the connection in SQLConnection.free() just before thread c-10 fails, also in SQLConnection.free(). Again, there's no indication of the thread being released for re-use before c-10 uses it.

Does it make sense that the two threads are using the same connection at the same time? If not, why would this happen?

Could the sharing of the connection also be causing the original "cursor state not valid" error? I'm thinking it's caused by the processing of a ResultSet after the other thread had closed the connection.

Here's the log snippet (this time it's complete, nothing removed)

=== 2016-03-29 11:15:13,442 [c-10] INFO  IpIDACall - Processing DataSource ShippingTerms
=== 2016-03-29 11:15:13,443 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] Performing fetch operation with
    criteria: {}    values: {}
=== 2016-03-29 11:15:13,444 [c-10] INFO  SQLWhereClause - [builtinApplication.ShippingTerms_fetch] empty condition
=== 2016-03-29 11:15:13,444 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] derived query: SELECT $defaultSelectClause FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE $defaultWhereClause
=== 2016-03-29 11:15:13,444 [c-10] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] 2468: Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,         
                                9
                                  
                AS inUse,         
                                9
                                   
             AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE ('1'='1')
=== 2016-03-29 11:15:13,444 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Borrowed connection '1588800931'
=== 2016-03-29 11:15:13,444 [c-10] DEBUG SQLDriver - [builtinApplication.ShippingTerms_fetch] About to execute SQL query in 'iptsfil' using connection '1588800931'
=== 2016-03-29 11:15:13,444 [c-10] INFO  SQLDriver - [builtinApplication.ShippingTerms_fetch] Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,         
                                9
                                  
                AS inUse,         
                                9
                                   
             AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE ('1'='1')
=== 2016-03-29 11:15:13,480 [ec-4] INFO  RequestContext - URL: '/ipgui/ipgui/sc/IDACall', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.87 Safari/537.36': Safari with Accept-Encoding header
=== 2016-03-29 11:15:13,484 [ec-4] INFO  IpIDACall - Performing 3 operation(s)
=== 2016-03-29 11:15:13,484 [ec-4] INFO  IpIDACall - Processing DataSource IPSTORE
=== 2016-03-29 11:15:13,485 [ec-4] INFO  DSResponse - [builtinApplication.IPSTORE_fetch] DSResponse: List with 1355 items
=== 2016-03-29 11:15:13,485 [ec-4] DEBUG SQLDriver - [builtinApplication.IPSTORE_fetch] Freeing SQLDriver dbConnection 1588800931
=== 2016-03-29 11:15:13,485 [ec-4] DEBUG SQLConnectionManager - [builtinApplication.IPSTORE_fetch] About to close connection with hashcode "1588800931"
=== 2016-03-29 11:15:13,507 [ec-4] INFO  IpIDACall - Processing DataSource ShippingTerms
=== 2016-03-29 11:15:13,508 [ec-4] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] Performing fetch operation with
    criteria: {}    values: {}
=== 2016-03-29 11:15:13,508 [ec-4] INFO  SQLWhereClause - [builtinApplication.ShippingTerms_fetch] empty condition
=== 2016-03-29 11:15:13,508 [ec-4] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] derived query: SELECT $defaultSelectClause FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE $defaultWhereClause
=== 2016-03-29 11:15:13,509 [ec-4] INFO  SQLDataSource - [builtinApplication.ShippingTerms_fetch] 2468: Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,         
                                9
                                  
                AS inUse,         
                                9
                                   
             AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE ('1'='1')
=== 2016-03-29 11:15:13,509 [ec-4] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Borrowed connection '1588800931'
=== 2016-03-29 11:15:13,509 [ec-4] DEBUG SQLDriver - [builtinApplication.ShippingTerms_fetch] About to execute SQL query in 'iptsfil' using connection '1588800931'
=== 2016-03-29 11:15:13,509 [ec-4] INFO  SQLDriver - [builtinApplication.ShippingTerms_fetch] Executing SQL query on 'iptsfil': SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,         
                                9
                                  
                AS inUse,         
                                9
                                   
             AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE ('1'='1')
=== 2016-03-29 11:15:13,509 [c-10] DEBUG SQLTransform - [builtinApplication.ShippingTerms_fetch] isBeforeFirst()/isAfterLast() throwing exceptions - attempting workaround
=== 2016-03-29 11:15:13,509 [c-10] INFO  SQLDriver - [builtinApplication.ShippingTerms_fetch] Execute of select: SELECT ShippingTerms.id, ShippingTerms.name, ShippingTerms.incoterm, ShippingTerms.rateTable, IPFDSTD.QDES, ShippingTerms.isDeprecated,         
                                9
                                  
                AS inUse,         
                                9
                                   
             AS isNotDeprecatedOrIsInPo, IPFDSTD.QFDQ01, IPFDSTD.QFDY01, IPFDSTD.QFDV01 FROM
                ShippingTerms left join IPFDSTD on ShippingTerms.rateTable=IPFDSTD.QCOD
             WHERE ('1'='1') on db: iptsfil threw exception: java.sql.SQLException: Cursor state not valid. - assuming stale connection and retrying query.
=== 2016-03-29 11:15:13,509 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] About to close connection with hashcode "1588800931"
=== 2016-03-29 11:15:13,531 [ec-4] INFO  DSResponse - [builtinApplication.ShippingTerms_fetch] DSResponse: List with 1 items
=== 2016-03-29 11:15:13,531 [ec-4] INFO  IpIDACall - Processing DataSource IPCUCOD
=== 2016-03-29 11:15:13,532 [ec-4] INFO  SQLDataSource - [builtinApplication.IPCUCOD_fetch] Performing fetch operation with
    criteria: {}    values: {}
=== 2016-03-29 11:15:13,532 [ec-4] INFO  SQLWhereClause - [builtinApplication.IPCUCOD_fetch] empty condition
=== 2016-03-29 11:15:13,532 [ec-4] INFO  SQLDataSource - [builtinApplication.IPCUCOD_fetch] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2016-03-29 11:15:13,533 [ec-4] INFO  SQLDataSource - [builtinApplication.IPCUCOD_fetch] 3198: Executing SQL query on 'iptsfil': SELECT IPCUCOD.CUCOCOD, IPCUCOD.CUCODES, IPCUCOD.CUCODEC, IPCUCOD.CUCOVAR, IPCUCOD.CUCOMUT, IPCUCOD.CUCOREG, IPCUCOD.CUCOCHK, IPCUCOD.CUCOSYM, IPCUCOD.CUCOEMU, IPCUCOD.CUCODAT, IPCUCOD.CUCOTIM, IPCUCOD.CUCOUSR FROM IPCUCOD WHERE ('1'='1')
=== 2016-03-29 11:15:13,533 [ec-4] DEBUG SQLConnectionManager - [builtinApplication.IPCUCOD_fetch] Borrowed connection '1588800931'
=== 2016-03-29 11:15:13,533 [ec-4] DEBUG SQLDriver - [builtinApplication.IPCUCOD_fetch] About to execute SQL query in 'iptsfil' using connection '1588800931'
=== 2016-03-29 11:15:13,533 [ec-4] INFO  SQLDriver - [builtinApplication.IPCUCOD_fetch] Executing SQL query on 'iptsfil': SELECT IPCUCOD.CUCOCOD, IPCUCOD.CUCODES, IPCUCOD.CUCODEC, IPCUCOD.CUCOVAR, IPCUCOD.CUCOMUT, IPCUCOD.CUCOREG, IPCUCOD.CUCOCHK, IPCUCOD.CUCOSYM, IPCUCOD.CUCOEMU, IPCUCOD.CUCODAT, IPCUCOD.CUCOTIM, IPCUCOD.CUCOUSR FROM IPCUCOD WHERE ('1'='1')
=== 2016-03-29 11:15:13,533 [c-10] DEBUG SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Really closing and invalidating PoolableConnection with hashcode "1588800931"
=== 2016-03-29 11:15:13,551 [ec-4] INFO  DSResponse - [builtinApplication.IPCUCOD_fetch] DSResponse: List with 1 items
=== 2016-03-29 11:15:13,581 [ec-1] INFO  RequestContext - URL: '/ipgui/ipgui/authentication', User-Agent: 'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.87 Safari/537.36': Safari with Accept-Encoding header
=== 2016-03-29 11:15:13,585 [ec-2] INFO  Download - Returning 304: Not modified on conditional get of: C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ipgui\ipgui\sc\skins\Enterprise\images\headerIcons\calculator.png
=== 2016-03-29 11:15:13,588 [ec-6] INFO  Download - Returning 304: Not modified on conditional get of: C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ipgui\ipgui\sc\skins\Enterprise\images\actions\close.png
=== 2016-03-29 11:15:13,591 [ec-2] INFO  Download - Returning 304: Not modified on conditional get of: C:\Program Files\Apache Software Foundation\Tomcat 7.0\webapps\ipgui\ipgui\sc\skins\Enterprise\images\ListGrid\row_collapsed.png
=== 2016-03-29 11:15:13,598 [c-10] ERROR SQLConnectionManager - [builtinApplication.ShippingTerms_fetch] Error attempting to commit and close a connection
java.lang.NullPointerException
    at com.isomorphic.sql.SQLConnectionManager.free(SQLConnectionManager.java:313)
    at com.isomorphic.sql.SQLDriver.getTransformedResults(SQLDriver.java:688)
    at com.isomorphic.sql.SQLDriver.executeQuery(SQLDriver.java:1013)
    at com.isomorphic.sql.SQLDataSource.executeNativeQuery(SQLDataSource.java:559)
    at com.isomorphic.sql.SQLDataSource.executeNativeQuery(SQLDataSource.java:553)
    at com.isomorphic.sql.SQLDataSource.SQLExecute(SQLDataSource.java:1927)
    at com.isomorphic.sql.SQLDataSource.processRequest(SQLDataSource.java:444)
    at com.isomorphic.sql.SQLDataSource.executeFetch(SQLDataSource.java:389)
    at com.islandpacific.gui.server.customDataSource.ShippingTermsDS.executeFetch(ShippingTermsDS.java:37)
    at com.isomorphic.datasource.DataSource.execute(DataSource.java:1922)
    at com.islandpacific.gui.server.customDataSource.IpDataSource.getResponse(IpDataSource.java:375)
    at com.islandpacific.gui.server.customDataSource.IpDataSource.execute(IpDataSource.java:151)
    at com.isomorphic.application.AppBase.executeDefaultDSOperation(AppBase.java:726)
    at com.isomorphic.application.AppBase.executeAppOperation(AppBase.java:658)
    at com.isomorphic.application.AppBase.execute(AppBase.java:491)
    at com.isomorphic.datasource.DSRequest.execute(DSRequest.java:2548)
    at com.isomorphic.servlet.IDACall.handleDSRequest(IDACall.java:220)
    at com.islandpacific.gui.server.customDataSource.IpIDACall.handleDSRequest(IpIDACall.java:117)
    at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:185)
    at com.islandpacific.gui.server.customDataSource.IpIDACall.processRPCTransaction(IpIDACall.java:67)
    at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:152)
    at com.isomorphic.servlet.IDACall._processRequest(IDACall.java:117)
    at com.isomorphic.servlet.IDACall.doPost(IDACall.java:76)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
    at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:156)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:728)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:343)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
    at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:83)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:97)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:100)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:35)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:188)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at com.islandpacific.gui.security.IpConcurrentSessionFilter.doFilter(IpConcurrentSessionFilter.java:55)
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:355)
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:149)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at com.isomorphic.servlet.CompressionFilter._doFilter(CompressionFilter.java:260)
    at com.isomorphic.servlet.BaseFilter.doFilter(BaseFilter.java:83)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:947)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1009)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)
=== 2016-03-29 11:15:13,619 [c-10] DEBUG PoolableSQLConnectionFactory - [builtinApplication.ShippingTerms_fetch] makeObject() created a pooled Connection '1588800931'
=== 2016-03-29 11:15:13,640 [c-10] INFO  DSResponse - [builtinApplication.ShippingTerms_fetch] DSResponse: List with 1 items
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 138375065
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "138375065"
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1101562616
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "1101562616"
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLDriver - Freeing SQLDriver dbConnection 1588800931
=== 2016-03-29 11:15:13,643 [c-10] DEBUG SQLConnectionManager - About to close connection with hashcode "1588800931"
=== 2016-03-29 11:15:13,644 [c-10] INFO  Compression - /ipgui/ipgui/sc/IDACall: 16077 -> 2935 bytes
=== 2016-03-29 11:15:13,745 [ec-4] INFO  Compression - /ipgui/ipgui/sc/IDACall: 1537701 -> 164301 bytes

[Isomorphic]

Yes, this does look like a concurrency issue; database connections managed by SmartGWT Server are not supposed to be accessible to more than one thread at a time. Is it possible to provide more of this log? We are interested to see what is happening on thread "ec-4" in the run up to this. Also, please share your settings for database connection and DataSource pooling (or just share your entire server.properties file). You can email to support@isomorphic.com if logs are too big to post here.

[Isomorphic]

Also, please have a read of this document and verify that you are not doing anything we tell you not to do. In particular, please confirm that your DynamicDSGenerator implementations always return a new DataSource instance.

[lgorlin]

Here's the additional info. The database configuration involves both server.properties and tomcat's context.xml. I've also e-mailed a larger portion of the log, including the leadup to the earlier log snippet to the address you provided.

Thanks.

The Connection setup

Server.properties

sql.iptsfil.driver.databaseName: IPTSFIL
sql.iptsfil.driver.driverType: thin
sql.iptsfil.driver.name: jdbc/IPTSFIL
sql.iptsfil.driver.networkProtocol: tcp
sql.iptsfil.interface.type: jndi
sql.iptsfil.database.type: db2iSeries
sql.iptsfil.driver.serverName: XXXXXXX
sql.iptsfil.interface.credentialsInURL: true
sql.iptsfil.pool.enabled: true
sql.iptsfil.driver: com.ibm.as400.access.AS400JDBCDriver
sql.iptsfil.driver.url: jdbc:as400://XXXXXXX;naming=system;prompt=false;user=XXXXXXX;password=XXXXXXX;libraries=,IPSRFIL,IPTSFIL,IPWMFIL,IPDSFIL,IPPAFIL,IPASFIL,IPTSUTL,DCXDTALIB;translate binary=true;date format=iso;time format=iso
sql.iptsfil.ipmsRelease: 4.0
sql.iptsfil.autoJoinTransactions: false
sql.iptsfil.defaultDateType: date
sql.iptsfil.trimTextFields: true
sql.iptsfil.naming: system

Context.xml

<Resource name="jdbc/IPTSFIL" auth="Container" type="javax.sql.DataSource"
               maxActive="100" maxIdle="30" maxWait="10000" connectionProperties="defaultDateType=date;autoJoinTransactions=false;trimTextFields=true"
               username="XXXXXXX" password="XXXXXXX" defaultAutoCommit="true" defaultTransactionIsolation="NONE" driverClassName="com.ibm.as400.access.AS400JDBCDriver"
        validationQuery="SELECT 1 FROM sysibm.sysdummy1"
               url="jdbc:as400://XXXXXXX;naming=system;prompt=false;user=XXXXXXX;password=XXXXXXX;libraries=IPSRFIL,IPTSFIL,IPWMFIL,IPDSFIL,IPPAFIL,IPASFIL,IPTSUTL,DCXDTALIB;translate binary=true"/>

[Isomorphic]

You appear to have both JNDI connection pooling and SmartGWT's own connection pooling running at the same time. It is hard to predict what kind of problems this might cause, but it could be anything - it is obviously not right, and asking for trouble. Please switch one or the other off and let us know if that makes the problem go away. To switch off SmartGWT connection pooling, change the setting of "sql.iptsfil1.pool.enabled" to false

[lgorlin]

When this problem first popped up at the customer site, JNDI wasn't being used at all, so I don't believe it's caused by both types of pooling being in place together. However, it does raise hope that setting sql.iptsfil.pool.enabled to false may just solve this (and is certainly a good idea!). In that case, it would point to SmartGWT's pooling as the culprit. I'll make the change at the customer site and let you know how it goes. Thanks!

[lgorlin]

The pool.enabled flag has been set to false for a while now and the problem has continued to happen, so it doesn't appear it's caused by the two connection pooling mechanisms running concurrently. Any other ideas? This is popping up a lot for the customer in the last week or so.

Does it mean anything that the log always says the following before the error pops up (now and back when I posted the log in an earlier comment):

=== 2016-05-04 18:41:36,586 [-415] DEBUG SQLTransform - [builtinApplication.ShippingTerms_fetch] isBeforeFirst()/isAfterLast() throwing exceptions - attempting workaround
==

It's as if the workaround is attempting to use the cursor after it's already been lost and not handling the error. Is that a possibility?

[Isomorphic]

Yes, that will be what is happening, but not because of anything to do with the workaround code - that logic catches any exceptions it gets when it attempts getBeforeFirst() and getAfterLast(), and assumes they are coming from known API weirdnesses in various database products. In this case, however, they are happening because we are trying to use a database connection that has been closed out underneath us. The message coming from the workaround code has the same cause as the NPE that results in the stacktrace.

Looking at the original log you sent us back at the end of March, I can walk you through the problem, which will hopefully give you more insight into it (but doesn't explain what is causing it). If you search the log for '1588800931', you will see that it refers to a database connection object that is re-used a number of times. The correct pattern of usage in the logs looks like this (from lines 167-269 of your log):

=== 2016-03-29 11:15:03,458 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.IPSTORE_fetch] Borrowed connection '1588800931'
=== 2016-03-29 11:15:03,458 [ec-1] DEBUG SQLDriver - [builtinApplication.IPSTORE_fetch] About to execute SQL query in 'iptsfil' using connection '1588800931'
...
=== 2016-03-29 11:15:03,596 [ec-1] DEBUG SQLDriver - [builtinApplication.IPSTORE_fetch] Freeing SQLDriver dbConnection 1588800931
...
=== 2016-03-29 11:15:03,597 [ec-1] DEBUG SQLConnectionManager - [builtinApplication.IPSTORE_fetch] About to close connection with hashcode "1588800931"

So the connection is borrowed, used and then freed (and it is closed as part of the freeing logic). You can see this pattern repeated again 9 seconds later on thread [ec-4]. Then you see a different pattern, starting at line 1002. Thread [c-10] borrows the connection at line 1002, and then thread [ec-4] closes the connection at line 1017 (to make matters worse, it then immediately re-borrows the connection and begins to use it again, but by then the damage is already done).

This is the issue: thread [ec-4] has no business using or freeing that database connection: it already freed it on line 982, and the connection now belongs to a different thread. But something is reusing the connection for a different operation later on thread [ec-4] - when it borrows the connection (and correctly frees it), it is for "ProductionDelivery_fetch"; the erroneous free at line 1017 is done for "IPSTORE_fetch".

It is hard to say why this is happening because we don't have sight of your code. Hopefully, the above description will help you to get to the bottom of the problem; if not, we are going to have look at things in the context of your application code, via a consulting engagement.

Regards,
Isomorphic Software Support