Feature: logging support

This is a proposal with draft implementation to add support for a logging framework to VTK originally introduce in this mailing list thread.

Here’s an extract from the header docs in vtkLogger.h that summarizes how to use this logging capability.

/// Optional, but useful to time-stamp the start of the log.
// Will also detect verbosity level on the command line as -v.

vtkLogger::Init(argc, argv);

// Put every log message in "everything.log":
vtkLogger::LogToFile("everything.log", vtkLogger::APPEND, vtkLogger::VERBOSITY_MAX);

// Only log INFO, WARNING, ERROR to "latest_readable.log":
vtkLogger::LogToFile("latest_readable.log", vtkLogger::TRUNCATE, vtkLogger::VERBOSITY_INFO);

// Only show most relevant things on stderr:
vtkLogger::SetStderrVerbosity(vtkLogger::VERBOSITY_1);

// add a line to log using the verbosity name.
vtkLogF(INFO, "I'm hungry for some %.3f!", 3.14159);
vtkLogF(0, "same deal");

// add a line to log using the verbosity enum.
vtkVLogF(vtkLogger::VERBOSITY_INFO, "I'm hungry for some %.3f!", 3.14159);
vtkVLogF(vtkLogger::VERBOSITY_0, "same deal");

// to add a indentifier for a vtkObjectBase or subclass
vtkLogF(INFO, "The object is %s", vtkLogIdentifier(vtkobject));

// add a line conditionally to log if the condition is true:
vtkLogIfF(INFO, ptr == nullptr, "ptr is nullptr (some number: %.3f)", *  3.14159);

vtkLogScopeF(INFO, "Will indent all log messages within this scope.");
// in a function, you may use vtkLogScopeFunction(INFO)

// alternatively, you can use streams instead of printf-style
vtkLog(INFO, "I'm hungry for some " << 3.14159 << "!");
vtkLogIf(INFO, ptr != nullptr, "ptr is " << "nullptr");

A few things to note:

  • based on loguru 2.0.0 however we expose VTK specific APIs and macros to support future replacing underlying implementation, if needed
  • supports printf-style and streams via vtkLog..() are stream based macros, while vtkLog..F() are their printf-style counter parts.
  • CMake flag available to disable logging entirely at which point all these macros simply become no-ops.
  • level based logging with support for multiple outputs with different verbosity levels.
  • vtkErrorMacro, vtkWarningMacro etc. automatically log the messages as well (without the extra filename, line number info since that is already captured by the log more cleanly). It’s possible to bypass the vtkOutputWindow based legacy support entirely and just rely on logging by calling vtkObject::GlobalWarningDisplayOff(). Additionally, to avoid duplicate messages on the terminal, when VTK is built with logging support vtkOutputWindow doesn’t output the messages to the stdout or stderr. It will still fire the appropriate message signals, just not show them on the standard output streams to avoid messing up with the log stream.
  • loguru supports for adding handlers/callbacks; currently working on adding VTK exposed API for the same. The plan is make it available for developers so developers can capture messages being logged for doing things like reporting in an message window etc.
  • loguru supports ability to format log generated; currently working on VTK-exposed API for the same which will be finalized in time for the merge (or soon after)

The changes are being developed/tested here: https://gitlab.kitware.com/vtk/vtk/merge_requests/5132

Any feedback, suggestions, comments are welcome as always.

Edits:

  • changed class name to vtkLogger from vtkLog
  • changed macro case / style as suggested.
  • changed to use F suffix instead of f for format overloads
  • corrected docs for vtkLogIfF
3 Likes

In keeping with how most classes in VTK are named with nouns (e.g., vtkPicker, vtkMapper, vtkXMLReader), I wonder if the class should be named vtkLogger instead of vtkLogging?

fair point. I’ll change it shortly.

Why all caps and underscores for LOGGING_CALLS? The old methods followed standard naming conventions/capitalization, visually it looks like a step backwards. I guess they are macros, hence the _F and _S, could we consider vtkLogString and vtkLogStream to be a little more explicit and less screamy?

you’re correct, because they are macros and that was the style loguru & VTK-m used.

Sure. Given VTK tradition, how about we use vtkLog(...) for stream-based variants (as I suspect that’d be more common) and use vtkLogf(...) for the printf variants?

1 Like

Nice!

How does one enable/configure vtkLogging in their own vtk application?

See docs in vtkLogger.h, or TestLogger.cxx.

