tango-controls/TangoTickets

[question] log message format

Closed this issue · 9 comments

Is there a way to change the tango logger message format?

I think it is done here: log4tango/src/PatternLayout.cpp

Currently I have

1600871748 [140114969720640] DEBUG id00/bliss_nxwriter/nexus_writer_session -> NexusWriter.scan_exists()
1600871748 [140114969720640] DEBUG id00/bliss_nxwriter/nexus_writer_session <- NexusWriter.scan_exists()

which weirdly does not correspond to

#ifdef LOG4TANGO_HAS_NDC
    const char* PatternLayout::BASIC_CONVERSION_PATTERN = "%R %p %c %x: %m%n";
#else
    const char* PatternLayout::BASIC_CONVERSION_PATTERN = "%R %p %c %m%n";
#endif

I would want to change it to

DEBUG 2020-09-23 16:35:48,967 id00/bliss_nxwriter/nexus_writer_session -> NexusWriter.scan_exists()
DEBUG 2020-09-23 16:35:49,015 id00/bliss_nxwriter/nexus_writer_session <- NexusWriter.scan_exists()

Hi @woutdenolf

I don't think there is a way to change it. You are right that it is done in the cppTango layer. I would have liked to change it for SKA work, but we ended up implementing our own Python logging and monkey patching the log methods like debug_stream. Then added a Python logging handler that forwards our formatted messages to the standard Tango logger again. Of course for logs forwarded to a Tango logger, we still get the standard format. However, in general use, we write logs to stdout, and that goes directly into ElasticSearch.

I have moved this issue from PyTango to the more general TangoTickets repo, so cppTango and JTango developers can comment.

t-b commented

I've just dived a bit into the code.

So I don't think there is a way without touching cppTango code. Your proposed format is also not optimal. The timestamp should be a standard format like ISO8601, i.e. "2020-09-23T16:35:49.015" . Maybe even with timezone information.

I can imagine having the pattern be configurable in cppTango. FYI: The original developer of log4tango has left the project. If you start diving into it I'm happy to review your API change proposal.

The original developer (@nleclercq is still around 8-) maybe he can comment ...

I'm there :)

Tango appenders (i.e. coutappender, tangoappender, rollingfileappender) inherit from log4tango::LayoutAppender (1). It means that one can write a custom log4tango::Layout (or log4tango::PatternLayout) and attach it to any of the appenders currently attached to the tango device logger (i.e. tango or user defined appenders).

The idea is to first get a reference to the device logger (there's only one logger per device instance):

log4tango::Logger *logger = my_device->get_logger();

We can then obtain the list of appenders from the logger:

AppenderList appenders = logger->get_all_appenders();

We finally attach our custom layout (e.g. BlissLayout) to the existing appenders (pseudo code):

for appender in appenders:
    appender->set_layout(new BlissLayout());

EDIT: this would have a side effect on the tango::rollingfileappender which makes use of a log4tango::XmlLayout. The latter is the format expected by the LogViewer.

Hope this helps.

(1) I just discovered that the tango::tangoappender inherits from log4tango::Appender but supports the log4tango::LayoutAppender interface. That's just a trick to have a uniform interface. The tango::tangoappender::set_layout does nothing.

Regarding the OP's use case, we would have to expose a tango::Device::set_logging_layout(const std::string& pattern) in order to be able to easily change the log pattern.

A typical implementation would be:

void tango::Device::set_logging_layout (const std::string& custom_pattern)
     AppenderList appenders = this->get_logger()->get_all_appenders()
     for appender in appenders:
         log4tango::PatternLayout *pl = log4tango::PatternLayout()
         pl->set_conversion_pattern(custom_pattern)
         appender->set_layout(pl)

Have a look to the log4tango::PatternLayout documentation for syntax details of the "custom_pattern" parameter.

EDIT: this would have a side effect on the tango::rollingfileappender which makes use of a log4tango::XmlLayout. The latter is the format expected by the LogViewer.

t-b commented

@nleclercq Thanks for chiming, much better compared to what I figured out in half an hour.

I just stumbled over the same peculiarity that timestamps in logs are not comprehensible by human beings.

Do I understand the above correct, that there is no official Tango way to modify the log line format in Python?

t-b commented

Do I understand the above correct, that there is no official Tango way to modify the log line format in Python?

I'm afraid yes.

Wow. That's very unexpected because I thought that the incomprehensible timestamps were something that had been added later.

Well, good that SKA has it already figured out. I guess that we then tag along with their logging module. 😄

Thanks for replying, @t-b .