Add `ITcoLogger` interface and default logger implementation.

[github-actions[bot]]

closes #139

[PTKu]

Hi, guys I drafted this PR indicating where the logging could go... I would leave it to you if you think it is more appropriate to do it some other way... the only thing I would ask... let's be OOP.

@RGrabichler @philippleidig

[philippleidig]

Unfortunately, I am unable to push my basic idea onto this pull request due to missing permissions.

@PTKu, do I need any special access right?

[PTKu]

@philippleidig check again, please.

[philippleidig]

Thank you, it worked :) Alltough "stefan-koehler" is displayed as the author. But that should not detract from the actual idea.

[jozefchmelar]

@philippleidig very well documented code!

[PTKu]

@philippleidig looks great to me!!! Thanks!

I just synched with the 'dev' branch.

I've been looking at @benhar-dev CSV logger; we may get some inspiration there as well...

Would you mind setting LineIDs into a separate file?

We will have fewer irrelevant changes in the repo.

I do not know who stefan-koehler the committer is 😄 but it is probably because of your git settings... you should check the name and email.

[philippleidig]

I didn't know @benhar-dev CSV logger at all. I'll definitely have a look at it for some inspiration, thanks :) You're right, my mistake. The "seperate line-id" setting was still wrong as I did some tests for clients. Thanks for the hint!

The basic idea is to pass the explicit implementation of a logger from the outside. This allows the user of the library to decide for himself where to log. Similar to the use of C# Serilog with different sinks.

[PTKu]

@philippleidig that's the way to go... we should allow for different sinks!

I am simultaneously working on logging user actions from the front-end application... this will be an inxton related feature. There is a preliminary implementation of Serilog.

I am saying this here to avoid confusion as we have two logging-related activities in the repo. This one here aims to log messages from the PLC, the other one the user-activity.

I will keep in mind that we should envision the use of higher-level logging frameworks for use without inxton... and will try to keep it organized that way.

[philippleidig]

@PTKu sounds very good! I like the idea of outsourcing the evaluation and display of log messages in order to be able to use existing tools.

A few years ago I made an ASP.NET web service including Angular front-end and a TwinCAT ADS server for live stream logging via SignalR / websocket and to other destinations with Serilog. Basically, it was just a cyclic PLC buffer that sent the data to the ADS server in the ASP.NET web service at regular intervals via fire and forget. Via the front-end, the log level and destination of individual logger instances could be configured in the PLC. However, it was never used productively.

In general it was similar to this (new) project by mbc-engineering. https://mbc-engineering.github.io/log4TC/

[PTKu]

@philippleidig would have a look at https://github.com/TcOpenGroup/TcOpen/pull/140/commits/3d0c83b756d07407cc7741f6b84fbfbc5807de1f I fixed some build (CheckAllObjects) issues with the logger code.
There some blocks added; experimenting with Context builder, but those are build-disabled you can ignore that for the moment.

[philippleidig]

The approach with the ITcoContextBuilder looks very promising. I'll have a deeper look at it :-)

[PTKu]

The approach with the ITcoContextBuilder looks very promising. I'll have a deeper look at it :-)

I am just sketching it... the idea is to have explicit implementations injected with the builder pattern. I would like to have separate instances for loggers and other stuff for each context. The reason for that is to avoid concurrency/race conditions when using multiple PLC tasks in the same program...

[philippleidig]

@PTKu, I have spent the last hour trying to implement the basic idea of .NET Serilog within TcoLogger at commit. The whole implementation is strongly inspired by https://serilog.net/. In order to be able to use it in general, however, there is still a lot missing. Since I am unsure whether this approach makes sense, I wanted to hear your opinion or that of others.

Whether this idea is generally suitable for use in the PLC, I am currently still unsure. I think it could quickly reach its limits. In addition, the approach is very bloated for logging only.

The idea was to use a general sealed/final logger TcoLogger. The user of the library can then extend the TcoLoggerConfiguration with his own sinks and enrichers via inheritance. I have implemented two example extensions with "ExtendedLoggerSinkConfiguration" and "ExtendedLoggerEnricherConfiguration".

[PTKu]

@philippleidig I am having a look into it. The implementation is very interesting and worth exploring further. I like it... My concern is performance issues but before we can judge we need to make some testing. Give me a couple of days to explore it in more detail. Will try to design some test to see where we are from the performance perspective. and how we can optimize.

