Getting detailed logging for Universal Connection Pool (UCP) / Fast Connection Failover (FCF) Testing

While testing UCP/FCF I was having some issues with the RAC cluster setup. One useful way to determine exactly what is happening or not happening from the FAN events sent from RAC cluster to the pool was to setup logging as described below.

1. Create a properties file as follows.

# This is the sample logging properties file that configures
# loggers of some classes (FCF-related ones) to produce detailed logging
# (all levels) and just SEVERE and WARNING level messages for the rest
# of loggers. Console output via UCPFormatter (ODL-like messages).

handlers = java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter = oracle.ucp.util.logging.UCPFormatter

.level = WARNING

oracle.ucp.common.FailoverEventHandlerThreadBase.level = ALL

oracle.ucp.jdbc.oracle.ONSDatabaseEventHandlerThread.level = ALL
oracle.ucp.jdbc.oracle.ONSDatabaseFailoverEvent.level = ALL
oracle.ucp.jdbc.oracle.ONSOracleFailoverEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.OracleDatabaseInstanceInfo.level = ALL
oracle.ucp.jdbc.oracle.OracleDatabaseInstanceInfoList.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventNotification.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverEventSubscriber.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverHandler.level = ALL
oracle.ucp.jdbc.oracle.OracleFailoverablePooledConnection.level = ALL
oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OraclePooledConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleXAConnectionConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.level = ALL
oracle.ucp.jdbc.oracle.OracleUniversalPooledConnection.level = ALL

2. Add the JVM command line option as follows - -Djava.util.logging.config.file=ucp_fcf_log.properties.

Then you should see some detailed output as follows. Very useful information in diagnosing UCP/FCF issues with your pool. Just showing small snippet as this is detailed output.

[java] 2010-02-24T10:44:16.734+1100 UCP FINE seq-103,thread-11 oracle.ucp.jdbc.oracle.ONSDatabaseEventHandlerThread.run event
triggered: Service name: orcl.apemrac.au.oracle.com, Instance name: orcl1, Unique name: orcl, Host name: apemrac1, Status: down,
Cardinality: 0, Reason: user, Event type: database/event/service
[java] 2010-02-24T10:44:16.734+1100 UCP FINEST seq-104,thread-11 oracle.ucp.jdbc.oracle.ONSDatabaseEventHandlerThread.run che
ck for events
[java] 2010-02-24T10:44:16.734+1100 UCP FINEST seq-105,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setEventType
eventType: database/event/service
[java] 2010-02-24T10:44:16.750+1100 UCP FINEST seq-106,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.validateEvent
Type eventType: database/event/service
[java] 2010-02-24T10:44:16.750+1100 UCP FINEST seq-107,thread-11 oracle.ucp.jdbc.oracle.ONSDatabaseFailoverEvent. event
Type: database/event/service, eventBody: VERSION=1.0 service=HASERVICE.apemrac.au.oracle.com instance=orcl1 database=orcl host=ape
mrac1 status=down reason=failure
[java] 2010-02-24T10:44:16.765+1100 UCP FINEST seq-108,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setServiceNam
e serviceName: HASERVICE.apemrac.au.oracle.com
[java] 2010-02-24T10:44:16.765+1100 UCP FINEST seq-109,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setInstanceNa
me instanceName: orcl1
[java] 2010-02-24T10:44:16.765+1100 UCP FINEST seq-110,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setDbUniqueNa
me dbUniqueName: orcl
[java] 2010-02-24T10:44:16.765+1100 UCP FINEST seq-111,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setHostName h
ostName: apemrac1
[java] 2010-02-24T10:44:16.765+1100 UCP FINEST seq-112,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setStatus sta
tus: down
[java] 2010-02-24T10:44:16.781+1100 UCP FINEST seq-113,thread-11 oracle.ucp.jdbc.oracle.OracleFailoverEventImpl.setReason rea
son: failure
[java] 2010-02-24T10:44:16.781+1100 UCP FINEST seq-114,thread-11 oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.handleFailov
erEvent failover event: Service name: HASERVICE.apemrac.au.oracle.com, Instance name: orcl1, Unique name: orcl, Host name: apemrac
1, Status: down, Cardinality: 0, Reason: failure, Event type: database/event/service
[java] 2010-02-24T10:44:16.796+1100 UCP FINEST seq-115,thread-11 oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.handleFailov
erEvent service name HASERVICE.apemrac.au.oracle.com in event does not match that in the pool: haservice.apemrac.au.oracle.com. No
FCF attempt.