shorten long message because it's a bit too long

[slabarque]

Hi @bengeisler

I had to remove some letters from the long message because it was still a bit too long.

On the issue of the timestamps (I've not yet created a separate issue for it, sorry) Last week I installed Twincat3 on a new machine (a VM in Virtualbox), I noticed that on that machine I did not have the issue with the timestamps, I'm not sure why. And although the file now has a correct timestamp in the name it only contains the first message that I log. All subsequent messages are not logged and I notice the following error in TcLogCore.Error:

Message 4/3/2023 10:30:15 899 ms | 'Tests_Task' (351): Closing file failed. Error thrown by FB_FileClose. Consult Beckhoff InfoSys. Internal Error: 1795

[bengeisler]

Thanks for following up! I could reproduce the issue with the long string name. However, it was due to another unit test that set the delimiter (which was an empty string by default) and thus changing the length of the complete log string. I changed the other unit test by resetting the delimiter in the teardown of the test in cc2f9b6. This ensures the maximum string length being logged no matter in which order the unit tests are being run.

I'm glad to hear that the timestamp issue is working on the new machine! Since I can't reproduce it, I'll leave it for now.

I will have a look into the issue with FB_FileClose. I somehow have the suspicion it could be due to logging every cycle. Did you run any tests with fewer logging calls?

[slabarque]

I think it is indeed related to logging every cycle, my cycle time is 50ms, I tried the following:

• logging once every 10 cycles => that works
• changing the cycle time to 500ms => that does not work

[bengeisler]

I can reproduce this issue with a unit test introduced in 4fd3dbc. I'm working on a solution to this, but I need some time. I don't want to wrap all the file system calls into a while loop to finish it in one cycle because logging is not the most important job of a real time system.

I guess the underlying problem is that in every cycle log messages get appended to the buffer, and in each cycle one log message gets appended to the file, so the file is kept open. When you keep logging forever, the file stays open forever...

For now, I'd suggest you use triggered logging as it is described here. For logging every cycle TcLog is probably not the right tool. You can have a look at TwinCAT Scope which could be more appropriate for this.

[bengeisler]

Hi @slabarque,

I did some more work on this in 6c01f09. The unit test is now parameterized and tests up to 100 consecutive logging calls. To be able to do this, I increased the string buffer size that works in the background and caches the logging messages. To make this more explicit, I introduced a breaking change: the buffer size has to be specified in the declaration of TcLogCore like this:

VAR
    CoreLogger  :   TcLogCore(nBufferSize := 100000);
END_VAR

I updated the library to version 0.2.0.

Let me know if that works for you :)

[slabarque]

I did some tests and I definitely get better results, at least if I stick to 1 log line per cycle. But like you said, logging is not a mission critical part of a PLC system and should only be done when there is time left (or asynchronously so it does not block other, more critical, code). As mentioned before I come from a different background, that is software development, where cyclic near real-time processing is not that much of a concern. So I am using this library in a way it was not designed for: I am running 21 TCUnit tests that all log 1 line per cycle, so that's 21 lines per cycle! That is a lot of I/O-work to do in 50ms, too much it seems.

I would make sure that your documentation warns about not using the library this way. Only logging on certain special events (using triggers) makes more sense.

Thanks for pointing me in the direction of TwinCAT Scope, I definitely check that out.

One minor bug I encountered during my latest tests with 0.2.0: when the total log message exceeds 255 chars the message is truncated (which makes sense), but also the line feed (new line) is cut off which makes the next message appear on the same line.

Thanks for your time and investing in open source code for PLC!

[bengeisler]

Actually, I think the point is more to stop logging at some point than how many logs per cycle you use. I introduced a new unit test in 76fdfd4 that logs 100 messages in one cycle, but only once. So if you could refactor your TcUnit tests in a way to only log the results, 21 of them in one cycle should absolutely be feasible (given the buffer size is large enough).

Also, there should be not too much I/O overhead, since all the log messages are cached and the file is opened once, all messages get popped from the cache and written into the file, then the file is closed. Thats why the persisting mechanism is "baked into" the logger. However, the state machine responsible for this action only does at most one thing per cycle. This means, if you log 21 logs in one cycle, you'd have to give it 21 + 2 cycles in order to persist the data. That does not necessarily mean that you have to take a break after each logging, but you need to stop logging before the log message buffer overflows. As you said before, logging is not mission critical, so I designed the library rather conservatively.

As for the missing truncation above 255 chars: I use the FB_FilePuts from Beckhoff, which is designed to write every string on a new line. The datatype T_MaxString can take more than 255 chars, but as Beckhoff notes, the string functions can only handle 255 chars. I'd stick to that limit in order to avoid unspecified behavior.

[slabarque]

I've tried some things based on your recommendations. When I log x messages in 1 cycle and then wait x+2 cycles I get good results but that is not feasible as a permanent solution in my case. When init with a large buffer size (I tried 100000 and went up to 1000000) and I log x messages per cycle for y cycles and then wait x*y+2 cycles I still get the fileClose issue (where x = 21 and y = 17). I'm running out of investigation time, so I will stick to ADS logging for these TcUnit tests and will experiment more with file logging and triggers on a next project.

I also added some additional logging to TcLog to investigate the fileClose issue was amazed to see that the DynamicStringBuffer goes from state STATE_APPEND_DATA_TO_FILE to STATE_OPEN_FILE.

If you are interested I can give you access to my project on Github. It is a project I made to review some code a colleague of mine wrote and demonstrate to him the importance of unit testing and logging.

Thanks for your time!

[bengeisler]

Hi, thanks for the idea with logging the state machine! I'll have a look at this. I'm about to finish my masters thesis, so I'm also a little bit short of time right now. I can't promise to fix it within the next days.

However, I'd like to point out that the persisting mechanism is optional for this library. You can also use it to log to ADS, but with the added benefit of the string builder built in. Maybe that's helpful in your case.

I'd be happy to have a look at your project to run my fixes against it. And I'm also happy to see that logging and unit testing are slowly making their way into the PLC world :)

[bengeisler]

I finally found time to follow up on this issue and fixed it in #4. Thanks for the detailed analysis, it was very helpful!

I introduced unit tests for testing up to 50 consecutive cycles with 50 messages logged per cycle without any problems.

I found that for x cycles with y messages each it takes roughly x * y * 4 + 4 cycles to persist them. Better allow for some more cycles.

The necessary buffer size can roughly be calculated by x * y * ~270. 270 is just a rough guess, the Beckhoff info system is quite vague about it. It should be the max string size + a little bit.

Do you still have your project so I can test the fix against it? Thanks!

[slabarque]

I'll try make some time in coming days to check the fix.

[bengeisler]

Thanks! There is a new release that introduces a major performance upgrade for the persistence mechanism and allows to persist up to 100 messages per cpu cycle. The total time is roughly 1.5 * # consecutive cycles with logging. A unit test with 50 consecutive logging cycles and 50 logs per cycle executes now within 75 cycles compared to 10.004 cycles in the last version.