Logging Library User Guide#
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. A custom logger is created
by declaring a constant or a variable of type logger_t.
constant my_logger : logger_t := get_logger("system0:uart0");
get_logger will internally create an identity for the name
provided in the call (see identity package)
which means that the concept of name hierarchy is inherited by
loggers. In this case a logger will also be created for system0
if it didn’t already exist.
A logger can also be created directly from an identity.
constant my_id : id_t := get_id("system0:uart0");
constant my_logger : logger_t := get_logger(my_id);
Log Handlers#
Log messages made to a logger are handled by a log handler. By default there are two 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);
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
The 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.
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 either 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
errorandfailure.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)
Print Procedure#
print is a procedure that unconditionally outputs its message to stdout or file without any formatting.
print("Message to stdout");
print("Append this message to an existing file or create a new file if it doesn't exist", "path/to/file");
print("Create new file with this message", "path/to/file", write_mode);
It’s also possible to print to an open file object.
print("Message to file object", my_file_object);
This procedure can be used to optimize performance by printing many messages before flushing or closing the file.
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);
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 ensure that all future calls to the logger
are recorded and not sent to a 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 loggers 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#
For simulators supporting VHDL-2019 VUnit adds file name and line number location information to all log entries. Currently only Riviera-PRO and Active-HDL supports VHDL-2019 and they restrict the feature to debug compiled files. You can compile all files or just the ones using logging. For example,
testbenches = lib.get_source_files("*tb*")
testbenches.set_compile_option("rivierapro.vcom_flags", ["-dbg"])
For earlier VHDL standards there is an optional location preprocessor that can
be used to serve the same purpose. The preprocessor is enabled from
the run.py file like this:
ui = VUnit.from_argv()
ui.add_vhdl_builtins()
ui.enable_location_preprocessing()
Regardless of method the location information is appended to the end of the log entry:
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. For VHDL-2019 you can use the path_offset
parameter to specify a number of steps earlier in the call stack. For
example,
procedure my_convenience_procedure(
<my parameters>) is
begin
<some code>
info("Some message", path_offset => 1);
<some code>
end procedure my_convenience_procedure;
When path_offset is set to 1 the location of the caller to
my_convenience_procedure will be used in the log output.
With earlier VHDL standard you can add the line_num and
file_name parameters to the end of the parameter list for the
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;
use work.id_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. A new one is created if it doesn't
-- already exist. Can also optionally be relative to a parent logger.
-- If a new logger is created then a new identity with the name/parent
-- is also created.
impure function get_logger(name : string;
parent : logger_t := null_logger) return logger_t;
-- Get logger by identity. Create a new identity and/or logger if they
-- don't already exist.
impure function get_logger(id : id_t) return logger_t;
-- Return true if logger with id already exists, false otherwise.
impure function has_logger(id : id_t) return boolean;
-------------------------------------
-- Log procedures for each log level
-------------------------------------
procedure trace(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure debug(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure pass(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure info(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure warning(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure error(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure failure(logger : logger_t;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure warning_if(logger : logger_t;
condition : boolean;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure error_if(logger : logger_t;
condition : boolean;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure failure_if(logger : logger_t;
condition : boolean;
msg : string;
path_offset : natural := 0;
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;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure debug(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure pass(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure info(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure warning(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure error(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure failure(msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure warning_if(condition : boolean;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure error_if(condition : boolean;
msg : string;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure failure_if(condition : boolean;
msg : string;
path_offset : natural := 0;
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;
path_offset : natural := 0;
line_num : natural := 0;
file_name : string := "");
procedure log(msg : string;
log_level : log_level_t := info;
path_offset : natural := 0;
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 identity for this logger.
impure function get_id(logger : logger_t) return id_t;
-- 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);
impure function new_log_handler(file_name : string;
format : log_format_t := verbose;
use_color : boolean := false) return log_handler_t;
---------------------------------------------
-- Private parts not intended for public use
---------------------------------------------
impure function get_id_number(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 := "");
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.