Keep separators between time part of logfile names

The timestamp part of the log filename becomes a dense series of
numbers because sanitize_filename removes ":" as it is a special
character on windows.  So use a custom replacement character to fix
work around this.

appveyor.yml

@@ -1,4 +1,5 @@
 environment:
+  RUST_BACKTRACE: full
   matrix:
     - APPVEYOR_BUILD_WORKER_IMAGE: Visual Studio 2017
 

deltachat-ffi/src/lib.rs

@@ -24,7 +24,7 @@ use num_traits::{FromPrimitive, ToPrimitive};
 
 use deltachat::constants::DC_MSG_ID_LAST_SPECIAL;
 use deltachat::contact::Contact;
-use deltachat::context::Context;
+use deltachat::context::{Context, ContextBuilder};
 use deltachat::dc_tools::{
     as_path, dc_strdup, to_opt_string_lossy, to_string_lossy, OsStrExt, StrExt,
 };
@@ -248,22 +248,15 @@ pub unsafe extern "C" fn dc_open(
     }
     let ffi_context = &*context;
     let rust_cb = move |_ctx: &Context, evt: Event| ffi_context.translate_cb(evt);
-
-    let ctx = if blobdir.is_null() || *blobdir == 0 {
-        Context::new(
-            Box::new(rust_cb),
-            ffi_context.os_name.clone(),
-            as_path(dbfile).to_path_buf(),
-        )
-    } else {
-        Context::with_blobdir(
-            Box::new(rust_cb),
-            ffi_context.os_name.clone(),
-            as_path(dbfile).to_path_buf(),
-            as_path(blobdir).to_path_buf(),
-        )
-    };
-    match ctx {
+    let mut builder = ContextBuilder::new(
+        Box::new(rust_cb),
+        ffi_context.os_name.clone(),
+        as_path(dbfile).to_path_buf(),
+    );
+    if !blobdir.is_null() && *blobdir != 0 {
+        builder = builder.blobdir(as_path(blobdir).to_path_buf());
+    }
+    match builder.create() {
         Ok(ctx) => {
             let mut inner_guard = ffi_context.inner.write().unwrap();
             *inner_guard = Some(ctx);

examples/repl/main.rs

@@ -366,11 +366,12 @@ fn main_0(args: Vec<String>) -> Result<(), failure::Error> {
         println!("Error: Bad arguments, expected [db-name].");
         return Err(format_err!("No db-name specified"));
     }
-    let context = Context::new(
+    let context = ContextBuilder::new(
         Box::new(receive_event),
         "CLI".into(),
         Path::new(&args[1]).to_path_buf(),
-    )?;
+    )
+    .create()?;
 
     println!("Delta Chat Core is awaiting your commands.");
 

examples/simple.rs

@@ -39,8 +39,9 @@ fn main() {
     let dir = tempdir().unwrap();
     let dbfile = dir.path().join("db.sqlite");
     println!("creating database {:?}", dbfile);
-    let ctx =
-        Context::new(Box::new(cb), "FakeOs".into(), dbfile).expect("Failed to create context");
+    let ctx = ContextBuilder::new(Box::new(cb), "FakeOs".into(), dbfile)
+        .create()
+        .expect("Failed to create context");
     let running = Arc::new(RwLock::new(true));
     let info = ctx.get_info();
     let duration = time::Duration::from_millis(4000);

src/context.rs

@@ -15,6 +15,7 @@ use crate::imap::*;
 use crate::job::*;
 use crate::job_thread::JobThread;
 use crate::key::*;
+use crate::log;
 use crate::login_param::LoginParam;
 use crate::lot::Lot;
 use crate::message::{self, Message, MsgId};
@@ -62,6 +63,7 @@ pub struct Context {
     /// Mutex to avoid generating the key for the user more than once.
     pub generating_key_mutex: Mutex<()>,
     pub translated_stockstrings: RwLock<HashMap<usize, String>>,
+    pub logger: RwLock<log::Logger>,
 }
 
 #[derive(Debug, PartialEq, Eq)]
@@ -94,30 +96,92 @@ pub fn get_info() -> HashMap<&'static str, String> {
     res
 }
 
-impl Context {
-    /// Creates new context.
-    pub fn new(cb: Box<ContextCallback>, os_name: String, dbfile: PathBuf) -> Result<Context> {
-        let mut blob_fname = OsString::new();
-        blob_fname.push(dbfile.file_name().unwrap_or_default());
+/// Builder for [Context].
+///
+/// # Example
+///
+/// ```
+/// use deltachat::context::ContextBuilder;
+/// let dir = tempfile::tempdir().unwrap();
+/// let dbfile = dir.path().join("my-context.db");
+/// let ctx = ContextBuilder::new(Box::new(|_, _| 0), "AppName".into(), dbfile)
+///     .blobdir(dir.path().join("my-context-blobs"))
+///     .logdir(dir.path().join("my-context-logs"))
+///     .create()
+///     .unwrap();
+/// assert_eq!(ctx.get_blobdir(), dir.path().join("my-context-blobs"));
+/// ```
+#[derive(DebugStub)]
+pub struct ContextBuilder {
+    #[debug_stub = "Callback"]
+    cb: Box<ContextCallback>,
+    os_name: String,
+    dbfile: PathBuf,
+    blobdir: PathBuf,
+    logdir: PathBuf,
+}
+
+impl ContextBuilder {
+    pub fn new(cb: Box<ContextCallback>, os_name: String, dbfile: PathBuf) -> Self {
+        let db_fname = OsString::from(dbfile.file_name().unwrap_or(&OsString::from("dc-context")));
+        let mut blob_fname = db_fname.clone();
         blob_fname.push("-blobs");
-        let blobdir = dbfile.with_file_name(blob_fname);
-        if !blobdir.exists() {
-            std::fs::create_dir_all(&blobdir)?;
+        let mut log_fname = db_fname.clone();
+        log_fname.push("-logs");
+        ContextBuilder {
+            cb,
+            os_name,
+            blobdir: dbfile.with_file_name(blob_fname),
+            logdir: dbfile.with_file_name(log_fname),
+            dbfile,
         }
-        Context::with_blobdir(cb, os_name, dbfile, blobdir)
     }
 
-    pub fn with_blobdir(
+    pub fn blobdir(mut self, path: PathBuf) -> Self {
+        self.blobdir = path;
+        self
+    }
+
+    pub fn logdir(mut self, path: PathBuf) -> Self {
+        self.logdir = path;
+        self
+    }
+
+    pub fn create(self) -> Result<Context> {
+        if !self.blobdir.exists() {
+            std::fs::create_dir_all(&self.blobdir)?;
+        }
+        if !self.logdir.exists() {
+            std::fs::create_dir_all(&self.logdir)?;
+        }
+        Context::new(
+            self.cb,
+            self.os_name,
+            self.dbfile,
+            self.blobdir,
+            self.logdir,
+        )
+    }
+}
+
+impl Context {
+    fn new(
         cb: Box<ContextCallback>,
         os_name: String,
         dbfile: PathBuf,
         blobdir: PathBuf,
+        logdir: PathBuf,
     ) -> Result<Context> {
         ensure!(
             blobdir.is_dir(),
             "Blobdir does not exist: {}",
             blobdir.display()
         );
+        ensure!(
+            logdir.is_dir(),
+            "Logdir does not exist: {}",
+            logdir.display()
+        );
         let ctx = Context {
             blobdir,
             dbfile,
@@ -150,6 +214,7 @@ impl Context {
             perform_inbox_jobs_needed: Arc::new(RwLock::new(false)),
             generating_key_mutex: Mutex::new(()),
             translated_stockstrings: RwLock::new(HashMap::new()),
+            logger: RwLock::new(log::Logger::new(logdir)?),
         };
 
         ensure!(
@@ -526,7 +591,7 @@ mod tests {
         let tmp = tempfile::tempdir().unwrap();
         let dbfile = tmp.path().join("db.sqlite");
         std::fs::write(&dbfile, b"123").unwrap();
-        let res = Context::new(Box::new(|_, _| 0), "FakeOs".into(), dbfile);
+        let res = ContextBuilder::new(Box::new(|_, _| 0), "FakeOs".into(), dbfile).create();
         assert!(res.is_err());
     }
 
@@ -541,7 +606,9 @@ mod tests {
     fn test_blobdir_exists() {
         let tmp = tempfile::tempdir().unwrap();
         let dbfile = tmp.path().join("db.sqlite");
-        Context::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile).unwrap();
+        ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .create()
+            .unwrap();
         let blobdir = tmp.path().join("db.sqlite-blobs");
         assert!(blobdir.is_dir());
     }
@@ -552,7 +619,7 @@ mod tests {
         let dbfile = tmp.path().join("db.sqlite");
         let blobdir = tmp.path().join("db.sqlite-blobs");
         std::fs::write(&blobdir, b"123").unwrap();
-        let res = Context::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile);
+        let res = ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile).create();
         assert!(res.is_err());
     }
 
@@ -562,7 +629,9 @@ mod tests {
         let subdir = tmp.path().join("subdir");
         let dbfile = subdir.join("db.sqlite");
         let dbfile2 = dbfile.clone();
-        Context::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile).unwrap();
+        ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .create()
+            .unwrap();
         assert!(subdir.is_dir());
         assert!(dbfile2.is_file());
     }
@@ -572,7 +641,9 @@ mod tests {
         let tmp = tempfile::tempdir().unwrap();
         let dbfile = tmp.path().join("db.sqlite");
         let blobdir = PathBuf::new();
-        let res = Context::with_blobdir(Box::new(|_, _| 0), "FakeOS".into(), dbfile, blobdir);
+        let res = ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .blobdir(blobdir)
+            .create();
         assert!(res.is_err());
     }
 
@@ -581,10 +652,36 @@ mod tests {
         let tmp = tempfile::tempdir().unwrap();
         let dbfile = tmp.path().join("db.sqlite");
         let blobdir = tmp.path().join("blobs");
-        let res = Context::with_blobdir(Box::new(|_, _| 0), "FakeOS".into(), dbfile, blobdir);
+        ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .blobdir(blobdir.clone())
+            .create()
+            .unwrap();
+        assert!(blobdir.is_dir());
+    }
+
+    #[test]
+    fn test_with_empty_logdir() {
+        let tmp = tempfile::tempdir().unwrap();
+        let dbfile = tmp.path().join("db.sqlite");
+        let logdir = PathBuf::new();
+        let res = ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .logdir(logdir)
+            .create();
         assert!(res.is_err());
     }
 
+    #[test]
+    fn test_with_logdir_not_exists() {
+        let tmp = tempfile::tempdir().unwrap();
+        let dbfile = tmp.path().join("db.sqlite");
+        let logdir = tmp.path().join("logs");
+        ContextBuilder::new(Box::new(|_, _| 0), "FakeOS".into(), dbfile)
+            .logdir(logdir.clone())
+            .create()
+            .unwrap();
+        assert!(logdir.is_dir());
+    }
+
     #[test]
     fn no_crashes_on_context_deref() {
         let t = dummy_context();

src/lib.rs

@@ -22,7 +22,7 @@ extern crate jetscii;
 extern crate debug_stub_derive;
 
 #[macro_use]
-mod log;
+pub mod log;
 #[macro_use]
 pub mod error;
 

src/log.rs

@@ -1,4 +1,167 @@
-//! # Logging macros
+//! # Logging support
+
+use std::fmt;
+use std::fs;
+use std::io;
+use std::io::prelude::*;
+use std::path::{Path, PathBuf};
+
+/// A logger for a [Context].
+#[derive(Debug)]
+pub struct Logger {
+    created: std::time::Instant,
+    logdir: PathBuf,
+    logfile: String,
+    file_handle: fs::File,
+    max_files: u32,
+    max_filesize: usize,
+    bytes_written: usize,
+}
+
+#[derive(Debug, Clone, PartialEq, Eq)]
+pub enum LogLevel {
+    Info,
+    Warning,
+    Error,
+}
+
+impl fmt::Display for LogLevel {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match self {
+            LogLevel::Info => write!(f, "I"),
+            LogLevel::Warning => write!(f, "W"),
+            LogLevel::Error => write!(f, "E"),
+        }
+    }
+}
+
+#[derive(Debug, Clone, PartialEq, Eq)]
+pub struct Callsite<'a> {
+    pub file: &'a str,
+    pub line: u32,
+}
+
+impl fmt::Display for Callsite<'_> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "{}:{}", self.file, self.line)
+    }
+}
+
+impl Logger {
+    pub fn new(logdir: PathBuf) -> Result<Logger, io::Error> {
+        let (fname, file) = Self::open(&logdir)?;
+        let max_files = 5;
+        Self::prune(&logdir, max_files)?;
+        Ok(Logger {
+            created: std::time::Instant::now(),
+            logdir,
+            logfile: fname,
+            file_handle: file,
+            max_files,
+            max_filesize: 4 * 1024 * 1024, // 4 Mb
+            bytes_written: 0,
+        })
+    }
+
+    /// Opens a new logfile, returning a tuple of (file_name, file_handle).
+    ///
+    /// This tries to create a new logfile based on the current time,
+    /// creating .0.log, .1.log etc if this file already exists (up to 32).
+    fn open(logdir: &Path) -> Result<(String, fs::File), io::Error> {
+        let basename =
+            chrono::offset::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true);
+        let mut fname = sanitize_filename::sanitize_with_options(
+            format!("{}.log", &basename),
+            sanitize_filename::Options {
+                truncate: true,
+                windows: true,
+                replacement: ".",
+            },
+        );
+        let mut counter = 0;
+        loop {
+            match std::fs::OpenOptions::new()
+                .write(true)
+                .create_new(true)
+                .open(logdir.join(&fname))
+            {
+                Ok(file) => {
+                    return Ok((fname, file));
+                }
+                Err(e) => {
+                    if counter >= 32 {
+                        return Err(e);
+                    } else {
+                        counter += 1;
+                        fname =
+                            sanitize_filename::sanitize(format!("{}-{}.log", &basename, counter));
+                        continue;
+                    }
+                }
+            }
+        }
+    }
+
+    /// Cleans up old logfiles.
+    fn prune(logdir: &Path, max_files: u32) -> Result<(), io::Error> {
+        let mut names: Vec<std::ffi::OsString> = Vec::new();
+        for dirent in fs::read_dir(logdir)? {
+            names.push(dirent?.file_name());
+        }
+        // Sorting like this sorts: 23.log, 24.1.log, 24.2.log,
+        // 24.log, 25.log.  That is 24.log is out of sequence.  Oh well.
+        names.sort();
+        names.reverse();
+        while names.len() > max_files as usize {
+            if let Some(name) = names.pop() {
+                fs::remove_file(logdir.join(name))?;
+            }
+        }
+        Ok(())
+    }
+
+    pub fn log(
+        &mut self,
+        level: LogLevel,
+        callsite: Callsite,
+        msg: &str,
+    ) -> Result<(), std::io::Error> {
+        if self.bytes_written > self.max_filesize {
+            self.flush()?;
+            let (fname, handle) = Self::open(&self.logdir)?;
+            self.logfile = fname;
+            self.file_handle = handle;
+            Self::prune(&self.logdir, self.max_files)?;
+        }
+        let thread = std::thread::current();
+        let msg = format!(
+            "{time:8.2} {level} {thid:?}/{thname} [{callsite}]: {msg}\n",
+            time = self.created.elapsed().as_secs_f64(),
+            level = level,
+            thid = thread.id(),
+            thname = thread.name().unwrap_or("unnamed"),
+            callsite = callsite,
+            msg = msg,
+        );
+        self.file_handle.write_all(msg.as_bytes())?;
+        self.bytes_written += msg.len();
+        Ok(())
+    }
+
+    pub fn flush(&mut self) -> Result<(), std::io::Error> {
+        self.file_handle.flush()
+    }
+}
+
+#[macro_export]
+macro_rules! callsite {
+    () => {
+        $crate::log::Callsite {
+            file: file!(),
+            line: line!(),
+        }
+    };
+}
 
 #[macro_export]
 macro_rules! info {
@@ -7,6 +170,9 @@ macro_rules! info {
     };
     ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
         let formatted = format!($msg, $($args),*);
+        if let Ok(mut logger) = $ctx.logger.write() {
+            logger.log($crate::log::LogLevel::Info, callsite!(), &formatted).ok();
+        }
         emit_event!($ctx, $crate::Event::Info(formatted));
     }};
 }
@@ -18,6 +184,9 @@ macro_rules! warn {
     };
     ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
         let formatted = format!($msg, $($args),*);
+        if let Ok(mut logger) = $ctx.logger.write() {
+            logger.log($crate::log::LogLevel::Warning, callsite!(), &formatted).ok();
+        }
         emit_event!($ctx, $crate::Event::Warning(formatted));
     }};
 }
