What’s that Skippy ? Mike’s doing too much typing to Instrument his PL/SQL code ?

Australian readers will be pleased to note that, despite the Antipodean flavour of this post, there will be no mention of The Ashes. It is a well known fact that Kangaroos are not interested in cricket.

My brother used to run a motorcycling school. One of his teaching techniques, out on the road was to say things like “What’s that Skippy ? Mike’s left his indicator on after the turn ?”
This is in reference to Skippy the Bush Kangaroo – a children’s TV program about the adventures of the eponymous hero with and uncanny knack of communicating life-threatening situations to humans, simply by means of a few tongue-clicking sounds.
My son spent quite a bit of time with his Uncle Steve.
Uncle Steve had quite a bit of influence on said child.
As a result, I’d often be on the receiving end of the distilled wisdom of Skippy…
“What’s that Skippy ? Dad’s left his keys on the table ?”
“What’s that Skippy ? Dad’s left the eight-ball over the pocket ?”
“What’s that Skippy ? Pocket money should be going up in line with inflation ?”

Over the years, this began to seep into my internal monologue… “What’s that Skippy ? I’ve forgotten to close the cursor ?”
It is with thanks to “Uncle Steve” and the help of a know-it-all marsupial with a unique linguistic talent that I will be looking at logging in PL/SQL applications and ways of…well…doing less typing to achieve the same level of instrumentation.
Specifically, what we’ll cover is :

  • Why logging in PL/SQL is special
  • Logging error messages by magic
  • Using OWA_UTIL.WHO_CALLED_ME
  • Using PL/SCOPE to figure out where you are
  • An neater way to log runtime parameter values
  • A logging package that incorporates these techniques

The ultimate combination of all of these changes may well not be ideal in every situation.
However, Skippy has tried to reduce the instrumentation code required to and absolute minimum. After all, kangaroos don’t like typing.

Like most of the Oracle world, Skippy and myself are still on 11gR2.
The sunny uplands of 12c remain, for the moment, the province of messing about in VirtualBox.
Therefore, we won’t be covering any of the 12c utilities ( e.g. UTL_CALL_STACK) here.

What’s that Skippy ? Oh yes, if you are considering a replacement for your existing logging sub-system, or even planning one from scratch, then you might want to check out the OraOpenSource Logger.

The Logging Application

Typically, a PL/SQL logging application will consist of a table that looks something like this :

create table application_message_logs
(
    log_id number not null,
    log_ts timestamp not null,
    username varchar2(30) not null,
    session_id number not null,
    program_unit varchar2(30),
    sub_program varchar2(30),
    location number,
    message_type varchar2(1) not null,
    message varchar2(4000) not null
)
/

…complete with a sequence to generate the LOG_ID values…

create sequence aml_log_id_seq
/

NOTE – I’ve kept things relatively simple here. Of course, there may be instances where you want to log a message of more than 4000 characters ( maybe when debugging a dynamic SQL statement for example). For such eventualities you’d probably have an “overflow” column for a continuation of the message.

The logging package would probably resemble this :

create or replace package log_pkg
as

    --
    -- Set the logging level
    --
    -- E(rror) = just log error messages
    -- I(nfo) = log Error and Information messages
    -- D(ebug) = log everything
    
    g_log_level varchar2(1) := 'E';
    
    procedure write_pr
    (
        i_program_unit in application_message_logs.program_unit%type default null,
        i_sub_program in application_message_logs.sub_program%type default null,
        i_location in application_message_logs.location%type,
        i_message_type in application_message_logs.message_type%type,
        i_message in application_message_logs.message%type
    );
end log_pkg;
/

create or replace package body log_pkg
as

    function log_level_to_num_fn( i_level in varchar2)
        return pls_integer
    is
        --
        -- Private function to convert the log level or message type
        -- from a character to a number
        --
    begin
        return
        case i_level
            when 'E' then 1
            when 'I' then 2
            when 'D' then 3
        end;
    end log_level_to_num_fn;
    
    procedure write_pr
    (
        i_program_unit in application_message_logs.program_unit%type default null,
        i_sub_program in application_message_logs.sub_program%type default null,
        i_location in application_message_logs.location%type,
        i_message_type in application_message_logs.message_type%type,
        i_message in application_message_logs.message%type
    )
    is
    --
    -- Check the message_type against the current log level setting
    -- (g_log_level) and if, appropriate, write the message to the log table
    --
        pragma autonomous_transaction;
    begin
        if log_level_to_num_fn( nvl(i_message_type, 'E')) > log_level_to_num_fn( g_log_level)
        then
            --
            -- Nothing to do
            --
            return;
        end if;
        insert into application_message_logs
        (
            log_id, log_ts, username, session_id,
            program_unit, sub_program, location,
            message_type, message
        )
        values
        (
            aml_log_id_seq.nextval, systimestamp, user, sys_context('userenv', 'sessionid'),
            i_program_unit, i_sub_program, i_location,
            i_message_type, substr(i_message, 1, 4000)
        );
        commit;
    exception
        when others then
            rollback;
    end write_pr;

