Logging Library

Introduction

The VUnit logging library is used internally by VUnit for various logging purposes but it can also be used standalone for general purpose logging. It provides many of the features that you find in SW logging frameworks. For example

  • Logging of simple text messages with different pre-defined log levels
  • Can create hierarchical loggers which can be individually configured
  • Can be mocked to be able to unit-test failures from verification libraries
  • Configurable formatting of message output
  • Automatic file and line number tagging of output messages
  • File and stdout output channels with independent formatting and visibility settings

Architecture

A log entry is made to a logger. You can think of a logger as a named channel. There is a default logger that is used when none is specified but you can also create multiple custom loggers. For example

info("Hello world");

will use the default logger while

info(my_logger, "Hello world");

will use the custom my_logger.

Log messages are then handled by a log handler. By default there are two output handlers, one for handling display (stdout) output and one for handling output to a file. Every log entry you do is passed to both these handlers. Each handler may have a different output format and log level setting. The format is used to control the layout and amount of information being displayed.

Log Levels

Every log entry you make has a log level which is defined by dedicated procedure calls for each log level. The standard log levels and their associated procedure calls are:

-- Visible to display by default
failure("Fatal error, there is most likely no point in going further");
error("An error but we could still keep running for a while");
warning("A warning");
info("Informative message for very useful public information");

-- Not visible by default
pass("Message from a passing check");
debug("Debug message for seldom useful or internal information");
trace("Trace messages only used for tracing program flow");

There are also conditional log procedures for warning, error and failure:

warning_if(True, "A warning happened");
warning_if(False, "A warning did not happen");

-- There are also variants for error and failure as well as with
-- non-default logger argument.

It’s also possible to create custom log levels. For example

license_info := new_log_level("license", fg => red, bg => yellow, style => bright);

The last optional parameters define the foreground, background and style of the output color. Valid values are defined in ansi_pkg.

To make a log entry with the custom level use any of the log procedures:

log("Mozilla Public License, v. 2.0.", license_info);
log(my_logger, "Mozilla Public License, v. 2.0.", license_info);

Stopping simulation

By default the simulation will come to a stop if a single log with level error or failure is made. In VUnit a simulation stop before test_runner_cleanup is considered a failure.

Simulation stop is controlled via a stop count mechanism. The stop count mechanism works in the following way:

  • Stop count may be ether set or not set for a specific logger and log level.
  • When a log is made to a logger it is checked if there is a stop count set.
    • If set it is decremented and reaching zero means simulation stops.
    • If not set the decrementation is recursively propagated to the parent logger.
  • It is possible to disable stopping simulation by setting an infinite stop count.
  • By default only the root logger has a stop count set.
    • Root logger has stop count set to 1 for error and failure.
    • Root logger has stop disabled for all other log levels.

Example:

-- Allow 10 errors from my_logger and its children
set_stop_count(my_logger, error, 10);

-- Disable stop on errors from my_logger and its children
disable_stop(my_logger, error);

-- Short hand for stopping on error and failure but not warning globally
set_stop_level(error);

-- Short hand for stopping on warning, error and failure for specific logger
set_stop_level(get_logger("my_library:my_component"), warning)

Formatting

The default display format is verbose and the default file format is csv to enable simple log file parsing. The format can be changed to any of raw, level, verbose and csv.

set_format(display_handler, level);
info("Hello world");

which will result in the following output.

INFO: Hello world

There default verbose format which adds more details to the output looks like this:

1000 ps - default -    INFO - Hello world

The verbose output will always contain the simulator time, the log level, the logger, and the message.

The raw formatter just emits the log message and nothing else. The csv formatter emits all information in the log entry as a comma separated list for convenient parsing.

Logging hierarchy

Custom hierarchical loggers can be created to provide more information and control of what is being logged.

constant temp_logger : logger_t := get_logger("temperature_sensor");
warning(temp_logger, "Over-temperature (73 degrees C)!");

results in something like this with the verbose formatter.

1000 ps - temperature_sensor -    INFO - Over-temperature (73 degrees C)!

Log visibility

Log visibility to a log handler can be configured for specific log levels of a logger.

-- Disable all logging to the display.
hide_all(display_handler);

-- Show debug log level of system0 logger to the display
show(get_logger("system0"), display_handler, debug);

-- Show all logging from the uart module in system0 to the display
show_all(get_logger("system0:uart"), display_handler);

-- Hide all debug output to display handler
hide(display_handler, debug);

