SQLDataSource Exception Warning

[claudiobosticco]

SmartClient Version: v9.0p_2014-01-05/PowerEdition Deployment (built 2014-01-05)

I've got a recurrent warning in some DMI methods:

2014-05-15 11:30:54,064 WARN SQLDataSource Exception while ending transaction connection 
java.lang.Exception: No current connection for 'null'
	at com.isomorphic.sql.SQLTransaction.endTransaction(SQLTransaction.java:220)
	at com.isomorphic.sql.SQLTransaction.endTransaction(SQLTransaction.java:215)
	at com.isomorphic.sql.SQLDataSource.freeResources(SQLDataSource.java:2998)
	at com.isomorphic.datasource.DSRequest.freeResources(DSRequest.java:4104)
	at com.isomorphic.rpc.RPCManager.freeRPCResources(RPCManager.java:1493)
	at com.isomorphic.rpc.RPCManager.completeResponse(RPCManager.java:1469)
	at com.isomorphic.rpc.RPCManager.send(RPCManager.java:620)
	at com.isomorphic.servlet.IDACall.processRPCTransaction(IDACall.java:172)
	at com.isomorphic.servlet.IDACall.processRequest(IDACall.java:137)
	at com.isomorphic.servlet.IDACall.doPost(IDACall.java:74)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:647)
	at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:152)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at com.juve.utils.Log4jSessionFilter.doFilter(Log4jSessionFilter.java:66)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:368)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)
	at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:97)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:101)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:55)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:36)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:178)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.ui.DefaultLoginPageGeneratingFilter.doFilter(DefaultLoginPageGeneratingFilter.java:92)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:189)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:189)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:106)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:79)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:110)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:110)
	at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:380)
	at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:170)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:238)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:168)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at com.isomorphic.servlet.CompressionFilter.doFilter(CompressionFilter.java:260)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at com.isomorphic.js.JSSyntaxScannerFilter.doFilter(JSSyntaxScannerFilter.java:242)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.jasig.cas.client.session.SingleSignOutFilter.doFilter(SingleSignOutFilter.java:77)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:89)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:205)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:124)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:473)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:101)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:954)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:120)
	at org.apache.catalina.connector.Request.isComet(Request.java:2536)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:410)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1014)
	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$Worker.runTask(ThreadPoolExecutor.java:896)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:919)
	at java.lang.Thread.run(Thread.java:662)

do you have any clues on what can cause this warning?
In those DMI I'm always using automatic transaction management and there are queries which are using a dblink.

[Isomorphic]

From just this information, all we can say is pretty much what the error message said - the system is trying to close an automatically created transaction but there's no SQLConnection object.

We don't see any obvious way this condition could arise. Best guess is something like trying to modify the automatic transaction policy when a transaction has already started or already completed.

Let us know if you can put together a test case suggesting a framework issue.

[claudiobosticco]

Actually I don't modify automatic transaction policy, not on purpose at least.

I create DSRequest(s) with the constructor new DSRequest(..., ..., rpcManager)

some of these requests are using a dblink and maybe in some transactions I create requests passing DataSources which use different databases and so different connection pools, and I always pass the same rpcManager object. Is it correct?

As you could sense from my questions, for now I'm thinking more of a misuse in my code than a bug in the framework.

[Isomorphic]

Yes, it's correct to always pass the same RPCManager object even if there are different databases in the transaction.

And this error does seem to have something to do with transactions that involve multiple databases. In this case, the RPCManager tracks the active SQLConnection for each database, and somehow this ends up as null for the database configured as sql.defaultDatabase.

Does this transaction perhaps involve operations performed against various databases, but with the sql.defaultDatabase never involved?

Note it's definitely worth updating to the latest patched build, or better yet to 4.1 or 5.0d, just in case this is actually a framework bug and it was already fixed.

[claudiobosticco]

Yes, it's correct to always pass the same RPCManager object even if there are different databases in the transaction.

And this error does seem to have something to do with transactions that involve multiple databases. In this case, the RPCManager tracks the active SQLConnection for each database, and somehow this ends up as null for the database configured as sql.defaultDatabase.