end log_pkg;
/

Once again, for the sake of simplicity, I’ve used package variable to control the logging level rather than something a bit more elaborate.

What’s that Skippy ? A programmer’s trapped in the Standards Document ?

Before we go any further, it’s worth stopping to consider this package.
As well as using an Autonomous Transaction, it also employs another much despised feature of PL/SQL – the WHEN-OTHERS exception without a re-raising of the error.

In other contexts, use of these features would be a sure-fire way of inviting the opprobrium of the QA department.
Here, however, both are entirely reasonable, not to say necessary.

If you’re adding a log record in a job that’s part way through a transaction, you definitely want to save the log record, without affecting that ongoing transaction. Indeed, even if that transaction is subsequently rolled back, you want to keep the log record.
Therefore, the autonomous transaction is, in this context, entirely appropriate.

The WHEN-OTHERS with no re-raise is probably a bit more contentious at first sight. However, consider that the package’s one procedure is used to log any messages, not simply errors.
Say, for the sake of argument that the logging table is on a different tablespace from your application tables.
There might be an occasion where an insert into this table would cause an error due to the tablespace being full.
Do you really want your batch data load to fail because there has been an unexpected error logging a message to say the job has started ?
If the answer is no, then such errors are by definition non-fatal. Therefore, the lack of a re-raise is sensible in this context.

It’s not just the code itself that is somewhat out of the ordinary when it comes to logging.
Consider the following code, in which the logging package is called.
Incidentally, this isn’t the actual algorithm used by the UK Met Office to produce a weather forecast…although sometimes I wonder…

create or replace package forecast_pkg
as
    procedure tomorrow_pr
    (
        i_forecast_date date,
        i_detail in varchar2,
        i_just_guess in boolean default true,
        o_forecast out varchar2
    );
end forecast_pkg;
/

create or replace package body forecast_pkg
as
    procedure tomorrow_pr
    (
        i_forecast_date date,
        i_detail in varchar2,
        i_just_guess in boolean default true,
        o_forecast out varchar2
    )
    is
        lc_proc_name constant application_message_logs.sub_program%type := 'TOMORROW_PR';
        l_params application_message_logs.message%type;
        l_loc pls_integer;
        l_forecast varchar2(10);
    begin
        -- record the fact that we're starting...
        log_pkg.write_pr
        (
            i_program_unit => $$plsql_unit, 
            i_sub_program => lc_proc_name, 
            i_location => $$plsql_line, 
            i_message_type => 'I', 
            i_message => 'Starting forecast for tomorrow'
        );
        -- ...and the parameter values we've been passed
        l_params := 'i_forecast_date = '||to_char(i_forecast_date, sys_context('userenv', 'nls_date_format'))||', '
            ||' i_detail = '||i_detail||', '
            ||' i_just_guess = '||case i_just_guess when true then 'TRUE' else 'FALSE' end;
        log_pkg.write_pr
        ( 
            i_program_unit => $$plsql_unit, 
            i_sub_program => lc_proc_name, 
            i_location => $$plsql_line, 
            i_message_type => 'I', 
            i_message => substr(l_params,1,4000)
        );
        l_loc := $$plsql_line;
        --
        -- Do some weather forecasting here... and throw in a debug message as well..
        --
        log_pkg.write_pr
        (
            i_program_unit => $$plsql_unit, 
            i_sub_program => lc_proc_name, 
            i_location => $$plsql_line, 
            i_message_type => 'D', 
            i_message => 'Running complicated algorithm to get forecast'
        );
        if floor( dbms_random.value(1,3)) = 1 then
            o_forecast := 'SUNNY';
        else
            o_forecast := 'SOGGY';
        end if;
        -- then...
        --
        log_pkg.write_pr
        (
            i_program_unit => $$plsql_unit, 
            i_sub_program => lc_proc_name, 
            i_location => $$plsql_line, 
            i_message_type => 'I', 
            i_message => 'Forecast completed outlook is '||o_forecast
        );
    exception when others then
        log_pkg.write_pr
        ( 
            i_program_unit => $$plsql_unit, 
            i_sub_program => lc_proc_name, 
            i_location => l_loc, 
            i_message_type => 'E', 
            i_message => sqlerrm||chr(10)||dbms_utility.format_error_backtrace
        );
        -- What's that Skippy ? Oh, yes...
        raise;
    end tomorrow_pr;
