add test progress feedback in the log

[Aliazzzz]

I'd like to see a feature wherein the user gets feedback in between tests on the testrunner progress: it could send a message to the log stating progress in % or in test x out of y for every new test. Tradeoff is some extra performance and clutter in the log, but at this stage the user gets no progress indication at all (only errors, if any), apart from checking the testrunner state in online mode. I think this progress feedback is especially essential in large unittests ( engage FB's with timers etc) As personal usecase involves this a lot, as it's really annoying to guess what the current progress is.

[sagatowski]

This is a very good suggestion. I'm currently working on a concept where the result is reported in standard XUnit xml format so it's possible to integrate it into Jenkins, which will be the standard report result. The ADS-logger will only be used if the tests are run locally. The only thing that needs to be considered is how to best add feedback without cluttering the logger too much.

[Aliazzzz]

The logger can show 3 types of messages: Errors, warnings and messages. You can use the category messages like this; PROGRESS: Test ["testname"] 2 of 18 PROGRESS: Test ["testname"] 3 of 18 etc, etc.

Implementing this is should be a breeze as you have all indgredients allready. Plus in the log these three categories can be filtered for viewing so we can filter out the clutter.

The export to jenkins should NOT contain this progress, i.e. the jenkinslogger should write only Errors to xml, not verbose messages. So the category filter is very useful because the ADS logger (VS.NET messages pane) also uses these three levels for filtering. Vanilla Codesys Device also uses this mechanism.

I can not implement this in CfUnit yet because I want to stay as close to TcUnit functionality (1:1) as possible. This is why I asked you to add it, so it will flow in CfUnit organicly in an update. I can however provide you with code/idea's hints.

[sagatowski]

Ideas are mostly welcome. I'll start by implementing the XUnit-functionality (issue #11 ) and then decide where/how the status should go to. But it makes full sense to put it in a separate category as you mentioned (such as in the warning and or log instead of err). It's still nice to be able to run the unit tests locally and being able to just see the results though.

Edit: Out of curiosity... how does the logging work in Codesys? I assume you're not using ADS-logger?

[Aliazzzz]

In Codesys there exists a devicelogger. It's always present in every (online) runtime and it works very similar like the ADS-Logger(!) It captures device log and/or component messages and user messages. The following gif shows it in action;

https://forge.codesys.com/prj/cfunit/code/HEAD/tree/trunk/images/Logger.gif?format=raw

and the CfUnit output

https://forge.codesys.com/prj/cfunit/code/HEAD/tree/tags/v0.0.2.1/CfUnitVerifier%20output.png?format=raw

As it is always present, we can use it to present CfUnit output in a very clean way.

[Aliazzzz]

I worked out a new idea. How about we extend the UnitTest framework with a function called VERBOSE which takes two arguments (Prio, Message). The developer can use this function to send verbose messages to the console whenever he/she desires. By setting a priority in the message, they can be filtered on or off in the console Extra bonus is that you don't have to use it if you do not need it, it's up to the developer.

I personally found this very useful to keep me informed on the progress as my personal usecase makes extended use of timed testing. The testsuite duration takes over 4 hours realtime and I wanted to know the current automated progress state without much effort.

The idea;

TEST('Status_xAlarmSignalEqualsTRUE');
VERBOSE( eMsgPrio := eMsgPrio.Information, sMsg := 'TEST Status_xAlarmSignalEqualsTRUE Started');

_Input.xAlarmSignal := TRUE;
_Timer(IN := _SO.xAlarmSignal,
      PT := _TimeDuration );

// sends information message to the console
VERBOSE( eMsgPrio := eMsgPrio.Information, sMsg := CONCAT('Timer ET: ', TO_STRING(_Timer.ET) ) );

IF _Timer.Q THEN
    AssertTRUE( Condition := _Status.xAlarm,
            Message := 'Values differs' );
    TEST_FINISHED();
END_IF

This test sends a signal that the test has commenced and the time-progress of the test to the console

[Aliazzzz]

see above message

[Aliazzzz]

Implementation suggestion;

FUNCTION VERBOSE : BOOL
VAR_INPUT
    MsgPrio : UDINT := LogClass.LOG_INFO; // The prio of the message, DEFAULT: LogClass.LOG_INFO; ( CmpLog should be referenced )
    Message : T_MaxString; // The verbose message
END_VAR

===================================

LOGSTR(msgCtrlMask := MsgPrio,
                      msgFmtStr := '%s',
                      strArg := Message );

Offcourse the function should be tweaked for TwinCAT console prio's

[sagatowski]

Implementation suggestion;

FUNCTION VERBOSE : BOOL
VAR_INPUT
  MsgPrio : UDINT := LogClass.LOG_INFO; // The prio of the message, DEFAULT: LogClass.LOG_INFO; ( CmpLog should be referenced )
  Message : T_MaxString; // The verbose message
END_VAR

===================================

LOGSTR(msgCtrlMask := MsgPrio,
                      msgFmtStr := '%s',
                      strArg := Message );

Offcourse the function should be tweaked for TwinCAT console prio's

Is it really necessary with the function VERBOSE()? Can't you call LOGSTR directly? I don't see the function verbose doing anything than acting as an alias for logstr?

[Aliazzzz]

Yes, true...

But also consider the following, the default message prio differs. It is declared in a constant (Tc2_System.ADSLOG_MSGTYPE_ERROR) instead of an enum within the it's library (on vanilla CODESYS side) which makes calling (ADS)LogString not 'user-friendly' because you have to search the library for the correct constant. I am very Lazy:-) An overload is a more fitting solution but IEC isn't capable of function overloads. So I opted for a different function which has the correct setting as default and a differten function name to avoid any confusion. In long words point taken!

What are your thoughts on a simple yet flexible solution?

[Aliazzzz]

What are your thoughts on this?

[sagatowski]

I still think adding a function that replaces the well-known ADSLOGSTR() makes little sense. It would make sense if it actually added some functionality, for example some form of buffering of the log-messages as it seems that a huge amount of calls to ADSLOGSTR() make some of them not display, which most likely means that some form of buffering would be added.