Skippy – Lazy Logging for Lazy PL/SQL Devs

What’s that Skippy ? Mike’s finally gotten round to publishing that logging framework ?
Yes, it’s only taken around seven years but I’ve finally managed to put together a coherent version of the PL/SQL logger I described in this post.

Yes, Skippy has now bounded into view on Github.

Skippy is fairly lightweight, the core components consisting of one package, one view and three tables.
It’s also designed for people like me, who just don’t want to be bothered with using a variable to hold the name of the current package member and remembering to include it in every single logging statement.
Skippy does that for you, and a bit more besides.

What I’ll cover here is :

• installing Skippy
• using Skippy in your PL/SQL code
• options for configuriation
• running the unit tests
• some notes on it’s behaviour in 11g
• The SQLDeveloper Reports

Right, let’s hop to it…

Installation

Skippy has been tested against multiple Oracle Database versions and works on everything from 11gR2 onwards. So, provided your Oracle version falls into this very broad range, you’re good to go.

In terms of database privileges and grants you need the following system privileges…

• create table
• create view
• create package
• create sequence

…execute permissions on these packages ( granted to PUBLIC by default )…

• DBMS_DB_VERSION
• OWA_UTIL
• DBMS_DEBUG_JDWP

…and a quota on the schema’s default tablespace.

Now you can head over to Github and grab a copy of the Skippy Repo.

Once it’s on your machine, navigate to the top-level directory.
You can then connect to the database as the schema you want to install into and run :

install.sql

The script output should be similar to the following ( as they say in the phone ads, some sequences have been shortened) :

SQL> @install.sql
Installing the Skippy Logging framework :

Creating Tables...


Table created.


Comment created.


Comment created.

***snip***

Creating Reference Data...


1 row created.


1 row created.

*** snip ***

Commit complete.

Creating Package


Package created.

Package body created.
Creating Views


View created.

You should now have some new objects in the schema :

select object_name, object_type
from user_objects
where object_name like 'SKIPPY%'
order by 2,1
/

OBJECT_NAME                    OBJECT_TYPE            
------------------------------ -----------------------
SKIPPY_LOGS_PK                 INDEX                  
SKIPPY_MESSAGE_TYPES_PK        INDEX                  
SKIPPY_USERENV_PARAMETERS_PK   INDEX                  
SKIPPY                         PACKAGE                
SKIPPY                         PACKAGE BODY           
SKIPPY_LOGS_ID_SEQ             SEQUENCE               
SKIPPY_LOGS                    TABLE                  
SKIPPY_MESSAGE_TYPES           TABLE                  
SKIPPY_USERENV_PARAMETERS      TABLE                  
SKIPPY_ENV                     VIEW                   

10 rows selected. 

Now it’s installed, we can start playing with our logging framework.

Using Skippy

The examples that follow are taken from the demo package which is included in the demo folder in the repo.

The source for this package is :

Simply calling skippy with a message like this…

skippy.log('Morning everyone !');

…will result in quite a bit of message meta-data being logged…

Whilst Skippy will accept explicit values for the message source and line number, it’s smart enough to work these out if you don’t provide them.

That’s not all.

Capturing Parameter Values

To record a list of parameter values, you can use the ADD_PARAM procedure to build the list. Once the list is complete, it can be logged in the normal way.
Parameters of type VARCHAR2, DATE, NUMBER and BOOLEAN are supported :

Grouping Messages

You can assign messages to a group. This can be useful if you are running a batch process which invloves calls to a number of database objects.

You can either assign a message to a group explicitly…

…or you can set the group at session level, after which all logs will be assigned to the group…

Logging Level

Skippy supports four logging levels out-of-the-box :

• E(rror)
• W(arning)
• I(nformation)
• D(ebug)
• A(ll) – the default

You can set the logging level for a session.

For example, if you only want Warning and Error messages recorded :

You can turn off logging altogether in the current session by running :

You can configure logging levels by editing/adding them in the SKIPPY_MESSAGE_TYPES table.

USERENV Parameters

Do you want to log the SYS_CONTEXT userenv parameter settings ? Can’t remember what they all are ? Don’t worry, Skippy knows…

All sys_context userenv parameters with not null values in the session are logged.

Incidentally, after many years of being unable to find exactly where Oracle keep the userenv parameter settings in the data dictionary, I’ve made my own list by combing through the various release notes since 11gR2 and putting them into the SKIPPY_USERENV_PARAMETERS.
If you want to see you’re current settings in one place, you can use the SKIPPY_ENV view :

Capturing the Error Stack

To log the current error stack :

