Create a logging facility

[janfeitsma]

Given that all data (including state) is explicit on the interface, it is only natural to log it to file for every tick. That would help with troubleshooting and test driven development.

Currently I just use a lazy approach: #define DEBUG at https://github.com/janfeitsma/MRA-prototype/blob/main/components/falcons/velocity-control/tick.cpp#L9 This has been proven valuable and I think it is time to mature it into a facility.

Jurge suggested spdlog, it seems very powerful.

Some ideas / thoughts:

• default disabled, define some environment variables MRA_LOGGING_ENABLED etc
• log tick durations
• data format
  • json is easiest to read&manage
  • but if data size grows large, we might want to go for something like hdf5
• prevent excessive file growth
  • zip compression?
  • only log changed data? especially params is supposed to not change often.
• include function tracing? (see falcons TRACE and TRACE_FUNCTION)
• make it possible to visualize ticks / durations using Catapult traceviewer
• make it possible to extract data series for plotting over time (matplotlib? kstplot?)

Please add thoughts and ideas in this thread! (Jurge, share your ideas from the ppt?)

[jveijck]

• I suggested spdlog, because it seems to be a mature component. It is quite a generic component, therefore it is better to use an existing well supported component, then writing itself. (Just wrap it)
• Enabling should be configurable for all components and/or individual components. A default setting for all components and an more extensive for the component under test/development.
• Logging is preferred in a separate thread to prevent it is blocking the main loop.
• It would be useful if logging in memory is supported and on a trigger the data is written to file (in case of failure)
• Separate logging collection and logging processing
• Logging processing (ideas)
  • plot data in time (time on x-axis and data on y-axis)
  • create plot based on given component name, phase (if pre and post tick is used), data.name, plot-color, line-style, scaling
  • plotting via script (fixed plots) or UI (interactive)
• compressing logging can be useful if files become big (plot and analyse tooling should be able to handle this)
• I suggest also allow logging before and after tick : can be used to log changes in state. At least logging after each tick, but then a crash in the tick is harder to see (and reproduce)
• Each component should have a unique id to distinguish between components.
  • should subcomponent id be possible ? getball-fetch and subcomponents (variants): getball-fetch-asml or getball-fetch-robotsports. This allows generic tooling for same component and see differences between variants.
• logging should be unique with following key: component-id+ timestamp +phase
• I prefer complete logging instead of only the changed data, because tooling must be more intelligent to catch the last occurence of unchanged data. (or log per variable, then latest logging of a data piece can be easily found)

[janfeitsma]

Started with a first quick version to replace the #ifdef DEBUG stdout dumping. I also added binary file dumping, which is useful because I now need to plot opencv protobuf data, rather in python than C++.

No configurability, spdlog yet etc.

Here you can see how it is currently used as oneliner, that is also close to how I intend to have it at each tick.cpp: https://github.com/janfeitsma/MRA-prototype/blob/localization-from-scratch/components/falcons/localization-vision/tick.cpp#L26

Note for instance how that scoped object logs the state before and after tick. Might need some more macro/codegen sauce to figure out component etc.

[jveijck]

The proposed WoW requires that every component it must implement it self. I had the idea to replace the abstract MRAInterface class by a MRAcomponent class. Each MRA component will inherited from it.

This allow to create generic methods like:

• get_component_id() = 0 (must be implemented by each MRA component)
• attach_logger
• detach_logger.
• implement generic tick algorithm. Each component must have a calculation method (abstract in base class). Then in the tick logging of inputs can be optional done (only if logger is attached), then calculate (component tick), optional logging of outputs. -also internal logging can be provided via the base class.

Roughly the following sequence diagram will be used

[jveijck]

the baseclass approach also allow to monitor the calculation time etc.

[janfeitsma]

