Discussion about our logging mechanism

OpenEMS Tech Exchange
1

Hey everyone,

We had a Tech Exchange session today where we discussed our Logging Architecture and where we want to take it next.

The slides from today’s session are attached to this post:

Logging discussion.pdf (174.2 KB)

Key topics we covered:

  • How do we pass the logger (without losing the component id) to other objects in a OpenemsComponent?
  • How do we log exceptions? Can we log the full stacktrace and not only the exception message?

We’re currently looking into Log4j2 Markers to evaluate how they could improve our logging strategy.

Feel free to review the slides and share your thoughts, questions, or concerns in this thread.
Looking forward to the discussion!

2

this hunts me for quite some time as well. In our fork, we changed some log messages to the standard log interface again to get stack traces. Some errors are just super hard to get. I understand the intuition behind the custom log interfaces, but I’m totally in favor in keeping this with markers. It has only upsides - no one has to get used to a project specific logging interface.

However, since this is a bigger change (>500 calls) I’ve avoided that up to now. I’m happy that you bring that up :wink:

Are you planning to implement that?

slf4j offers an elegant way to do that (I’ve skipped the boilerplate overwrites in this example, to focus on the important bits):

public final class ComponentLogger extends AbstractLogger {

      private final Logger delegate;
      private final Supplier<String> id;

      private ComponentLogger(Logger delegate, Supplier<String> id) {
            this.delegate = delegate;
            this.id = id;
      }

      public static Logger of(OpenemsComponent c) {
            // id() is only set in activate(), so resolve it lazily
            // (falling back to getClass().getSimpleName(), like getComponentIdentifier())
            return new ComponentLogger(LoggerFactory.getLogger(c.getClass()), c::id);
      }

      @Override
      protected void handleNormalizedLoggingCall(Level level, Marker marker, String pattern, Object[] args, Throwable t) {
            var message = "[" + this.id.get() + "] " + pattern;
            var arguments = t == null ? args : append(args, t); // trailing Throwable = the cause
            switch (level) {
              case ERROR -> this.delegate.error(message, arguments);
              case WARN -> this.delegate.warn(message, arguments);
              // ... INFO / DEBUG / TRACE, plus the Marker variants
            }
      }

      private static Object[] append(Object[] args, Throwable t) {
            if (args == null || args.length == 0) {
                  return new Object[] { t };
            }
            var result = Arrays.copyOf(args, args.length + 1);
            result[args.length] = t;
            return result;
      }
}

Migration is then one line per file:

- private final Logger log = LoggerFactory.getLogger(FooImpl.class);
+ private final Logger log = ComponentLogger.of(this);

For your other questions in the powerpoint:

  1. logging format: we switched to json, makes it much more flexible to parse
  2. How can we store the logs without destroying the flash? > If feasible consider using a log server like Loki in your backend infrastructure. Then you’ll also have an easier time to answer the rest of your questions I hope :wink: