How should logging be handled in the various Veracruz tests?

[dominic-mulligan-arm]

At the moment, we are using println() extensively throughout the Veracruz tests. However, dedicated logging frameworks exist for Rust that allow you to filter messages by their respective log levels (DEBUG, TRACE, ERROR, INFO, etc.), with a logging crate (log) providing a facade that each of these logging frameworks implement. Log messages are emitted using dedicated macros–––info!(), error!(), and the like.

I've used the env_logger framework in the past and it's incredibly easy to use, simply call env_logger::init() at the start of main() and then set the RUST_LOG=info environment variable to only show the log messages originating from the INFO log level.

The main advantage over println() based logging is that all log messages are also accompanied by a precise source location in the codebase from where they originate (rather than e.g. having to grep for the text of the log message, when something goes wrong). They also provide a timestamp of when they were emitted, though this is probably not a concern in our case.

On the other hand, they are slightly more complex to configure, with the setting of environment variables to be able to see any output.

What's the consensus?

[ShaleXIONG]

I prefer env_logger, too. We are using it in our veracruz-test and sinaloa-test (main branch).
However, in term of development, it might be easier to use println!. I think we can be more liberal between milestone releases but do a dedicate clean-up on development code in every milestone release.

[dreemkiller]

I've expressed my opinion on this in a code review, but I'll put it here for posterity:

I find dedicated loggers, no matter how simple or easy to use, difficult to use for people new to the code base. It adds another level of abstraction to figure out before the user can get to seeing the actual output, and they spend unnecessary time trying to figure out why they aren't seeing the messages they expect.

I've spent ridiculous amounts of time trying to figure out how to configure a logger when working in new code bases. I think on big enough projects, they can be helpful, but I've never entered a new code base and been happy that they used a logging framework.

There's also the additional overhead of classifying messages as DEBUG, INFO, etc. that seems to never actually be done, so that users end up setting DEBUG whenever they want to see any details, so that many of the promised benefits of dedicated logging frameworks never actually materialize.

[geky]

One advantage of a logging framework is enforcing a standard output with context (timestamp/line as @dominic-mulligan-arm mentioned), this can be very useful for long running servers when you're trying to figure out why users are reporting sporadic Sinaloa timeouts over the past week (though note most general programs are not long running servers).

I also think that the standard number logging levels is usually too many, but having a difference between INFO (normal output), WARN/ERROR (should not happen) is useful. As a new user seeing some output about the tabasco spiciness may be confusing, but seeing a warning about tabasco spiciness has more meaning.

One thing that would help is standardizing all of our programs to default info! to be on. This would make it effectively the same as println!. Having to learn how to turn on the logging framework was confusing the first time, but is a hiccup that could easily be avoided.