Logger 2.0.0 - Session Specific Logging - Advanced Features

In preparation for the release of Logger 2.0.0 I've decided to write a few posts highlighting some of the new features. 

In my previous post I covered how to set and unset session specific logging based on the Client Identifier. In this post I'll cover some advanced options for this functionality. Before continuing, please be sure to read the previous post or else this won't make sense.

In the previous post the demo code to set a session specific logging level only used two parameters: the logging level and the Client Identifier. In logger.set_level they're actually four parameters:

p_level

This is the level to set. If p_client_id is null then it will set the system level configuration in logger_prefs > LEVEL.


The additional parameters are only valid if p_client_id is defined.

p_client_id

If not null, will apply p_level for the specific client_id only. If null then p_level will be applied for the system level configuration.

p_include_call_stack

Determines if the call stack should be stored. If null then will use the default setting in logger_prefs > INCLUDE_CALL_STACK. Valid values are TRUE and FALSE (strings).

p_client_id_expire_hours

Will end session specific logging after set hours. If not defined then the default setting will be used logger_prefs > PREF_BY_CLIENT_ID_EXPIRE_HOURS. Note that this will not be exact as a job is run hourly to clean up expired session specific logging that has expired for a given client_id. Instead of waiting for the job to clean up expired sessions you can explicitly unset them.


How to View All Client_id Settings

To view the system level settings you can use the logger.status procedure. There was debate as to whether or not we include all the client_id settings in this procedure. In the end we did not include it list them in this procedure as the list may get very long. To view all the session specific logging configurations use the following query:

select *
from logger_prefs_by_client_id;

Renewing

When calling logger.set_level with a client_id that already exists in logger_prefs_by_client_id it will update the values and update the expiry date (i.e. you extend the setting).

Logger 2.0.0 - Enable Session Specific Logging

In preparation for the release of Logger 2.0.0 I've decided to write a few posts highlighting some of the new features.

One of the most common feature request for Logger has been the ability to enable logging (or setting the logger level) for a given session. This post covers how to set and unset session specific logging.

Logger Levels

There is no "on/off" switch for Logger. Instead, like most other logging and code instrumentation tools, it supports multiple levels. This allows developers to turn up and down the amount of logging. In most development systems the logging level is set to debug mode and in most production instances it's set to error mode. This means that in production only items that are explicitly logged using logger.log_error will be stored. For more information read the configuration section of the documentation.

Setting the Logger Level

Prior to Logger 2.0.0 you could only configure the logging level for the entire schema. To following code snippet highlights this:

exec logger.set_level('DEBUG');

begin
  -- All of these will be logged
  logger.log('Logging log level');
  logger.log_information('Logging information level');
  logger.log_warning('Logging warning level');
  logger.log_error('Logging error level');
end;
/

exec logger.set_level('WARNING');

begin
  logger.log('Logging log level'); -- Not stored
  logger.log_information('Logging information level'); -- Not stored
  logger.log_warning('Logging warning level'); -- Stored
  logger.log_error('Logging error level'); -- Stored
end;
/

What happens in production systems when a user is experiencing some issues and you want to see all their logging information? The only way to do this before was to set the logging level to debug mode and the entire schema would be affected. This could slow down all the applications in the schema which is an undesired affect.

Setting by Session
 
The term "session" is a bit misleading. Since more most Oracle applications are stateless it's not realistic to enable logging for a specific Oracle session (SID). Instead Logger uses the client_identifier (also referred to as client_id). Client identifiers can easily be configured and are commonly used in stateless applications. For example, APEX sets the client_id with: :APP_USER || ':' || :APP_SESSION

The following example demonstrates how to enable "session" specific logging in Logger:

-- Connection 1
exec logger.set_level ('ERROR');

begin
  logger.log('will not get stored');
  logger.log_error('will get stored');
end;
/

select id, logger_level, text, client_identifier
from logger_logs_5_min;

  ID LOGGER_LEVEL TEXT                 CLIENT_IDENTIFIER
---- ------------ -------------------- --------------------
  13            2 will get stored      


-- Connection 2 (i.e a different connection)
exec dbms_session.set_identifier('logger_demo');

exec logger.set_level('DEBUG', sys_context('userenv','client_identifier'));
-- Or could have used: logger.set_level('DEBUG', 'logger_demo');

begin
  logger.log('will get stored');
  logger.log_error('will get stored');
end;
/

select id, logger_level, text, client_identifier
from logger_logs_5_min;

  ID LOGGER_LEVEL TEXT                 CLIENT_IDENTIFIER
---- ------------ -------------------- --------------------
  14           16 will get stored      logger_demo
  15            2 will get stored      logger_demo

Unsettting by Session

When setting a session specific logging level, Logger will apply an expiration time to it. By default  this is set to 12 hours but can be configured by setting the logger_prefs value:  PREF_BY_CLIENT_ID_EXPIRE_HOURS  You can also pass in the time using the parameter p_client_id_expire_hours. If you don't explicitly unset a specific session then logger will automatically clean up these sessions after the desired time.