[RGrabichler]

@PTKu encouraged me a long time ago to try things out with the TwinCat EventLogger. Here i want to share my approach and how i used it. As i am still not able to build the whole project and also am not sure, how to contribute with pull request i just lay out my idea here and we can further talk about it.

The Architecture of my Implementation consists of:

• Interface Ifault
• corresponding so called "features", the implementation of the interfaceD
• Composition of this features in my Actuator-Models for the internal fault-evaluation
• Component of iFaultCreator for general Faults

Pros:

• i can change my Implementations, as long as the interface remains
• manually tested and working system (unit testing has to be added)
• usable in different components, just mapping and it works
• with tf2000, beckhoff hmi, easy logging and displaying

Cons:

• i need to create the eventClasses in the menu Type System, perhaps better ways possible

Enhancements:

• logging of different severity level with filtering
• ...

If the pFault Property is set, in the mSetFault() Method get the mCreateEvent() and mRaiseAlarm() called once. _alarm.ipArguments.Clear().AddString(_InfoName);

i can and will improve/alter the necessary interfaces, because im not fully satisified. So i can easily change this to requirements. I tried a few things with tests with TcUnit and will try to add tests.

If this looks promising, i need guidance to start implementing this, because im pretty overwhelmed by the speed and information, how this is going on.

[PTKu]

@philippleidig I have been playing a bit with the design. It seems kind of heavy. My CX2040 goes black even before running the program 😄, when I run it on my Xeon workstation it seems to run. I do not know the exact reason yet. I will give it a try again tomorrow. Maybe we could think about a single sink on the PLC side and rather deffer the collection of messages in the higher-level applications e.g. C#.

[philippleidig]

@PTKu Holy ... I knew it was performance intensive, but I didn't expect that even a CX2040 would "reach its limit" 😄

I will also check more closely what the cause is in the next few days. Perhaps the fluent interface code style is the problem in general?!

But I totally agree with you that we should significantly reduce the number of possible sinks. The call of Info(), Warning(), etc. should be as lean and performant as possible. However, in my opinion, it should not be necessary to call a logger cyclically.

I just generally like the way Serilog defines the logger configuration. 💯

[PTKu]

OFF TOPIC! @philippleidig automation interface is giving me (us) headaches for a long time. The only reason why we use is for compiling plc libraries and to add/replace libraries in the project (we use nuget to deliver packages). The main problem is that it wraps around VS which brings a lot of instability in the automated pipeline. We have to click occasionally on some dialogue and so CI/CD becomes semi-automatic. It also requires to have VS installed on the agents. Would there be a way something like CLI that would compile the library and install dependencies?

[PTKu]

@PTKu encouraged me a long time ago to try things out with the TwinCat EventLogger. Here i want to share my approach and how i used it. As i am still not able to build the whole project and also am not sure, how to contribute with pull request i just lay out my idea here and we can further talk about it.

The Architecture of my Implementation consists of:

• Interface Ifault
• corresponding so called "features", the implementation of the interfaceD
• Composition of this features in my Actuator-Models for the internal fault-evaluation
• Component of iFaultCreator for general Faults

Pros:

• i can change my Implementations, as long as the interface remains
• manually tested and working system (unit testing has to be added)
• usable in different components, just mapping and it works
• with tf2000, beckhoff hmi, easy logging and displaying

Cons:

• i need to create the eventClasses in the menu Type System, perhaps better ways possible

Enhancements:

• logging of different severity level with filtering
• ...

If the pFault Property is set, in the mSetFault() Method get the mCreateEvent() and mRaiseAlarm() called once. _alarm.ipArguments.Clear().AddString(_InfoName);

i can and will improve/alter the necessary interfaces, because im not fully satisified. So i can easily change this to requirements. I tried a few things with tests with TcUnit and will try to add tests.

If this looks promising, i need guidance to start implementing this, because im pretty overwhelmed by the speed and information, how this is going on.

@RGrabichler thanks for the input... I would like to prepare a short video explaining how to make PR and in general how to work on GitHub... we may also schedule a meeting online to chat about this topic if there is an interest. There is basically no tradition to work open-source in industrial automation... we shall all learn along the way 😃

[PTKu]

@philippleidig I did not have much time to look deeply into this.. and need to get some rest over the weekend... anyways I did some attempts to make it work but without much success... could you see it you can run it on your hardware and eventually find out why the plc goes black... if you are able to replicate. Nice weekend!

