Just another Log Helper

Maik Skoddow · ‎12-11-2021

Table of Contents

Introduction
Requirements
Solution
Examples
Enhancements
Source Code

I am sure that in the depths of this community one or the other article / blog post about logging can be found, and nevertheless I wrote a new article about it. You may wonder why. The reason is that I was not satisfied with the OOTB logging means offered to me. And so I developed my own logging helper, which I improved more and more over several projects.

Hint:
ServiceNow offers a number of different logs, but for this article only the facilities of server-side scripts are of interest. For client-side logging, please refer to the relevant documentation.

Introduction

Why do we need logging?

A good log allows insights into the process and the health of a system or an application, which would otherwise not be possible via an interface. Having a good log and monitoring infrastructure is a key feature allowing system administrators, support teams, and even developers to be more prepared to face possible problems. And because this is not trivial, from the very beginning this must be a topic that every project leader, architect, and developer has to keep in mind. They must define what, how, and when to log and even how to extract meaningful data from logs. Moreover, they must keep a sharp eye during reviews in order to ensure that the code satisfies the definitions. Developers and everyone involved in the project must not forget to send log messages at least in every layer of the architecture.

What should be logged?

It is not enough to log errors in order to use them for troubleshooting purposes. It is also useful to log successful requests and the interactions of users, so we can have a clear understanding of how users work with our application.

Tables syslog & syslog_app_scope

These two tables contain all outputs generated by one of the log commands. In addition, the stack traces of all uncaught exceptions are also written here. While the syslog table contains output from both global and scoped applications, the syslog_app_scope table only holds output written within scoped applications. Furthermore, you can define the log level for scoped applications, from which on outputs should be written into the table syslog_app_scope (see Application Logging and the logging.destination and logging.verbosity System Properties for more information). In addition, both tables differ in the level of detail.

Example output at table syslog:

Example output at table syslog_app_scope

Session Log

The Session Log is not stored in any table but can be viewed by navigating to System Diagnostics > Session Debug > Debug Log

As a result, a separate and well-know window with the Script Tracer, the Script Debugger and the Session Log will open. In addition to the log outputs, a lot of other information is continuously printed here, and it is therefore useful to narrow down the list with the help of the filters and the additional free-text search.

Example output at the Session Log:

Log Commands

The following table summarizes which logging methods exists for writing server-side log outputs:

	Table syslog	Table syslog_app_scope	Session Log
gs.log()	x		x
gs.debug()		x¹	x
gs.info()	x	x¹	x
gs.warn()	x	x¹	x
gs.error()	x	x¹	x

¹_{only if logging verbosity is set at the respective application and log level}

As you can see in the above table for script-based log outputs only the commands gs.info(), gs.warn() & gs.error() are suitable as they work in global scope as well as in scoped applications.

ℹ️ Did you know?
The "Level" column in the syslog table also has the value "Fatal" however the GlideSystem variable does not provide the corresponding method gs.fatal() to write log messages with that level.

Requirements

Over the course of various projects, I have encountered recurring challenges and needs that shaped the following requirements for designing a custom logging solution. These requirements aim to address limitations in standard logging approaches and ensure maintainability, consistency, and adaptability across applications.

Extending logging to syslog child tables

While all logging methods of the GlideSystem variable "gs" are by default tied to the syslog table, there have been cases where I needed to log directly to a child table of syslog. This requirement made it necessary to develop a custom implementation that supports specifying the desired target table.

Simple switch to debug mode

The OOTB method gs.debug() is not helpful as in the global scope no outputs are written to the syslog table and for scoped application a respective system property has to be set. However, this system property only applies to the specified application and not for all applications globally. More helpful would be a single method call from a global Script Include to enable debug outputs immediately, which are also written to the syslog table.

Debugging fatal errors

There are situations where I need another debugging level to log thrown and caught exceptions. In this scenario also a condensed and formatted output of the caught exception should be included into the output.

Unique source logging

This is the most important requirement. While for scoped applications in the syslog_app_scope table the origin is rendered in a clickable version (column "Source Script"), such a feature is completely missing in the syslog table for the logging methods via "gs" variable.

Usage of numbered Placeholders

From the method gs.getMessage() we are used to specifying numbered placeholders like "{0}" in the message key, which are replaced with the also passed values automatically. Such a feature would also be helpful for the logging methods to keep the source code as simple as possible.

Support of Functional Programming

And additionally, it would be nice if the logging methods would return the final logging message to support the functional programming paradigm.

Solution

The solution is a comparatively simple Script Include which allows to modes. When using the static methods, all outputs are written to the syslog table.

