Use RUST_LOG env to configure logging if present #247

jsturtevant · 2024-02-23T18:30:44Z

We identified a perf impact when writing logs. In this case it would be helpful to only run with logs set at a "warning" or "error" level. We attempted to turn most logs off via containerd with containerd -l fatal but it still dumped logs.

After some investigation it appears containerd only sets a flag not a level (https://github.com/containerd/containerd/blob/7467d81987e1a54dd2a89e052ae9429a4c921e9e/core/runtime/v2/binary.go#L66-L68) and our code will default to info

rust-extensions/crates/shim/src/logger.rs

Lines 135 to 139 in cc445f5

    
           let level = if debug { 
        
               log::LevelFilter::Debug 
        
           } else { 
        
               log::LevelFilter::Info 
        
           };

changes

This reads the environment variable RUST_LOG and will use value from there if set. It can be set to any values in the log crate. Otherwise the behavior is the same. If the -debug flag is passed it will choose the highest of the two values.

This also introduces ability to configure the default setting through the shim Config object:

run::<Shim>(&id, Some(Config{default_log_level: "error", ..Default::default()}));

If all the configuration fails it will fallback to logging to to info level.

Signed-off-by: James Sturtevant <jstur@microsoft.com>

Mossaka

Love to see this!

Mossaka · 2024-02-23T19:02:52Z

crates/shim/src/logger.rs

+fn configure_logging_level(debug: bool, default_log_level: &str) {
+    let debug_level = std::env::var(LOG_ENV).unwrap_or(default_log_level.to_string());
+    let debug_level = log::LevelFilter::from_str(&debug_level).unwrap_or(log::LevelFilter::Info);
+    let level = if debug && log::LevelFilter::Debug > debug_level {


Why do you still need this special handling of debug logic?

I kept it there so that it was backwards compatible. If a user turns that value on they would expect logs and I didn't want to break that.

Some context about defaults is above, but we may simplify this a bit to:

level = DEFAULT_LOG_LEVEL

if there is an env - parse & set level from env

if debug { level = debug } (may be output a warning that containerd forced debug mode)
?

I wasn't sure that we could push out a warning as the logger wasn't fully set up at this point but I can try it

the reason for if debug && log::LevelFilter::Debug > debug_level was I wanted to ensure that if the ENV variable was more verbose than debug that we honor it.

Mossaka · 2024-02-23T19:03:32Z

crates/shim/src/logger.rs

@@ -34,6 +34,8 @@ use crate::error::Error;
 #[cfg(windows)]
 use crate::sys::windows::NamedPipeLogger;

+pub const LOG_ENV: &str = "RUST_LOG";


I wonder if we should name the env var to be SHIM_LOG because this is probably not specific to rust, no?

RUST_LOG is used by another popular (128m downloads) logging crate - env_logger to customize log output. We could integrate env_logger with pipes to offer same level of functionality or use other name here to avoid confusion - users might expect same level of customization, which we don't offer.

I did consider trying to integrate env_logger initially and can take closer look if we want to add that level of customization or can change the name

Mossaka · 2024-02-23T19:05:21Z

crates/shim/src/lib.rs

 pub struct Config {
    /// Disables automatic configuration of logrus to use the shim FIFO
    pub no_setup_logger: bool,
+    // Sets the the default log level. Default is info
+    pub default_log_level: String,


nit: Is this case sensitive?

from my testing it was not

default_log_level is a bit confusing to me. We have a default one and env variable to customize it if default doesn't work. Customizing both default value and env log is a bit excessive?

I was thinking that some shims owners would want to set it different from info with requiring customization through an Environment variable

but they can use environment variable to customize it, if they don't like default value, right?

mxpv · 2024-02-23T23:17:53Z

We identified a perf impact when writing logs.

Would be curious to learn more about costs of logging to pipe/fifo.

jsturtevant · 2024-02-23T23:43:27Z

Would be curious to learn more about costs of logging to pipe/fifo.

@radu-matei @lann could you share some of your findings?

lann · 2024-02-23T23:45:48Z

I suspect that the performance issues have more to do with mutex contention in FifoLogger, but I haven't done any analysis to confirm.

mxpv · 2024-02-24T02:36:36Z

mutex contention

I wonder if going this route would be more viable instead of introducing a custom env var? parking_lot's mutex or maintaining a message queue.

jsturtevant · 2024-02-28T22:39:01Z

I think it should be both. There is an expectation from users that since they are using env crate they can adjust the log level. In the current set up, it is impossible to get trace logs from the shim or other components since we only go to the debug level.

mxpv

LGTM

jsturtevant · 2024-03-05T23:41:08Z

@mxpv I've logged #249 for further investigation on the logging issue.

Of the feedback in the PR above above which changes would you like to see before merging this?

mxpv · 2024-03-06T20:28:25Z

Let's have this one in. We can follow up with further improvements.

Use RUST_LOG env to configure logging if present

c7c504e

Signed-off-by: James Sturtevant <jstur@microsoft.com>

github-actions bot added the C-shim Containerd shim label Feb 23, 2024

jsturtevant mentioned this pull request Feb 23, 2024

Disable shim logging to stdout spinkube/containerd-shim-spin#17

Closed

jsturtevant requested a review from mxpv February 23, 2024 18:37

Mossaka reviewed Feb 23, 2024

View reviewed changes

mxpv approved these changes Mar 4, 2024

View reviewed changes

jsturtevant mentioned this pull request Mar 5, 2024

Possible Performance issue related to logging in shim #249

Open

mxpv added this pull request to the merge queue Mar 6, 2024

Merged via the queue into containerd:main with commit 0e77608 Mar 6, 2024
18 checks passed

Mossaka mentioned this pull request Apr 18, 2024

Proposal: a more customizable logger #260

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use RUST_LOG env to configure logging if present #247

Use RUST_LOG env to configure logging if present #247

jsturtevant commented Feb 23, 2024

Mossaka left a comment

Mossaka Feb 23, 2024

jsturtevant Feb 23, 2024

mxpv Feb 23, 2024

jsturtevant Feb 23, 2024

jsturtevant Feb 23, 2024

Mossaka Feb 23, 2024

mxpv Feb 23, 2024 •

edited

Loading

jsturtevant Feb 23, 2024

Mossaka Feb 23, 2024

jsturtevant Feb 23, 2024

mxpv Feb 23, 2024 •

edited

Loading

jsturtevant Feb 23, 2024

mxpv Feb 24, 2024

mxpv commented Feb 23, 2024

jsturtevant commented Feb 23, 2024

lann commented Feb 23, 2024 •

edited

Loading

mxpv commented Feb 24, 2024 •

edited

Loading

jsturtevant commented Feb 28, 2024

mxpv left a comment

jsturtevant commented Mar 5, 2024

mxpv commented Mar 6, 2024

	let level = if debug {
	log::LevelFilter::Debug
	} else {
	log::LevelFilter::Info
	};

Use RUST_LOG env to configure logging if present #247

Use RUST_LOG env to configure logging if present #247

Conversation

jsturtevant commented Feb 23, 2024

changes

Mossaka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mxpv Feb 23, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mxpv Feb 23, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mxpv commented Feb 23, 2024

jsturtevant commented Feb 23, 2024

lann commented Feb 23, 2024 • edited Loading

mxpv commented Feb 24, 2024 • edited Loading

jsturtevant commented Feb 28, 2024

mxpv left a comment

Choose a reason for hiding this comment

jsturtevant commented Mar 5, 2024

mxpv commented Mar 6, 2024

mxpv Feb 23, 2024 •

edited

Loading

mxpv Feb 23, 2024 •

edited

Loading

lann commented Feb 23, 2024 •

edited

Loading

mxpv commented Feb 24, 2024 •

edited

Loading