Ringbuffer size for ADS-logger should be increased and stored as user parameter

[sagatowski]

Having a testsuite, like the MultipleAssertWithSameParametersInSameCycleWithSameTest in the verifier, with multiple asserts and a single test, makes TcUnit skip the detailed reporting (ID=x number of tests=y, number of failed tests=z). It simply skips the reporting and goes on to the next testsuite, like so:

Message	1014	2020-01-13 19:26:07 022 ms | 'PlcTask' (350): | Test suite ID=10 'PRG_TEST.MultipleAssertWithSameParametersInSameCycleWithSameTest'		
Message	1027	2020-01-13 19:26:07 282 ms | 'PlcTask' (350): | Test suite ID=11 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests

It seems the messages are actually sent to ADS, but some messages (between 1014 and 1027 in example above) are skipped

Correction:
The messages between 1014 and 1027 do actually exist, though these are the assertion failures:

Message	1014	2020-01-13 19:39:12 253 ms | 'PlcTask' (350): | Test suite ID=10 'PRG_TEST.MultipleAssertWithSameParametersInSameCycleWithSameTest'		
Error	1015	2020-01-13 19:39:12 273 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1016	2020-01-13 19:39:12 293 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1017	2020-01-13 19:39:12 313 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1018	2020-01-13 19:39:12 333 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1019	2020-01-13 19:39:12 353 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1020	2020-01-13 19:39:12 373 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1021	2020-01-13 19:39:12 393 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgainAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1022	2020-01-13 19:39:12 413 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgainAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1023	2020-01-13 19:39:12 433 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests@Assert_SeveralTimesAgainAgain', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1024	2020-01-13 19:39:12 453 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1025	2020-01-13 19:39:12 473 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Error	1026	2020-01-13 19:39:12 493 ms | 'PlcTask' (350): FAILED TEST 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesAndInSameTest@Assert_SeveralTimes', EXP: 0x12345678, ACT: 0x90ABCDEF, MSG: Values differ		
Message	1027	2020-01-13 19:39:12 513 ms | 'PlcTask' (350): | Test suite ID=11 'PRG_TEST.MultipleAssertWithSameParametersInDifferentCyclesButWithDifferentTests'		
Message	1028	2020-01-13 19:39:12 533 ms | 'PlcTask' (350): | ID=11 number of tests=3, number of failed tests=3	

Update: The bug has nothing to do with that specific test. The bug has to do with the FB_AdsLogStringMessageFifoQueue. It's not a coincidence the logging bugs out at 1000, which is the buffersize of the FifoQueue.

[sagatowski]

It's not a bug. The buffer was simply too small.
Running the code cycle-by-cycle it was discovered that many test-cases of TcUnit-Verifier (~220) simply quickly filled up the buffer with all the messages being transmitted at more or less the same time (3-4 PLC-cycles) as most tests are run in the same cycle. This made the buffer go above 1000 entries, which made some messages to be dropped. The buffer of 1000 entries today takes:
ST_AdsLogStringMessage = 256(t_maxstring)+256(t_maxstring)+4(dword)+(4 internally used by twincat) = 520 bytes per entry * 1000 = ~0.5mb of the router-memory.
The solution will be:

1. Move the buffer-size to GVL_Param_TcUnit
2. Change the default to 2000 entries (1mb of router memory will be consumed by default)

This means that in worst case, if all tests are executed in the same (or near same) cycle, TcUnit will be able to handle around 400 test cases. If the user wants to be able to handle more than this.

A future improvement could be to improve ST_ADSLogStringMessage, as the MsgFmtStr parameter usually only is a few bytes and T_MaxString is not necessary.

It's necessary to update the documentation to point this out.

Update: It should be pointed out that the default router AMS-size is 32mb in TwinCAT, which can be increased if needed.

[sagatowski]

Solved in commit d90a219.