end forecast_pkg;
/

Aside from the fact that the input parameters are there purely for the purposes of demonstration, we have three distinct logging scenarios in this package :

  • Recording Parameter values
  • recording where we are in the procedure at various points
  • Logging an error from an exception handler

If we set the log level to Debug and run the procedure…

set serveroutput on size unlimited
declare
    l_forecast varchar2(100);
begin
    log_pkg.g_log_level := 'D';
    forecast_pkg.tomorrow_pr
    (
        i_forecast_date => to_date('12052015', 'DDMMYYYY'),
        i_detail => 'Some random value',
        i_just_guess => false,
        o_forecast => l_forecast
    );
    dbms_output.put_line('The forecast is '||l_forecast);
end;
/

The forecast is SOGGY

PL/SQL procedure successfully completed.

SQL> 

…we then get the following entries in our log table :

select program_unit, sub_program, location,
    message_type, message
from application_message_logs
order by log_id
/

PROGRAM_UNIT	SUB_PROGRAM	LOCATION MESSA MESSAGE
--------------- --------------- -------- ----- --------------------------------------------------------------------------------
FORECAST_PKG	TOMORROW_PR	      21 I     Starting forecast for tomorrow
FORECAST_PKG	TOMORROW_PR	      33 I     i_forecast_date = 12-MAY-15 i_detail = Some random value i_just_guess = FALSE
FORECAST_PKG	TOMORROW_PR	      45 D     Running complicated algorithm to get forecast
FORECAST_PKG	TOMORROW_PR	      60 I     Forecast completed outlook is SOGGY

Now, the coding standards being applied here include :

  • DATE and BOOLEAN IN parameter values must be explicitly converted to VARCHAR2 prior to logging
  • Calls to stored program units must pass parameters by reference (one parameter per line)
  • The naming convention is that packages are suffixed pkg and procedures suffixed pr

Whilst, of themselves, these standards are fairly reasonable, it does add up to an awful lot of typing to do some fairly standard instrumentation.
This in turn serves to make it that bit harder to spot the actual application code.

So, how can we make logging more readable and less of an overhead in terms of the amount of code required, whilst still capturing the same level of information ?

Well, for a start, we apply some common sense in lieu of standards.

To digress for a moment, I’m firmly of the opinion that standards documents should always contain a get-out-clause for situations such as this.

Firstly, we don’t really need those suffixes on the logging package and procedure names.
If you see a call to logs.write in a package, you can be reasonably sure that it’s a call to a packaged procedure that’s writing to a logging table. OK, it could be a type method, but either way, it’s clear what’s going on.
In case you’re wondering, log is a reserved word which is why I’m proposing to call the package logs.

The next thing we can do is to re-order the parameters to be better able to pass arguments by position rather than by reference.
We can do this by putting the optional parameters (i.e. those with default values) last.
We can also apply a reasonable default value for the message type.

Therefore, we could change our procedure’s signature to this :

procedure write
(
    i_message in message_logs.message%type
    i_location in message_logs.location%type,
    i_program_unit in message_logs.program_unit%type default null,
    i_sub_program in message_logs.sub_program%type default null,
    i_message_type in message_logs.message_level%type default 'E'
);

…which means that the call to it could be simplified (at minimum) to something like …

log.write( 'Logging a message', $$plsql_line);

It’s a start, I suppose. However, such a call isn’t going to result in a particularly useful log record. We wouldn’t know the program unit or the sub program name.
It would be good if we could get rid of the need for some of these parameters altogether but still be able to record the relevant information.

It would be even better if we could find a way not to have to type in the code to format the error stack in every exception handler in the application.

What’s that Skippy? Do I want to see a magic trick ?

Logging the Error Stack – the lazy way

Skippy’s knocked up a quick example :

create or replace procedure nothing_up_my_sleeves
as
begin
    dbms_output.put_line(sqlerrm||chr(10)||dbms_utility.format_error_backtrace);
end;
/

