use log and env_logger, and add some logging around sync

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"

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"

cli/src/bin/task.rs

@@ -17,6 +17,7 @@ fn bail<E: std::fmt::Display>(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) => {

cli/src/cmd/shared.rs

@@ -66,9 +66,9 @@ impl CommandInvocation {
 
     pub(super) fn get_replica(&self) -> Fallible<Replica> {
         let settings = self.get_settings()?;
-        let replica_config = ReplicaConfig {
+        let taskdb_dir = settings.get_str("data_dir")?.into();
-            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,
         })?)
     }

cli/src/settings.rs

@@ -18,12 +18,14 @@ pub(crate) fn read_settings() -> Fallible<Config> {
 
     // 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<FileSourceFile> = 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<FileSourceFile> = dir.into();
         settings.merge(config_file.required(false))?;
     }

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
+```

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"

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<dyn Storage> = 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()

sync-server/src/server.rs

@@ -49,8 +49,15 @@ pub(crate) fn add_version<'a>(
     parent_version_id: VersionId,
     history_segment: HistorySegment,
 ) -> Fallible<AddVersionResult> {
+    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)?;

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"

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<Task> {
         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.

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<Utc>;
@@ -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(())

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<Operation> = 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<Operation> = 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;