I agree, it is almost time to rework the fundaments of the component, using such a baseclass for instance. But that is an activity which we may want to hold off until gathering input from other MSL-MRA community members. Related to that, note how this is a prototype repository. It was intended a) to demo and b) to get experience. It has served its purpose. Now I have a much better feeling for what we want and roughly how to do it. So perhaps it is better to start fresh in MSL github project, afterwards migrate all prototype content / good concepts into it.

[janfeitsma]

Let's leave the base class and codegen ideas out of scope for now. It would have far too large impact... need to discuss with MSL-MRA community.

Also I prefer to hide stuff like attach/detach from developers. Macros can handle this for us?

Some design ideas/directions which I soon want to dive into, make a branch from yours. Some is very similar as we already have or as you added; some new stuff.

• for now, components need to include logging.hpp explicitly and specify the dependency, no base class / automation (that is left for later)
  • example: components/robotsports/proof-is-alive/tick.cpp
• no compile-time #define DEBUG anymore
• not strictly related: whitespace: no tabs, instead spaces [4]
• define a LogRecord, which is an object that lives during a function call and would be written/dispatched on function exit
• we need to use macros, because these can detect file and line number, derive component
• proposal for macros
  • MRA_LOG_FUNCTION;
  • log any function start+end, only timing, no i/o data
  • put this one on top of the function
  • it will use a scoped object to detect function exit
  • MRA_LOG_TICK();
  • log the standard MRA component tick function with specific i/o protobuf data
  • put this one on top of the function (later: automatically, if we would generate tick function)
  • specifically can write .bin file, if enabled
  • as current logtick::scoped
  • MRA_LOG_FORMAT(...); MRA_LOG_FORMAT(loglevel, ...);
  • these behave as printf, can be put anywhere
  • as your log(...) additions
  • MRA_LOG_FUNCTION_INPUT(...); MRA_LOG_FUNCTION_OUTPUT(...);
  • put anywhere (input typically at the top, output typically at bottom)
  • modifies current record
  • intended for arguments which are input/output to the function (either on interface)
  • requires a string for now (or something that can be converted to string?)
  • used by LOG_TICK
• make a logging_backend which wraps spdlog or equivalent to handle the log records (rename MRA_logger)
• make a logging_controller which is used by backend and can be manipulated externally (environment variables, commandline)
  • to start/stop logging of certain components
  • to set target file, set log level, etc
  • probably using IPC

[jveijck]

The point about spaces vs tabs, can perhaps solved by a pipeline action. (convert tabs to spaces). Let's discuss the points when we speak, I agree on most points, but some are not 100% clear. We can also check if the original points are addressed as we originally intended.

[janfeitsma]

Open issue: how should we handle logging of nested components.

In a different branch, building on top of the open PR, I am enabling tick logging for all my components. This is what we get during testsuite:

-rw-r--r-- 1 jan jan    651 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsGetballIntercept.log
-rw-r--r-- 1 jan jan    651 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsGetball.log
-rw-r--r-- 1 jan jan   4239 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsGetballFetch.log
-rw-r--r-- 1 jan jan   6750 Sep  8 08:01 /tmp/testsuite_mra_logging/RobotsportsProofIsAlive.log
-rw-r--r-- 1 jan jan   3312 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsTrajectoryGeneration.log
-rw-r--r-- 1 jan jan 586539 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsVelocityControl.log
-rw-r--r-- 1 jan jan   6227 Sep  8 08:01 /tmp/testsuite_mra_logging/FalconsLocalizationVision.log

The component FalconsTrajectoryGeneration uses FalconsVelocityControl. Bazel test runs all tests in parallel. The logging of FalconsVelocityControl shows two running tick logs interlaced...

I am thinking of having nested logging in the calling component, so in this example: FalconsTrajectoryGeneration.

Another minor note: maybe tick io logging should be at debug level, not info level.

[janfeitsma]

I think PR #24 is good enough to close this open issue, since a lot of ground has been covered now.

[janfeitsma]

Mostly completed

[jveijck]

I propose to make a new issues if remaining functionality is required. A big step forward is made via this issue.