On the face of it, this doesn’t look that impressive. However, there’s more to SQLERRM and SQLCODE than meets the eye.

When we invoke this procedure…

set serveroutput on size unlimited
begin
    raise_application_error(-20000, q'[What's that Skippy ?]');
exception
    when others then
        nothing_up_my_sleeves;
        -- for demonstration purposes only - no raise here.
end;
/

ORA-20000: What's that Skippy ?
ORA-06512: at line 2



PL/SQL procedure successfully completed.

SQL> 

All of which means that, with the appropriate changes to the logging procedure, we could just use the following code in our exception handlers :

exception when some_error then
    logs.err;
    raise;

But hang on, that still won’t give us the name of the program or the location. How can we get this information without passing it in from the calling program ?

What’s that Skippy? Why don’t we use OWA_UTIL.WHO_CALLED_ME ?

OWA_UTIL.WHO_CALLED_ME provides information about the program unit from which the current program has been called. This includes both the name of the program unit and it’s current line number.
This procedure takes no in parameters and populates four out parameters :

  • owner – the owner of the calling program unit
  • name – the name of the calling program unit
  • lineno – the line number within the program unit where the call was made
  • caller_t – the type of program unit that made the call

To demonstrate :

create or replace function get_caller_fn
    return varchar2 
is
    l_owner varchar2(30);
    l_name varchar2(30);
    l_line number;
    l_type varchar2(30);
begin
    owa_util.who_called_me
    (
        owner => l_owner,
        name => l_name,
        lineno => l_line,
        caller_t => l_type
    );
    
    return 'Called from line '||l_line||' of a program of type '||l_type;
end;
/

If I now call this from an anonymous block…

set serveroutput on size unlimited
begin
    dbms_output.put_line(get_caller_fn);
end;
/

Called from line 2 of a program of type ANONYMOUS BLOCK

PL/SQL procedure successfully completed.

SQL> 

One point to bear in mind is that, when called from a package, the procedure passes the package name on the name out parameter, rather than the name of the package member. This is something we’ll come back to in a moment.

In the meantime, however, we can now eliminate the need for both the program name and the location parameters. The signature of the write procedure now looks like this :

procedure write
(
    i_message in message_logs.message%type
    i_sub_program in message_logs.sub_program%type default null,
    i_message_type in message_logs.message_level%type default 'E'
);

One thing to be aware of, this procedure will return details of where it was called from, irrespective of whether that’s another member of the current package. Therefore, the call to this needs to go in-line in our logs.write and logs.err procedures. This will enable us to capture the details of the program unit we’re logging from.

At this point, you may consider that the logging of the sub-program name is superfluous. After all, we know the line number from which the logging call originated so it should be simple enough to figure out which package member it came from.
To do this programmatically would no doubt require interrogation of the _SOURCE views, together with the application of some clever regular expressions.
On the other hand, you could avoid the top row of your keyboard…

PL/SCOPE

In case you are unfamiliar with it, PL/SCOPE is, to quote the documentation
“… a compiler driven tool that collects data about identifiers in PL/SQL source code at program-unit compilation time…”

In short, when you set the plscope_settings parameter appropriately and then compile a program unit, information about the program unit is written to the _IDENTIFIERS views.

Now, you may have heard that there were some issues with PL/SCOPE in 11.1.
It looks like 11GR2 doesn’t have this problem as the STANDARD and DBMS_STANDARD packages are compiled with PL/SCOPE enabled.
To verify this, run the following :

select distinct object_name, object_type
from dba_identifiers
where owner = 'SYS'
and object_name in ('STANDARD', 'DBMS_STANDARD');

OBJECT_NAME		       OBJECT_TYPE
------------------------------ -------------
DBMS_STANDARD		       PACKAGE
STANDARD		       PACKAGE

In any event, we do not need to touch these packages. For our present purposes, we’re only interested in our application code.
However, it’s probably worth reviewing the aforementioned documentation before deciding to enable PL/SCOPE across your entire database.

So, if we now enable PL/SCOPE in our current session…

alter session set plscope_settings = 'identifiers:all'
/

…and recompile our package…

alter package forecast_pkg compile
/
alter package forecast_pkg compile body
/

…we should now have some information about the package in USER_IDENTIFIERS…

select name, type, usage,
    line, usage_id, usage_context_id
from user_identifiers
where object_name = 'FORECAST_PKG'
and object_type = 'PACKAGE BODY'
and usage = 'DEFINITION'
order by line
/

