Add log messages to nitrocli

[robinkrahl]

Currently, we only have the log messages generated by libnitrokey which can make it difficult to track down issues with nitrocli itself. I suggest to add log messages to nitrokey (especially regarding device and connection handling and PIN caching) to make it easier to debug such issues. The log level should be set according to the --verbose option.

[d-e-s-o]

Yeah, I was also thinking about that. I agree it would be nice to have more visibility into it. I actually have had pretty good experience with tracing for other stuff I work on. Runtime configurability is good, it can span crates etc. But I think it may be too heavy weight here and provide a lot of stuff that we don't really need (it really provides the most benefit in async contexts, and you'll probably tell me to eff off if I suggested making nitrokey-rs async as part of the raw hidapi rework ;-) ). It would also mean bumping the supported Rust version more regularly (based on experience...).

So probably just some simple logging backend that we can convince to emit to stderr as I think libnitrokey is doing.

I suggest to add log messages to nitrokey

Do you mean nitrocli, nitrokey-rs, or both?

[robinkrahl]

I’d start off with log + simple_logger (or something similar). We can always use something more elaborate, but I think this should suite us well. If there is a use case for async nitrokey-rs, patches are welcome, but I don’t really see that at the moment. ;)

Do you mean nitrocli, nitrokey-rs, or both?

Sorry, that was a typo and supposed to say nitrocli. As long as nitrokey-rs is a rather thin wrapper around libnitrokey, I don’t think it needs separate logging.

[robinkrahl]

What is a bit of an issue is that we can’t easily share multiple mutable references to our stderr vector in src/tests/mod.rs. But we would need that if we want the logging framework to use our custom stderr stream. What do you think about printing the log messages directly to the real stderr? We currently don’t test verbosity anyway.

[d-e-s-o]

All libnitrokey stuff also goes directly to stderr even in tests (though we don't enable that as you said), correct? If so, yeah, it should be fine. (sorry, can't test right now)

[robinkrahl]

Yes, libnitrokey goes to std::clog which is stderr. Ideally, we would be able to use a custom logging function with libnitrokey to have all messages in the same format, see Nitrokey/libnitrokey#202.

[d-e-s-o]

👍
From the sounds of it (if stderr is the problem), we could just introduce another member, say log, and use that. That has the big benefit that it would allow us to easily separate out other, true error stuff (which I recall we briefly touched on before in the extensions discussion) if we need to.
I think that may be nice and forward looking and while I doubt we test logging itself, I'd say it's clean and in line with what we already do. What do you think?

[robinkrahl]

That would be nice, but it would require some refactoring because the logger has to take ownership of the writer. So I think this could not be part of Context but would have to be a separate argument to the run and handle_arguments functions.

[d-e-s-o]

I suppose we'd just need to embed an Arc or something. But yeah, doesn't seem worth it right now. Let's just emit logs to stderr. I suppose we can do more that later.

[robinkrahl]

I’ve started looking into the implementation. Some thoughts:

1. Suggested semantics for log levels:
   • Error: for errors (additionally to the Error returned by a function – maybe have customcontext and bail implementations that add logging?)
   • Warning: for conditions that might cause an error or that might be unintended by the user
   • Info: for information about the actions being taken. Should be concise enough to make it a sensible choice as the default log level for users who want to see what’s going on.
   • Debug: for information that makes it easier to follow the program flow and to understand why nitrocli is doing what it does
   • Trace: for everything more detailed
2. Question: Should verbosity zero (= no -v/--verbose argument) should set the log level to error or to off?
3. Suggestion: Introduce a new --log-level argument that supports setting the log level for all loggers or for specific loggers (i. e. nitrocli vs nitrokey once libnitrokey supports custom log handlers). --verbose would then be an alias for setting either the global or the nitrocli log level (tbd).
4. Suggestion: Introduce a new --log-file argument to write the log to a file instead.

Some pseudo-code as an example for the different log levels:

fn connect(model: Model) -> Result<Device, Error> {
    log::debug!("Trying to connect to a Nitrokey with model = {}", model);
    let devices = nitrokey::list_devices()?;
    
    log::trace!("{} Nitrokey devices found:", devices.len());
    for device in devices {
        log::trace!("- {} at {}", device.model, device.usb_path);
    }

    let devices = devices.iter().filter(|d| d.model == model).collect();
    if devices.is_empty() {
        log::error!("No Nitrokey device with model {} found", model);
         anyhow::bail!("No Nitrokey device with model {} found", model);
    } else if devices.len() > 1 {
        log::error!("More than one Nitrokey device with model {} found", model);
         anyhow::bail!("More than one Nitrokey device with model {} found", model);
    }

    match device.connect() {
        Ok(device) => {
            log::info!("Connected to Nitrokey device at {}", device.usb_path);
            Ok(device)
        }
        Err(err) => {
            log::error!("Failed to connect to Nitrokey device: {}", err);
            Err(err)
        }
    }
}

[d-e-s-o]

Thanks for looking into this topic!

• Suggested semantics for log levels:

  • Error: for errors (additionally to the Error returned by a function – maybe have customcontext and bail implementations that add logging?)
  • Warning: for conditions that might cause an error or that might be unintended by the user
  • Info: for information about the actions being taken. Should be concise enough to make it a sensible choice as the default log level for users who want to see what’s going on.
  • Debug: for information that makes it easier to follow the program flow and to understand why nitrocli is doing what it does
  • Trace: for everything more detailed

Makes sense. Yeah, to cut down on duplication we should definitely consider piggy backing on the existing anyhow related functionality (and overriding it sounds fine to me).

• Question: Should verbosity zero (= no -v/--verbose argument) should set the log level to error or to off?

Given what you suggest, I think it should be off. Otherwise whenever an error is emitted won't any error appear twice (because we don't suppress errors anywhere from what I recall)?

• Suggestion: Introduce a new --log-level argument that supports setting the log level for all loggers or for specific loggers (i. e. nitrocli vs nitrokey once libnitrokey supports custom log handlers). --verbose would then be an alias for setting either the global or the nitrocli log level (tbd).

Yeah, I think that makes sense, although perhaps an environment variable would be better: this seems to be fairly developer centric and then it would not show up and cause confusion with -v/--verbose? I don't feel strongly, and if we add --log-file as you propose we may as well add this.

• Suggestion: Introduce a new --log-file argument to write the log to a file instead.

I suppose just redirecting output from the shell falls short in some cases or why do we need this option?

[robinkrahl]

I suppose just redirecting output from the shell falls short in some cases or why do we need this option?

Two aspects: We can’t separate “regular” error messages and log messages. If we redirect stderr, we don’t see the error messages either. And --log-file could be set in the configuration file.

The use case I have in mind for this is pre-emptive logging, for example for errors that are hard to reproduce. The user could set log-level = "trace" and log-file = "/run/user/1000/nitrocli.log" in the configuration file and inspect the log file once an error occurs, without affecting the regular command usage.

[d-e-s-o]

Okay, that's what I thought, thanks. 👍