@@ -29,6 +198,9 @@ macro_rules! error {
     };
     ($ctx:expr, $msg:expr, $($args:expr),* $(,)?) => {{
         let formatted = format!($msg, $($args),*);
+        if let Ok(mut logger) = $ctx.logger.write() {
+            logger.log($crate::log::LogLevel::Error, callsite!(), &formatted).ok();
+        }
         emit_event!($ctx, $crate::Event::Error(formatted));
     }};
 }
@@ -39,3 +211,80 @@ macro_rules! emit_event {
         $ctx.call_cb($event);
     };
 }
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn test_basic_logging() {
+        let tmp = tempfile::tempdir().unwrap();
+        let dir = tmp.path();
+        let mut logger = Logger::new(dir.to_path_buf()).unwrap();
+        logger.log(LogLevel::Info, callsite!(), "foo").unwrap();
+        logger.log(LogLevel::Warning, callsite!(), "bar").unwrap();
+        logger.log(LogLevel::Error, callsite!(), "baz").unwrap();
+        logger.flush().unwrap();
+        let log = fs::read_to_string(logger.logdir.join(logger.logfile)).unwrap();
+        println!("{}", log);
+        let lines: Vec<&str> = log.lines().collect();
+
+        assert!(lines[0].contains(" I "));
+        assert!(lines[0].contains(format!("{:?}", std::thread::current().id()).as_str()));
+        assert!(lines[0]
+            .contains(format!("{}", std::thread::current().name().unwrap_or("unnamed")).as_str()));
+        assert!(lines[0].contains(&format!("src{}log.rs", std::path::MAIN_SEPARATOR)));
+        assert!(lines[0].contains("foo"));
+
+        assert!(lines[1].contains(" W "));
+        assert!(lines[1].contains(format!("{:?}", std::thread::current().id()).as_str()));
+        assert!(lines[1]
+            .contains(format!("{}", std::thread::current().name().unwrap_or("unnamed")).as_str()));
+        assert!(lines[1].contains(&format!("src{}log.rs", std::path::MAIN_SEPARATOR)));
+        assert!(lines[1].contains("bar"));
+
+        assert!(lines[2].contains(" E "));
+        assert!(lines[2].contains(format!("{:?}", std::thread::current().id()).as_str()));
+        assert!(lines[2]
+            .contains(format!("{}", std::thread::current().name().unwrap_or("unnamed")).as_str()));
+        assert!(lines[2].contains(&format!("src{}log.rs", std::path::MAIN_SEPARATOR)));
+        assert!(lines[2].contains("baz"));
+    }
+
+    #[test]
+    fn test_reopen_logfile() {
+        let tmp = tempfile::tempdir().unwrap();
+        let dir = tmp.path();
+        let mut logger = Logger::new(dir.to_path_buf()).unwrap();
+        logger.max_filesize = 5;
+
+        let fname0 = logger.logfile.clone();
+        assert!(fname0.ends_with(".log"));
+        logger
+            .log(LogLevel::Info, callsite!(), "more than 5 bytes are written")
+            .unwrap();
+        logger.log(LogLevel::Info, callsite!(), "2nd msg").unwrap();
+        let fname1 = logger.logfile.clone();
+        assert!(fname1.ends_with("-1.log"));
+        assert_ne!(fname0, fname1);
+        let log0 = fs::read_to_string(logger.logdir.join(&fname0)).unwrap();
+        assert!(log0.contains("more than 5 bytes are written"));
+        let log1 = fs::read_to_string(logger.logdir.join(&fname1)).unwrap();
+        assert!(log1.contains("2nd msg"));
+    }
+
+    #[test]
+    fn test_prune() {
+        let tmp = tempfile::tempdir().unwrap();
+        let dir = tmp.path();
+        Logger::new(dir.to_path_buf()).unwrap();
+        Logger::new(dir.to_path_buf()).unwrap();
+        Logger::new(dir.to_path_buf()).unwrap();
+        Logger::new(dir.to_path_buf()).unwrap();
+        let dirents0: Vec<fs::DirEntry> = fs::read_dir(&dir).unwrap().map(|r| r.unwrap()).collect();
+        assert_eq!(dirents0.len(), 4);
+        Logger::prune(&dir, 3).unwrap();
+        let dirents1: Vec<fs::DirEntry> = fs::read_dir(&dir).unwrap().map(|r| r.unwrap()).collect();
+        assert_eq!(dirents1.len(), 3);
+    }
+}