Note that this is less useful in versions after 11gR2 as the error stack is much better at reporting the location at which the error occured, as opposed to where it was raised.

Show current settings

To see the message group that’s currently set in the session :

For the current logging level :

Design Decisions

In writing Skippy, I’ve adopted attempted to ensure that :

• it’s lightweight and simple to install
• it does not use any features which may require additional licensing ( e.g. partitioning)
• it can to run on 11gR2
• the database objects are easily identifiable (hence the SKIPPY_ prefix)

As I have no way of anticipating the data volumes, performance requirements, archiving requirements etc that may be required I have left these matters open for the user to customize as they see fit.

I have steered away from using a CLOB to store the message text in SKIPPY_LOGS because the number of log messages that would exceed the size of a standard VARCHAR2 (currently 4000) is likely to be relatively small.
Using a VARCHAR2 means that we’ll never have to worry about out-of-line storage of messages with the potential administrative and performance overheads that may bring.

Some Edge Cases where behaviour differs in 11g

Skippy uses the Oracle supplied OWA_UTIL package to determine the source of the log message.
This involves OWA_UTIL.WHO_CALLED_ME parsing the call stack ( i.e. the output from DBMS_UTILITY.FORMAT_CALL_STACK) to determine this information.
In 11g, the call stack only holds the name of the top level calling object ( e.g. a package name).
In later versions it holds the package_name.package_member.
This limitation means that, in 11g, Skippy uses ALL_IDENTIFIERS to derive the name of a package member where required. This approach throws up a couple of differences in terms of reporting the LOG_SOURCE.

Firstly, if you’re logging from a function/procedure that’s local to a package member itself, Skippy will report the name of the nested program unit.
In 12c and later, the name of the outer package member will be reported.

For example :

If we run the above in 11g, the log_source is reported as ROO.POUCH.

In later versions, it is more accurately identified as ROO.DOE.POUCH

Note that the correct line number is returned in both instances.
We’d need to provide some override values to make 11g behave consistently with later releases. For example :

Another situation where you may experience different behaviour between Oracle versions is where you have a block in the main package body :

In releases after 11g, the log_source is reported as KANGAROOS.__pkg_init

However, in 11g, the framework just picks up the previous procedure in the package.

Once again, we could use override values to correct this.

An alternative workaround would be to add an empty private procedure to the package :

Unit Tests

There are 24 unit tests in the repository, written using the utPLSQL 3.x test framework.
If you’re so inclined ( and have the framework installed), you can run the tests by connecting via your favourite Oracle tool and running :

run_all_tests.sql

Here’s the output for a test execution on an Oracle 21c instance :

Running Full Test Suite on Oracle Database Version 21.0.0.0.0
skippy_ut
  skippy_log
    default message [.088 sec]
    non-default valid message level [.005 sec]
    message group [.005 sec]
    override source [.004 sec]
    override_line_no [.004 sec]
    long_message [.01 sec]
    logging_disabled [.004 sec]
  skippy_group
    set group [.006 sec]
    unset group [.004 sec]
    log group [.007 sec]
    log no group [.005 sec]
  skippy_err
    exception_block [.009 sec]
    specify_group [.006 sec]
  skippy_env
    environment variables [.019 sec]
    override message type [.007 sec]
    specify message group [.007 sec]
  skippy_current_settings
    Get Current Log Level [.008 sec]
    Get current Message Group when set [.003 sec]
    Get current Message Group when not set [.003 sec]
  skippy_params
    add varchar param [.004 sec]
    add number param [.003 sec]
    add date param [.003 sec]
    add boolean param [.004 sec]
    build param string [.003 sec]
 
Finished in .250975 seconds
24 tests, 0 failed, 0 errored, 0 disabled, 0 warning(s)
 


PL/SQL procedure successfully completed.

Reports

For anyone using SQLDeveloper, I’ve included a suite of User Defined reports to play with :

• Log entries for last n hours
• Message group log entries with intervals
• Tail Log Table ( log entries are ordered by timestamp, latest first)

The message group report, for example, accepts two parameters :

• Log Date ( defaults to today)
• Message Group

After running the demo package, the report might look like this :

Acknowledgements

I’d like to say a particular thank-you to Jacek Gebal, who first suggested I publish this code to Github.

What’s that Skippy ? Don’t forget Uncle Steve – daredevil and corrupter of youth ?
How could I.
Finally, thanks to the youth in question, my favourite (only) son, Michael. It’s taken so long to put this all together that he’s now a grown-up IT Professional in his own right and the current de facto first line support for all family printer problems !