Hi,

Some times we face issues while invoking some JDBC statements using the DataSource JDBC Connection. Many times it is not easily identifiable that which part of the JDBC code is actually causing the failure or issue. So it is better to have a Spy logging kind of feature inside the datasource which can tell us all the activities which an application performs on the Jdbc connection & Statements retrieved from the DataSource.

JBoss AS7 uses Jacmar for implementing it’s datasource mechanism. Also JBoss AS7 provides a very effecient way of enabling the spy logging which can log all the informations related to the connection/statements and any method whcih is invoked on the JDBC Objects.

In order to enable the DataSource Spy logging in JBoss AS7 we will need to do the following two things:

Step1). Enable the “jboss.jdbc.spy” to DEBUG inside your “standalone-full.xml” or “domain.xml” file present inside “jboss-as-7.1.0.Beta1/standalone/confguration” directory as following:

        <subsystem xmlns="urn:jboss:domain:logging:1.1">
            <console-handler name="CONSOLE">
                <level name="INFO"/>
                <formatter>
                    <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
                </formatter>
            </console-handler>
            <periodic-rotating-file-handler name="FILE">
                <formatter>
                    <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="server.log"/>
                <suffix value=".yyyy-MM-dd"/>
                <append value="true"/>
            </periodic-rotating-file-handler>
            <logger category="com.arjuna">
                <level name="WARN"/>
            </logger>
            <logger category="org.apache.tomcat.util.modeler">
                <level name="WARN"/>
            </logger>
            <logger category="sun.rmi">
                <level name="WARN"/>
            </logger>
            <logger category="jacorb">
                <level name="WARN"/>
            </logger>
            <logger category="jacorb.config">
                <level name="ERROR"/>
            </logger>

            <!-- ************* Enabling Spy logging category ************ -->
            <logger category="jboss.jdbc.spy">
                <level name="TRACE"/>
            </logger>
            <!-- *************************************************-->

            <root-logger>
                <level name="INFO"/>
                <handlers>
                    <handler name="CONSOLE"/>
                    <handler name="FILE"/>
                </handlers>
            </root-logger>
        </subsystem>

Step2). Create a DataSource from JBoss Console or using “jboss-admin.sh” utility. You can refer to the following article for more details on creating DataSources:
How to create Oracle DataSource And Install Oracle JDBC Driver in JBoss AS7
OR
How to create MySQL datasource And Install MySQL JDBC driver in JBoss AS7

NOTE: The only thing you need to remember is to add the spy=”true” attribute in your DataSource configuration as following:

        <subsystem xmlns="urn:jboss:domain:datasources:1.0">
            <datasources>
                <datasource jndi-name="java:jboss/datasources/ExampleDS" pool-name="H2DS" enabled="true">
                    <connection-url>
                        jdbc:h2:mem:test;DB_CLOSE_DELAY=-1
                    </connection-url>
                    <driver>
                        h2
                    </driver>
                    <security>
                        <security-domain>
                            encrypted-ds
                        </security-domain>
                    </security>
                </datasource>


                <!-- ****** Below is MySqlDS with Spy logging enabled ****** -->
                <datasource jndi-name="java:/MySqlDS" pool-name="MySqlDS_Pool" enabled="true" spy="true" jta="false" use-ccm="false">
                    <connection-url>
                        jdbc:mysql://localhost:3306/testDB
                    </connection-url>
                    <driver-class>
                        com.mysql.jdbc.Driver
                    </driver-class>
                    <driver>
                        mysql-connector-java-5.1.13-bin.jar
                    </driver>
                    <security>
                        <security-domain>
                            encrypted-ds
                        </security-domain>
                    </security>
                </datasource>
                <!-- ****** Above is MySqlDS with Spy logging enabled ****** -->


                <drivers>
                    <driver name="h2" module="com.h2database.h2">
                        <xa-datasource-class>
                            org.h2.jdbcx.JdbcDataSource
                        </xa-datasource-class>
                    </driver>
                </drivers>
            </datasources>
        </subsystem>

NOTE: In order to enable the spy logging you must follow both the steps “Step-1” and “Step-2” together.

Step3). Now suppose if you have following kind of JSP Page inside your application which uses the JBoss DataSource Jdbc Connection in order to perform some JDBC operations:

