| Author: | Tyler D. Muth | |
| Contributing Author: | Christopher Beck | |
| Last Updated: | 8/11/2011 | |
| Project Version: | 1.4.0 | |
| Related Products: | APEX, PL/SQL | |
| Supported DB Versions: | XE, 10.2, 11.1, 11.2. |
This is a PL/SQL logging and debugging framework. The goal of logger is to be as simple as possible to install and use. The primary use cases for this utility include:
grant connect,create view, create job, create table, create sequence,
create trigger, create procedure, create any context to existing_user
/
@logger_install.sql
@create_user.sql
@logger_install.sql
Once installed, logger is automatically set to DEBUG level. Run logger.status to view more details as discussed later in this document.
exec logger.log('hello world');
select text from logger_logs_5_min;That's it for the basic use of logger. This use-case will never change for this project as I don't want there to be a learning curve for a debugging utility.
All procedures in logger have a parameter named p_scope. The idea behind scope is to give some context to the log message, such as the application, package.procedure where it was called. Logger does capture the call stack, as well as module and action which are great for APEX logging as they are app number / page number. However, none of these options gives you a clean, consistent way to group messages. So, the p_scope parameter is really nothing special as it simply performs a lower() on the input and stores it in the scope column.
In the following example, I'm working on an application called "people". I will separate the components of scope with a simple dot. So, log / error message in this application will start with "people.".
exec logger.log('Some Text','people.people_api.refresh');
exec logger.log('Some Other Text','people.apex.page4.updateprocess');
exec logger.log('Some More Text','people.apex.app-process.ajax-get-details');
select id,text,scope from logger_logs where scope like 'people.%' order by id;
ID TEXT SCOPE
---- -------------------- ----------------------------------------
37 Some Text people.people_api.refresh
38 Some Other Text people.apex.page4.updateprocess
39 Some More Text people.apex.app-process.ajax-get-details
declare
x number;
begin
execute immediate 'select count(*) into x from foo1234';
exception when others then
logger.log_error('Intentional error');
raise;
end;
/
select * from logger_logs where logger_level = 2;
ID LOGGER_LEVEL TEXT CALL_STACK TIME_STAMP APP_SESSION MODULE ACTION USER_NAME UNIT_NAME LINE_NO COMMENTS SCN
-- ------------ -------- ---------- ------------------------ ------------ ------------- ------ ---------- ----------------- -------- --------- ---
2 2 ORA-0094 ORA-06512: 13-OCT-09 09.14.50.07 AM SQL Developer LOGGER INTENTIONAL ERROR 6
In this example, procedure test1 calls procedure test2 which in turn class test3. Test3 has a run-time error.
create or replace procedure test3 as
begin
execute immediate 'select count(*) into x from foo1234';
end test3;
/
create or replace procedure test2 as
begin
test3;
end;
/
create or replace procedure test1 as
begin
test2;
exception when others then
logger.log_error();
raise;
end;
/
exec test1;
SQL> select call_stack from logger_logs where id = 4;
CALL_STACK
-----------------------------------------
ORA-00942: table or view does not exist
ORA-06512: at "LOGGER.TEST3", line 5
ORA-06512: at "LOGGER.TEST2", line 5
ORA-06512: at "LOGGER.TEST1", line 4
declare
l_number number;
begin
logger.time_reset;
logger.time_start('foo');
logger.time_start('bar');
for i in 1..500000 loop
l_number := power(i,15);
l_number := sqrt(1333);
end loop; --i
logger.time_stop('bar');
for i in 1..500000 loop
l_number := power(i,15);
l_number := sqrt(1333);
end loop; --i
logger.time_stop('foo');
end;
/
select text from logger_logs_5_min;
TEXT
---------------------------------
START: foo
> START: bar
> STOP : bar - 1.000843 seconds
STOP : foo - 2.015953 seconds
begin
logger.log_permanent('This is a permanent message, good for upgrades and milstones.');
logger.log_warning('This is a warning message.');
logger.log_information('This is an informational message.');
logger.log('This is a debug message.');
end;
/
There are many occassions when the value of one of the USERENV session variables (Documentation: Overview, list of variables) is a big step in the right direction of finding a problem. A simple call to the logger.log_userenv procedure is all it takes to save them in the "EXTRA" column of logger_logs.
logger.log_userenv(
p_detail_level in varchar2 default 'USER',-- ALL, NLS, USER, INSTANCE
p_show_null in boolean default false,
p_scope in varchar2 default null)
SQL> exec logger.log_userenv('NLS');
SQL> select text,extra from logger_logs_5_min;
TEXT EXTRA
---------------------------------------------- -----------------------------------------------------------------
USERENV values stored in the EXTRA column NLS_CALENDAR : GREGORIAN
NLS_CURRENCY : $
NLS_DATE_FORMAT : DD-MON-RR
NLS_DATE_LANGUAGE : AMERICAN
NLS_SORT : BINARY
NLS_TERRITORY : AMERICA
LANG : US
LANGUAGE : AMERICAN_AMERICA.WE8MSWIN1252
SQL> exec logger.log_userenv('USER');
SQL> select text,extra from logger_logs_5_min;
TEXT EXTRA
-------------------------------------------------- -------------------------------------------------------
USERENV values stored in the EXTRA column CURRENT_SCHEMA : LOGGER
SESSION_USER : LOGGER
OS_USER : tmuth
IP_ADDRESS : 192.168.1.7
HOST : WORKGROUP\TMUTH-LAP
TERMINAL : TMUTH-LAP
AUTHENTICATED_IDENTITY : logger
AUTHENTICATION_METHOD : PASSWORD
SQL> exec logger.log_cgi_env; select extra from logger_logs where text like '%CGI%'; TEXT EXTRA -------------------------------------------------- ------------------------------------------------------- ... SERVER_SOFTWARE : Oracle-Application-Server-10g/10.1.3.1.0 Oracle-HTTP-Server GATEWAY_INTERFACE : CGI/1.1 SERVER_PORT : 80 SERVER_NAME : 11g REQUEST_METHOD : POST PATH_INFO : /wwv_flow.show SCRIPT_NAME : /pls/apex REMOTE_ADDR : 192.168.1.7 ...
Have you ever run into an issue with a string that contains control characters such as carriage returns, line feeds and tabs that are difficult to debug? The sql dump() function is great for this, but the output is a bit hard to read as it outputs the character codes for each character, so you end up comparing the character code to an ascii table to figure out what it is. The function get_character_codes and the procedure log_character_codes make it much easier as they line up the characters in the original string under the coorisponding character codes from dump. Additionally, all tabs are replaced with "^" and all other control characters such as carriage returns and line feeds are replaced with "~".
SQL> exec logger.log_character_codes('Hello World'||chr(9)||'Foo'||chr(13)||chr(10)||'Bar');
SQL> select extra from logger_logs_5_min;
EXTRA
----------------------------------------------------------------------------------
Common Codes: 13=Line Feed, 10=Carriage Return, 32=Space, 9=Tab
72,101,108,108,111, 32, 87,111,114,108,100, 9, 70,111,111, 13, 10, 66, 97,114
H, e, l, l, o, , W, o, r, l, d, ^, F, o, o, ~, ~, B, a, r
This feature is useful in debugging issues in an APEX application that are related session state. The developers toolbar in APEX provides a place to view session state, but it won't tell you the value of items midway through page rendering or right before and after an AJAX call to an application process.
Before using this feature it's important to note that it must be configured first. The next section discusses this configuration.
-- in an on-submit page process
begin
logger.log_apex_items('Debug Edit Customer');
end;
select id,logger_level,text,module,action,client_identifier from logger_logs where logger_level = 128;
ID LOGGER_LEVEL TEXT MODULE ACTION CLIENT_IDENTIFIER
------- ------------ -------------------- ---------------------- --------- --------------------
47 128 Debug Edit Customer APEX:APPLICATION 100 PAGE 7 ADMIN:45588554040361
select * from logger_logs_apex_items where log_id = 47; --log_id relates to logger_logs.id
ID LOG_ID APP_SESSION ITEM_NAME ITEM_VALUE
------- ------- ---------------- ------------------------- ---------------------------------------------
136 47 45588554040361 P1_QUOTA
137 47 45588554040361 P1_TOTAL_SALES
138 47 45588554040361 P6_PRODUCT_NAME 3.2 GHz Desktop PC
139 47 45588554040361 P6_PRODUCT_DESCRIPTION All the options, this machine is loaded!
140 47 45588554040361 P6_CATEGORY Computer
141 47 45588554040361 P6_PRODUCT_AVAIL Y
142 47 45588554040361 P6_LIST_PRICE 1200
143 47 45588554040361 P6_PRODUCT_IMAGE
144 47 45588554040361 P4_CALENDAR_DATE 20091103
145 47 45588554040361 P7_CUSTOMER_ID 6
146 47 45588554040361 P7_BRANCH 2
147 47 45588554040361 P29_ORDER_ID_NEXT
148 47 45588554040361 P29_ORDER_ID_PREV
149 47 45588554040361 P29_ORDER_ID_COUNT 0 of 0
150 47 45588554040361 P7_CUST_FIRST_NAME Albert
151 47 45588554040361 P7_CUST_LAST_NAME Lambert
152 47 45588554040361 P7_CUST_STREET_ADDRESS1 10701 Lambert International Blvd.
153 47 45588554040361 P7_CUST_STREET_ADDRESS2
154 47 45588554040361 P7_CUST_CITY St. Louis
155 47 45588554040361 P7_CUST_STATE MO
156 47 45588554040361 P7_CUST_POSTAL_CODE 63145
157 47 45588554040361 P7_CUST_EMAIL
158 47 45588554040361 P7_PHONE_NUMBER1 314-555-4022
159 47 45588554040361 P7_PHONE_NUMBER2
160 47 45588554040361 P7_CREDIT_LIMIT 1000
161 47 45588554040361 P6_PRODUCT_ID 1
162 47 45588554040361 P29_ORDER_ID 9
To enable logging:
exec logger.set_level('DEBUG');
To disable logging:
exec logger.set_level('OFF');
Instead of disabling all logging, setting the level to "ERROR" might be a better approach:
exec logger.set_level('ERROR');
Also take a look at the NO-OP section later in this document.
To view the status of the logger:
logger@11g> exec logger.status; Project Home Page : https://logger.samplecode.oracle.com/ Logger Version : 1.1 Debug : Enabled APEX Tracing : Enabled SCN Capture : Enabled Min. Purge Level : g_debug Purge Older Than : 7 PL/SQL procedure successfully completed.
| Flashback | To enable this option, grant execute on dbms_flashback to
the user that owns the logger packages. Every insert into
logger_logs will include the SCN (System Commit Number).
This allows you to flashback a session to the time when the
error occured to help debug it or even undo any data
corruption. As SYS from sql*plus: grant execute on dbms_flashback to logger; |
| APEX | This option allows you to call logger.log_apex_items which
grabs the names and values of all APEX items from the
current session and stores them in the
logger_logs_apex_items table. This is extremely useful in
debugging APEX issues. This option is enabled automatcially
by logger_configure if APEX is installed in the database. |
Once you perform the previously described steps for the Flashback or APEX option, simply run the logger_configure procedure, then run logger.status to check validate your changes.
exec logger_configure; exec logger.status;
To make sure there is no fear of leaving debug statements in production code, logger comes with a NO-OP (No Operation) installation file (logger_no_op.sql). This installs only the a shell of the logger package. All procedures are essentially NO-OPs. It does not even create the tables so there is absolutely no chance it is doing any logging. Personally, I would leave the full version installed and simply dial-down the level to "ERROR" as the performance hit is exceptionally small.
By default, the DBMS_SCHEDULER job "LOGGER_PURGE_JOB" runs every night at 1:00am and deletes any logs older than 7 days that are of error level g_debug or higher which includes g_debug and g_timing. This means logs with any lower level such as g_error or g_permanent will never be purged. You can also manually purge all logs using logger.purge_all, but this will not delete logs of error level g_permanent.
The following database objects are installed with logger:
OBJECT_TYPE OBJECT_NAME
------------------- ------------------------------
JOB LOGGER_PURGE_JOB
PACKAGE LOGGER
PROCEDURE LOGGER_CONFIGURE
SEQUENCE LOGGER_APX_ITEMS_SEQ
LOGGER_LOGS_SEQ
TABLE LOGGER_LOGS
LOGGER_LOGS_APEX_ITEMS
LOGGER_PREFS
VIEW LOGGER_LOGS_5_MIN
LOGGER_LOGS_60_MIN
LOGGER_LOGS_TERSE
LOGGER_GLOBAL_CTX CONTEXT -- Global Application Contexts are owned by SYS
Simply run @drop_logger.sql as the logger user.
g_permanent constant number := 1; g_error constant number := 2; g_warning constant number := 4; g_information constant number := 8; g_debug constant number := 16; -- Any level > debug (16) is enabled when the LEVEL is set to DEBUG, but you cannot explicitly set the LEVEL to say TIMING. -- The additional levels are there for reporting purposes only. g_timing constant number := 32; g_sys_context constant number := 64; g_apex constant number := 128;