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