Custom Loggers

Previous chapters have used the built-in default logger for the examples but you can also create your own loggers. You do that by declaring a constant of type logger_t.

constant my_logger : logger_t := get_logger("system0:uart0");

and then you use that variable as the first parameter in the procedure calls presented in the previous chapters, for example.

info(my_logger, "Hello world");

Logger names are hierarchical which means setting the log level of system0 will also set it for uart0.

Mocking

When writing libraries and verification components it is very important to verify that they produce failures as intended. Using the VUnit logging system it is very easy to test that the expected failures are produced by mocking a logger object and checking the expected calls to it.

logger := get_logger("my_library");
mock(logger, failure);
my_library.verify_something(args);
check_only_log(logger, "Failed to verify something", failure);
unmock(logger);

The check_only_log procedure checks that one and only one log message was produced. There is also the check_log procedure which checks and consumes one log message from the list of recorded log calls to check a sequence of log messages.

The mock procedures ensures that all future calls to the logger are recorded and not sent to a any log handler or cause simulation abort. The unmock procedure restores the logger to its normal state. The unmock call also checks that all recorded log messages have been checked by a corresponding check_log or check_only_log procedure.

It is possible to mock several logger or log levels simultaneously. All mocked log messages are written to the same global mock queue. The number of log messages in this queue is returned by the mock_queue_length function.

The mock queue length can be used in a test bench to wait for a log to occur before issuing the check_log procedure.

mock(logger, failure);
trigger_error(clk);
wait until mock_queue_length > 0 and rising_edge(clk);
check_only_log(logger, "Error was triggered", failure);
unmock(logger);

Disabled logs

In addition to visibility settings a log level from a specific logger can be disabled. The use case for disabling a log is to ignore an irrelevant or unwanted log message. Disabling prevents simulation stop and all visibility to log handlers. A disabled log is still counted to get statistics on disabled log messages.

-- Irrelevant warning
disable(get_logger("memory_ip:timing_check"), warning);

Log Location Preprocessing

The optional VUnit location preprocessor can be used to add file name and line number location information to all log calls. This functionality is enabled from the run.py file like this:

ui = VUnit.from_argv()
ui.enable_location_preprocessing()

and will change the output to something like this.

1000 ps - temperature_sensor -    INFO - Over-temperature (73 degrees C)! (logging_example.vhd:79)

If you’ve placed your log call(s) in a convenience procedure you most likely want the location of the calls to that procedure to be in the output and not the location of the log call in the definition of the convenience procedure. You can do that by adding the line_num and file_name parameters to the end of the parameter list for that convenience procedure

procedure my_convenience_procedure(
  <my parameters>
  line_num : natural := 0;
  file_name : string := "") is
begin
  <some code>
  info("Some message", line_num => line_num, file_name => file_name);
  <some code>
end procedure my_convenience_procedure;

and then let the location preprocessor know about the added procedure

ui = VUnit.from_argv()
ui.enable_location_preprocessing(additional_subprograms=['my_convenience_procedure'])

Deprecated Interfaces

To better support testbenches developed before VUnit 3.0 it’s still possible to configure a logger using the logger_init procedure. The procedure uses best effort to map old behavior to contemporary functionality.

Public API

logger_pkg

Contains logger_t datatype and logger local procedures.

use work.log_levels_pkg.all;
use work.log_handler_pkg.all;
use work.integer_vector_ptr_pkg.all;