They're three ways to explicitly unset session specific logging:

-- Unset by specific client_id
exec logger.unset_client_level(p_client_id => 'logger_demo');

-- Unset all sessions that have expired
exec logger.unset_client_level;

-- Unset all sessions (regardless of expiration time)
exec logger.unset_client_level_all

Summary

By setting session specific logging you can allow for an individual connection to have logging enabled without affecting the rest of the applications in the schema.

They're some other interesting features in session specific logging that I wasn't able to fit this article. In the next article I'll discuss these features.
 

Logger 2.0.0 - Logging Parameters

In preparation for the release of Logger 2.0.0 I've decided to write a few posts highlighting some of the new features. 

After using Logger for several years one thing I found that I was doing over and over again is logging the parameters to functions and parameters. The beginning of a procedure usually looked like this:

procedure my_proc(
  p_empno in number,
  p_hiredate in date,
  p_boolean in boolean) -- not really relevant for proc, but good for demo
as
  l_scope logger_logs.scope%type := 'my_proc';
begin
  logger.log('START', l_scope);
  logger.log('p_empno: ' || to_char(p_empno), l_scope);
  logger.log('p_hiredate: ' || to_char(p_hiredate, 'DD-MON-YYYY HH24:MI:SS'), l_scope);
  logger.log('p_boolean: ' || case when p_boolean then 'TRUE' else 'FALSE' end, l_scope);
  
  ...
  
end my_proc;  

When you have data types that aren't strings the conversion process can become a bit tedious especially if you have to log a lot of parameters. Of course snippets can help reduce some of the time but it was still annoying.

Another issue that I found was that developers would use their own formatting for logging parameters. Some would include a dash instead of a colon, some would include spaces and others wouldn't, etc. Eventually it became difficult to read the logs with all the different formatting.

To get around these issues Logger now takes in a parameter, p_params, which is an array of name/value pairs. Besides visual consistency, it will also handle all the formatting of the different data types so you don't need to spend time on it. The following code snippet is the same as above, but using the new parameters feature:

procedure my_proc(
  p_empno in number,
  p_hiredate in date,
  p_boolean in boolean) -- not really relevant for proc, but good for demo
as
  l_scope logger_logs.scope%type := 'my_proc';
  l_params logger.tab_param;
begin
  logger.append_param(l_params, 'p_empno', p_empno);
  logger.append_param(l_params, 'p_hiredate', p_hiredate);
  logger.append_param(l_params, 'p_boolean', p_boolean);
  logger.log('START', l_scope, null, l_params);
  ...

end my_proc;  

If you now query logger_logs you'll now see the parameters appeneded to the extra column (note if you defined something in the p_extra parameter it would still appear):

select text, scope, extra
from logger_logs_5_min;

TEXT  SCOPE     EXTRA
----- --------- ----------------------------------
START my_proc   *** Parameters ***
                p_empno: 123
                p_hiredate: 26-APR-2013 03:14:58
                p_boolean: TRUE

You'll notice that all the formatting and implicit conversions have been taken care of.

Performance

Unless you are running Logger in no-op mode then there will be a slight performance hit each time you append a parameter (for the cost of appending to an array and implicit conversion). You'll need to factor this in when leveraging this feature. Odds are you'll be able to use the p_params parameter on most of your procedures and functions, but not on frequently used methods.

Other Considerations

Not all people will use the parameters option, and that's fine. We made it an optional parameter specifically for that reason. We added this feature to support one of the primary goals of Logger which is "to be as simple as possible to use".

Logger 2.0.0 Beta

Logger is a PL/SQL logging and debugging framework. It's used in many organizations to instrument code in their Oracle applications. Tyler Muth created Logger a few years ago and has since released several upgrades, the last being 1.4.0. 

After some great feedback, I'm pleased to announce that we've just launched  Logger 2.0.0 Beta. Please download it, install, and provide us with your feedback or any issues you encounter. If you installed the alpha version you'll need to do a complete uninstall and reinstall before using the beta version. The beta version will upgrade over 1.4.0.

The beta release includes some minor bug fixes and documentation updates. The major change is that the log_params procedure has been dropped (I had hinted that this may happen in my previous post). Instead, to remain consistent, a fourth parameter has been added to the major log procedures to support a parameters array. For more information, see the documentation regarding p_params.

If you have any feedback, suggestions, or issues please use the project's issues page. If you don't already have a GitHub account, you'll need to create one (it's free). If your curious as to the direction of this project, please look at the issues page and you'll see what we have planned and what others have requested.

This release will be the last major release before officially launching Logger 2.0.0. Once it's released I'd like to start working on some of the feature requests that have been suggested.

Special thanks to Mark Wagoner for helping test and provide some additional feedback on the latest release.