Merge pull request #75 from djmitche/issue54

use log and env_logger, and add some logging around sync
This commit is contained in:
Dustin J. Mitchell 2020-11-29 18:34:01 -05:00 committed by GitHub
commit 33283658d5
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
13 changed files with 109 additions and 14 deletions

42
Cargo.lock generated
View file

@ -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"

View file

@ -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"

View file

@ -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) => {

View file

@ -66,9 +66,9 @@ impl CommandInvocation {
pub(super) fn get_replica(&self) -> Fallible<Replica> {
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,
})?)
}

View file

@ -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))?;
}

View file

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

View file

@ -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"

View file

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

View file

@ -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)?;

View file

@ -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"

View file

@ -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.

View file

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

View file

@ -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;