NAME			       TYPE		  USAGE 	    LINE   USAGE_ID USAGE_CONTEXT_ID
------------------------------ ------------------ ----------- ---------- ---------- ----------------
FORECAST_PKG		       PACKAGE		  DEFINITION	       1	  1		   0
TOMORROW_PR		       PROCEDURE	  DEFINITION	       3	  2		   1

We can see from this that the FORECAST_PKG package body has a single top-level procedure.
We can tell that TOMORROW_PR is a top-level procedure because the usage_context_id is the same value as the usage_id for the package definition ( i.e. 1).
We can also see that the definition of this procedure begins on line 3 of the package body.
As we’ll already have a line number in the logging procedure, all we’ll need to do is to work backwards and find the last top-level definition prior to the call to the logging procedure. This query should do the trick :

with sub_progs as
(
    select name, line
    from user_identifiers
    where object_name = 'FORECAST_PKG'
    and object_type = 'PACKAGE BODY'
    and type in ('FUNCTION', 'PROCEDURE')
    and usage = 'DEFINITION'
    and usage_context_id = 1
)
select name 
from sub_progs
where line = (select max(line) from sub_progs where line < 17)
/

NAME
------------------------------
TOMORROW_PR

SQL> 

What’s that Skippy ? Oh, if you want to find out how much space is being taken up to store all of this additional metadata, you can run the following query :

select space_usage_kbytes 
from v$sysaux_occupants
where occupant_name = 'PL/SCOPE'
/

By setting aside our coding standards and getting Oracle to do more of the work, we’ve got almost all of the components we need to build our logging procedure with a more streamlined interface.
There is, however, one issue that we still need to address.

Logging parameter values

It is possible to find the parameters defined for a given program unit, or sub-program by means of the _ARGUMENTS views.
However, getting the runtime values of those parameters is something that’s only really practical from within the program unit being executed.
Additionally, given that we want to log the runtime parameter values as a string, we’re faced with the issue of conversion.
Implicit conversion from NUMBER to VARCHAR2 is probably not an issue in this instance. However, DATE and BOOLEAN values present something more of a challenge.

The aforementioned OraOpenSource Logger has an elegant approach to this problem and it’s from that, that I have taken my lead here.

The approach will be to have some overloaded procedures in the logging package which handle the various datatype conversions and then append the resulting string to the VARCHAR2 value passed in as an in-out parameter.
These can then be called from the program unit we’re logging from.
Once all of the parameters have been processed, the final string can be logged in the usual way.

It’s probably easier to see what I mean with a quick demo :

create or replace package convert_pkg
as
    -- Overload for varchar values
    procedure add_param
    (
        i_name in varchar2,
        i_value in varchar2,
        io_list in out varchar2
    );
    
    -- Overload for date values
    procedure add_param
    (
        i_name in varchar2,
        i_value in date,
        io_list in out varchar2
    );
    
    -- Overload for boolean values
    procedure add_param
    (
        i_name in varchar2,
        i_value in boolean,
        io_list in out varchar2
    );
end convert_pkg;
/

create or replace package body convert_pkg
as
    procedure add_param
    (
        i_name in varchar2,
        i_value in varchar2,
        io_list in out varchar2
    )
    is
    begin
        if io_list is not null then
            io_list := io_list||', ';
        end if;
        dbms_output.put_line('Varchar');
        io_list := io_list||' '||i_name||' => '||i_value;
    end add_param;
    
    procedure add_param
    (
        i_name in varchar2,
        i_value in date,
        io_list in out varchar2
    )
    is
    begin
        dbms_output.put_line('Date');
        if io_list is not null then
            io_list := io_list||', ';
        end if;
        io_list := io_list||' '||i_name||' => '
            ||to_char(i_value, sys_context('userenv', 'nls_date_format'));
    end add_param;
    
    procedure add_param
    (
        i_name in varchar2,
        i_value in boolean,
        io_list in out varchar2
    )
    is
    begin
        dbms_output.put_line('Boolean');
        if io_list is not null then
            io_list := io_list||', ';
        end if;
        io_list := io_list||' '||i_name||' => '
        ||case i_value when true then 'TRUE' when false then 'FALSE' end;
    end add_param;
end convert_pkg;
/

If we run the following script to test this :

set serveroutput on size unlimited
declare
    l_paramlist varchar2(4000);
