From 0a1ee470f785663847743517bed4d74950f5b00e Mon Sep 17 00:00:00 2001 From: "Dustin J. Mitchell" Date: Sun, 29 Nov 2020 18:18:28 -0500 Subject: [PATCH] use log and env_logger, and add some logging around sync --- Cargo.lock | 42 +++++++++++++++++++++++++++++++++++++ cli/Cargo.toml | 2 ++ cli/src/bin/task.rs | 1 + cli/src/cmd/shared.rs | 11 ++++++---- cli/src/settings.rs | 2 ++ docs/src/usage.md | 8 +++++++ sync-server/Cargo.toml | 2 ++ sync-server/src/main.rs | 3 ++- sync-server/src/server.rs | 11 ++++++++++ taskchampion/Cargo.toml | 1 + taskchampion/src/replica.rs | 6 +++++- taskchampion/src/task.rs | 4 ++++ taskchampion/src/taskdb.rs | 30 +++++++++++++++++++------- 13 files changed, 109 insertions(+), 14 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5d4662bb0..ed6533c58 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -787,6 +787,19 @@ dependencies = [ "syn", ] +[[package]] +name = "env_logger" +version = "0.8.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f26ecb66b4bdca6c1409b40fb255eefc2bd4f6d135dab3c3124f80ffa2a9661e" +dependencies = [ + "atty", + "humantime", + "log", + "regex", + "termcolor", +] + [[package]] name = "error-chain" version = "0.12.4" @@ -1080,6 +1093,12 @@ version = "1.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cd179ae861f0c2e53da70d892f5f3029f9594be0c41dc5269cd371691b1dc2f9" +[[package]] +name = "humantime" +version = "2.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3c1ad908cc71012b7bea4d0c53ba96a8cba9962f048fa68d143376143d863b7a" + [[package]] name = "idna" version = "0.2.0" @@ -2189,6 +2208,7 @@ dependencies = [ "failure", "kv", "lmdb-rkv", + "log", "proptest", "serde", "serde_json", @@ -2205,7 +2225,9 @@ dependencies = [ "clap", "config", "dirs 3.0.1", + "env_logger", "failure", + "log", "predicates", "prettytable-rs", "taskchampion", @@ -2218,9 +2240,11 @@ dependencies = [ "actix-rt", "actix-web", "clap", + "env_logger", "failure", "futures", "kv", + "log", "serde", "tempdir", "uuid", @@ -2261,6 +2285,15 @@ dependencies = [ "winapi 0.3.9", ] +[[package]] +name = "termcolor" +version = "1.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" +dependencies = [ + "winapi-util", +] + [[package]] name = "textwrap" version = "0.11.0" @@ -2731,6 +2764,15 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" +[[package]] +name = "winapi-util" +version = "0.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" +dependencies = [ + "winapi 0.3.9", +] + [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 36e313f8e..61c79b052 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -11,6 +11,8 @@ failure = "^0.1.8" prettytable-rs = "^0.8.0" config = { version="^0.10.1", default-features=false, features=["yaml"] } dirs = "^3.0.1" +log = "^0.4.11" +env_logger = "^0.8.2" [dev-dependencies] assert_cmd = "^1.0.1" diff --git a/cli/src/bin/task.rs b/cli/src/bin/task.rs index e90ead9d2..ab21c54bc 100644 --- a/cli/src/bin/task.rs +++ b/cli/src/bin/task.rs @@ -17,6 +17,7 @@ fn bail(err: E, output: Output, code: i32) -> ! { } fn main() { + env_logger::init(); let command = match parse_command_line(std::env::args_os()) { Ok(command) => command, Err(err) => { diff --git a/cli/src/cmd/shared.rs b/cli/src/cmd/shared.rs index 9744ea6f3..006b08ac5 100644 --- a/cli/src/cmd/shared.rs +++ b/cli/src/cmd/shared.rs @@ -66,9 +66,9 @@ impl CommandInvocation { pub(super) fn get_replica(&self) -> Fallible { let settings = self.get_settings()?; - let replica_config = ReplicaConfig { - taskdb_dir: settings.get_str("data_dir")?.into(), - }; + let taskdb_dir = settings.get_str("data_dir")?.into(); + log::debug!("Replica data_dir: {:?}", taskdb_dir); + let replica_config = ReplicaConfig { taskdb_dir }; Ok(Replica::from_config(replica_config)?) } @@ -76,8 +76,11 @@ impl CommandInvocation { let settings = self.get_settings()?; let client_id = settings.get_str("server_client_id")?; let client_id = Uuid::parse_str(&client_id)?; + let origin = settings.get_str("server_origin")?; + log::debug!("Using sync-server with origin {}", origin); + log::debug!("Sync client ID: {}", client_id); Ok(server::from_config(ServerConfig::Remote { - origin: settings.get_str("server_origin")?, + origin, client_id, })?) } diff --git a/cli/src/settings.rs b/cli/src/settings.rs index f8a92582e..02e554c76 100644 --- a/cli/src/settings.rs +++ b/cli/src/settings.rs @@ -18,12 +18,14 @@ pub(crate) fn read_settings() -> Fallible { // load either from the path in TASKCHAMPION_CONFIG, or from CONFIG_DIR/taskchampion if let Some(config_file) = env::var_os("TASKCHAMPION_CONFIG") { + log::debug!("Loading configuration from {:?}", config_file); let config_file: PathBuf = config_file.into(); let config_file: File = config_file.into(); settings.merge(config_file.required(true))?; env::remove_var("TASKCHAMPION_CONFIG"); } else if let Some(mut dir) = dirs::config_dir() { dir.push("taskchampion"); + log::debug!("Loading configuration from {:?} (optional)", dir); let config_file: File = dir.into(); settings.merge(config_file.required(false))?; } diff --git a/docs/src/usage.md b/docs/src/usage.md index f60e07e07..84ee5626c 100644 --- a/docs/src/usage.md +++ b/docs/src/usage.md @@ -32,3 +32,11 @@ The following configuration parameters are available: Run `taskchampion-sync-server` to start the sync server. Use `--port` to specify the port it should listen on, and `--data-dir` to specify the directory which it should store its data. It only serves HTTP; the expectation is that a frontend proxy will be used for HTTPS support. + +## Debugging + +Both `task` and `taskchampio-sync-server` use [env-logger](https://docs.rs/env_logger) and can be configured to log at various levels with the `RUST_LOG` environment variable. +For example: +```shell +$ RUST_LOG=taskchampion=trace task add foo +``` diff --git a/sync-server/Cargo.toml b/sync-server/Cargo.toml index 7047a3028..23f8df85e 100644 --- a/sync-server/Cargo.toml +++ b/sync-server/Cargo.toml @@ -14,6 +14,8 @@ futures = "^0.3.8" serde = "^1.0.104" kv = {version = "^0.10.0", features = ["msgpack-value"]} clap = "^2.33.0" +log = "^0.4.11" +env_logger = "^0.8.2" [dev-dependencies] actix-rt = "^1.1.1" diff --git a/sync-server/src/main.rs b/sync-server/src/main.rs index 17821e36e..68260f1c7 100644 --- a/sync-server/src/main.rs +++ b/sync-server/src/main.rs @@ -27,6 +27,7 @@ pub(crate) fn app_scope(server_state: ServerState) -> Scope { #[actix_web::main] async fn main() -> Fallible<()> { + env_logger::init(); let matches = clap::App::new("taskchampion-sync-server") .version("0.1.0") .about("Server for TaskChampion") @@ -58,7 +59,7 @@ async fn main() -> Fallible<()> { let server_box: Box = Box::new(KVStorage::new(data_dir)?); let server_state = ServerState::new(server_box); - println!("Serving on port {}", port); + log::warn!("Serving on port {}", port); HttpServer::new(move || App::new().service(app_scope(server_state.clone()))) .bind(format!("0.0.0.0:{}", port))? .run() diff --git a/sync-server/src/server.rs b/sync-server/src/server.rs index da8960c0f..a518189ce 100644 --- a/sync-server/src/server.rs +++ b/sync-server/src/server.rs @@ -49,8 +49,15 @@ pub(crate) fn add_version<'a>( parent_version_id: VersionId, history_segment: HistorySegment, ) -> Fallible { + log::debug!( + "add_version(client_id: {}, parent_version_id: {})", + client_id, + parent_version_id, + ); + // check if this version is acceptable, under the protection of the transaction if client.latest_version_id != NO_VERSION_ID && parent_version_id != client.latest_version_id { + log::debug!("add_version request rejected: mismatched latest_version_id"); return Ok(AddVersionResult::ExpectedParentVersion( client.latest_version_id, )); @@ -58,6 +65,10 @@ pub(crate) fn add_version<'a>( // invent a version ID let version_id = Uuid::new_v4(); + log::debug!( + "add_version request accepted: new version_id: {}", + version_id + ); // update the DB txn.add_version(client_id, version_id, parent_version_id, history_segment)?; diff --git a/taskchampion/Cargo.toml b/taskchampion/Cargo.toml index 5dcbb497b..ed9382dbe 100644 --- a/taskchampion/Cargo.toml +++ b/taskchampion/Cargo.toml @@ -13,6 +13,7 @@ failure = {version = "^0.1.5", features = ["derive"] } kv = {version = "^0.10.0", features = ["msgpack-value"]} lmdb-rkv = {version = "^0.12.3"} ureq = "^1.5.2" +log = "^0.4.11" [dev-dependencies] proptest = "^0.9.4" diff --git a/taskchampion/src/replica.rs b/taskchampion/src/replica.rs index 6e4550ebd..34e3b6f31 100644 --- a/taskchampion/src/replica.rs +++ b/taskchampion/src/replica.rs @@ -6,6 +6,7 @@ use crate::taskdb::TaskDB; use crate::taskstorage::{KVStorage, Operation, TaskMap, TaskStorage}; use chrono::Utc; use failure::Fallible; +use log::trace; use std::collections::HashMap; use uuid::Uuid; @@ -128,6 +129,7 @@ impl Replica { pub fn new_task(&mut self, status: Status, description: String) -> Fallible { let uuid = Uuid::new_v4(); self.taskdb.apply(Operation::Create { uuid })?; + trace!("task {} created", uuid); let mut task = Task::new(uuid, TaskMap::new()).into_mut(self); task.set_description(description)?; task.set_status(status)?; @@ -144,7 +146,9 @@ impl Replica { if self.taskdb.get_task(&uuid)?.is_none() { return Err(Error::DBError(format!("Task {} does not exist", uuid)).into()); } - self.taskdb.apply(Operation::Delete { uuid: *uuid }) + self.taskdb.apply(Operation::Delete { uuid: *uuid })?; + trace!("task {} deleted", uuid); + Ok(()) } /// Synchronize this replica against the given server. diff --git a/taskchampion/src/task.rs b/taskchampion/src/task.rs index 20ac753d5..49ba279db 100644 --- a/taskchampion/src/task.rs +++ b/taskchampion/src/task.rs @@ -2,6 +2,7 @@ use crate::replica::Replica; use crate::taskstorage::TaskMap; use chrono::prelude::*; use failure::Fallible; +use log::trace; use uuid::Uuid; pub type Timestamp = DateTime; @@ -230,6 +231,7 @@ impl<'r> TaskMut<'r> { let now = format!("{}", Utc::now().timestamp()); self.replica .update_task(self.task.uuid, "modified", Some(now.clone()))?; + trace!("task {}: set property modified={:?}", self.task.uuid, now); self.task.taskmap.insert(String::from("modified"), now); self.updated_modified = true; } @@ -242,8 +244,10 @@ impl<'r> TaskMut<'r> { .update_task(self.task.uuid, property, value.as_ref())?; if let Some(v) = value { + trace!("task {}: set property {}={:?}", self.task.uuid, property, v); self.task.taskmap.insert(property.to_string(), v); } else { + trace!("task {}: remove property {}", self.task.uuid, property); self.task.taskmap.remove(property); } Ok(()) diff --git a/taskchampion/src/taskdb.rs b/taskchampion/src/taskdb.rs index 4cdb927ca..0dd759814 100644 --- a/taskchampion/src/taskdb.rs +++ b/taskchampion/src/taskdb.rs @@ -2,6 +2,7 @@ use crate::errors::Error; use crate::server::{AddVersionResult, GetVersionResult, Server}; use crate::taskstorage::{Operation, TaskMap, TaskStorage, TaskStorageTxn}; use failure::{format_err, Fallible}; +use log::{info, trace, warn}; use serde::{Deserialize, Serialize}; use std::collections::HashSet; use std::str; @@ -172,10 +173,12 @@ impl TaskDB { // version twice, then we have diverged. let mut requested_parent_version_id = None; loop { + trace!("beginning sync outer loop"); let mut base_version_id = txn.base_version()?; // first pull changes and "rebase" on top of them loop { + trace!("beginning sync inner loop"); if let GetVersionResult::Version { version_id, history_segment, @@ -184,14 +187,14 @@ impl TaskDB { { let version_str = str::from_utf8(&history_segment).unwrap(); let version: Version = serde_json::from_str(version_str).unwrap(); - println!("applying version {:?} from server", version_id); // apply this verison and update base_version in storage + info!("applying version {:?} from server", version_id); TaskDB::apply_version(txn.as_mut(), version)?; txn.set_base_version(version_id)?; base_version_id = version_id; } else { - println!("no child versions of {:?}", base_version_id); + info!("no child versions of {:?}", base_version_id); // at the moment, no more child versions, so we can try adding our own break; } @@ -199,24 +202,26 @@ impl TaskDB { let operations: Vec = txn.operations()?.to_vec(); if operations.is_empty() { - println!("no changes to push to server"); + info!("no changes to push to server"); // nothing to sync back to the server.. break; } + trace!("sending {} operations to the server", operations.len()); + // now make a version of our local changes and push those let new_version = Version { operations }; let history_segment = serde_json::to_string(&new_version).unwrap().into(); - println!("sending new version to server"); + info!("sending new version to server"); match server.add_version(base_version_id, history_segment)? { AddVersionResult::Ok(new_version_id) => { - println!("version {:?} received by server", new_version_id); + info!("version {:?} received by server", new_version_id); txn.set_base_version(new_version_id)?; txn.set_operations(vec![])?; break; } AddVersionResult::ExpectedParentVersion(parent_version_id) => { - println!( + info!( "new version rejected; must be based on {:?}", parent_version_id ); @@ -264,22 +269,31 @@ impl TaskDB { // it. If it happens for server op, then we must copy the remaining local ops. let mut local_operations: Vec = txn.operations()?; for server_op in version.operations.drain(..) { + trace!( + "rebasing local operations onto server operation {:?}", + server_op + ); let mut new_local_ops = Vec::with_capacity(local_operations.len()); let mut svr_op = Some(server_op); for local_op in local_operations.drain(..) { if let Some(o) = svr_op { - let (new_server_op, new_local_op) = Operation::transform(o, local_op); + let (new_server_op, new_local_op) = Operation::transform(o, local_op.clone()); + trace!("local operation {:?} -> {:?}", local_op, new_local_op); svr_op = new_server_op; if let Some(o) = new_local_op { new_local_ops.push(o); } } else { + trace!( + "local operation {:?} unchanged (server operation consumed)", + local_op + ); new_local_ops.push(local_op); } } if let Some(o) = svr_op { if let Err(e) = TaskDB::apply_op(txn, &o) { - println!("Invalid operation when syncing: {} (ignored)", e); + warn!("Invalid operation when syncing: {} (ignored)", e); } } local_operations = new_local_ops;