src/test_utils.rs

@@ -7,7 +7,7 @@ use tempfile::{tempdir, TempDir};
 
 use crate::config::Config;
 use crate::constants::KeyType;
-use crate::context::{Context, ContextCallback};
+use crate::context::{Context, ContextBuilder, ContextCallback};
 use crate::events::Event;
 use crate::key;
 
@@ -33,7 +33,9 @@ pub fn test_context(callback: Option<Box<ContextCallback>>) -> TestContext {
         Some(cb) => cb,
         None => Box::new(|_, _| 0),
     };
-    let ctx = Context::new(cb, "FakeOs".into(), dbfile).unwrap();
+    let ctx = ContextBuilder::new(cb, "FakeOs".into(), dbfile)
+        .create()
+        .unwrap();
     TestContext { ctx: ctx, dir: dir }
 }
 

tests/stress.rs

@@ -219,7 +219,9 @@ struct TestContext {
 fn create_test_context() -> TestContext {
     let dir = tempdir().unwrap();
     let dbfile = dir.path().join("db.sqlite");
-    let ctx = Context::new(Box::new(cb), "FakeOs".into(), dbfile).unwrap();
+    let ctx = ContextBuilder::new(Box::new(cb), "FakeOs".into(), dbfile)
+        .create()
+        .unwrap();
     TestContext { ctx, dir }
 }