USD Logging

OpenUSD doesn't offer logging configuration in the way that a Python or Rust library does. By default, USD's logging approach is to write strings to the library's stdout and stderr. Status messages (mostly in examples and tests) go to stdout and warnings and errors go to stderr. So, for instance, you might see common logging output that looks like below, warning that you are creating a SdfPath with an empty string.

>>> Sdf.Path('')
Warning: in SdfPath at line 127 of /src/USD/pxr/usd/sdf/path.cpp -- Ill-formed SdfPath <>: :1:1: parse error matching pxrInternal_v0_25_5__pxrReserved__::Sdf_PathParser::Path

It is possible to intercept these logging messages and avoid the default behavior. You'd do this by registering a C++ class that derives from TfDiagnosticMgr::Delegate. There are a few of these provided by default, UsdUtilsCoalescingDiagnosticDelegate and UsdUtilsConditionalAbortDiagnosticDelegate.

Coalescing Delegate

The coalescing delegate will capture all log messages reported and store them in a thread safe queue until they are requested. A caller can request the log messages by calling TakeCoalescedDiagnostics or TakeUncoalescedDiagnostics. These functions pop messages from the queue and return them in a vector ordered from oldest to newest. Then the caller can report those log messages in whatever way they choose to.

The "Coalesced" version takes repeated messages from the same line of source code and collapses them into one entry with a list of messages that has each message from that source line.

These can be instantiated from Python, here's a quick example in a python repl. I don't think Tf Diagnostic messages can be created from Python, so we'll need a way to get some messages logged. Since creating a SdfPath with an empty string logs a warning, we'll create a few of those.

>>> from pxr import Sdf, UsdUtils
>>> delegate = UsdUtils.CoalescingDiagnosticDelegate()
>>> _ = Sdf.Path('')
>>> _ = Sdf.Path('')
>>> messages = delegate.TakeCoalescedDiagnostics()
>>> for m in messages:
...     print(f"{len(m.unsharedItems)} messages from {m.sharedItem.sourceFunction}")
...     for i in m.unsharedItems:
...         print(f"    {i.commentary}")
...
2 messages from pxrInternal_v0_25_5__pxrReserved__::SdfPath
    Ill-formed SdfPath <>: :1:1: parse error matching pxrInternal_v0_25_5__pxrReserved__::Sdf_PathParser::Path
    Ill-formed SdfPath <>: :1:1: parse error matching pxrInternal_v0_25_5__pxrReserved__::Sdf_PathParser::Path

We report the warning with just a function name, followed by an indented line for each warning message. Notice that when the warnings were generated nothing was written to stderr. This gives you a way to capture these messages and redirect them to a logging system, or to a status console in a GUI application. The messages will be redirected for the lifetime of the delegate object.

The coalescing delegate captures status and warning messages, but does not capture error messages. It also doesn't track whether a message was a status or a warning message. In C++ you could use a TfErrorMark to also capture error messages and redirect those to the logs. I wrote another article on approaches to handling USD errors in Python. The short version in Python is that errors are converted into exceptions of type Tf.ErrorException, which you can handle and log as appropriate.

Conditional Abort Delegate

The conditional abort delegate is an interesting one. I'm not sure when you'd use it, so I'll keep this a bit short. This delegate still prints to stderr (for status also), but lets you define a regex pattern to match against either the message (called the commentary in the api) or against the path to the source code file that generated the log message. There's an include and exclude regex. If a message passes the include regex and isn't excluded by the exclude regex, the application will abort as though it crashed.

I suppose this might be useful for testing scenarios, but I'd think the coalescing delegate could also be used to check for an expected log message, or for the absence of warnings, or what have you.

If you can think of a good use for this, it's here for you.

Custom Delegates

Naming aside, the coalescing delegate probably provides what you need in most cases. Especially if you use the non-coalesced api to get an unfiltered stream of log messages.

If your needs are more specific you can write a new TfDiagnosticMgr::Delegate subclass to do custom handling of log messages. Unfortunately I don't believe there is any way to do this from Python, but you can create a C++ one and expose it to Python the same way the provided delegates in UsdUtils do it.

Personally, I wish that when I was running in Python USD would use Python's logging system. That way USD's logs would intermingle with other well behaved Python library logs. I could set log levels, formatting, etc.

I would also like it if I didn't need to drain the log message queue in my code, as is required by the coalescing delegate. Doing so inevitably introduces some latency to the log messages. If my code is calling into USD and other Python libraries that log, the other Python libraries will log right away but my USD logs won't get reported until I ask the coalescing delegate for messages and log them.

To get around this I've been using a diagnostic delegate that calls into the Python logging module directly. I'll put a version up on the Confusing Acronym github. If you're compiling USD yourself feel free to grab this and incorporate it with your build. It's also available in the USD alpine linux images I maintain on dockerhub, in the extra image. (If there is enough interest I could also try to package this as a separate plugin project, but plugin distribution for USD is a complex beast)

Some Closing Thoughts

So, why is it like this? 😆 I don't have any insider information. I can say that in my career I've almost never seen a C++ application or library with a modern logging setup like you might see in Python, Go or Rust.

I suspect that those languages just have a more standard logging library available, so logging is kind of a no-brainer. At a minimum you use the standard logging support, and maybe if it isn't sufficient you use a more robust logging library. In C++ there is no standard logging library, especially more than a decade ago when USD was coming together.

Today in C++ I think spdlog is growing in popularity. I like it for my personal projects. One alternative is boost.log, but I think less dependency on boost is better for USD, to help with portability and linkability. I'm glad USD didn't standardize on boost.log in the olden times.

I can't imagine that logging is something that's high priority for USD developers. There's a system that works currently, even if it has a few warts. I won't hold out hope that USD will go to spdlog or some other more modern system. I would love it though if it just stopped writing to stderr by default!