목차

JBoss Datasource SPY logging

Datasource SPY logging 이라는것은 JBoss 컨테이너에서 제공하는 데이터소스를 사용할때 모든 SQL트랜잭션을 로깅할 수 있는 기능이다.

설정하는 법은 아래와 같다.

logging subsystem

logging subsystem에서 SPY logging을 위한 새로운 카테고리를 생성한다. 

    <logger category="jboss.jdbc.spy">
        <level name="TRACE"/>
    </logger>

실제 configuration파일에는 아래와 같이 입력된다. 

<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>

datasource subsystem

datasource subsystem에서는 해당 datasource의 spy=“true” 속성값을 추가해주도록 한다. 이 속성값은 JBoss Management WEB UI에서는 수정할 수 없으므로 jboss-cli.sh 를 이용하거나 직접 configuration파일을 수정해주도록 한다. 

        <!-- ****** 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 ****** -->

output

위와같이 설정하면 로그파일에 아래와같이 쿼리 내용이 출력된다. 

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()

jca logging

추가적으로 jca 정보를 표현하려면 아래와같은 카테고리를 추가해주도록 한다. 

<logger category="org.jboss.jca">
    <level name="TRACE"/>
</logger>

jca 카테고리를 추가하게 되면 아래와같이 datasource 커넥션 정보가 로그로 출력된다. 

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]

참고링크