Stream: cranelift

Topic: logging

Andrew Brown (Mar 23 2021 at 16:45):

@Chris Fallin, @Benjamin Bouvier: I am surprised that https://github.com/bytecodealliance/wasmtime/pull/2755 is needed... I haven't looked at the implementation of debug! but I assumed that the point of having such a macro is that the expressions passed to the logger are not evaluated _unless_ logging is enabled. Why do we have to have another check around that?!?

Chris Fallin (Mar 23 2021 at 16:46):

Indeed, I was surprised too -- will be curious to know more details about @Benjamin Bouvier 's environment (ie loggingg module setup)

Chris Fallin (Mar 23 2021 at 16:46):

if it is the case that args are always evaluated, or we can't rely on them not being so, then we should audit a bunch of hot paths!

Chris Fallin (Mar 23 2021 at 16:47):

(a lot of debug logging just prints primitive locals that exist anyway, so I imagine there's no overhead there aside from the do-I-log branch; but there may be other cases where we explicitly build a string in a call somewhere)

Andrew Brown (Mar 23 2021 at 16:56):

yes, exactly!

Alex Crichton (Mar 23 2021 at 16:58):

@Andrew Brown @Chris Fallin regardless of logging level the arguments to the logging macro are always evaluated

Alex Crichton (Mar 23 2021 at 16:59):

regardless of whichever logging crate you're using I believe

Chris Fallin (Mar 23 2021 at 16:59):

@Alex Crichton that is very much a TIL for me and I now know what I'm doing with high-ish priority. Thanks :-)

Andrew Brown (Mar 23 2021 at 16:59):

That seems broken, though... most of us expect logging to be lazily evaluated?

Alex Crichton (Mar 23 2021 at 17:00):

wait no, don't quote me on this

Andrew Brown (Mar 23 2021 at 17:00):

@Alex Crichton, is this something that could/should be fixed in log? Or does it have to be this way?

Alex Crichton (Mar 23 2021 at 17:00):

the source disagrees with me

Andrew Brown (Mar 23 2021 at 17:00):

do you have the link?

Alex Crichton (Mar 23 2021 at 17:01):

@Chris Fallin no I am wrong

Alex Crichton (Mar 23 2021 at 17:01):

arguments are not evaluated

Alex Crichton (Mar 23 2021 at 17:01):

so this is probably the tokio bug and a crate that wasn't updated

Alex Crichton (Mar 23 2021 at 17:01):

@Andrew Brown I just checked locally and log::debug!("{:?}", println!("")); doesn't print anything

Alex Crichton (Mar 23 2021 at 17:01):

so arguments aren't evaluated unless the log level is enabled

Alex Crichton (Mar 23 2021 at 17:02):

sorry I thought it was the other way around which is why I approved...

Andrew Brown (Mar 23 2021 at 17:02):

phew... my faith in log is restored

Chris Fallin (Mar 23 2021 at 17:02):

Phew. Crisis averted.

Andrew Brown (Mar 23 2021 at 17:02):

but does that mean that @Benjamin Bouvier's PR was necessary?

Chris Fallin (Mar 23 2021 at 17:03):

Well, it's possible that others may be running with older (buggy) logging environments for which this is not true, I suppose

Alex Crichton (Mar 23 2021 at 17:03):

it means it shouldn't be necessary, no

Andrew Brown (Mar 23 2021 at 17:03):

yeah

Andrew Brown (Mar 23 2021 at 17:03):

Alex, what's the tokio bug?

Alex Crichton (Mar 23 2021 at 17:04):

https://github.com/tokio-rs/tracing/issues/1249

Andrew Brown (Mar 23 2021 at 17:07):

cool, thanks

Benjamin Bouvier (Mar 23 2021 at 17:19):

oh really? i just spent some time looking at the log's code and concluded that it was necessary... let me back it up

lqd (Mar 23 2021 at 17:42):

I was equally surprised by this, the arguments are not evaluated if the max_level is correctly set

lqd (Mar 23 2021 at 17:43):

which could happen if the buggy version of tracing-subscriber is used, or if some incorrect code is used to set up the loggers

lqd (Mar 23 2021 at 17:48):

to make sure, I've added panics at the same places the PR changes things:

• using env_logger default's init: no issues
• using the "unexpected" tracing-subscriber init that wycats had trouble with: no issues now with the most recent tracing-subscriber version with the fix
• using the recommended way to setup tracing-subscriber: no issues
• setting up tracing-subscriber differently, "incorrectly": unexpected logs from regalloc

Benjamin Bouvier (Mar 23 2021 at 18:20):

It might have been a red herring then: we're using tracing-subscriber, as well as another small log wrapper that might be doing something silly. I'll confirm, but then we can probably revert the change I've made.

Benjamin Bouvier (Mar 23 2021 at 19:02):

Yep, that was it: we were using a default ctor of tracing_subscriber which sets the max_level to LevelFilter::Max, by default -_-'

Benjamin Bouvier (Mar 23 2021 at 19:02):

Good thing that the log macros are actually sane, and that we don't need to audit the full code base for other log uses!

Pat Hickey (Mar 25 2021 at 18:14):

its a bummer that the log ecosystem and tracing-subscriber dont work together perfectly well, but fastly uses tracing-subscriber in a lot of contexts and i expect many other users will as well, so its worthwhile to make sure we are optimized properly for using tracing-subscriber as well as the usual env_logger or equivelant

Chris Fallin (Mar 25 2021 at 18:22):

@Pat Hickey we have a nice solution now suggested by Alex in #2758 -- agreed that we want to avoid performance footguns like this lest we drive folks away thinking our backend is too slow

Last updated: Nov 22 2024 at 17:03 UTC