Add a file output for "tracing" and ensure that panics are included

[patowen]

Since people playing Hypermine are not necessarily expected to run it with the command line, we should have logs available to help streamline debugging, since the user can just read the log file instead of needing to reproduce the issue with the shell open.

I wasn't quite sure how to abstract this. I put most of the logic in "client" instead of "common", since the "server" application is meant to be run in a shell, making it less necessary to write log files.

[Ralith]

Do we have any reason to believe log file size is a realistic concern? In practice it will be bounded by client runtime, and we should prefer not to emit anything ruinously verbose for other reasons regardless.

[patowen]

That's fair. The main risk is that someone adds logging temporarily while developing, and it fills up their hard drive, but that seems very unlikely. I do wish "tracing" had a failsafe for such mistakes, though. An open three-year old PR with no open requests from reviewers worries me that "tracing" is in danger of being abandoned.

[Ralith]

Rotating log files every minute is extremely weird and may make it quite difficult to usefully debug issues that don't lead to instant crashes. I'd prefer to see a simpler scheme that just keeps logs from the current and previous run.

[patowen]

Do you know of a good way to do that with the tracing library? I'd be happy to expand it to hourly if we don't expect it to be an issue, but I'm not convinced tracing supports the use case you are suggesting without additional dependencies or custom logic, both of which seem difficult to prioritize.

[Ralith]

Don't use the built in rotation mechanism at all. Just always write to a fixed file, and if you like, rename any preexisting file to have a ".old" suffix or something on startup.

[patowen]

That might work. If I go this route, though, I'll need to open "tracing"'s black box a bit, since the previous implementation did not require me to consider what file name "tracing" used.

[Ralith]

You don't need to reverse-engineer its choice of filename because you're dropping the part that comes up with filenames entirely; you can just pass any io::Write impl to tracing_appender::new_nonblocking. Here's one I use in another project:

use std::{
    fs,
    fs::{File, OpenOptions},
    io,
    path::PathBuf,
};

pub struct Logfile {
    path: PathBuf,
    old_path: PathBuf,
    file: Option<File>,
}

impl Logfile {
    pub fn new(path: PathBuf) -> Self {
        let mut old_path = path.clone();
        old_path.set_file_name(format!("{}.old", path.display()));
        Self {
            old_path,
            path,
            file: None,
        }
    }
}

impl io::Write for Logfile {
    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
        let file = match self.file {
            Some(ref mut file) => file,
            None => loop {
                match OpenOptions::new()
                    .write(true)
                    .create_new(true)
                    .open(&self.path)
                {
                    Ok(file) => break self.file.insert(file),
                    Err(ref e) if e.kind() == io::ErrorKind::AlreadyExists => {
                        fs::rename(&self.path, &self.old_path)?;
                    }
                    Err(e) => return Err(e),
                }
            },
        };
        file.write(buf)
    }

    fn flush(&mut self) -> io::Result<()> {
        if let Some(ref mut file) = self.file {
            file.flush()?;
        }
        Ok(())
    }
}

[Ralith]

Not really sure why I deferred opening to the write impl in retrospect, but w/e.

[patowen]

Makes sense. My hope was that the defaults that "tracing" provides would be sufficient for us, since I don't think we have too strict a design constraint.

I did submit some changes to this PR, as it looks like tracing_appender::rolling::never explicitly says that the file name I pass in is the exact name of the file. I think this logic is sufficient for our purposes, but if you would like me to use your code snippet instead, please let me know.

[patowen]

I looked into this further. The main issue with your version is that if, for some reason, the log file cannot be renamed, the resulting error will be swallowed entirely: https://github.com/tokio-rs/tracing/blob/efc690fa6bd1d9c3a57528b9bc8ac80504a7a6ed/tracing-appender/src/worker.rs#L82.

Of course, not deferring opening to the write impl can help with this, but at the same time, this deferring has the advantage of allowing us to manually log issues to the console with "tracing" if we want to.

I have warmed up to the idea of using a custom implementation, as it seems like tracings's version does have some issues, so it will likely save us time in the long run.

EDIT: However, this is nontrivial, as juggling log files can have a fair amount of edge cases. What if multiple instances of Hypermine are open? I don't think it's worth the effort to try to work around tracing's poor support for logging errors within tracing itself or resolve every edge case. I'll go ahead and copy your implementation with a few minor enhancements to try to avoid silent failures in the most obvious places.

[patowen]

I've now added your implementation with some modifications. Thanks for the help!