begin
    convert_pkg.add_param( 'i_char_param', 'MIKE', l_paramlist);
    convert_pkg.add_param( 'i_date_param', sysdate, l_paramlist);
    convert_pkg.add_param( 'i_bool_param', true, l_paramlist);
    
    dbms_output.put_line(l_paramlist);
end;
/

Varchar
Date
Boolean
i_char_param => MIKE,  i_date_param => 14-AUG-15,  i_bool_param => TRUE

PL/SQL procedure successfully completed.


What’s that Skippy ? If you pass in a null value for the parameter, you will get an error :

set serveroutput on size unlimited
declare
    l_paramlist varchar2(4000);
begin
    convert_pkg.add_param( 'i_null_param', null, l_paramlist);

    dbms_output.put_line(l_paramlist);
end;
/

    convert_pkg.add_param( 'i_null_param', null, l_paramlist);
    *
ERROR at line 4:
ORA-06550: line 4, column 5:
PLS-00307: too many declarations of 'ADD_PARAM' match this call
ORA-06550: line 4, column 5:
PL/SQL: Statement ignored

As NULL is a valid value for a VARCHAR2, a DATE and a BOOLEAN, Oracle gets confused about which overload to use.

Therefore, you may want to weigh the convenience of this approach against the fact that you need to remember to handle potential null values in your parameters before logging them.

In our headlong rush to minimize typing in our application code, Skippy and I have decided to accept this responsibility. As a result we now have…

The new improved logging package

create or replace package logs
as
    --
    -- Set the logging level
    --
    -- E(rror) = just log error messages 
    -- I(nfo) = log Error and Information messages
    -- D(ebug) = log everything
    -- Note that we also have a message_type of P(arameter). 
    -- Messages of this type will be treated as being the same level as
    -- E(rror) - i.e. they will always be logged.
    
    g_log_level varchar2(1) := 'E'; 
    
    -- Parameter conversion procedures - overloaded for VARCHAR2, DATE and BOOLEAN
    procedure add_param
    (
        i_name in varchar2,
        i_value in varchar2,
        io_list in out varchar2
    );
    
    procedure add_param
    (
        i_name in varchar2,
        i_value in date,
        io_list in out varchar2
    );

    procedure add_param
    (
        i_name in varchar2,
        i_value in boolean,
        io_list in out varchar2
    );

    -- Mainly for P(arameter), I(nformation) and D(ebug) messages but also possible
    -- to log E(rror) messages if the message is something other than the error stack
    procedure write
    (
        i_message in application_message_logs.message%type,
        i_message_type in application_message_logs.message_type%type default 'E' 
    );
    
    -- Just log the error stack - i.e.
    -- sqlerrm||chr(10)||dbms_utility.format_error_backtrace
    procedure err;
end logs;
/

