log4rs icon indicating copy to clipboard operation
log4rs copied to clipboard

`log4rs::init_file` should not leave log files on disk when init fails due to a previously set logger.

Open abmpicoli opened this issue 3 years ago • 2 comments

Hi, I've made the following change to the example log_to_file.rs, to check if the behavior for log4rs initialization is the expected one, which is that, if there is already an active log configuration, do not even begin to try to use/parse a different log configuration and fail early.

And here I found a partial antipattern: it seems that the init_file IS trying to parse the configuration file, open the streams, etc, and only in the end of the process send an error.

Here is the code sample: that can be found at https://github.com/abmpicoli/log4rs/commit/3024f929f4a3db99f815af22c456693c4e3c9e33

use log::{debug, error, info, trace, warn, LevelFilter, SetLoggerError};
use log4rs::{
    append::{
        console::{ConsoleAppender, Target},
        file::FileAppender,
    },
    config::{Appender, Config, Root},
    encode::pattern::PatternEncoder,
    filter::threshold::ThresholdFilter,

};
use std::fs;
use std::path::Path;

fn main() -> Result<(), SetLoggerError> {
    let level = log::LevelFilter::Info;
    let file_path = "/tmp/foo.log";

    // Build a stderr logger.
    let stderr = ConsoleAppender::builder().target(Target::Stderr).build();

    // Logging to log file.
    let logfile = FileAppender::builder()
        // Pattern: https://docs.rs/log4rs/*/log4rs/encode/pattern/index.html
        .encoder(Box::new(PatternEncoder::new("{l} - {m}\n")))
        .build(file_path)
        .unwrap();

    // Log Trace level output to file where trace is the default level
    // and the programmatically specified level to stderr.
    let config = Config::builder()
        .appender(Appender::builder().build("logfile", Box::new(logfile)))
        .appender(
            Appender::builder()
                .filter(Box::new(ThresholdFilter::new(level)))
                .build("stderr", Box::new(stderr)),
        )
        .build(
            Root::builder()
                .appender("logfile")
                .appender("stderr")
                .build(LevelFilter::Trace),
        )
        .unwrap();

    // Use this to change log levels at runtime.
    // This means you can change the default log level to trace
    // if you are trying to debug an issue and need more logs on then turn it off
    // once you are done.
    let _handle = log4rs::init_config(config)?;

    error!("Goes to stderr and file");
    warn!("Goes to stderr and file");
    info!("Goes to stderr and file");
    debug!("Goes to file only");
    trace!("Goes to file only");

    // abmpicoli: this is a check for an antipattern: initialization overrides can cause unpredictable
    // log shifting, and logs all over unpredictable places. So this can never happen.

    // the this_config_shouldnt_be_read.yml creates a log file at /tmp/log4rs_EXAMPLE_LOG_TO_FILE_OH_OH.log.
    // if this initialization is fine, the file should not exist.

    // making sure the file really doesn't exists before initialization.
    let file_created_inside_the_config_that_shoudlnt_be_read = Path::new("/tmp/log4rs_EXAMPLE_LOG_TO_FILE_OH_OH.log");

    let _remove_file_outcome = fs::remove_file(file_created_inside_the_config_that_shoudlnt_be_read);
    if file_created_inside_the_config_that_shoudlnt_be_read.exists() {
        error!("FAILURE!!! THE FILE REMOVAL DIDNT WORK!");
    }

    let init_file_result = log4rs::init_file("examples/this_config_shouldnt_be_read.yml", Default::default());
    if init_file_result.is_err() {
        info!("SUCCESS!! It should be really an error to reconfigure logs at runtime");
    };
    if file_created_inside_the_config_that_shoudlnt_be_read.exists() {
        error!("FAILURE!! Although init file DIDN'T reconfigure logs, it has tried to do so anyway, creating extraneous log files");
    }


    Ok(())
}

I'm right now in rust alphabet in the letter J, so I still don't know for sure how to fix this.

The expected outcome would see no "FAILURE!!" messages in the logs by running this sample.

abmpicoli avatar Apr 24 '22 18:04 abmpicoli

@estk although this is the immediate perceptible defect, the file gets created, the issue is deeper: any attempt of changing configuration using init methods should immediately fail. Because otherwise it could cause performance degradation.

The fact that the file was created shows that:

  1. The configuration file was parsed, and it was "discovered" that a file was necessary;
  2. the file was opened;

Imagine if the pattern used for the init_auto thing (#258 ) used by developers begin to be

log4rs::init_auto();
info!("bla!");

And then the guy decides to run that inside a loop :)

abmpicoli avatar Apr 24 '22 19:04 abmpicoli

@abmpicoli I'm not sure the problem that you're talking about is solvable without violating the "Principle of least astonishment" but I would be happy to mentor you as you take a crack at it in the init_auto() method. Additionally, I'm not sure tolerance of reckless use is really a design goal of this project.

estk avatar Apr 24 '22 22:04 estk