Shouldn't `log!` check the equivalent of `log_enabled!` before calling into `Log::log`?

[bnjbvr]

The log! macro runs whenever the following conditions are met:

        if lvl <= $crate::STATIC_MAX_LEVEL && lvl <= $crate::max_level() {

The log_enabled! macro returns the following:

        lvl <= $crate::STATIC_MAX_LEVEL
            && lvl <= $crate::max_level()
            && $crate::__private_api_enabled(lvl, $target)

that is, it also calls into the Log::enabled impl.

Because of this, there can be cases where logs will be output or not, depending on whether they're guarded behind a log_enabled!(), if the implementation of Log::enabled isn't consistent with what's in the Log::log implementation. That means that it's the implementation's duty to ensure that it's consistent with itself, which is an easy footgun, for example in Tokyo's tracing-log crate: tokio-rs/tracing@5fdbcbf.

Even the doc showing an example impl of Log suggests doing just that: https://docs.rs/log/0.4.14/log/#implementing-a-logger, so making it the default could avoid issues.

In particular, in the suggested implementation of Log::log:

if (self.enabled()) {
  do_actual_logging(record);
}

The log record that was instantiated in the first place could be just thrown away just after being created, if it didn't pass the self.enabled() check. It's effectively a problem if the log contains lots of data that takes time to generate in the first place, because this data might be thrown away directly, even if it's created as an argument to a log macro. Having the equivalent of a log_enabled! check in the macro would avoid that problem too, by putting the costly computation into the if's body itself, instead of computing it and then only deferring to the Log impl to decide whether it's used or not.

Would people be inclined to have the equivalent of the log_enabled! check happen directly in the log! macro, to avoid running into those two pitfalls? It would make log_enabled! a bit less useful, but still useful in my opinion for cases where one doesn't want to use expression blocks inside log macros.

[sfackler]

That is the way this crate used to behave and the behavior was changed when it was converted into a logging facade: #3.

The example Log implementation does that because it's the simple way to implement log, but not the only way. In particular, more advanced loggers with e.g. multiple outputs will perform filtering at the same time as deciding where to emit the log. Always running enabled! before log! then performs the filtering twice.

There are far more people logging things than people writing loggers, so on the balance it's better to add an extra requirement to Log implementations than slow down all logging calls.

[bnjbvr]

Ah interesting, thanks for the historical background. Then I guess that undoing this change would be a large breaking API change, and would not be easy to do at all in the context of the log crate, plus not everyone would be interested in doing so, as you rightfully note.

It's also interesting to consider that it's become a facade, and to which point it could be even more of a facade. For instance, right now the maximum level filter is set per process, and it might be useful having it per-thread (e.g. stored in TLS), for multi-threaded contexts. Right now having a per-process level is a choice set in stone in log, and not easy to change; it might be interesting to consider whether it'd be possible to use different strategies for that too. But a bit unrelated to the current issue; could be another topic.

I also wonder if the choice of always checking Self::enabled() before doing the actual logging of a Record could be done automatically if the Log impl opted in doing so, with some abstraction and a default that implements the current way it's done.

At the very least, would it make sense to add documentation indicating that Log::enabled() returning false doesn't ensure that the corresponding Record won't be logged, and that it's up to the Log impl to decide whether to do so or not? Probably a useful bit of documentation to have both for the log_enabled macro and the Log::enabled() doc comment.

[sfackler]

Right now having a per-process level is a choice set in stone in log, and not easy to change; it might be interesting to consider whether it'd be possible to use different strategies for that too. But a bit unrelated to the current issue; could be another topic.

That is a filtering behavior you can easily add to a logger implementation. The global level exists to be an optimization to quickly skip things like trace logging without needing to call into the logger when applicable.