Common Log Interface

[LarsAsplund]

This is a request for a common log interface in OSVVM as discussed in VUnit/vunit#776.

Such an interface has already been released for VUnit and can be used to redirect VUnit log messages to another logging framework as described here: https://vunit.github.io/logging/user_guide.html#external-logging-framework-integration

There is also an example (https://github.com/VUnit/vunit/tree/master/examples/vhdl/osvvm_log_integration) showing the interface in action by redirecting VUnit logs to AlertLogPkg:

That example also contains a limited modification of AlertLogPkg that would allow OSVVM log messages to be redirected into VUnit. It is limited in the sense that it hasn't been modified in all places where log messages are generated:

[JimLewis]

Hi Lars,
This can be done, but I am not sure I understand the point. Yes it makes all the messages uniform. This is a nice to have feature. The current version of OSVVM already has a common print handler, but it is also more complicated than the old one.

However, this ignores what I would consider the more important feature - a shared set of error counts. Otherwise end of test reporting is complicated.

I am not concerned about the underlying policies. For an OSVVM testbench that uses some VUnit VC, or a VUnit testbench that uses some OSVVM VC, there needs to be a way in the VC to use the appropriate IDs, alerts, logs, affirmations, and checks that correspond to the system chosen for the test case. I was thinking this would take an outer layer of abstraction and not necessarily an inner layer of abstraction.

Cheers,
Jim

[LarsAsplund]

Hi Jim,

If every log call made in framework X is transformed into a log call in framework Y then framework Y would count them just the same. Framework X may maintain it's own set of counters which you may retrieve but I don't think there is a need for that. In my example I have an implementation that transforms VUnit calls to OSVVM Log or Alert (https://github.com/VUnit/vunit/blob/master/examples/vhdl/osvvm_log_integration/osvvm_integration/vunit_to_osvvm_common_log_pkg-body.vhd). They would all be counted, right?

/Lars

[LarsAsplund]

I had a look at the latest AlertLogPkg and I think the LocalPrint procedure can serve as a good example for the type of refactoring that is needed:

    procedure LocalPrint (
      AlertLogID      : AlertLogIDType ;
      AlertLogName    : string ; 
      WriteErrorCount : boolean ; 
      WriteLevel      : boolean ; 
      LevelName       : string ; 
      WriteName       : boolean ; 
      Message         : string ;
      WriteTime       : boolean
    )

If we compare that with the write_to_log interface we see that:

1. msg maps to Message
2. log_time maps to the now function
3. log_level maps to LevelName
4. log_source_name maps to AlertLogName

Then there are a number of more specific OSVVM parameters of type boolean and integer which needs to be passed to write_to_log as one of the val_x parameters. We could also consider adding a set of bool_x parameters to write_to_log in order to avoid a boolean to integer conversion.

The body of LocalPrint is then moved to the body of write_to_log. Local aliasing of the val_x (and bool_x) parameters to their "real" names means the the original code can be used as is. This is important because write_to_log should no require that the outcome of the original implementation has to change.

A difference between VUnit and OSVVM is that VUnit treats file and output separately. A VUnit log entry may, for example, have different formats on file and on output. For that reason VUnit calls write_to_log twice (if a file handler has been defined). OSVVM uses mirroring with identical format and a single call is sufficient . We can handle this difference as follows:

1. OSVVM first calls write_to_log with log_destination set to output. The OSVVM implementation of write_to_log would ignore log_destination a perform mirroring as it does today.
2. A VUnit implementation would make use of log_destination.
3. After the first call, OSVVM uses the deferred constant is_original_pkg to determined if another call is needed. is_original_pkg is located in the common_log_pkg and I suggested it in the original discussion. Never added it though but that's an easy fix. Only the original OSVVM body of common_log_pkg will have that variable set to true. A third-party implementation will have it set to false and cause OSVVM to make a second call to write_to_log in case mirroring has been enabled.

Searching through AlertLogPkg I see that there are more places calling writeline. These may or may not be considered as log entries that should be made through write_to_log but they may also be something else. I would say that anything with a time stamp, a LevelName, or an AlertLogName is a log entry that should use write_to_log. Everything else are just "print statements" which are excluded from the common log concept.

[JimLewis]

OSVVM justifies messages based on the width of the ID and Parent ID names. How do these items get shared?

Currently in OSVVM levels: FAILURE, ERROR, WARNING, and PASSED get counted. Nothing else. This is done separately from printing.

The other writeline are part of writing out results. Some of this leads to our YAML file creation. This capability looses information if we just try to create the wrapper at the lower layer.

My thought for interoperation was to put an outer abstraction layer - just thinking in terms of OSVVM this would be:

subtype CommonIDType is AlertLogIDType ;
NewID
Alert
Log

This would imply that OSVVM AlertLogPkg would need to be split to be "CorePkg" and helper functions (such as AlertIf, ..., AffirmIf, ...). It is probably more work than what you are thinking, but it ensures

The intent would be that we handle all reporting that is done by the VC and by the OSVVM CoveragePkg, ScoreboardPkg, and MemoryPkg

The test cases then would have to use the package picked by the common logging package and call the controls and such that are associated with that package.

[JimLewis]

With respect to closing the gap on the differences (or entirely removing the differences) between VUnit and OSVVM Alert/Log capability:
I am open to handling mocking (this is just puts the results in a string based scoreboard rather than a file right?). I have plans for handling multiple files. I am open to refactoring the controls so they get common control. I set up my control paradigms so that no additional settings were needed in the data structure - but I am open to adding switches to indicate whether something like a stop count is set or not. I am open to supporting both CamelCase and snake_case. I am not open to not supporting CamelCase.

A required paradigm of OSVVM is maintaining backward compatibility - except to gain a high value feature - and then backward compatibility should only be broken in a minimal way. This is important as the expense for a project to switch revisions should be zero and not something significant. Old VC should work with new VC without issue.

With respect to handling differences between the packages, I have been thinking that OSVVM needs some static file settings that could handle some of the differences - such as the initial Error stop count. Maybe it would be multiple files, one that is static and one that is specific to a test case. I think it needs to be files as some settings such as enabling log levels need to be controlled by the scripts - are we debugging interactively or are we running a regression/CI. We could define a common control format YAML, JSON, or other (such as the .ini file formats). I think VUnit already has some capability in this area - maybe you want to propose something.

I would like to find a way the file settings can be applied automatically when a test runs. Although, OSVVM does have some required elements and it could potentially be done then - such as SetTestName("<TestName>") is now required and could read the settings itself.

On the alerts OSVVM added a print count that allows an upper bound to be put on the number of times an alert prints. I am open to counting all of the logs - and adding the same sort of printing controls for them too. Sometimes it would be nice to see the first 10 PASSED messages and stop printing after that.

For all of the report files that OSVVM generates, late last year, I refactored the TCL files that generate those so that they can be called from outside - with VUnit in mind.

What happened last time (2018?) was unfortunate.

If we had a common AlertLog capability, other differences in our approaches don't matter and can be merged slowly over time or can remain separate as one wishes.

If we could do this, we could close the gap on SystemVerilog or push past it. Currently in FPGA world wide OSVVM is 28% and UVM is 44%. In Europe, I expect that OSVVM is significantly ahead of UVM (as it was in the past).

In your terms, yes I am being ambitious - but there are big rewards for doing so.

[LarsAsplund]

The last time we discussed aligning our logging frameworks we set the ambition at one commonly shared framework. My conclusion was that it is a complex task which comes with a cost, mainly in terms of breaking backward compatibility. That cost didn't exceed the perceived value of such an exercise.

I don't think much has change since then. The feedback I get from users is not that one framework would be great because that would create a larger feature set. Users already picked one framework and what they want is to feed log entries from one framework to the other in order to get a consistent output in a mixed environment. There is also a 80/20 rule at play here. 80% of users use 20% of the feature set. What's used is the basic stuff more or less common to all frameworks. Those VCs using all whistles and bells will mix with VCs using the basics. Logging isn't fully aligned even if only one framework is used.

I still think a standard logging framework would be good for the VHDL community in the long run but as with any complex task it's better done in several small steps. What I suggested is an approach designed to only require refactoring of current implementations. There shouldn't be any behavioral changes so existing tests suites can be used to verify that no mistake was made. That is how it was done for VUnit. We basically had two calls to writeline before. These were replaced with calls to write_to_log and some code previously executed before the writeline call has now been moved unmodified to the body of write_to_log, and then in the end there is a call to writeline. There may be unique challenges to OSVVM that I haven't foreseen but that is the basic idea.

Since there are no changes to the behavior of OSVVM and VUnit, it is the alternative implementations, piping logs from one framework to another, that take the hit. Some OSVVM features may not be preserved when piping logs to "the other" framework but the basics will, and most people use the basics.

In the future we can see if there are more features that we can consider common. That would lead to more explicit parameters in the interface or maybe higher level of interfaces. However, we must show in practice that we can align at the lowest level where there are no backward compatibility issues (and the user value is high) before considering further alignment. At least that is how I look at it.

When it comes to casing I'm perfectly fine with you providing a procedure/package using CamelCase naming convention as long as the names are the "same" (write_to_log becomes WriteToLog). Otherwise it will just be confusing for those getting involved.

Justification is one of the things that I consider framework-specific as it is related to style. As such it is not part of the named parameters. The OSVVM implementation may still have to pass such information to write_to_log using val_1 for example. VUnit uses val_5 for that purpose. An alternative implementation may use these parameters as well if needed but in the case of justification I don't think it's very useful/needed. Whatever OSVVM thinks about justification may not be valid when the log is passed to VUnit as VUnit may have longer names. And vice versa of course. My test implementation for a VUnit style write_to_log for OSVVM is also registering any unknown OSVVM ID names as logger names in VUnit and after that VUnit has the full picture and can do proper justification of the output.