create or replace package body logs
as

    function log_level_to_num_fn( i_level in varchar2)
        return pls_integer
    is
    --
    -- Private function to convert the log level or message type
    -- from a character to a number
    --
    begin
        return
        case i_level
            when 'E' then 1
            when 'P' then 1
            when 'I' then 2
            when 'D' then 3
        end;
    end log_level_to_num_fn;

        
    procedure add_param
    (
        i_name in varchar2,
        i_value in varchar2,
        io_list in out varchar2
    )
    is
    -- Overload for VARCHAR2 parameter values
    begin
        if io_list is not null then
            io_list := io_list||' , ';
        end if;
        io_list := io_list||i_name||' => '||i_value;
    end add_param;
    
    procedure add_param
    (
        i_name in varchar2,
        i_value in date,
        io_list in out varchar2
    )
    is
    -- Overload for DATE parameter values
    begin
        if io_list is not null then
            io_list := io_list||' , ';
        end if;
        io_list := io_list||i_name||' => '
            ||to_char( i_value, sys_context( 'userenv', 'nls_date_format'));
    end add_param;
    
    procedure add_param
    (
        i_name in varchar2,
        i_value in boolean,
        io_list in out varchar2
    )
    is
    -- Overload for BOOLEAN parameter values
    begin
        if io_list is not null then
            io_list := io_list||' , ';
        end if;
        io_list := io_list||i_name||' => '||case when i_value then 'TRUE' else 'FALSE' end;
    end add_param;
    
    procedure process_log_pr
    (
        i_owner in varchar2,
        i_name in varchar2,
        i_type in varchar2,
        i_line in number,
        i_message in application_message_logs.message%type,
        i_message_type in application_message_logs.message_type%type
    )
    is
    --
    -- Private procedure to process the log record
    -- Called from the write and err procedures.
    --
    
        l_sub_program application_message_logs.sub_program%type;
        
        pragma autonomous_transaction;
    
    begin
    
        if i_type = 'PACKAGE BODY' then
            -- find the sub-program name
            -- Do this in a nested block just in case the package in question
            -- has not been compiled with PL/SCOPE enabled
            begin
                with sub_progs as
                (
                    select name, line
                    from dba_identifiers
                    where type in ('FUNCTION', 'PROCEDURE')
                    and usage = 'DEFINITION'
                    and usage_context_id = 1
                    and  owner = i_owner
                    and object_name = i_name
                    and object_type = i_type
                )
                select name
                into l_sub_program
                from sub_progs
                where line =
                (
                    select max(line)
                    from sub_progs
                    where line < i_line
                );
            exception 
                when no_data_found then
                    -- Calling package was not compiled with PL/SCOPE enabled
                    l_sub_program := null;
            end;
        end if;

        insert into application_message_logs
        (
            log_id, log_ts, username, session_id,
            program_unit, sub_program, location,
            message_type, message
        )
        values
        (
            aml_log_id_seq.nextval, systimestamp, user, sys_context('userenv', 'sessionid'),
            i_name, l_sub_program, i_line,
            i_message_type, substr( i_message, 1, 4000)
        );
        commit;
    exception 
        when others then
            rollback;
    end process_log_pr;



    procedure write
    (
        i_message in application_message_logs.message%type,
        i_message_type in application_message_logs.message_type%type default 'E'
    )
    is
        --
        -- Main procedure for general messages ( usually non-error).
        -- Check that the message is of a level that needs to be recorded based on
        -- the current g_log_level setting. If so, find out where the call originates
        -- from
        --
        
        l_owner varchar2(30);
        l_name varchar2(30);
        l_line number;
        l_type varchar2(30);
        
        l_sub_program application_message_logs.sub_program%type;
        
    begin

        if log_level_to_num_fn( nvl(i_message_type, 'E')) > log_level_to_num_fn( g_log_level)
        then
            -- Don't need to log this message at the current logging level
            return;
        end if;
        
        -- What's that Skippy ?
        -- This call needs to be in-line. If we move it to a function and call
        -- it from here, then it'll just return details of the current package ?
        owa_util.who_called_me
        (
            owner => l_owner,
            name => l_name,
            lineno => l_line,
            caller_t => l_type
        );
        
        process_log_pr
        (
            i_owner => l_owner,
            i_name => l_name,
            i_type => l_type,
            i_line => l_line,
            i_message_type => i_message_type,
            i_message => i_message
        );
    exception when others then
        -- If you're going to break a taboo, do it properly !
        null;
    end write;
    
    procedure err 
    is
    --
    -- Retrieve the error stack, get the details of the caller and
    -- then pass it for logging.
    --
        l_message application_message_logs.message%type;
        
        l_owner varchar2(30);
        l_name varchar2(30);
        l_line number;
        l_type varchar2(30);
        
        l_sub_program application_message_logs.sub_program%type;

    begin
        l_message := sqlerrm|| chr(10) ||dbms_utility.format_error_backtrace;
        
        -- As per Skippy - this call needs to be in-line (see write procedure above)
        owa_util.who_called_me
        (
            owner => l_owner,
            name => l_name,
            lineno => l_line,
            caller_t => l_type
        );

        process_log_pr
        (
            i_owner => l_owner,
            i_name => l_name,
            i_type => l_type,
            i_line => l_line,
            i_message_type => 'E',
            i_message => l_message
        );
    exception
        when others then
            -- And again, just in case QA aren't annoyed enough by this point
            null;
    end err;   
end logs;
/

Just a minute. That package looks quite a bit bigger than the one we started with.
On the plus side however, we’ve got all that code in one place.
As a result of this, our application code is somewhat less cluttered :

