How to Capture Oracle JDBC PL/SQL Function Call's Parameter Values in WebSphere 7

Question

We are placing PL/SQL function calls via Oracle JDBC driver (11.2) (using Spring JDBCTemplate* framework), and we have set com.ibm.ws.rsadapter.jdbc.*=all in WebSphere server's logging details (Runtime), but the captured data in the trace.log file does not contain the actual translated PL/SQL function call nor the values of the parameters being passed to the function.

How can I achieve this logging detail? We are using SLF4j library for logging as well.

Answer 1

The following solution works regardless of what logging framework you have deployed for your application, i.e. Log4j, java.util.logging, SLF4j, etc.:

1. Obtain a corresponding Oracle JDBC driver that has been compiled with tracing code enabled (ending with "_g.jar"). As long as the Oracle JDBC driver's major version matches the underlying database's, it's best to get the latest minor version (in our case, 11.2.0.4.0) as it outputs additional information for each call.

   The latest diagnostic driver is going to be compatible with the older versions of your Oracle database. You can obtain them from Oracle's website here.

2. If you have used a WebSphere variable (i.e. Oracle JDBC Driver) to specify the location of Oracle JDBC driver, place the diagnostic JDBC driver in the same folder as the regular driver (for ease of tracking). Nonetheless, you can place it anywhere on the file system.

3. Make sure the WebSphere user that starts up the server has proper file system permission to access the driver, i.e. ojdbc6_g.jar.

4. From WebSphere Admin Console, change the JDBC provider to point to the new driver:

   • Expand Resources
   • Expand JDBC
   • Select JDBC providers
   • Select "Oracle JDBC Driver" (or whatever Java Database Connectivity provider has been named on the server)
   • Alter the "Class path" from "${ORACLE_JDBC_DRIVER_PATH}/ojdbc6.jar" to "${ORACLE_JDBC_DRIVER_PATH}/ojdbc6_g.jar"
   • Click Apply

5. To set the trace logging level:

   • Expand Servers
   • Expand Server Types
   • Click WebSphere application servers
   • Select the target server
   • Scroll down to "Troubleshooting" sub-section
   • Select "Change Log Detail Levels"
   • Switch to Runtime tab
   • Change the Components from "*=info" to "*=info: oracle.jdbc.*=all" (without double quotations)
   • Click Apply
   • Note the logging level can be altered at runtime, i.e. rather than "all", you can supply "fine", "finer", or "finest". The list of what each logging level entails to is here.

6. Locate the server logging folder:

   • Repeat 5a to 5e
   • Select "Logging and tracing"
   • Select "Diagnostic Trace"
   • Under "General Properties/Trace Output" section, File Name should provide the name of the trace file (the default is ${SERVER_LOG_ROOT}/trace.log). Note that the trace log file could be in rolling/rotating mode based on size or date

7. Restart the WebSphere server

8. Execute a code that invokes a PL/SQL function call

9. WebSphere should capture all the detail JDBC calls in trace.log file now, i.e. calling schema_user.plsql_package.procedure() with three parameters and values of parameter 1, parameter 2, and parameter 3, would result in ({call ...} is how I'm calling stored procedures from Spring's JdbcTemplate*, but you can see how at the low level, Oracle driver translates it into a PL/SQL anonymous block call):

...

[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Enter: 1, "parameter 1", 2
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Public Enter: 1, "parameter 1"
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 1, "parameter 1", 2
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 1, "parameter 1", 2, 0
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 1, "parameter 1", 2, 0
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 1, oracle.sql.NUMBER@42764276
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.0409ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.1926ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.2515ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.3107ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Exit [0.4817ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Exit [0.5556ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Enter: 2, "parameter 2"
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Public Enter: 2, "parameter 2"
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 2, "parameter 2"
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 2, "parameter 2"
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.0049ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.0691ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Exit [0.1276ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Exit [0.2008ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Enter: 3, "parameter 3"
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Public Enter: 3, "parameter 3"
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 3, "parameter 3"
[1/20/15 10:22:14:431 EDT] 00000020 driver        2   263D263D Enter: 3, "parameter 3"
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.0036ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        <   263D263D Exit [0.0549ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        1   263D263D Exit [0.1094ms]
[1/20/15 10:22:14:431 EDT] 00000020 driver        Z   263D263D Exit [0.161ms]

...

[1/20/15 10:22:14:433 EDT] 00000020 driver        2   32B732B7 Enter: "

{call schema_user.plsql_package.procedure(
param_1 => :param_1,
param_2 => :param_2,
param_3 => :param_3)}"

...

[1/20/15 10:22:14:434 EDT] 00000020 driver        2   32B732B7 Return: 

BEGIN schema_user.plsql_package.procedure(
param_1 => :param_1,
param_2 => :param_2,
param_3 => :param_3); END;

...

The Oracle JDBC driver does perform caching of stored procedure calls made by the applications. Consequently, after the first invocation, the log file does not capture all the needed information that it does on the first try -- the scope of captured information is not going to be as comprehensive as the first invocation. Moreover, the trace logging is detailed enough that can make the parsing the interested sections unwieldy.

Therefore, in order to purge the cached stored procedure calls by the driver after the first invocation, follow the instructions below:

1. Log-in to WebSphere Admin Console (Integrated Solutions Console)

2. Navigate to Resources -> JDBC -> Data sources

3. Check an appropriate data source box which handles procedure calls, if any different

4. Click the "Manage state..." button on the top of the grid table

5. On "JCA lifecycle management" page, check box the same resource

6. Click the "Purge" button

Also, if you are running/testing your WebSphere in the Windows environment, you can use SnakeTail tool to tail (like Unix/Linux systems) trace.log file (quite fast and responsive with large buffer size).