1 Like

I’m a little late to the discussion, but since vtk-m is already using loguru, would it be possible to share the same backend and log from both to the same file?

https://gitlab.kitware.com/vtk/vtk-m/blob/master/vtkm/cont/Logging.h

I am afraid not. VTK-m is not a required dependency of VTK or vice-versa. In the long run, when VTK-m becomes a required dependency we can revisit. Right now, both loguru’s are mangled separately and hence will end up in different logs – is my guess.

This looks nice, but from the example:

I found this quite confusing when I read it. The function name is vtkLogIff and takes a condition, but it will log if the condition doesn’t hold? If so, I would call it vtkLogIfNot or vtkLogUnless, and maybe have a vtkLogIf that does the opposite for those who prefer that style.

The way it is, I read vtkLogIff(INFO, ptr != nullptr, ...) as “log if ptr is not nullptr” which is opposite to what the function seems to do.

Also, the vtkLogIff with the extra f (I guess for “format”) is a bit unfortunate, since I think many might read that as “if and only if”, adding even more to the confusion? EDIT: One way to avoid it is to name it vtkLogIfF. I know it’s sort of ugly, but it does makes sense if one follows camel case and consider that the F is short for Formatted.

Or perhaps I’m just a confused person :slight_smile:

good point. I think I will change it to log if condition is true, which seems a more natural way – incidentally, that’s how it’s implemented, I just had it wrong in the docs – I’ll update it.

The vtkLogIff is indeed a unfortunate occurrence. The lower f was chosen to match printf, but by strict VTK style, -f should indeed be capitalized. Unless there’s objection I will change that accordingly as well.

fixes included here

1 Like

IDK if this is related, but i have been getting runtime errors from loguru when running examples today:

To run a test, enter the test number: 54
( 3.611s) [ ] loguru.cpp:529 FATL| CHECK FAILED: argc > 0 (0 > 0) Expected proper argc/argv

I see this on windows and linux in the master branch. Any ideas what is wrong?
Best
Jeff

looks like the examples are passing malformed argc,argv. loguru::init(..) confirms that argv[argc] == nullptr and argc > 0. what’s the callstack?

i remember it was in vtkLogger::Init, ill have to wait until finished build to get exact.

i got one on linux…

Stack trace:
4 0x4421d9 vtkCommonCoreCxxTests() [0x4421d9]
3 0x7fb83746ed20 __libc_start_main + 256
2 0x442668 vtkCommonCoreCxxTests() [0x442668]
1 0x7fb836197275 vtkLogger::Init(int&, char**, char const*) + 63
0 0x7fb83485777c vtkloguru::init(int&, char**, char const*) + 295
( 1.668s) [ 379ED720] loguru.cpp:529 FATL| CHECK FAILED: argc > 0 (0 > 0) Expected proper argc/argv

totally strange, what’s the name of the test that this is failing for?

seems to be all tests on both linux and windows. i’m trying a clean clone…

CHECK FAILED: argc > 0 (0 > 0) Expected proper argc/argv

Is there code calling loguru::init(0, nullptr); somewhere? We ran into this on vtk-m, and it takes a bit of work to fool loguru into taking a dummy argv/argc:

  int argc = 1;
  char dummy[1] = { '\0' };
  char* argv[2] = { dummy, nullptr };
  loguru::init(argc, argv);

https://gitlab.kitware.com/vtk/vtk-m/blob/master/vtkm/cont/Logging.cxx#L148-154

Thanks Utkarsh, Allison,
sorry for late reply, i am still building and will let you know if the problem is still there… if you are not seeing it when running the examples like vtkCommonCoreCxxTests, then it is probably an issue with my build.

with a fresh pull and build, still the following from vtkRenderingAnnotationCxxTests: are you not seeing this?

Stack trace:
4 0x4052f9 vtkRenderingAnnotationCxxTests() [0x4052f9]
3 0x7f1d79322d20 __libc_start_main + 256
2 0x405bc5 vtkRenderingAnnotationCxxTests() [0x405bc5]
1 0x7f1d71f72275 vtkLogger::Init(int&, char**, char const*) + 63
0 0x7f1d6b64477c vtkloguru::init(int&, char**, char const*) + 295
( 3.187s) [ 79761820] loguru.cpp:529 FATL| CHECK FAILED: argc > 0 (0 > 0) Expected proper argc/argv