Common log interface

[LarsAsplund]

Some years ago we had discussions with @JimLewis about creating a logging library common to VUnit and OSVVM. In the end we couldn't come to a solution that provided a value exceeding the costs of making the required and somewhat disruptive changes.

Some days ago we had a discussion if it was possible to do a much less ambitious integration that still provide some significant value. The idea is that we should investigate if we can allow log messages to be piped from one framework to the other by redirecting data at the lowest level.

At the lowest level we have a number of data items that are transformed into a line written to file or stdout. If the procedure doing that transformation is placed in a standalone package it is possible to provide an alternative implementation that passes the data set to another logging system such that logging output becomes consistent for the user. Simple principle that provides some user value. If this is successful we could consider higher levels of integrations in the future but the key is that we do so in small steps rather than going for the complete integration in one big step.

A drawback with the low-level integration is that the data sets are not the same which means that the representation of the data in the "other" system is done on a best effort basis. However, many of the core data items are the same or very similar. For example, time, "log level", the actual message, and the named source of the log message.

Note that alert/checks are just log messages with some extra actions. They are also within the scope of this discussion.

Providing alternative implementations is something that is possible already today. The purpose of this PR is to investigate how this can be made easier by isolating related functionality. By sharing a common concept for this we also provide a clear statement that we endorse such an approach and it isn't against the intentions of the frameworks.

What I've done so far is to create a prototype to get a feel for what such a shared concept may look like. The transformation of the data set to a log line has been encapsulated in a single package containing a single procedure:

package common_log_pkg is
  constant no_time : time := -1 ns;
  constant no_val : integer := integer'low;
  constant default_mode : natural := 0;

  procedure write_to_log(
    file log_destination : text;
    msg : string := "";
    log_time : time := no_time;
    log_level : string := "";
    log_source_name : string := "";
    mode : natural := default_mode;
    str_1, str_2, str_3, str_4, str_5, str_6, str_7, str_8, str_9, str_10 : string := "";
    val_1, val_2, val_3, val_4, val_5, val_6, val_7, val_8, val_9, val_10 : integer := no_val);
end package;

Some highlights:

• There are a number of named inputs that most frameworks have (this extends beyond VUnit and OSVVM but I'm starting small).
• There are no complicated types. VHDL-93 is sufficient
• The are some generic string and integer inputs that the caller may use. It is important that the interface can take all the data needed to implement the original functionality of the framework. For example, OSVVM provide a message prefix that VUnit doesn't have. That prefix can be provided through one of the str_x parameters. I'm not sure about these nameless inputs since it's bad programming style although alias can be used within the procedure implementation to clarify what the parameters are used for. An alternative is allow each framework to add as many named parameters as they like. Better looking code but the interface can't be provided by an external shared repository so the statement of supporting this approach is less obvious.
• I'm not sure about mode. The idea is that the frameworks have modes that affect how the data set is represented and the nameless parameters can also be given different meaning depending on mode. However, in general one mode may not be sufficient so maybe we should just hide any mode in the set of nameless parameters.

In this commit I created an example VUnit testbench that calls both VUnit and OSVVM log/alert/check:

  main : process
    constant logger : logger_t := get_logger("My component");
    constant checker : checker_t := new_checker(logger);
  begin
    test_runner_setup(runner, runner_cfg);
    set_stop_level(failure);

    osvvm.AlertLogPkg.Log(GetAlertLogID("My component"), "Hello from OSVVM");
    Alert(GetAlertLogID("My component"), "An error from OSVVM");

    info(logger, "Hello from VUnit");
    check(checker, false, "An error from VUnit");

    test_runner_cleanup(runner);
  end process;

The output today looks like this in GHDL

In this case OSVVM and VUnit have their default implementations of common_log_pkg. If I replace the OSVVM implementation with one piping OSVVM logs/alerts to VUnit I get.

Someone not using VUnit for compilation would simply update the list of files to compile but in this commit I also added an extra argument to the method including OSVVM in the project

prj.add_osvvm(use_vunit_log=True)

Similarily, the VUnit log/checks could be made looking like OSVVM or any other logging system by replacing the VUnit default implementation of common_log_pkg. To do that I added an extra argument to the add_builtins method:

prj.add_builtins(use_external_log=Path(root / "osvvm_integration" / "common_log_pkg_vunit_to_osvvm.vhd"))

The result when doing so is

I've taken some short cuts in this first commit. For example,

• I've only tested with stdout and not with logging to file
• I've not replaced all calls for logging with calls to write_to_log. For example the last FAILURE is from VUnit and is still always logged VUnit style
• Hierarchical names for the log source have not been tested/implemented

I think this is just a matter of doing the work. I don't see that the concept shouldn't work for this. For now I'm mostly interested in comments on the basic concept to see if this can lead somewhere.

[JimLewis]

@LarsAsplund
First, thanks for working on this.

Will handle the ability to redirect outputs to different files?

OSVVM does not currently have mocking (for various reasons), but I thought if I were to add it, it would be a scoreboard that would receive the redirected output that was destined to a file.

I would like to maintain the ability to filter using grep. That is why I have the %% and Alert in there. And why the output is only one line.

[LarsAsplund]

@JimLewis With the current interface one would have to make one call for each output. Given that we working on the lowest level with little data transformation it shouldn't be much overhead doing it twice. In VUnit the formatting can also be different between stdout and file. For example, the file can have a CSV format for easier post-processing but CSV is probably never used for stdout which is intended for human reading.

[LarsAsplund]

@JimLewis I had a look at handling logging hierarchies. VUnit includes the hierarchy in the log, for example

0 fs - top:bottom           -    INFO - Hello from VUnit hierarchy

while OSVVM do not

%% Log   ALWAYS  in bottom, Hello from OSVVM hierarchy at 0 ns

This means that VUnit cannot extract the hierarchy when receiving OSVVM messages. That can be handled by requiring that log_source_name is the full hierarchy or that the hierarchy is provided with another parameter. Either way, the package implementation can decide whether or not to include the full name in the log.

For OSVVM you might not want the overhead of creating a hierarchical name if you don't intent to show it in your native implementation. A way to handle this is to include a deferred constant in the package

constant is_original_pkg : boolean;

Your native package body would set this value true while all third party implementations are required to set this false. The calling AlertLogPkg in OSVVM can use this constant to determine if the full name needs to be calculated or not.

[LarsAsplund]

@JimLewis WRT to %%. You would always pass the prefix as one of the nameless parameters to write_to_log. It will then be up to the third party implementation to decide whether or not to include that in the output. The VUnit implementation would ignore that parameter since it's not used by log entries coming from VUnit itself. In case you replace the VUnit implementation you would redirect our logs to yours and %% would be part of the output as I showed in the example above.

[JimLewis]

@LarsAsplund Does your proposed sharing include any sharing of counts and such?

[JimLewis]

@LarsAsplund Currently OSVVM bins do not report their parent in printing - but they do know their parent.

[umarcor]

There are no complicated types. VHDL-93 is sufficient

Is this a sensible requirement? Both OSVVM and VUnit do require VHDL 2008 for the intermediate and advanced HDL features. If using unconstrained arrays of strings might produce a better quality code and potentially better functionality, I believe it is acceptable to require VHDL 2008.

That can be handled by requiring that log_source_name is the full hierarchy or that the hierarchy is provided with another parameter.

I think it is ok to have log_source_name be the full hierarchy name. Furthermore, @JimLewis said the info is available already, although not used.

[JimLewis]

@LarsAsplund
What is our goal? Some level of interoperability/exchangeability?

I see only two ways:

1. Share a common information model that records and counts FAILURES, ERRORS, WARNINGS, and at least for OSVVM PASSED logs. OSVVM also has disabled FAILURES, ERRORS, and WARNINGS that it counts.

2. Have a common API that VC can use so that the VC can be use with either OSVVM or VUnit.

Are you working on 2?

[umarcor]

@JimLewis, why is counting required in order to handle printing messages to screen and/or to files?

I believe this is unrelated to VCs, and it's not meant to replace the logging functionality of VUnit or OSVVM. It's just about being able to forward info, warning and error messages from one framework to the other.

[LarsAsplund]

@JimLewis @umarcor I think we're starting to fall into the trap of being over-ambitious in the first step (me included). My goal is to:

1. Have all logs from framework x piped into framework y. Since we have centralized logging system that should be a rather localized modification. If this is just a thing for VCs we need to handle them in some special way and the end-user would still see a mix of log entries which removes much of the proposed value
2. Our challenge is not to come up with things that we could share given the similarity of our logging system. The challenge is to share something. That is where we need to start, extensions can be added later if the first step is successful. Note that we're not developing an end-user API so we don't have to be afraid of changing the API in a non-backward compatible ways as things progresses.

To keep the ambition low for the first step I think we shouldn't do more than is needed to maintain the same level of functionality we have today. My last suggestion on how we could have hierarchical information from OSVVM is really something for a future step as that is more information than OSVVM needs for its current implementation. For now we have to cope with what is available and I think it will take us far as my initial examples suggest.

Same thing with error counters. We both have them but that is at a higher and more ambitious abstraction level and that will inevitably lead to more things that have to be agreed upon. If I recall correctly error count stop levels don't work the same ways in our systems and the extent to which we use counters are different. VUnit's default behavior is to stop on the first error while OSVVM don't (right?). Such issues complicate things and should be addressed in a separate step. Even if we never get passed the first step I think it has value on it's own so there is no reason to speculate on what we can agree on in the future.

[umarcor]

@LarsAsplund, agree, word by word.

[LarsAsplund]

I've cleaned up this work and now there is an interface that can be used to redirect VUnit logs into other logging frameworks. The only difference is that I removed the mode parameter as discussed above.

I've also added an OSVVM integration example showing this in practice (https://github.com/VUnit/vunit/tree/common_log_interface/examples/vhdl/osvvm_log_integration). That example also includes a modified AlertLogPkg.vhd and an implementation of the interface that redirects OSVVM logs to VUnit. That is just a proof of concept and not intended for real use. OSVVM has several places producing log messages and I have not converted all of them to use the new interface. That is something that has to be provided and maintained in the OSVVM project. I've opened an issue for that (OSVVM/OSVVM#80) but will make a VUnit release regardless of the progress of that issue.