create or replace package body forecast_pkg
as
    procedure tomorrow_pr
    (
        i_forecast_date date,
        i_detail in varchar2,
        i_just_guess in boolean default true,
        o_forecast out varchar2
    )
    is
        l_params application_message_logs.message%type;

        l_forecast varchar2(10);
    begin
        -- Have randomly decided that all parameters need to be not null
        -- or the procedure will error.
        -- This is purely for cosmetic purposes...
        if i_forecast_date is null or i_detail is null or i_just_guess is null
        then
            raise_application_error( -20000, 'Missing mandatory parameters.');
        end if;
        -- record the fact that we're starting...
        logs.write('Starting forecast for tomorrow', 'I');
        
        -- ...and the parameter values we've been passed, which we now know, conveniently are not null
        
        logs.add_param('i_forecast_date', i_forecast_date, l_params);
        logs.add_param('i_detail', i_detail, l_params);
        logs.add_param('i_just_guess', i_just_guess, l_params);
        logs.write(l_params, 'P');
        --
        -- Do some weather forecasting here... and throw in a debug message as well..
        --
        logs.write('Running complicated algorithm to get forecast', 'D');
        if floor( dbms_random.value(1,3)) = 1 then
            o_forecast := 'SUNNY';
        else
            o_forecast := 'SOGGY';
        end if;
        -- then...
        --
        logs.write('Forecast completed outlook is '||o_forecast, 'I');
    exception when others then
        logs.err;
        raise;
    end tomorrow_pr;
end forecast_pkg;
/

If we run this now…

set serveroutput on size unlimited
declare
    l_forecast varchar2(100);
begin
    logs.g_log_level := 'D';
    forecast_pkg.tomorrow_pr
    (
        i_forecast_date => to_date('12052015', 'DDMMYYYY'),
        i_detail => 'Some random value',
        i_just_guess => false,
        o_forecast => l_forecast
    );
    dbms_output.put_line('The forecast is '||l_forecast);
end;
/

The forecast is SOGGY

PL/SQL procedure successfully completed.

SQL>

…we still get the same amount of information in the log table…

select program_unit, sub_program, location,
    message_type, message
from application_message_logs
order by log_id
/

PROGRAM_UNIT	SUB_PROGRAM	LOCATION MESSA MESSAGE
--------------- --------------- -------- ----- --------------------------------------------------------------------------------
FORECAST_PKG	TOMORROW_PR	      23 I     Starting forecast for tomorrow
FORECAST_PKG	TOMORROW_PR	      30 P     i_forecast_date => 12-MAY-15 , i_detail => Some random value , i_just_guess => FALSE
FORECAST_PKG	TOMORROW_PR	      34 D     Running complicated algorithm to get forecast
FORECAST_PKG	TOMORROW_PR	      42 I     Forecast completed outlook is SOGGY

SQL>

We can also record the error stack without having to physically enter it every time we call the logs package…

set serveroutput on size unlimited
declare
    l_forecast varchar2(100);
begin
    logs.g_log_level := 'D';
    forecast_pkg.tomorrow_pr
    (
        i_forecast_date => to_date('12052015', 'DDMMYYYY'),
        i_detail => 'Some random value',
        i_just_guess => null,
        o_forecast => l_forecast
    );
    dbms_output.put_line('The forecast is '||l_forecast);
end;
/

declare
*
ERROR at line 1:
ORA-20000: Missing mandatory parameters.
ORA-06512: at "MIKE.FORECAST_PKG", line 45
ORA-06512: at line 5

Sure enough, in the log table :

select program_unit, sub_program, location,
    message_type, message
from application_message_logs
order by log_id
/

PROGRAM_UNIT	SUB_PROGRAM	LOCATION MESSA MESSAGE
--------------- --------------- -------- ----- --------------------------------------------------------------------------------
FORECAST_PKG	TOMORROW_PR	      44 E     ORA-20000: Missing mandatory parameters.
					       ORA-06512: at "MIKE.FORECAST_PKG", line 20

Whilst you may well be skeptical about the abilities of a kangaroo in the matter of PL/SQL programming, there may be one or two techniques here that you’ll find useful.

Advertisements

2 thoughts on “What’s that Skippy ? Mike’s doing too much typing to Instrument his PL/SQL code ?

  1. Hi Mike.
    Really nice article on logging for Oracle and I’ve learned about Skippy, the kangaroo 😉
    I’ve seen many projects using quite old version of the open source common loggers you can find on the web. They do not utilise any of the nice features of oracle 9+ not to mention OWA_UTIL.WHO_CALLED_ME.
    Did you thought about placing your code on github?
    I see a great potential in the solution you’ve suggested though I’d do some things a bit different.
    If you would place your code on github or bitbucket I’d be interested in contributing.
    Cheers
    Jacek

    • Jacek,

      Thanks.
      I’m sure that you can find a number of ways to improve the code I’ve posted here 🙂
      Getting setup on GitHub is currently on my “To-do” list, but I’m not there yet.
      If you can drop me a mail at antikyte@gmail.com , I’d be happy to mail you the code.

      Mike

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s