DM-30996: Implement log4cxx appender which logs to Python logging #55

andy-slac · 2021-07-06T21:20:03Z

Adds new log4cxx Appender class that forwards everything to Python logging.

Work in progress, most things should work already, still need to figure out best way to handle MDC.

src/PyLogAppender.cc

src/PyLogAppender.h

ktlim · 2021-07-07T01:00:02Z

src/PyLogAppender.cc

+};
+
+/**
+ *  Re-raise Python exception as C++ exception.


Are you sure that we can't let this propagate through Python directly without catching it and possibly losing information? Seems like a shame otherwise.

This is not possible unfortunately. Usually C++ wrappers catch C++ exceptions and replace existing Python exception with contents of C++ exception message, so the only way is to save whatever info we could in C++ exception.

Even if we were to define an additional C++ exception type like PythonException and change pex_exceptions to detect it?

I think this is controlled by the code which wraps the C++ calls, catches C++ exceptions and converts them to Python (pybind11 or anything else). I'm not sure that different exception class can provide more control over that.

I thought we own at least some of this code at https://github.com/lsst/pex_exceptions/blob/master/python/lsst/pex/exceptions/exceptions.cc#L156-L164

I tried to look at that but it will take time for me to learn how it all works. If we want to add pex_exceptions as another dependency here maybe there is someone already knowledgeable at that who can look at new code. OTOH, most of the exceptions that I generate should not have Python traceback, so maybe it's fine to drop it?

Yeah, it's fine to keep this as is.

src/PyLogAppender.cc

doc/mainpage.dox

src/PyObjectPtr.h

Co-authored-by: Kian-Tat Lim <ktl@slac.stanford.edu>

andy-slac · 2021-07-08T05:27:03Z

@ktlim, I am messing around with all ideas and I have found issues that further complicate my already complicated plan.

I was hoping to make layout configuration optional and it almost worked that way, but unfortunately log4cxx generates an error message when layout is skipped in configuration:

    log4cxx: Could not find value for key log4j.appender.PyLog.layout

It is possible to suppress errors when parsing configuration but this also means missing all other possible errors in configuration. It looks like the only option for now is to drop support for layout and modifying message part of the LogRecord, and instead rely on LogRecord.MDC attribute and its rendering by logging formatters.

Another issue is the interaction between log4cxx and Python in MDC control/initialization, I'll need a bit more time to think about that.

ktlim · 2021-07-08T05:39:58Z

The error doesn't have something to do with https://github.com/lsst/log/blob/accbc96b7321847d4fc4cb6631d63964bfd86104/src/PyLogAppender.cc#L220-222, does it?

andy-slac · 2021-07-08T15:36:12Z

It does. I wanted to make layout optional but if I make requiresLayout return false then layout is never created even if it exists in configuration. Returning true does make layout optional, it prints this error message but continues to run without layout. I guess I need some other way to make a layout.

andy-slac · 2021-07-08T18:19:31Z

@ktlim, I have re-implemented much of the appender code to make/update one MDC attribute of the LogRecord. I do not know how to implement that convenience method that you mentioned, the code that needs that method (in daf_butler today) is supposed to run without lsst.log being setup, and there is some additional per-logger logic there that does not fit that simple model. I guess we'll figure it out when we update daf_butler.

If LogRecord does not have `MDC` attribute already then create it as an instance of a special `lsst.log.utils._MDC` dictionary class. If `MDC` attribute is already there (added by record factory) then assume it is a dictionary and update it with MDC contents. This allows adding MDC items at Python level as well.

ktlim

Looks great!

doc/mainpage.dox

ktlim · 2021-07-09T00:34:55Z

python/lsst/log/utils.py

+    This is internal class used for better formatting of MDC in Python logging
+    output. It behaves like `defaultdict(str)` but overrides ``__str__`` and
+    ``__repr__`` method to produce output better suited for logging records.
+    It also provides namespace-like access to


"too."? Or "to keys"? Or something else?

I was obviously distracted by something important (squirrels or 🐱), will expand 🙂

I am actually inclined to drop attribute-like access and only keep indexing access. It may be convenient to say MDC.key instead of MDC[key] in format string but it does not work for keys that do not look like identifiers, and it sort of adds additional requirement on other implementations of MDC dictionary.

I'm fine with just doing **MDC and having the formatting find the right element. We can always add the .key later. In python logging I would probably add **MDC directly into the kwargs in the LoggingAdapter and pull them out of the LogRecord directly later on.

But that exposes you to potential attribute collision.

Yes. If someone sets MDC to lineno or something. People can indeed shoot themselves in the foot like that but why would they? I don't think python lets me use a format string of %(extra['LABEL'])s though so how would I ever include it in a logging format string?

Use style='{'.

Okay. Hmm. So we are okay with a LogFormatter using f-style but all the Loggers using %-style?

Loggers don't have an option for style (would be nice to have but probably hard to implement). Formatter style is set in the same place as format string so we should be OK if we do it consistently.

python/lsst/log/utils.py

src/PyLogAppender.h

doc/mainpage.dox

Co-authored-by: Kian-Tat Lim <ktl@slac.stanford.edu>

`_MDC` is renamed to `MDCDict` and moved to `lsst.log` to avoid circular dependencies when implementing new `configure_pylog_MDC` method.

andy-slac · 2021-07-09T18:20:47Z

OK, I think I resolved all comments now, will merge in ~1 hour unless there are objections.

New convenience method to configure forwarding is configure_pylog_MDC(level: str, MDC_class: type[dict] = MDCDcit) and MDCDict had to be moved from lsst.log.utils to lsst.log to avoid circular imports.

Previous location caused usual mess with dynamic libraries in Python, it should work better in Python module. Both locations are probably not right for that piece of code but I do not want to introduce another dynamic library just for that class (and it also depends on Python module).

Just an additional protection, not really needed in this code, but may be useful if someone else uses it.

andy-slac added 4 commits July 6, 2021 13:16

Implement log4cxx appender which logs to Python logging (DM-30996)

faf8b6c

Work in progress, most things should work already, still need to figure out best way to handle MDC.

Improve MDC handling

5af06f0

Add PyLogAppender documentation

6598c04

Add unit test for PyLogAppender

011c47f

andy-slac force-pushed the tickets/DM-30996 branch from e4d811e to 011c47f Compare July 6, 2021 21:22

ktlim approved these changes Jul 7, 2021

View reviewed changes

andy-slac and others added 2 commits July 7, 2021 11:35

Update doc/mainpage.dox

accbc96

Co-authored-by: Kian-Tat Lim <ktl@slac.stanford.edu>

Implement review suggestions

686aa24

timj mentioned this pull request Jul 7, 2021

DM-30977: Add python log handler to store LogRecord as they come in lsst/daf_butler#546

Merged

2 tasks

andy-slac requested a review from ktlim July 8, 2021 18:19

andy-slac force-pushed the tickets/DM-30996 branch from 56eea92 to 4d24fb6 Compare July 8, 2021 19:59

ktlim approved these changes Jul 9, 2021

View reviewed changes

andy-slac and others added 2 commits July 9, 2021 08:57

Apply suggestions from code review

e327c4b

Co-authored-by: Kian-Tat Lim <ktl@slac.stanford.edu>

Implement all review suggestions.

4ca26c6

`_MDC` is renamed to `MDCDict` and moved to `lsst.log` to avoid circular dependencies when implementing new `configure_pylog_MDC` method.

andy-slac added 4 commits July 9, 2021 13:48

One more check of generated documentation

50c70a7

Replace INCREF with XINCREF.

ab3c920

Just an additional protection, not really needed in this code, but may be useful if someone else uses it.

Drop org.apache.log4j from PyLogAppender

51d3620

andy-slac merged commit d2ef7b4 into master Jul 12, 2021

andy-slac deleted the tickets/DM-30996 branch July 12, 2021 16:05

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DM-30996: Implement log4cxx appender which logs to Python logging #55

DM-30996: Implement log4cxx appender which logs to Python logging #55

andy-slac commented Jul 6, 2021

ktlim Jul 7, 2021

andy-slac Jul 7, 2021

ktlim Jul 7, 2021

andy-slac Jul 7, 2021

ktlim Jul 7, 2021

andy-slac Jul 9, 2021

ktlim Jul 9, 2021

andy-slac commented Jul 8, 2021

ktlim commented Jul 8, 2021

andy-slac commented Jul 8, 2021

andy-slac commented Jul 8, 2021

ktlim left a comment

ktlim Jul 9, 2021

andy-slac Jul 9, 2021

andy-slac Jul 9, 2021

timj Jul 9, 2021

ktlim Jul 9, 2021

timj Jul 9, 2021

ktlim Jul 9, 2021

timj Jul 9, 2021

andy-slac Jul 9, 2021

andy-slac commented Jul 9, 2021

DM-30996: Implement log4cxx appender which logs to Python logging #55

DM-30996: Implement log4cxx appender which logs to Python logging #55

Conversation

andy-slac commented Jul 6, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andy-slac commented Jul 8, 2021

ktlim commented Jul 8, 2021

andy-slac commented Jul 8, 2021

andy-slac commented Jul 8, 2021

ktlim left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andy-slac commented Jul 9, 2021