[philippleidig]

@PTKu, hope you had a relaxing weekend :) After a long search, I have found the somewhat strange cause. Now I understand what you meant by "goes black". The PLC task does not even start. I can't quite explain it at the moment, but I have found a solution.

The transfer of TcoLoggerConfiguration via FB_Init to TcoLoggerSinkConfiguration as probably the cause. I have now passed this via VAR_INPUT as specified in the general TcOpen conventions. Since then it has been running without problems.

On a CX2042 with 5000 logs (2 sinks, 2 enrichments, 2 arguments) per PLC cycle I get a duration of about 4ms. The duration increases almost linearly with the number of sinks and enrichments. From my point of view, a significantly better performance should be achieved here.

[PTKu]

@PTKu, hope you had a relaxing weekend :) After a long search, I have found the somewhat strange cause. Now I understand what you meant by "goes black". The PLC task does not even start. I can't quite explain it at the moment, but I have found a solution.

I had a somehow relaxing weekend mowing the lawn 😄

My CX2040 still goes down each time I activate configuration (not even starting the plc program; it restarts the whole system). The same thing is happing on build agents. What is the environment where you run it? (runtime version, etc.?) In the case of my workstation, I am able to activate the configuration, download the program, and start the run; however, I have the same issue you mention with the actual plc task not entering the cyclical execution

I had this sort of problem in the past and it must have been related to some obscure configuration/environment, I was really never able to find the problem in the actual PLC program.

The transfer of TcoLoggerConfiguration via FB_Init to TcoLoggerSinkConfiguration as probably the cause. I have now passed this via VAR_INPUT as specified in the general TcOpen conventions. Since then it has been running without problems.

On a CX2042 with 5000 logs (2 sinks, 2 enrichments, 2 arguments) per PLC cycle I get a duration of about 4ms. The duration increases almost linearly with the number of sinks and enrichments. From my point of view, a significantly better performance should be achieved here.

5k logs is a lot! Is it per PLC cycle?

[philippleidig]

I'll try to recreate the behaviour again on a second target system. I am currently using a CX2042 with XAR 4024.12 on an isolated core.

Yes, the 5k logs are per PLC cycle via a FOR loop each cycle. Per cycle it took about 4ms to execute the code.

[PTKu]

I'll try to recreate the behaviour again on a second target system. I am currently using a CX2042 with XAR 4024.12 on an isolated core.

I do run in a non-isolated core... will try in isolation. I am using 4024.15 engineering and 4024.12 on the target.

BTW I when I tested this branch this morning the PLC went down, but interesting was that when I switched to another branch the PLC went down as well, I had to clean the solution (removing all from _Boot, _CompileInfo, etc.) then I was able to work again... there is something strange at times happening... I do not think it is actually your code.

Yes, the 5k logs are per PLC cycle via a FOR loop each cycle. Per cycle it took about 4ms to execute the code.

I would not worry about the performance at this point. I think there is room for improvement. What worries me more is how many of those messages we can transfer in upper-level sinks (windows logs, rolling files) without losing some of them...

I would consider having a single logger instance on the TcoContext, instead of having a logger on each TcoObject.

[PTKu]

@philippleidig

I get this:

not sure what it exactly means any idea?

[philippleidig]

@PTKu, I guess it's the dynamically allocated memory inside the RingBuffer function block.

The block still comes from comparisons of performance between dynamically allocated memory with __NEW and the new Tc3_DynMemory library.

I'll take a closer look at the behavior when I get a chance. You can also simply comment out the declaration in the "VolatileSink".

Enjoy your weekend :-)

[PTKu]

@philippleidig thanks! This was a pretty peaceful weekend... got to rest 😄 We are getting pretty detached from the dev branch here... I am thinking about creating a separate library for the logger that would allow us to work in a cleaner way... I would move the interfaces to the TcoAbstraction and the logger logic into a separate project TcoLogging then we can use a form of DI to inject into TcoContext/TcoMessenger.... what do you think? (It would be also easier to test and debug the Logger in that way)

[PTKu]

@philippleidig I did not have much time recently, but finally I managed to place the logging into separate library. I may have misplaced something. The logging library is in src/TcoLoggers/TcoLoggers.slnf. When you have time have a look. Let's continue in that folder until we have it working and tested.