BeakerLib Newsletter #04: Text logging

BeakerLib offers some basic logging capabilities to tests. The logging commands mainly serve to give a unified and visually consistent look to any messages output by the test, both during execution and when generating the test protocol. These function are one of the oldest in BeakerLib, and unfortunately they suffer from some design decisions based mostly on the RHTS usage patterns at that time.

Summary: rlLog, rlLogDebug, rlLogError, rlLogFatal, rlLogWarning, rlLogInfo

Simply logging a message

There is a simple command to log any message: rlLog. Most often, it takes only one argument: a string with the message to print. rlLog has two effects: First,a formatted, time-stamped is immediately emitted to standard output, serving usually as visual anchor in the raw test output:

$ rlLog "This is a message emitted by rlLog"
:: [ 17:51:20 ] :: This is a message emitted by rlLog

Second, the message is also stored in the Journal, and can be later used e.g. when producing a test protocol.

Message priorities

Messages can have different priorities, allowing some configuration on when should different levels of messages output be produced. Unfortunately, this functionality is not well implemented, and is therefore rarely used, perhaps except for the Debug priority.

The priorities hierarchy could be, with a grain of salt, linearized as follows:

DEBUG < INFO < DEFAULT < WARNING < ERROR < FATAL

The grain of salt is there only because the priority really does not mean much. Currently, there is no good way how to actually control messages logged (except for the DEBUG priority), nor do the priorities have any side effect.

  • rlLogDebug: Perhaps the most useful of the bunch. These messages are printed and stored in the Journal only when an environmental variable DEBUG is set
  • rlLogWarning: Messages with ‘WARNING’ priority. This does not have any other side effect, like affecting results reported by the test. No ‘WARN’ result will be reported neither in Beaker nor locally.
  • rlLogError: Messages with ‘ERROR’ priority. These are usually used by other BeakerLib functions to emit their error messages
  • rlLogInfo: Messages with ‘INFO’ priority. These are usually used by other BeakerLib functions to emit their business details
  • rlLogFatal: Messages with ‘FATAL’ priority. Again, this does not have any side effect. It will not terminate the test.

All these functions will add the priority to the emitted message, like this:

$ DEBUG=1 rlLogDebug "Debugging message"
:: [ 18:07:17 ] :: [ DEBUG   ] :: Debugging message
$ rlLogFatal "Fatal message"
:: [ 18:09:12 ] :: [ FATAL   ] :: Fatal message

Weird things in rlLog

rlLog actually accepts two more positional arguments, and a single additional option:

rlLog MESSAGE [LOGFILE] [PRIORITY] [--prio-label]

This is the unfortunate remnant of the early RHTS days, where tests were supposed to put output to certain files, which would later be picked up by the harness. As we eventually decoupled from RHTS/Beaker and chose to abstract the files away, this lost sense. I believe the LOGFILE argument is no longer useful in any case. If it is set, the textual output will be appended to that file.

The third argument can be used to supply a custom priority tag to the log, but it currently does not work well, so it is preferable to use the rlLog* functions described above:

$ rlLog "message" /dev/null "TAG"
:: [ 17:00:00 ] :: TAG message

The --prio-label might be supplied to put the priority label to the the brackets instead of the timestamp, but only makes sense if you supply the third positional argument.

As you might see, there is really nothing of interest in the additional functionality.

Next time

Basic asserts

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.