package logger_pkg is

  -- Logger record, all fields are private
  type logger_t is record
    p_data : integer_vector_ptr_t;
  end record;
  constant null_logger : logger_t := (p_data => null_ptr);
  type logger_vec_t is array (natural range <>) of logger_t;
  impure function root_logger return logger_t;

  -- Get a logger with name.
  -- Can also optionally be relative to a parent logger
  impure function get_logger(name : string;
                             parent : logger_t := null_logger) return logger_t;

  -------------------------------------
  -- Log procedures for each log level
  -------------------------------------
  procedure trace(logger : logger_t;
                  msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure debug(logger : logger_t;
                  msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure pass(logger : logger_t;
                 msg : string;
                 line_num : natural := 0;
                 file_name : string := "");

  procedure info(logger : logger_t;
                 msg : string;
                 line_num : natural := 0;
                 file_name : string := "");

  procedure warning(logger : logger_t;
                    msg : string;
                    line_num : natural := 0;
                    file_name : string := "");

  procedure error(logger : logger_t;
                  msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure failure(logger : logger_t;
                    msg : string;
                    line_num : natural := 0;
                    file_name : string := "");

  procedure warning_if(logger : logger_t;
                       condition : boolean;
                       msg : string;
                       line_num : natural := 0;
                       file_name : string := "");

  procedure error_if(logger : logger_t;
                     condition : boolean;
                     msg : string;
                     line_num : natural := 0;
                     file_name : string := "");

  procedure failure_if(logger : logger_t;
                       condition : boolean;
                       msg : string;
                       line_num : natural := 0;
                       file_name : string := "");

  ------------------------------------------------
  -- Log procedure short hands for default logger
  ------------------------------------------------

  -- The default logger, all log calls without logger argument go to this logger.
  impure function default_logger return logger_t;

  procedure trace(msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure debug(msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure pass(msg : string;
                 line_num : natural := 0;
                 file_name : string := "");

  procedure info(msg : string;
                 line_num : natural := 0;
                 file_name : string := "");

  procedure warning(msg : string;
                    line_num : natural := 0;
                    file_name : string := "");

  procedure error(msg : string;
                  line_num : natural := 0;
                  file_name : string := "");

  procedure failure(msg : string;
                    line_num : natural := 0;
                    file_name : string := "");

  procedure warning_if(condition : boolean;
                       msg : string;
                       line_num : natural := 0;
                       file_name : string := "");

  procedure error_if(condition : boolean;
                     msg : string;
                     line_num : natural := 0;
                     file_name : string := "");

  procedure failure_if(condition : boolean;
                       msg : string;
                       line_num : natural := 0;
                       file_name : string := "");

  -- Log procedure with level as argument
  procedure log(logger : logger_t;
                msg : string;
                log_level : log_level_t := info;
                line_num : natural := 0;
                file_name : string := "");

  procedure log(msg : string;
                log_level : log_level_t := info;
                line_num : natural := 0;
                file_name : string := "");

  -- Get the name of this logger get_name(get_logger("parent:child")) = "child"
  impure function get_name(logger : logger_t) return string;

  -- Get the full name of this logger get_name(get_logger("parent:child")) = "parent:child"
  impure function get_full_name(logger : logger_t) return string;

  -- Get the parent of this logger
  impure function get_parent(logger : logger_t) return logger_t;

  -- Get the number of children of this logger
  impure function num_children(logger : logger_t) return natural;

  -- Get the idx'th child of this logger
  impure function get_child(logger : logger_t; idx : natural) return logger_t;

  -- Set the threshold for stopping simulation for a specific log level and
  -- logger tree
  procedure set_stop_count(logger : logger_t;
                           log_level : log_level_t;
                           value : positive;
                           unset_children : boolean := false);

  -- Disable stopping simulation for a specific log level and
  -- logger tree
  procedure disable_stop(logger : logger_t;
                         log_level : log_level_t;
                         unset_children : boolean := false);

  -- Set the threshold for stopping simulation for a specific log level in
  -- the entire logging tree.

  -- NOTE: Removes all other stop count settings for log_level in entire tree.
  procedure set_stop_count(log_level : log_level_t;
                           value : positive);

  -- Disable stopping simulation for a specific log level in
  -- the entire logging tree.

  -- NOTE: Removes all other stop count settings for log_level in entire tree.
  procedure disable_stop(log_level : log_level_t);

  -- Shorthand for configuring the stop counts for (warning, error, failure) in
  -- a logger subtree. Set stop count to infinite for all levels < log_level and
  -- 1 for all (warning, error, failure) >= log_level.

  -- NOTE: Removes all other stop count settings from logger subtree.
  procedure set_stop_level(logger : logger_t;
                           log_level : alert_log_level_t);

  -- Shorthand for configuring the stop counts in entire logger tree.
  -- Same behavior as set_stop_level for specific logger subtree above
  procedure set_stop_level(level : alert_log_level_t);

  -- Unset stop count for stopping simulation for a specific log level and
  -- logger tree
  procedure unset_stop_count(logger : logger_t;
                             log_level : log_level_t;
                             unset_children : boolean := false);

  -- Returns true if logger has stop count set
  impure function has_stop_count(logger : logger_t;
                                 log_level : log_level_t) return boolean;

  -- Get the stop count for logger and log_level if set, else fail
  impure function get_stop_count(logger : logger_t;
                                 log_level : log_level_t) return positive;

  -- Disable a log_level from specific logger including all children.
  -- Disable is used when a log message is unwanted and it should be ignored.

  -- NOTE: A disabled log message is still counted to get a disabled log count
  --       statistics.
  --       errors and failures can be disabled but the final_log_check must
  --       explicitly allow it as well as an extra safety mechanism.
  procedure disable(logger : logger_t;
                    log_level : log_level_t;
                    include_children : boolean := true);

  -- Returns true if the logger and log_level is disabled
  impure function is_disabled(logger : logger_t;
                              log_level : log_level_t) return boolean;

  -- Hide log messages of specified level to this handler.
  procedure hide(log_handler : log_handler_t;
                 log_level : log_level_t);

  -- Hide log messages from the logger of the specified level to this handler
  procedure hide(logger : logger_t;
                 log_handler : log_handler_t;
                 log_level : log_level_t;
                 include_children : boolean := true);

  -- Hide log messages of the specified levels to this handler.
  procedure hide(log_handler : log_handler_t;
                 log_levels : log_level_vec_t);

  -- Hide log messages from the logger of the specified levels to this handler
  procedure hide(logger : logger_t;
                 log_handler : log_handler_t;
                 log_levels : log_level_vec_t;
                 include_children : boolean := true);

  -- Show log messages of the specified log_level to this handler
  procedure show(log_handler : log_handler_t;
                 log_level : log_level_t);

  -- Show log messages from the logger of the specified log_level to this handler
  procedure show(logger : logger_t;
                 log_handler : log_handler_t;
                 log_level : log_level_t;
                 include_children : boolean := true);

  -- Show log messages of the specified log_levels to this handler
  procedure show(log_handler : log_handler_t;
                 log_levels : log_level_vec_t);

  -- Show log messages from the logger of the specified log_levels to this handler
  procedure show(logger : logger_t;
                 log_handler : log_handler_t;
                 log_levels : log_level_vec_t;
                 include_children : boolean := true);

  -- Show all log levels to the log handler
  procedure show_all(log_handler : log_handler_t);

  -- Show all log levels to the handler from specific logger
  procedure show_all(logger : logger_t;
                     log_handler : log_handler_t;
                     include_children : boolean := true);

  -- Hide all log levels from this handler
  procedure hide_all(log_handler : log_handler_t);

  -- Hide all log levels from this handler from specific logger
  procedure hide_all(logger : logger_t;
                     log_handler : log_handler_t;
                     include_children : boolean := true);

  -- Return true if logging to this logger at this level is visible anywhere
  -- Can be used to avoid expensive string creation when not logging a specific
  -- level
  impure function is_visible(logger : logger_t;
                             log_level : log_level_t) return boolean;

  -- Return true if logging to this logger at this level is visible to handler
  impure function is_visible(logger : logger_t;
                             log_handler : log_handler_t;
                             log_level : log_level_t) return boolean;

  -- Get the current visible log levels for a specific logger to this log handler
  impure function get_visible_log_levels(logger : logger_t;
                                         log_handler : log_handler_t) return log_level_vec_t;

  -- Get the current invisible log levels for a specific logger to this log handler
  impure function get_invisible_log_levels(logger : logger_t;
                                           log_handler : log_handler_t) return log_level_vec_t;

  -- Get the number of log handlers attached to this logger
  impure function num_log_handlers(logger : logger_t) return natural;

  -- Get the idx'th log handler attached to this logger
  impure function get_log_handler(logger : logger_t; idx : natural) return log_handler_t;

  -- Get all log handlers attached to this logger
  impure function get_log_handlers(logger : logger_t) return log_handler_vec_t;

  -- Set the log handlers for this logger
  procedure set_log_handlers(logger : logger_t;
                             log_handlers : log_handler_vec_t;
                             include_children : boolean := true);

  -- Get the total number of log calls to all loggers
  impure function get_log_count return natural;

  -- Get number of log calls to a specific level or all levels when level = null_log_level
  impure function get_log_count(logger : logger_t;
                                log_level : log_level_t := null_log_level) return natural;

  -- Reset the log call count of a specific level or all levels when level = null_log_level
  procedure reset_log_count(logger : logger_t;
                            log_level : log_level_t := null_log_level;
                            include_children : boolean := true);


  -- Perform a check of the log counts and fail unless there are no errors or failures.
  -- By default no disabled errors or failures are not allowed.
  -- Disabled errors and failrues can be allowed by setting the corresponding
  -- arguments to true.
  -- By default warnings are allowed but failure on warning can be enabled.
  -- When fail on warning is enabled it also allows disabled warnings.
  procedure final_log_check(allow_disabled_errors : boolean := false;
                            allow_disabled_failures : boolean := false;
                            fail_on_warning : boolean := false);

  impure function final_log_check(allow_disabled_errors : boolean := false;
                                  allow_disabled_failures : boolean := false;
                                  fail_on_warning : boolean := false) return boolean;

  ---------------------------------------------------------------------
  -- Mock procedures to enable unit testing of code performing logging
  ---------------------------------------------------------------------

  -- Mock the logger preventing simulaton abort and recording all logs to it
  procedure mock(logger : logger_t);

  -- Mock log_level of logger preventing simulaton abort and recording all logs to it
  procedure mock(logger : logger_t; log_level : log_level_t);

  -- Unmock the logger returning it to its normal state
  -- Results in failures if there are still unchecked log calls recorded
  procedure unmock(logger : logger_t);

  -- Returns true if the logger is mocked
  impure function is_mocked(logger : logger_t) return boolean;

  -- Constant to ignore time value when checking log call
  constant no_time_check : time := -1 ns;

  -- Check that the earliest recorded log call in the mock state matches this
  -- call or fails. Also consumes this recorded log call such that subsequent
  -- check_log calls can be used to verify a sequence of log calls
  procedure check_log(logger : logger_t;
                      msg : string;
                      log_level : log_level_t;
                      log_time : time := no_time_check;
                      line_num : natural := 0;
                      file_name : string := "");

  -- Check that there is only one recorded log call remaining
  procedure check_only_log(logger : logger_t;
                           msg : string;
                           log_level : log_level_t;
                           log_time : time := no_time_check;
                           line_num : natural := 0;
                           file_name : string := "");

  -- Check that there are no remaining recorded log calls, automatically called
  -- during unmock
  procedure check_no_log;

  -- Return the number of unchecked messages in the mock queue
  impure function mock_queue_length return natural;

end package;

log_handler_pkg

Contains log_handler_t datatype and log handler local configuration procedures.

use work.integer_vector_ptr_pkg.all;
use work.log_levels_pkg.all;

package log_handler_pkg is
  type deprecated_log_format_t is (
    -- The raw log format contains just the message without any other information
    raw,

    -- The level log format contains the level and message
    level,

    -- The verbose log format contains all information
    verbose,

    -- The csv format contains all information in machine readable format
    csv,

    -- Deprecated value not supported by new interfaces but kept for backward
    -- compatibility reasons. NOT for new designs
    off);

  subtype log_format_t is deprecated_log_format_t range raw to csv;

  -- Log handler record, all fields are private
  type log_handler_t is record
    p_data : integer_vector_ptr_t;
  end record;
  constant null_log_handler : log_handler_t := (p_data => null_ptr);
  type log_handler_vec_t is array (natural range <>) of log_handler_t;

  -- Display handler; Write to stdout
  impure function display_handler return log_handler_t;

  -- Get the name of the file used by the handler
  impure function get_file_name (log_handler : log_handler_t) return string;

  -- File name used by the display handler
  constant stdout_file_name : string := ">1";

  constant null_file_name : string := "";

  -- Set the format to be used by the log handler
  procedure set_format(log_handler : log_handler_t;
                       format : log_format_t;
                       use_color : boolean := false);

  -- Get the format used by the log handler
  procedure get_format(constant log_handler : in log_handler_t;
                       variable format : out log_format_t;
                       variable use_color : out boolean);

  ---------------------------------------------
  -- Private parts not intended for public use
  ---------------------------------------------
  impure function get_id(log_handler : log_handler_t) return natural;
  procedure update_max_logger_name_length(log_handler : log_handler_t; value : natural);
  impure function get_max_logger_name_length(log_handler : log_handler_t) return natural;

  procedure log_to_handler(log_handler : log_handler_t;
                           logger_name : string;
                           msg : string;
                           log_level : log_level_t;
                           log_time : time;
                           sequence_number : natural;
                           line_num : natural := 0;
                           file_name : string := "");

  impure function new_log_handler(file_name : string;
                                  format : log_format_t;
                                  use_color : boolean) return log_handler_t;

  procedure init_log_handler(log_handler : log_handler_t;
                             format : log_format_t;
                             file_name : string;
                             use_color : boolean := false);
end package;

Example

A runnable example using logging can be found in Logging Example.