Does this transaction perhaps involve operations performed against various databases, but with the sql.defaultDatabase never involved?

actually I haven't got a sql.defaultDatabase setting in the server.properties. This could be the problem? (note: my dataSources always declare the dbName).
Anyway I'll add it and retest.

Note it's definitely worth updating to the latest patched build, or better yet to 4.1 or 5.0d, just in case this is actually a framework bug and it was already fixed.

I'm pretty sure that the latest build of 9.1 shows the same behavior, but I'll retest. I'll also try the 10.0d.

[claudiobosticco]

I've added the sql.defaultDatabase setting in the server.properties, and I've also tested with:

SmartClient Version: v9.1p_2014-05-18/PowerEdition Deployment (built 2014-05-18)

and

SmartClient Version: SNAPSHOT_v10.0d_2014-05-18/EVAL Deployment (expires 2014.07.17_23.39.19) Licensed to: Isomorphic Software (#ISC_EVAL_NIGHTLY)

but the behavior is the same.

Now I'm trying to put together a test case and this is what I've found so far.

The transaction which gives that warning fetches some data (to produce and download a PDF).

In that transaction there are three types of fetches:
1. fetches which involve the sql.defaultDatabase and also use the dblink to make a join with tables from another database.
2. fetches which involve only the sql.defaultDatabase
3. fetches which involve only the other (non-default) database.

Now I've reduced my code so that I've got only 3 fetches, one fetch per type, and the warning still shows.

Strangely enough, I noticed that the warning doesn't show if I make the 3rd type fetch first, and then the other two type of fetches (any order between the other two).
In practice I've tested all the possible ordering possibility:
1-2-3, 1-3-2, 2-1-3, 2-3-1 the warning shows
3-1-2, 3-2-1 the warning doesn't show

with only two of those fetches the warning never shows.

Any clues on what's going on?

[Isomorphic]

We've had a closer look into this issue and discovered a defect in the server side framework for SQL datasources. The issue meant that on certain occasions SQL database connections would not be closed properly as they would not be found.

This issue does not affect Hibernate and JPA datasources however as they use a different mechanism for freeing up connections.

The defect has now been resolved and will be available in a nightly 9.0 or later build in the next day or two.

[claudiobosticco]

We've had a closer look into this issue and discovered a defect in the server side framework for SQL datasources. The issue meant that on certain occasions SQL database connections would not be closed properly as they would not be found.

does this means that the pools would leak connections?
I'm asking because I suspect we're having some problems and that's why I've started this analysis.

This issue does not affect Hibernate and JPA datasources however as they use a different mechanism for freeing up connections.

ok, actually we're using SQLDataSource only.

The defect has now been resolved and will be available in a nightly 9.0 or later build in the next day or two.

thank you very much

[claudiobosticco]

SmartClient Version: v9.0p_2014-05-20/PowerEdition Deployment (built 2014-05-20)

and

SmartClient Version: v9.1p_2014-05-20/PowerEdition Deployment (built 2014-05-20)

I've just verified that the warning no longer appears, thank you very much!

would you please comment on this other question:

We've had a closer look into this issue and discovered a defect in the server side framework for SQL datasources. The issue meant that on certain occasions SQL database connections would not be closed properly as they would not be found.

does this means that the pools would leak connections?

[Isomorphic]

You mean prior to the bugfix?

No, it does not seem to the case that SQLConnections would be leaked, even prior to the bugfix.

[claudiobosticco]

You mean prior to the bugfix?

yes I do

No, it does not seem to the case that SQLConnections would be leaked, even prior to the bugfix.

please note that I'm using the oracle jdbc thin driver connection pool, with JNDI-based configuration. Not a problem either?

Also, do you recommend DBCP pooling over oracle jdbc driver pool? I've got commons-dbcp-1.3.jar, tomcat-dbcp.jar and tomcat-jdbc.jar in tomcat/lib which I think are sufficient fot trying it.

[Isomorphic]

It wouldn't matter which connection pooling mechanism was used.

We don't really have a recommendation for DBCP vs container-provided connection pooling.