Wednesday, November 21, 2007

Getting logging entering, exiting and throwing work at Oracle JVM

Java Logging package comes with JDK 1.4 and up so is included inside Oracle JVM.
Log4j package is a powerful and standard defacto package for logging, I am used it a lot for several year in my code inside Oracle JVM.
But, if you don't want to add another external dependency in your code and do not need powerful logging capabilities, you can use java.util.logging package which is already installed on 10g and 11g databases.
TestLog.sql is a simple test suite which uses logging console handler, the output log using SQLPlus is:
SQL> Hello world
Nov 21, 2007 9:11:23 AM my.LogTest main
SEVERE: main forced exception/ by zero

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.80

As you can see entering, exiting and throwing methods does not print messages and logger setLevel is defined to ALL. This is because logging level used by these methods are controlled by ConsoleHandler level.
To get these methods work copy logging.properties file from your JAVA_HOME/jre/lib to ORACLE_HOME/javavm/lib directory and edit the line which includes level property:
# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

Then shutdown and startup your Oracle database an re-test the code again, SQLPlus output will be:

SQL> exec Say('Hello world');
Dec 28, 2011 9:12:24 AM my.LogTest main
FINER: ENTRY Hello world
args[0]= Hello world
Dec 28, 2011 9:12:24 AM my.LogTest main
FINER: THROW
java.lang.ArithmeticException: / by zero
        at my.LogTest.main(LogTest:26)
Dec 28, 2011 9:12:24 AM my.LogTest main
FINER: RETURN 1

PL/SQL procedure successfully completed.



This solve the problem and you can go back to another level by changing your code at the static initializer block.
Remember that users who want to use Java Logging package requires dbms_java.grant_permission('SCOTT','SYS:java.util.logging.LoggingPermission', 'control', '' ); for example.

2 comments:

Anonymous said...

Your article is quite interesting and one of the best related to logging at Oracle JVM I have found in my searchs. I have read that you use log4j to log inside your java stored procedures. Could you explain the steps that must be taken to get it functioning? I am not able to get log4j writing to the file I have specified but only writing in the console. Thanks in advance

Marcelo Ochoa said...

Hi:
Actually to start using Log4J is quite simple :)
I am using it in several projects, such as DBPrism CMS.
In DBPrism CMS I have loaded Log4J library at SYS's schema using:
loadjava -r -s -g PUBLIC -u sys/pwd log4j-1.2.8.jar
Then if you need logging functionality at SCOTT you must to grant this OJVM permissions:
creta role LOGROLE;

begin
dbms_java.grant_permission( 'LOGROLE', 'SYS:java.lang.RuntimePermission', 'getClassLoader', '' );
dbms_java.grant_permission( 'LOGROLE', 'SYS:java.io.FilePermission', 'log/a.log', 'write' );
dbms_java.grant_permission( 'LOGROLE', 'SYS:java.io.FilePermission', 'log/b.log', 'write' );
end;
then grant LOGROLE to SCOTT.
Finally upload log4j.properties into SYS using:
loadjava -u sys/pwd -r -v -g PUBLIC log4j.properties
If you need per user log4j.properties functionality you can upload a different log4j.properties into each schema, but it will not work on 11g due changes into class loader functionality.
log4j.properties can be:
log4j.logger.mypkga=DEBUG, A
log4j.additivity.mypkga=false
log4j.logger.mypkgb=DEBUG, B
log4j.additivity.mypkgb=false

log4j.appender.A=org.apache.log4j.DailyRollingFileAppender
log4j.appender.A.File=log/a.log
log4j.appender.A.DatePattern='.'yyyy-MM-dd
log4j.appender.A.ImmediateFlush=true
log4j.appender.A.Append=true
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.layout.ConversionPattern=%d{MM-dd@HH:mm:ss} %-5p (%13F:%L) %3x - %m%n
log4j.appender.B=org.apache.log4j.DailyRollingFileAppender
log4j.appender.B.File=log/b.log
log4j.appender.B.DatePattern='.'yyyy-MM-dd
log4j.appender.B.ImmediateFlush=true
log4j.appender.B.Append=true
log4j.appender.B.layout=org.apache.log4j.PatternLayout
log4j.appender.B.layout.ConversionPattern=%d{MM-dd@HH:mm:ss} %-5p (%13F:%L) %3x - %m%n

Best regards, Marcelo.