<%@page contentType="text/html" import="java.util.*,javax.naming.*,javax.sql.DataSource,java.sql.*"%>

<%
DataSource ds = null;
Connection con = null; 
PreparedStatement pr = null; 
InitialContext ic; 

out.println("<html>");
out.println("<body>");
out.println("<center>");

	try 
	{
		ic = new InitialContext();
		ds = (DataSource)ic.lookup("java:/MySqlDS");
		con = ds.getConnection(); 
		
		out.println("<font color=green>");
		out.println("<b>Got Connection </b> = "+con);
		out.println("<br><br><br><br><br><br><b> This means our DataSource has been configured properly </b> ");
		out.println("</font>");
		System.out.println("==> Got Connection = "+con);

                Statement stmt=con.createStatement();
                ResultSet rs=stmt.executeQuery("SELECT * FROM emp");
                out.println("<TABLE>");
                while(rs.next())
                 {
                     out.println("<TR><TD>"+rs.getString(1)+"</TD><TD>"+rs.getString(2)+"</TD></TR>");
                 }
                out.println("</TABLE>");
	}

	catch (SQLException s)
	{
		out.println("<font color=red>");
		out.println("<b>!!! Did not get the connection </b> = " +s);
		out.println("<br><br><br><br><br><br><b>This means we might have to check our datasource configuration (i.e. URL, Username, Password etc) or might be the database is down </b> ");
		out.println("</font>");
		System.out.println("!!! Did not get the connection = " +s);
	}

	catch(Exception e)
	{
		out.println("<font color=red>");
		out.println("<b>!!! Exception thrown </b> = " +e);
		out.println("<br><br><br><br><br><br><b>This means we might have to check our datasource configuration (i.e. URL, Username, Password etc) or might be the database is down </b> ");
		out.println("</font>");
		System.out.println("!!! Exception thrown = "+e);
	}

	finally
	{
		if(con != null)
		{
			con.close();
		}      
	} 

out.println("</center>");
out.println("</body>");
out.println("</html>");
%>

Step4). Restart your JBoss after enabling the Spy Logging and then access the application which performs some activity on the JDBC Connection retrieved from the JBoss AS7 DataSource. The you will notice in your “server.log” file following kind of DEBUG messages:

23:01:14,744 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Connection] createStatement()
23:01:14,748 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Statement] executeQuery(SELECT * FROM emp)
23:01:14,756 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] next()
23:01:14,756 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] getString(1)
23:01:14,757 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] getString(2)
23:01:14,757 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] next()
23:01:14,757 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Connection] close()

Means whatever operations our application is performing on the JDBC Connection/Statement…etc objects everything is being logged. This can be very helpful in debugging/troubleshooting many JDBC Related issues.

Following is not part of Spy Logging but Useful

If you are running in Development environment and if it’s OK to have more logging then you can also enable the following category “org.jboss.jca” in your “standalone-full.xml” or “domain.xml” file to get more informations related to your DataSource:

            <logger category="org.jboss.jca">
                <level name="TRACE"/>
            </logger>
23:58:12,112 TRACE [org.jboss.jca.core.connectionmanager.NoTxConnectionManager] (http-localhost-127.0.0.1-8080-1) Subject: Subject:
	Principal: root
	Private Credential: javax.resource.spi.security.PasswordCredential@dd9c93cc

23:58:12,122 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (http-localhost-127.0.0.1-8080-1) internalRegisterPool: about to notify thread: old next: 1322937792121, new next: 1322937792121
23:58:12,123 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (http-localhost-127.0.0.1-8080-1) ManagedConnectionPool: 52e0cdc9
Method: getConnection(Subject:
	Principal: root
	Private Credential: javax.resource.spi.security.PasswordCredential@dd9c93cc
, null)
ManagedConnectionFactory:
  Class: org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory
  Object: 4200309
ConnectionListenerFactory:
  Class: org.jboss.jca.core.connectionmanager.notx.NoTxConnectionManagerImpl
  Object: 51a745fc
Pool:
  Name: MySqlDS_Pool
PoolConfiguration:
  MinSize: 0
  MaxSize: 20
  BlockingTimeout: 30000
  IdleTimeout: 1800000
  BackgroundValidation: false
  BackgroundValidationMillis: 0
  StrictMin: false
  UseFastFail: false