However, if instantiated as object, you can pass the table name in the constructor to redirect further loggings to that table.

Note:
Don't forget to set "Accessible from" with the value "All application scopes" if you want to save that Script Include at "Global" scope:

Examples

All method invocations follow the same structure:

global.LogHelper.[debug|info|warn|error|fatal]('<LOG SOURCE>', 'LOG MESSAGE'[, e][, values...]);

In case you want to specify an individual target logging table (only child tables of syslog are accepted!) you can implement it as follows:

var myLog = new global.LogHelper('u_my_app_log'); //u_my_app_log must be a child of syslog

myLog.info('MyApp', 'Hello World!');

Hint:

All method calls return the message as a string value to support the functional programming paradigm. This way, the resulting message will be also displayed in your background script console.

Simple info logging with placeholders

Use placeholders and any list of additional parameters to let the LogHelper methods generate a converted message.

Code:

var strSource = "EUR";
var strTarget = "USD"

global.LogHelper.info('CurrencyUtils.convert', 'Convert from {0} to {1}', strSource, strTarget);

Output at syslog table:

Enabling Debug Outputs

In order to be able to understand the circumstances that led to the error, detailed log outputs are essential. On the other hand, in a production environment you want to have as little "trivial" log output as possible, so that the really important error output can be found more quickly. My LogHelper supports that by providing a system property loghelper.enable.debug which can be set (for example on DEV). If enabled, all outputs created by LogHelper.debug() will be written to the log table, otherwise they will be suppressed.

Code:

global.LogHelper.debug('Test', 'Hello World');

Output at syslog:

Fatal logging of caught exceptions

As the GlideSystem object does not offer a gs.fatal() method, internally gs.error() is called instead. The added value of the fatal() method is handling and printing the exception.

Code:

try {
  a = b + 1;
}
catch (e) {
  global.LogHelper.fatal(
    'CurrenyUtils.convert', 'Internal error!', e
  );
}

Output at syslog:

Enhancements

The given source code only represents a base variant which can be further expanded. For example at method fatal() you could create an event and a notification email which consumes that event could inform some persons about the caught runtime error.

Another improvement would be to enrich the log outputs with information available in the session, such as the name of the logged-in user or the URL that was just accessed.

Source Code

The following source code is originally hosted on my public GitHub repo at https://github.com/mskoddow/sn-scripts/blob/master/LogHelper.js

Uncle Rob · ‎12-12-2021

IMMEDIATELY ENDORSED

Mwatkins · ‎12-13-2021

Nice article, Maik!

Maik Skoddow · ‎12-13-2021

Hi @Mwatkins

Thank you for the feedback!

Kind regards
Maik

Community Alums · ‎12-13-2021

I think the only thing I'd add to that would be more accurate timings. Sometimes getting things all bunched into the same second makes it hard to read. Adding the time down to the millisecond as the first bit of the Message can sometimes also help!

Maik Skoddow · ‎12-13-2021

Hi @Mike Reading

You put your finger in an open wound. I also thought about that and what kind of solution would be required.

You could introduce a counter which is added by the LogHelper to the log messages as an additional prefix. But that way a pattern change would be necessary as my approach of invoking static methods would not work anymore. But to keep the things simple I have decided against the concept of instantiation.

A workaround could be to extend the scope parameter with the number of milliseconds:

global.LogHelper.info(
  'Test:' + new GlideDateTime().getNumericValue(), 
  'Hello World'
);

By writing the scope in the first position, you can separate parallel executed threads by sorting the syslog table, but the number of milliseconds is not unique enough as a lot can happen during a millisecond.

A better approach is introducing a counter on consumer side:

function getPaddedNumber(strNumber, numSize) {
    var _strPadding = "000000000";
    var _strNumber  = _strPadding + strNumber;
    var _numSize    = numSize || _strPadding.length;
  
    return _strNumber.substr(_strNumber.length - _numSize);
}

var numCounter = 0;

global.LogHelper.info(
  'Test:' + getPaddedNumber(++numCounter),
  'Hello World 1'
);

global.LogHelper.info(
  'Test:' + getPaddedNumber(++numCounter),
  'Hello World 2'
);

While writing this answer, I find it is worth to be included into the Enhancements section of my article. Many thanks for your inspiration.

Kind regards
Maik

Community Alums · ‎12-14-2021

Good stuff. In a previous world as a customer, a partner wrote something similar for us.

Sorry if it caused you too much pain putting my finger in that wound :-).

Great article though - I didn't put that in my original post!!