Explicitly delimit EOM for logging

[jwnimmer-tri]

Desired behavior

The Console (i.e., logging) abstraction in libsdformat currently follows the semantics of something like std::cerr -- a simple text stream where the call sites conclude each call with a newline (sdferr << ... << "\n";). Even if we switch to use the ignition-common console per #351, it still currently embodies the same abstraction.

However, in a lot of production code, log message telemetry is not just a dedicated console read by human eyes -- it is recorded in a structured form, sent over the network, and/or otherwise treated on a message basis rather a stream basis.

My request here is to change the Console to use the same semantics -- where there is a clear "end of message" demarcation.

Several C++ logging frameworks (e.g., log4cpp) do this by using the logger lifetime to conclude the message. My patch file in RobotLocomotion/drake#16348 shows an example of this. The Console::ColorMsg function returns a short-lived stream by-value, instead of a long-lived stream by-reference. When the statement ends, the temporary is destroyed, and in its destructor the message is posted.

Another technique is what spdlog does -- the user makes a single function call to log, passing both the format string and all of the arguments all at once. This would be a more significant rewrite of the calling-code than the stream lifetime change, but would be a better choice in case the Console needed to be used from languages beyond just C++.

Alternatives considered

A different design would be to keep the streaming API unchanged, but to have the implementation monitor the character buffer insertions for newlines, and replace all newlines with EOM / log posting. I am not a fan of that design, because it removes the ability for a single log message to have embedded newlines, which I've often found to be useful.

Additional context

For sdformat in particular, as I've explained in #334 (comment) the library should never be printing to any console anyway. The calls to parse should have a structured way to report errors, and should be silent on cerr. The current design and use of sdf::Error gets us most of the way there, but there are still a ton of places in the library code that stream to sdferr (or sdfwarn, etc.) instead of appending an sdf::Error. If we fixed that problem instead, then we could delete the sdformat-specific Console class and this whole discussion here is moot (though would still apply to the ignition-common logging API design).

[azeey]

Thanks for the suggestions @jwnimmer-tri. This is definitely something we want to address. My initial thought is to go with the spdlog approach or actually add spdlog as a dependency. It's a lot of work, but it would be the most flexible to change in the long run.

[chapulina]

actually add spdlog as a dependency

Agreed that would be a nice alternative to #351. And if it works well on SDFormat, we should consider moving all of Ignition to spdlog.

[jwnimmer-tri]

In the context of a more disruptive change like porting to spdlog, I'd like to underline my "Additional context" paragraph from the original posting. A parsing library has no business printing to the console in the first place -- we should always use the Error struct instead, and the caller of the parser should be deciding how to display the errors or warnings.

For convenience, maybe the library could offer a "just keep it simple and display the errors to cerr anyway" sugar, but we don't need spdlog for that, we just need a "Dump a vector<Error> to std::cerr" helper function. The Error items are already intrinsically message-delimited (each one stands on its own). Free-form text logging in a parsing library (even if message-delimited) should be an anti-goal; we always need to give the caller of the parser the ability to govern the output to the user.

[azeey]

A parsing library has no business printing to the console in the first place -- we should always use the Error struct instead, and the caller of the parser should be deciding how to display the errors or warnings.

I agree that we should use the Error struct in as many places as possible, but that struct, in its current form, is intended for errors only. We need some other mechanism to emit warning or informational messages. We could create other structs for such messages and instead of returning std::vector<Error>, we could return a Result type that can be queried for error, warning, and informational messages separately. This would require a major refactor and change of APIs though. IMO, it would be simpler to use spdlog or something similar.

[jwnimmer-tri]

Many uses of sdfwarn are communicating real problems, and there should be some mechanism for the user to notice them (e.g., when asking to parse in the strictest mode), other than watching the console output.

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/Model.cc#L186-L188

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/parser.cc#L1153-L1156

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/parser.cc#L1174-L1178

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/parser.cc#L1206-L1209

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/World.cc#L206-L208

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/World.cc#L288-L291

https://github.com/ignitionrobotics/sdformat/blob/53b9d8ef57f0971929ed92f21243a7c71daddd34/src/ParamPassing.cc#L326-L329

If the answer is that they should all be using the Error struct instead, with the option for the user to choose EnforcementPolicy::WARN to gloss over them, that's fine. If that's the case, then there would be no more remaining uses of sdfwarn in the tree -- other than a few places when parsing SDFormat data declared to be version 1.6 or earlier.

There are no calls to sdfmsg in the sdf12 tree, other than tests. (I have no objection to using it in tests.)

I think that calls to sdfdbg go into the log file only by default. In which case, there is no problem keeping it as-is. The information is not critical, and in any case doesn't spam the console.

In short, I don't buy this statement:

We need some other mechanism to emit warning or informational messages.

Can you link to any example in the code that's emitting an informational message to the console, but that should never actually be communicated to the calling code in a structured way beyond the console? I couldn't find any.

[azeey]

If the answer is that they should all be using the Error struct instead, with the option for the user to choose EnforcementPolicy::WARN to gloss over them, that's fine. If that's the case, then there would be no more remaining uses of sdfwarn in the tree -- other than a few places when parsing SDFormat data declared to be version 1.6 or earlier.

If the user chooses EnforcementPolicy::WARN, is that idea to still print the warning messages to the console? If so, that would satisfy the need for a mechanism to emit warning messages. You're right about sdfmsg being only used in tests, so ignore the part about informational messages.

[jwnimmer-tri]

If the user chooses EnforcementPolicy::WARN, is that idea to still print the warning messages to the console?

Yes, I think so.

Users who want something more specific can parse and receive the std::vector<Error>& to do with as they wish. If they don't ask for the errors back (e.g., by calling the simple readFile(filename), instead of the more detailed readFile(filename, errors)), then displaying the warnings and/or errors to the console by default at that point is fine by me.

I haven't tried to weave these specific ideas in the current API, so there are probably a few loose ends still to design. I just have the one big-picture idea: it's fine if we have a Console class to help with streaming messages to the terminal, but it can only exist at the very outermost / highest layer of the parsing code. The parsing code should to produce a structured list of errors (of varying severity). If the user doesn't specify what to do with that list once the parsing is complete, then it's fine to just print it out. The only problem with printing is having the lower-layer code do it outside of the caller's control.

[azeey]

it can only exist at the very outermost / highest layer of the parsing code. The parsing code should to produce a structured list of errors (of varying severity).

Currently, the way EnforcementPolicy::WARN works is that if it's set, something that would be added to an Error list would instead immediately be printed to the console. This happens at all levels of parsing. To achieve the goal where all error and warning messages are collected in a structured list and the decision to print them to the console is only made at the highest layer of the parsing code we would need either a way for Error to represent varying severity or another struct to represent warning messages.

Both approaches would incur significant changes in API and general behavior. For example, if we added the ability to represent varying severity in Error, code that checks if the list of errors (sdf::Errors) is empty will have to be updated to check for the severity of each error.

[azeey]

We have started (#939 being the first PR) adding sdf::Error parameters to lower level parsing code that previously would print to the console.

[azeey]

Since we don't have a separate data structure for warnings, for now, the plan is to handle them by updating all sdfwarns to use enforcement policies. Then users can either get warnings on the console if enforcement policy is WARN, or in the Errors data structure if enforcement policy is ERR.

• We should also create an error code for warnings that get converted to errors so that end users can easily check for them.

[EricCousineau-TRI]

Per VC, remaining work is 2 PRs to be filed soon.