Available:
InUse:
Statistics:
  ActiveCount: 0
  AvailableCount: 20
  AverageBlockingTime: 0
  AverageCreationTime: 0
  CreatedCount: 0
  DestroyedCount: 0
  MaxCreationTime: 0
  MaxUsedCount: 0
  MaxWaitCount: 0
  MaxWaitTime: 0
  TimedOut: 0
  TotalBlockingTime: 0
  TotalCreationTime: 0
23:58:12,124 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-localhost-127.0.0.1-8080-1) Using properties: {user=root, password=--hidden--}
23:58:12,124 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-localhost-127.0.0.1-8080-1) Checking driver for URL: jdbc:mysql://localhost:3306/testDB
23:58:12,125 TRACE [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-localhost-127.0.0.1-8080-1) Driver not yet registered for url: jdbc:mysql://localhost:3306/testDB
23:58:12,125 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (http-localhost-127.0.0.1-8080-1) Driver loaded and instance created:com.mysql.jdbc.Driver@75589559
23:58:12,180 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) RecoverySecurityDomain was empty
23:58:12,180 DEBUG [org.jboss.jca.core.tx.jbossts.XAResourceRecoveryImpl] (Periodic Recovery) Subject for recovery was null
23:58:12,338 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (http-localhost-127.0.0.1-8080-1) supplying new ManagedConnection: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@4b7d94f8[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@21bf4c80 connection handles=0 lastUse=1322936892337 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject@163778cf pool internal context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@52e0cdc9]
23:58:12,338 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (http-localhost-127.0.0.1-8080-1) Got connection from pool: org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@4b7d94f8[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@21bf4c80 connection handles=0 lastUse=1322936892337 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject@163778cf pool internal context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@52e0cdc9]
23:58:12,347 INFO  [stdout] (http-localhost-127.0.0.1-8080-1) ==> Got Connection = org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@28892a87
23:58:12,350 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Connection] createStatement()
23:58:12,355 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Statement] executeQuery(SELECT * FROM emp)
23:58:12,362 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] next()
23:58:12,363 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] getString(1)
23:58:12,363 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] getString(2)
23:58:12,363 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [ResultSet] next()
23:58:12,363 DEBUG [jboss.jdbc.spy] (http-localhost-127.0.0.1-8080-1) java:/MySqlDS [Connection] close()
23:58:12,365 TRACE [org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener] (http-localhost-127.0.0.1-8080-1) unregisterConnection: 0 handles left
23:58:12,365 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (http-localhost-127.0.0.1-8080-1) ManagedConnectionPool: 52e0cdc9
Method: returnConnection(4b7d94f8, false)
ManagedConnectionFactory:
  Class: org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory
  Object: 4200309
ConnectionListenerFactory:
  Class: org.jboss.jca.core.connectionmanager.notx.NoTxConnectionManagerImpl
  Object: 51a745fc
Pool:
  Name: MySqlDS_Pool
PoolConfiguration:
  MinSize: 0
  MaxSize: 20
  BlockingTimeout: 30000
  IdleTimeout: 1800000
  BackgroundValidation: false
  BackgroundValidationMillis: 0
  StrictMin: false
  UseFastFail: false
Available:
InUse:
  4b7d94f8 (NORMAL)
Statistics:
  ActiveCount: 1
  AvailableCount: 19
  AverageBlockingTime: 0
  AverageCreationTime: 212
  CreatedCount: 1
  DestroyedCount: 0
  MaxCreationTime: 212
  MaxUsedCount: 1
  MaxWaitCount: 0
  MaxWaitTime: 0
  TimedOut: 0
  TotalBlockingTime: 0
  TotalCreationTime: 212
23:58:12,366 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject] (http-localhost-127.0.0.1-8080-1) Returning connection to pool org.jboss.jca.core.connectionmanager.listener.NoTxConnectionListener@4b7d94f8[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@21bf4c80 connection handles=0 lastUse=1322936892366 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.PoolBySubject@163778cf pool internal context=org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool@52e0cdc9]

.
.
Thanks
MiddlewareMagic Team

If you enjoyed this post, please consider leaving a comment or subscribing to the RSS feed to have future articles delivered to your feed reader.