How to turn on logging in libraries?

mav · February 18, 2021, 1:20am

Bit of a rust question…

In sn_node the logging is initialized in init_logging(config).

Within that there’s a line to determine the filter level:
format!("{}={}", NODE_MODULE_NAME, level_filter.to_string());
ie
sn_node=INFO
More details in log level docs.

We can use RUST_LOG env var to override it, eg in the shell
export RUST_LOG="info,bls_dkg=trace"
which should show trace level logging for the bls_dkg crate.

However I do not see any bls_dkg records in my node logs. Any ideas why? Is this just me or do other people see this too?

bochaco · February 18, 2021, 2:35am

I just gave it a try and I’m seeing some bls-dkg logs with RUST_LOG=bls_dkg=debug, perhaps the info I see in your "info,bls_dkg=trace" value is the problem?

mav · February 18, 2021, 5:58am

Thanks for confirming this.

I found the problem, sn_launch_tool seems to be clobbering the RUST_LOG environment variable via the --rust_log flag.

My short term fix was to remove that flag entirely from sn_launch_tool, but I’ll come up with a cleaner fix in a future PR.

My thinking-out-load thinks this line is missing a check for the actual environment variable (it only checks for the flag):

github.com

maidsafe/sn_launch_tool/blob/844c1f2c31854751c367c951686dbf91a6c417ce/src/lib.rs#L264


      
          
          // Fetch node_conn_info from $HOME/.safe/node/node_connection_info.config.
          let genesis_contact_info = read_genesis_conn_info(args.verbosity)?;
          
          if args.verbosity > 0 {
              println!(
                  "Common node args for launching the network: {:?}",
                  common_args
              );
          
              if let Some(overriden_env) = &args.rust_log {
                  println!(
                      "RUST_LOG env var has been overridden with '{}'",
                      overriden_env
                  );
              } else {
                  println!("No RUST_LOG override provided");
              }
          }
          
          // We can now run the rest of the nodes

and then this line seals the fate, ignoring any ‘real’ environment variable that was set:

github.com

maidsafe/sn_launch_tool/blob/844c1f2c31854751c367c951686dbf91a6c417ce/src/lib.rs#L389


      
          if verbosity > 1 {
              println!("{}", msg);
          }
          debug!("{}", msg);
          
          let default_rust_log = "sn_node=debug".to_string();
          let rust_log_value = rust_log.unwrap_or(&default_rust_log);
          
          let _child = Command::new(&path_str)
              .args(args)
              .env("RUST_LOG", rust_log_value)
              .stdout(Stdio::null())
              .stderr(Stdio::inherit())
              .spawn()
              .map_err(|err| {
                  format!(
                      "Failed to run '{}' with args '{:?}': {}",
                      path_str, args, err
                  )
              })?;

I was trying to change the sn_node init_logging to a hardcoded filter level, but a) the launcher was always overriding it with the RUST_LOG environment variable, and b) RUST_LOG was only loaded from the flag (never the environment).

So many permutations of flags and env vars!!

bochaco · February 18, 2021, 10:41am

Ah right, the idea behind all that was that RUST_LOG would apply only to the app you are effectively running, in this case the launch_tool, but that doesn’t necessarily mean it’s the log level you want for the sn-nodes being launched by it. So that was an attempt to make that separation. Since as you say it’s confusing, it’s probably ok to have both the tool and nodes being launched to all go with the same level which is just from RUST_LOG I guess…

mav · February 18, 2021, 8:12pm

I think we can probably still achieve this.

Add a --rust-log flag to $ safe node run-baby-fleming here
Pass that flag to sn_launch_tool here
the nodes will use the --rust_log flag, but sn_launch_tool and sn_api will use the RUST_LOG env var

Maybe rename --rust_log to --node_rust_log just so it’s clear it’s only able to affect the node log level…?

bochaco · February 18, 2021, 8:51pm

That sounds excellent to me, although

Note we already have the y flag here, and here, so we’d just need to rename/change them.

mav · February 18, 2021, 9:55pm

not just rename, also pass it correctly on to sn_launch_tool.

We’d need to add an extra flag here and here, something like

...
"--node_verbosity",
&arg_node_verbosity,
...

Note sn_cli has a hardcoded -v verbosity for the sn_launch_tool logs which is potentially easy to confuse with the desired node_verbosity.

I think logically the steps to take are

rename sn_launch_tool flag --rust_log to --node_verbosity
then update sn_cli
- pass --node_verbosity flag to sn_launch_tool in sn_cli/operations/node.rs
- rename -y to --node_verbosity in sn_cli/subcommands/node.rs

Sound ok?

I acknowledge this seems like a lot of messing around in the weeds but logging is an important feature to get right. When we need it we really need it.

bochaco · February 18, 2021, 10:42pm

Yes, I agree. We are on the same page, I was just trying to point out that the CLI -y flag actually ends up setting the -y flag in the launch tool here, which is done from here, that’s how it’s been supported till now. So we can change them as you describe, the -y is very confusing. It’ll be different though as the new --node-verbosity will expect a RUST_LOG value while the existing -y is just mapping from occurrences to log levels, but I don’t think we need that if we have all the power of the RUST_LOG value.

The hardcoded -v is for having the launch-tool to print out the messages about the nodes being launched and so forth on the stdout.

mav · February 18, 2021, 10:45pm

Oh right, I hadn’t picked up on that chain. Thanks for pointing it out.