XNSIO
  About   Slides   Home  
 
Managed Chaos
Naresh Jain's Random Thoughts on Software Development and Adventure Sports
      
`
 
RSS Feed
Recent Thoughts
Tags
Agile agile bengaluru 2010 Agile Coach Camp agileindia agile india agileindia2012 Agile India 2012 AgileIndia2013 Agile India 2013 Agile India 2013 Workshops agileindia2014 Agile India 2014 agile mumbai 2010 ASCI Attendees Profile Code Coverage code smells Conference Continuous Deployment Continuous Integration cyclomatic complexity Design duplicate code Evolutionary Design Extreme Programming Industrial Logic Lean Lean Startup LinkedIn Open Source pair programming post modern agile primitive obsession smell Refactoring Refactoring Teaser Scrum SDTConf simple design TDD technical debt Test Driven Development Testing unit testing user stories video
Recent Comments

Could not inspect JDBC autocommit mode

Saturday, January 9th, 2010

After switching to the DBCP (Database Connection Pool) drivers that comes bundled with Tomcat 5+, we started seeing a weird exception on our web app. If we leave our server idle for a long time (5-6 hrs) or if we put our laptop to sleep and 5-6+ hrs later when we bring up the laptop and try to access any page on our web app, we get the following error on the web page:

(The error was “could not inspect JDBC autocommit mode”)

When we see our logs, we find the following exception:

18:26:34,845 ERROR JDBCExceptionReporter:72 - Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed.
SEVERE: could not inspect JDBC autocommit mode
org.hibernate.exception.GenericJDBCException: could not inspect JDBC autocommit mode
	at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
	at org.hibernate.jdbc.JDBCContext.afterNontransactionalQuery(JDBCContext.java:248)
	at org.hibernate.impl.SessionImpl.afterOperation(SessionImpl.java:417)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1577)
	at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283)
	...
	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.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.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:347)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
	at java.lang.Thread.run(Thread.java:637)
Caused by: java.sql.SQLException: Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed.
	at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.checkOpen(DelegatingConnection.java:354)
	at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.getAutoCommit(DelegatingConnection.java:304)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.getAutoCommit(PoolingDataSource.java:224)
	at org.hibernate.jdbc.ConnectionManager.isAutoCommit(ConnectionManager.java:185)
	at org.hibernate.jdbc.JDBCContext.afterNontransactionalQuery(JDBCContext.java:239)
	... 29 more

On carefully looking at the exception, we find:

Caused by: java.sql.SQLException: Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed.

From the exception its clear that the reason for this exception is that the db connection is closed. Which is in sync with our finding so far, idle server causes this problem.

What happens is, the Database closes the connections since they are inactive. But DBCP & hence hibernate still thinks those connections are active and tries to execute some command on them. This is when an exception is thrown.

We can easily simulate this exception. When everything is running fine, restart your DB and you’ll see the same exception when you try to access any dynamic page on your site.

On reading DBCP configuration, I found:

Parameter Default Description
validationQuery The SQL query that will be used to validate connections from this pool
before returning them to the caller. If specified, this query
MUST be an SQL SELECT statement that returns at least
one row.
testOnBorrow true The indication of whether objects will be validated before being
borrowed from the pool. If the object fails to validate, it will be
dropped from the pool, and we will attempt to borrow another.
NOTE – for a true value to have any effect,
the validationQuery parameter must be set to a non-null
string.

Basically testOnBorrow is true by default, which means DBCP will test if the connection is valid (alive) before returning. But to test it, it needs a query using which it would validate the connection. Since in our case we did not specify any value, when hibernate would ask DBCP for a connection, it would just return a connection without testing if its a valid connection before returning. And then the stale connection throws an exception when we try to perform any operation on it. But if the validation query is specified, then DBCP will drop the connection and give us another valid connection. This avoiding this problem.

So the simple solution to this problem is to add a validationQuery to the connection pooling configuration (in our case it was the context.xml file).

validationQuery="select version();"

Q.E.D

Posted in Database, Tips | 2 Comments »

Cannot create JDBC driver of class ” for connect URL ‘null’

Monday, November 23rd, 2009

On, one of our tomcat boxes in production, we kept getting the following exception when trying to start the server:

17:06:30,823 ERROR SchemaUpdate:134 - could not get database metadata
org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot create JDBC driver of class '' for connect URL 'null'
        at org.apache.tomcat.dbcp.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1150)
        at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
        at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
        at org.hibernate.tool.hbm2ddl.SuppliedConnectionProviderConnectionHelper. prepare(SuppliedConnectionProviderConnectionHelper.java:27)
        at org.hibernate.tool.hbm2ddl.SchemaUpdate.execute(SchemaUpdate.java:127)
        at org.hibernate.impl.SessionFactoryImpl.(SessionFactoryImpl.java:314)
        at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1218)
        at javax.servlet.GenericServlet.init(GenericServlet.java:212)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1172)
        at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:808)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:129)
        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.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:347)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
        at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.NullPointerException
        at sun.jdbc.odbc.JdbcOdbcDriver.getProtocol(JdbcOdbcDriver.java:507)
        at sun.jdbc.odbc.JdbcOdbcDriver.knownURL(JdbcOdbcDriver.java:476)
        at sun.jdbc.odbc.JdbcOdbcDriver.acceptsURL(JdbcOdbcDriver.java:307)
        at java.sql.DriverManager.getDriver(DriverManager.java:253)
        at org.apache.tomcat.dbcp.dbcp.BasicDataSource.createDataSource(BasicDataSource.java:1143)
        ... 22 more

Googling for it, only kept suggesting to check our context.xml file, which appeared to be correct. In fact the same war works fine on other instances of tomcat.

All we were doing in our context.xml file is that we’re defining a Data Source Resource. Which gets referred in our Web.xml. Pretty straight forward.

Looking back at the exception, particularly the following part:

org.apache.tomcat.dbcp.dbcp.SQLNestedException: 
Cannot create JDBC driver of class '' for connect URL 'null'

suggests that tomcat was not able to find the Data Source definition which is of course defined in our context.xml file. So certainly there was something to do with Context.xml causing the failure.

On comparing this web app with the other, working tomcat instances, I found Context.xml file was present on both instance in the webapp/<web_app_name>/META-INF dir. Which is fine. But on the working tomcat instance I found another file called <web_app_name>.xml (with the same contents as Context.xml) file under the tomcat/conf/Catalina/localhost folder. This <web_app_name>.xml file was missing on the tomcat instance.

Solution: Copy the Context.xml file to tomcat/conf/Catalina/localhost folder and renaming it to <web_app_name>.xml got rid of the exception. This made it clear why tomcat was throwing this exception and failing to start.

Something was stopping tomcat from creating this file. And of course it turned out to be a tomcat user permission issue. The user under which tomcat was running did not have permission to write to these folders. So we changed the group ownership of tomcat and /etc/tomcat folder to the same group to which the tomcat user belonged and magically everything started working as before.

Posted in Deployment, Tips | 4 Comments »

Setting up Tomcat Cluster for Session Replication

Monday, November 9th, 2009

If you have your web application running on one tomcat instance and want to add another tomcat instance (ideally on a different machine), following steps will guide you.

Step 1: Independently deploy your web application (WAR file) on each instance and make sure they can work independently.

Step 2: Stop tomcat

Step 3: Update the <Cluster> element under the <Engine> element in the Server.xml file (under the conf dir in tomcat installation dir) on both your servers with:

<Engine name="<meaningful_unique_name>" defaultHost="localhost">      
     <Cluster className="org.apache.catalina.ha.tcp.SimpleTcpCluster"
              channelSendOptions="8">
          <Manager className="org.apache.catalina.ha.session.DeltaManager"
                   expireSessionsOnShutdown="false"
                   notifyListenersOnReplication="true"/>
          <Channel className="org.apache.catalina.tribes.group.GroupChannel">
               <Membership className="org.apache.catalina.tribes.membership.McastService"
                           address="228.0.0.4"
                           port="45564"
                           frequency="500"
                           dropTime="3000"/>
               <Receiver className="org.apache.catalina.tribes.transport.nio.NioReceiver"
                         address="auto"
                         port="4000"
                         autoBind="100"
                         selectorTimeout="5000"
                         maxThreads="6"/>
               <Sender className="org.apache.catalina.tribes.transport.ReplicationTransmitter">
                   <Transport className="org.apache.catalina.tribes.transport.nio.PooledParallelSender"/>
               </Sender>
               <Interceptor className="org.apache.catalina.tribes.group.interceptors.TcpFailureDetector"/>
               <Interceptor className="org.apache.catalina.tribes.group.interceptors.MessageDispatch15Interceptor"/>
          </Channel>
          <Valve className="org.apache.catalina.ha.tcp.ReplicationValve"
                 filter=".*\.gif;.*\.js;.*\.jpg;.*\.png;.*\.css;.*\.txt;"/>
          <ClusterListener className="org.apache.catalina.ha.session.ClusterSessionListener"/>
     </Cluster>
     ...
</Engine>

For more details on these parameters, check https://sec1.woopra.com/docs/cluster-howto.html

Step 4: Start tomcat and make sure it starts up correctly. You should be able to access http://locahost:8080. Most default tomcat installations come with an examples web app. Try access http://localhost:8080/examples/jsp/ You should see a list of JSP files.

Step 4.a: Also if you see catalina.out log file, you should see:

INFO: Initializing Coyote HTTP/1.1 on http-8080
Nov 9, 2009 9:29:43 AM org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 762 ms
Nov 9, 2009 9:29:43 AM org.apache.catalina.core.StandardService start
INFO: Starting service <server_name>
Nov 9, 2009 9:29:43 AM org.apache.catalina.core.StandardEngine start
INFO: Starting Servlet Engine: Apache Tomcat/6.0.16
Nov 9, 2009 9:29:43 AM org.apache.catalina.ha.tcp.SimpleTcpCluster start
INFO: Cluster is about to start
Nov 9, 2009 9:29:43 AM org.apache.catalina.tribes.transport.ReceiverBase bind
INFO: Receiver Server Socket bound to:/<server_ip>:4000
Nov 9, 2009 9:29:43 AM org.apache.catalina.tribes.membership.McastServiceImpl setupSocket
INFO: Setting cluster mcast soTimeout to 500
Nov 9, 2009 9:29:43 AM org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers
INFO: Sleeping for 1000 milliseconds to establish cluster membership, start level:4

Step 5: Stop tomcat.

Step 6: We’ll use the examples web app to test if our session replication is working as expected.

Step 6.a: Open the Web.xml file of the “examples” web app in your webapps. Mark this web app distributable, by adding a <distributable/> element at the end of the Web.xml file (just before the </web-app> element)

Step 6.b: Add the session JSP file. This JSP prints the contents of the session and also adds/increments a counter stored in the session.

Step 6.c: Start tomcat on both machines

Step 6.d: You should see the following log in catalina.out

Nov 9, 2009 9:29:44 AM org.apache.catalina.ha.tcp.SimpleTcpCluster memberAdded
INFO: Replication member added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{-64, -88, 0, 101}:4000,{-64, -88, 0, 101},4000, alive=10035,id={68 106 92 39 -110 -8 73 124 -116 -122 -15 -3 11 117 56 105 }, payload={}, command={}, domain={}, ] 
 
Nov 9, 2009 9:29:49 AM org.apache.catalina.ha.session.DeltaManager start
INFO: Register manager /examples to cluster element Engine with name <server_name>
Nov 9, 2009 9:29:49 AM org.apache.catalina.ha.session.DeltaManager start
INFO: Starting clustering manager at /examples
Nov 9, 2009 9:29:49 AM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions
WARNING: Manager [localhost#/examples], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{-64, -88, 0, 101}:4000,{-64, -88, 0, 101},4000, alive=15538,id={68 106 92 39 -110 -8 73 124 -116 -122 -15 -3 11 117 56 105 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds.
Nov 9, 2009 9:29:49 AM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions
INFO: Manager [localhost#/examples]; session state send at 11/9/09 9:29 AM received in 101 ms.
 
Nov 9, 2009 9:29:49 AM org.apache.catalina.core.ApplicationContext log
INFO: ContextListener: contextInitialized()
Nov 9, 2009 9:29:49 AM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: contextInitialized()
Nov 9, 2009 9:29:50 AM org.apache.coyote.http11.Http11Protocol start
INFO: Starting Coyote HTTP/1.1 on http-8080
Nov 9, 2009 9:29:50 AM org.apache.jk.common.ChannelSocket init
INFO: JK: ajp13 listening on /0.0.0.0:8009
Nov 9, 2009 9:29:50 AM org.apache.jk.server.JkMain start
INFO: Jk running ID=0 time=0/49  config=null
Nov 9, 2009 9:29:50 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 6331 ms

Step 6.e: Try to access http://localhost:8080/examples/jsp/session.jsp Try refreshing the page a few times, you should see the counter getting updated.

Step 6.f: You should see the same behavior when you try to access the other tomcat server. Open another tab in your browser and hit http://<other_server_ip>:8080/examples/jsp/session.jsp

Step 6.g: At this point we know the app works fine and the session is working correctly. Now we want to check if the tomcat cluster is replicating the session info. To check this, we want to pass the session from server 1 to session 2 and see if it increments the counter from where we left.

Step 6.h: Before accessing the page, make sure you copy the j_session_id from server 1 (displayed on the http://localhost:8080/examples/jsp/session.jsp). Also make sure to clear all cookies from server 2. (All browsers give you a facility to clear cookies from a specific host/ip).

Step 6.i: Now hit http://<server_2_ip>:8080/examples/jsp/session.jsp;jsessionid=<jsession_id_from_server1>

Step 6.j: If you see the counter incrementing from where ever you had left, congrats! You have session replication working.

Step 6.k: Also catalina.out log file should have:

Nov 9, 2009 9:42:03 AM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: sessionCreated('CDC57B8C5CFDFDDC2C8572E7D14C0D28')
Nov 9, 2009 9:42:03 AM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: attributeAdded('CDC57B8C5CFDFDDC2C8572E7D14C0D28', 'counter', '1')
Nov 9, 2009 9:42:05 AM org.apache.catalina.core.ApplicationContext log
INFO: SessionListener: attributeReplaced('CDC57B8C5CFDFDDC2C8572E7D14C0D28', 'counter', '2')

While this might like smooth, I ran into lot of issues when getting to this point. Following are some trap routes I ran into:

1) java.sql.SQLException: No suitable driver tomcat cluster
Make sure your DB Driver jar (in our case mysql-connector-java-x.x.xx-bin.jar) is in tomcat/lib folder

2) In catalina.org if you see the following exception:

Nov 7, 2009 3:48:53 PM org.apache.catalina.ha.session.DeltaManager requestCompleted
SEVERE: Unable to serialize delta request for sessionid [1F43C3926FF3CC231574EF248896DCA6]
java.io.NotSerializableException: com.company.product.Class
	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1156)
	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:326)
	at java.util.ArrayList.writeObject(ArrayList.java:570)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)

This means that you are storing com.company.product.Class object (or some other object that holds a reference to this Object) in your session. And you’ll need to make com.company.product.Class implement Serializable interface.

3) In your catalina.out log if you see

INFO: Register manager /<your_app_name> to cluster element Engine with name <tomcat_engine_name>
Nov 7, 2009 11:56:20 AM org.apache.catalina.ha.session.DeltaManager start
INFO: Starting clustering manager at /<your_app_name>
Nov 7, 2009 11:56:20 AM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions
INFO: Manager [localhost#/<your_app_name>]: <strong>skipping state transfer. No members active in cluster group</strong>.

If both your tomcat instance are up and running, then check if your tomcat servers can communicate with each other using Multicast with the following commands:

$ ping -t 1 -c 2 228.0.0.4
PING 228.0.0.4 (228.0.0.4): 56 data bytes
64 bytes from <server_1_ip>: icmp_seq=0 ttl=64 time=0.076 ms
64 bytes from <server_2_ip>: icmp_seq=0 ttl=64 time=0.645 ms

— 228.0.0.4 ping statistics —
1 packets transmitted, 1 packets received, +1 duplicates, 0.0% packet loss

or

$ sudo tcpdump -ni en0 host 228.0.0.4
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on en0, link-type EN10MB (Ethernet), capture size 65535 bytes
22:11:50.016147 IP <server_1_ip>.45564 > 228.0.0.4.45564: UDP, length 69
22:11:50.033336 IP <server_2_ip>.45564 > 228.0.0.4.45564: UDP, length 69
22:11:50.516746 IP <server_1_ip>.45564 > 228.0.0.4.45564: UDP, length 69
22:11:50.533613 IP <server_2_ip>.45564 > 228.0.0.4.45564: UDP, length 69
…

If you don’t see the results as described above, you might want to read my blog on Enabling Multicast.

Posted in Deployment, Java, Networking, Open Source, Tools | 4 Comments »
    Licensed under
Creative Commons License