diff options
author | Justus Winter <justus@sequoia-pgp.org> | 2018-01-11 17:07:50 +0100 |
---|---|---|
committer | Justus Winter <justus@sequoia-pgp.org> | 2018-01-17 11:50:30 +0100 |
commit | 6b3408662c9d3a4c27c6883f7bd1f88e60981094 (patch) | |
tree | d6d2f13742f935fe8ddf433f404d76a5d1353194 /store | |
parent | dbf75dedefc7c14705538d63257d8f8cf4a594ff (diff) |
store: Periodically update keys from the network.
- Update all keys stored in a store with network policy 'encrypted'
and 'insecure' periodically using the SKS keyserver pool.
- Slightly amend the net::ipc interface so that servers can spawn
futures on the reactor.
- As a background service cannot directly communicate failures, this
patch adds a logging mechanism.
- In sq, display the key update timestamp, and the status of the
last update.
Diffstat (limited to 'store')
-rw-r--r-- | store/Cargo.toml | 2 | ||||
-rw-r--r-- | store/src/backend.rs | 320 | ||||
-rw-r--r-- | store/src/lib.rs | 69 | ||||
-rw-r--r-- | store/src/macros.rs | 27 | ||||
-rw-r--r-- | store/src/store_protocol.capnp | 20 |
5 files changed, 382 insertions, 56 deletions
diff --git a/store/Cargo.toml b/store/Cargo.toml index d994f408..47fbd373 100644 --- a/store/Cargo.toml +++ b/store/Cargo.toml @@ -15,7 +15,9 @@ sequoia-net = { path = "../net" } capnp = "0.8" capnp-rpc = "0.8" futures = "0.1.17" +rand = "0.3" rusqlite = "0.12.0" +time = "0.1.38" tokio-core = "0.1.10" tokio-io = "0.1.4" diff --git a/store/src/backend.rs b/store/src/backend.rs index e405c059..48c192cb 100644 --- a/store/src/backend.rs +++ b/store/src/backend.rs @@ -1,6 +1,8 @@ //! Storage backend. +use std::cmp; use std::fmt; +use std::io; use std::ops::Add; use std::rc::Rc; use std::time::{SystemTime, Duration, UNIX_EPOCH}; @@ -9,22 +11,50 @@ use capnp::capability::Promise; use capnp; use capnp_rpc::rpc_twoparty_capnp::Side; use capnp_rpc::{self, RpcSystem, twoparty}; +use futures::Future; +use futures::future::{loop_fn, Loop}; +use rand::distributions::{IndependentSample, Range}; +use rand::thread_rng; use rusqlite::Connection; use rusqlite::types::{ToSql, ToSqlOutput}; use rusqlite; +use tokio_core::reactor::{Handle, Timeout}; use tokio_core; use tokio_io::io::ReadHalf; +use openpgp; use openpgp::tpk::{self, TPK}; use sequoia_core as core; +use sequoia_net as net; use sequoia_net::ipc; use store_protocol_capnp::node; +/* Configuration and policy. */ + +/// Minimum sleep time. +fn min_sleep_time() -> Duration { + Duration::new(60 * 5, 0) // 5 minutes. +} + +/// Interval after which all keys should be refreshed once. +fn refresh_interval() -> Duration { + Duration::new(60 * 60 * 24 * 7, 0) // A week. +} + +/// Returns a value from the uniform distribution over [0, 2*d). +/// +/// This function is used to randomize key refresh times. +fn random_duration(d: Duration) -> Duration { + Duration::new(Range::new(0, 2 * d.as_secs()).ind_sample(&mut thread_rng()), 0) +} + +/* Entry point. */ + /// Makes backends. #[doc(hidden)] -pub fn factory(descriptor: ipc::Descriptor) -> Option<Box<ipc::Handler>> { - match Backend::new(descriptor) { +pub fn factory(descriptor: ipc::Descriptor, handle: Handle) -> Option<Box<ipc::Handler>> { + match Backend::new(descriptor, handle) { Ok(backend) => Some(Box::new(backend)), Err(_) => None, } @@ -35,9 +65,9 @@ struct Backend { } impl Backend { - fn new(descriptor: ipc::Descriptor) -> Result<Self> { + fn new(descriptor: ipc::Descriptor, handle: Handle) -> Result<Self> { Ok(Backend { - store: node::ToClient::new(NodeServer::new(descriptor)?) + store: node::ToClient::new(NodeServer::new(descriptor, handle)?) .from_server::<capnp_rpc::Server>(), }) } @@ -51,6 +81,7 @@ impl ipc::Handler for Backend { } } +/* Server implementation. */ struct NodeServer { _descriptor: ipc::Descriptor, @@ -58,7 +89,7 @@ struct NodeServer { } impl NodeServer { - fn new(descriptor: ipc::Descriptor) -> Result<Self> { + fn new(descriptor: ipc::Descriptor, handle: Handle) -> Result<Self> { let mut db_path = descriptor.home.clone(); db_path.push("keystore.sqlite"); @@ -67,10 +98,12 @@ impl NodeServer { c.execute_batch("PRAGMA foreign_keys = true;")?; Self::init(&c)?; - Ok(NodeServer { + let server = NodeServer { _descriptor: descriptor, c: Rc::new(c), - }) + }; + KeyServer::start_housekeeping(server.c.clone(), handle)?; + Ok(server) } /// Initializes or migrates the database. @@ -433,7 +466,7 @@ impl KeyServer { Ok(x) } else { let r = c.execute( - "INSERT INTO keys (fingerprint, created) VALUES (?1, ?2)", + "INSERT INTO keys (fingerprint, created, update_at) VALUES (?1, ?2, ?2)", &[&fp, &Timestamp::now()]); // Some other mutator might race us to the insertion. @@ -452,6 +485,174 @@ impl KeyServer { }.map_err(|e| e.into()) } } + + /// Merges other into this key updating the database. + /// + /// Returnes the merged key as blob. + fn merge(&self, other: TPK) -> Result<Vec<u8>> { + let mut new = other; + + // Get the current key from the database. + let (fingerprint, key): (String, Option<Vec<u8>>) + = self.c.query_row( + "SELECT fingerprint, key FROM keys WHERE id = ?1", + &[&self.id], + |row| (row.get(0), row.get_checked(1).ok()))?; + + // If there was a key stored there, merge it. + if let Some(current) = key { + let current = TPK::from_bytes(¤t)?; + + if current.fingerprint().to_hex() != fingerprint { + // Inconsistent database. + return Err(node::Error::SystemError); + } + + if current.fingerprint() != new.fingerprint() { + return Err(node::Error::Conflict); + } + + new = current.merge(new)?; + } + + // Write key back to the database. + let mut blob = vec![]; + new.serialize(&mut blob)?; + + self.c.execute("UPDATE keys SET key = ?1 WHERE id = ?2", + &[&blob, &self.id])?; + + Ok(blob) + } + + /// Records a successful key update. + fn success(&self, message: &str, next: Duration) -> Result<()> { + let logid = log(&self.c, &self.slug(), message)?; + self.c.execute("UPDATE keys SET updated = ?2, log = ?3, update_at = ?4 + WHERE id = ?1", + &[&self.id, &Timestamp::now(), + &logid, + &(Timestamp::now() + next)])?; + Ok(()) + } + + /// Records an unsuccessful key update. + fn error(&self, message: &str, err: &str, next: Duration) -> Result<()> { + let logid = error(&self.c, &self.slug(), message, err)?; + self.c.execute("UPDATE keys SET log = ?2, update_at = ?3 + WHERE id = ?1", + &[&self.id, &logid, + &(Timestamp::now() + next)])?; + Ok(()) + } + + /// Returns when the next key using the given policy should be updated. + fn next_update_at(c: &Rc<Connection>, network_policy: core::NetworkPolicy) + -> Option<SystemTime> { + let network_policy_u8 = u8::from(&network_policy); + + // Select the key that was updated least recently. + let update_at: Option<i64> = c.query_row( + "SELECT keys.update_at FROM keys + JOIN bindings on keys.id = bindings.key + JOIN stores on stores.id = bindings.store + WHERE stores.network_policy = ?1 + ORDER BY keys.update_at LIMIT 1", + &[&network_policy_u8], |row| row.get(0)).ok(); + update_at.map(|secs| UNIX_EPOCH + Duration::new(secs as u64, 0)) + } + + /// Returns the number of keys using the given policy. + fn need_update(c: &Rc<Connection>, network_policy: core::NetworkPolicy) + -> Result<u32> { + let network_policy_u8 = u8::from(&network_policy); + + let count: i64 = c.query_row( + "SELECT COUNT(*) FROM keys + JOIN bindings on keys.id = bindings.key + JOIN stores on stores.id = bindings.store + WHERE stores.network_policy >= ?1", + &[&network_policy_u8], |row| row.get(0))?; + assert!(count >= 0); + Ok(count as u32) + } + + /// Updates the key that was least recently updated. + fn update(c: &Rc<Connection>, network_policy: core::NetworkPolicy) -> Result<()> { + assert!(network_policy != core::NetworkPolicy::Offline); + let network_policy_u8 = u8::from(&network_policy); + + // Select the key that was updated least recently. + let (id, fingerprint): (i64, String) = c.query_row( + "SELECT keys.id, keys.fingerprint FROM keys + JOIN bindings on keys.id = bindings.key + JOIN stores on stores.id = bindings.store + WHERE stores.network_policy >= ?1 + AND keys.update_at < ?2 + ORDER BY keys.update_at LIMIT 1", + &[&network_policy_u8, &Timestamp::now()], |row| (row.get(0), row.get(1)))?; + let fingerprint = openpgp::Fingerprint::from_hex(&fingerprint) + .ok_or(node::Error::SystemError)?; + + let key = KeyServer::new(c.clone(), id); + let doit = || -> Result<()> { + let ctx = core::Context::configure("org.sequoia-pgp.store") + .network_policy(network_policy).build()?; + let mut keyserver = net::KeyServer::sks_pool(&ctx)?; + + // Get key and merge it into the database. + let tpk = keyserver.get(&fingerprint.to_keyid())?; + key.merge(tpk)?; + Ok(()) + }; + let next = refresh_interval() / Self::need_update(c, network_policy)?; + if let Err(e) = doit() { + key.error("Update unsuccessful", &format!("{:?}", e), next / 2).unwrap_or(()); + } else { + key.success("Update successful", next).unwrap_or(()); + } + Ok(()) + } + + /// Starts the periodic housekeeping. + fn start_housekeeping(c: Rc<Connection>, handle: Handle) -> Result<()> { + let h = handle.clone(); + + let forever = loop_fn(0, move |_| { + // For now, we only update keys with this network policy. + let network_policy = core::NetworkPolicy::Encrypted; + + let now = SystemTime::now(); + let sleep_for = + if let Some(at) = Self::next_update_at(&c, network_policy) { + if at <= now { + if let Err(e) = Self::update(&c, network_policy) { + #[cfg(debug_assertions)] + eprintln!("Odd. Updating failed: {:?}", e); + } + min_sleep_time() + } else { + assert!(at > now); + cmp::max(min_sleep_time(), at.duration_since(now).unwrap()) + } + } else { + min_sleep_time() + }; + assert!(sleep_for > Duration::new(0, 0)); + + Timeout::new(random_duration(sleep_for), &h) + .unwrap() // XXX: May fail if the eventloop expired. + .then(move |timeout| { + if timeout.is_ok() { + Ok(Loop::Continue(0)) + } else { + Ok(Loop::Break(())) + } + }) + }); + handle.spawn(forever); + Ok(()) + } } impl Query for KeyServer { @@ -497,35 +698,8 @@ impl node::key::Server for KeyServer { mut results: node::key::ImportResults) -> Promise<(), capnp::Error> { bind_results!(results); - let mut new = sry!(TPK::from_bytes(&pry!(pry!(params.get()).get_key()))); - - let (fingerprint, key): (String, Option<Vec<u8>>) - = sry!(self.c.query_row( - "SELECT fingerprint, key FROM keys WHERE id = ?1", - &[&self.id], - |row| (row.get(0), row.get_checked(1).ok()))); - if let Some(current) = key { - let current = sry!(TPK::from_bytes(¤t)); - - if current.fingerprint().to_hex() != fingerprint { - // Inconsistent database. - fail!(node::Error::SystemError); - } - - if current.fingerprint() != new.fingerprint() { - fail!(node::Error::Conflict); - } - - new = sry!(current.merge(new)); - } - - // Write key back to the database. - let mut blob = vec![]; - sry!(new.serialize(&mut blob)); - - sry!(self.c.execute("UPDATE keys SET key = ?1 WHERE id = ?2", - &[&blob, &self.id])); - + let new = sry!(TPK::from_bytes(&pry!(pry!(params.get()).get_key()))); + let blob = sry!(self.merge(new)); pry!(pry!(results.get().get_result()).set_ok(&blob[..])); Promise::ok(()) } @@ -537,6 +711,10 @@ trait Query { fn id(&self) -> i64; fn connection(&self) -> Rc<Connection>; + fn slug(&self) -> String { + format!("{}::{}", Self::table_name(), self.id()) + } + fn query(&mut self, column: &str) -> Result<i64> { self.connection().query_row( &format!("SELECT {} FROM {} WHERE id = ?1", column, Self::table_name()), @@ -546,6 +724,19 @@ trait Query { fn query_stats(&mut self, mut stats: node::stats::Builder) -> Result<()> { let created = self.query("created")?; let updated = self.query("updated")?; + let (timestamp, item, message, error): (i64, String, String, String) + = self.connection().query_row( + &format!("SELECT log.timestamp, log.item, log.message, log.error FROM log + JOIN {0} on log.id = {0}.log + WHERE {0}.id = ?1", Self::table_name()), + &[&self.id()], |row| (row.get(0), row.get(1), row.get(2), + row.get_checked(1).unwrap_or("".into()))) + .or_else(|err| match err { + // No log messages. + rusqlite::Error::QueryReturnedNoRows => + Ok((0, "".into(), "".into(), "".into())), + _ => Err(err), + })?; let encryption_count = self.query("encryption_count")?; let encryption_first = self.query("encryption_first")?; let encryption_last = self.query("encryption_last")?; @@ -560,6 +751,11 @@ trait Query { stats.set_verification_count(verification_count); stats.set_verification_first(verification_first); stats.set_verification_last(verification_last); + let mut msg = stats.init_message(); + msg.set_timestamp(timestamp); + msg.set_item(&item); + msg.set_message(&message); + msg.set_error(&error); Ok(()) } } @@ -742,6 +938,24 @@ impl From<tpk::Error> for node::Error { } } +impl From<core::Error> for node::Error { + fn from(_: core::Error) -> Self { + node::Error::SystemError + } +} + +impl From<net::Error> for node::Error { + fn from(_: net::Error) -> Self { + node::Error::SystemError + } +} + +impl From<io::Error> for node::Error { + fn from(_: io::Error) -> Self { + node::Error::SystemError + } +} + /* Database schemata and migrations. */ @@ -760,6 +974,13 @@ CREATE TABLE stores ( name TEXT NOT NULL, UNIQUE (domain, name)); +CREATE TABLE log ( + id INTEGER PRIMARY KEY, + timestamp INTEGER NOT NULL, + item TEXT NOT NULL, + message TEXT NOT NULL, + error TEXT NULL); + CREATE TABLE bindings ( id INTEGER PRIMARY KEY, store INTEGER NOT NULL, @@ -768,6 +989,7 @@ CREATE TABLE bindings ( created INTEGER NOT NULL, updated DEFAULT 0, + log INTEGER NULL, encryption_count DEFAULT 0, encryption_first DEFAULT 0, @@ -778,7 +1000,8 @@ CREATE TABLE bindings ( UNIQUE(store, label), FOREIGN KEY (store) REFERENCES stores(id) ON DELETE CASCADE, - FOREIGN KEY (key) REFERENCES keys(id) ON DELETE CASCADE); + FOREIGN KEY (key) REFERENCES keys(id) ON DELETE CASCADE + FOREIGN KEY (log) REFERENCES log(id)); CREATE TABLE keys ( id INTEGER PRIMARY KEY, @@ -787,6 +1010,8 @@ CREATE TABLE keys ( created INTEGER NOT NULL, updated DEFAULT 0, + log INTEGER NULL, + update_at INTEGER NOT NULL, encryption_count DEFAULT 0, encryption_first DEFAULT 0, @@ -795,7 +1020,8 @@ CREATE TABLE keys ( verification_first DEFAULT 0, verification_last DEFAULT 0, - UNIQUE (fingerprint)); + UNIQUE (fingerprint), + FOREIGN KEY (log) REFERENCES log(id)); "; /* Timestamps. */ @@ -826,6 +1052,22 @@ impl Add<Duration> for Timestamp { } } +/* Logging. */ + +/// Writes a log message to the log. +fn log(c: &Rc<Connection>, item: &str, message: &str) -> Result<i64> { + c.execute("INSERT INTO log (timestamp, item, message) VALUES (?1, ?2, ?3)", + &[&Timestamp::now(), &item, &message])?; + Ok(c.last_insert_rowid()) +} + +/// Writes an error message to the log. +fn error(c: &Rc<Connection>, item: &str, message: &str, error: &str) -> Result<i64> { + c.execute("INSERT INTO log (timestamp, item, message, error) VALUES (?1, ?2, ?3, ?4)", + &[&Timestamp::now(), &item, &message, &error])?; + Ok(c.last_insert_rowid()) +} + /* Miscellaneous. */ impl<'a> From<&'a core::NetworkPolicy> for node::NetworkPolicy { diff --git a/store/src/lib.rs b/store/src/lib.rs index 8a3672ee..5064f6bd 100644 --- a/store/src/lib.rs +++ b/store/src/lib.rs @@ -50,7 +50,9 @@ extern crate capnp; #[macro_use] extern crate capnp_rpc; extern crate futures; +extern crate rand; extern crate rusqlite; +extern crate time; extern crate tokio_core; extern crate tokio_io; @@ -58,7 +60,7 @@ use std::cell::RefCell; use std::fmt; use std::io; use std::rc::Rc; -use std::time::{SystemTime, Duration, UNIX_EPOCH}; +use std::time::{SystemTime, SystemTimeError, Duration, UNIX_EPOCH}; use capnp::capability::Promise; use capnp_rpc::rpc_twoparty_capnp::Side; @@ -659,6 +661,9 @@ pub struct Stats { /// Records the time this item was last updated. pub updated: Option<SystemTime>, + /// Result of the latest update. + pub message: Option<Log>, + /// Records counters and timestamps of encryptions. pub encryption: Stamps, @@ -666,6 +671,52 @@ pub struct Stats { pub verification: Stamps, } +#[derive(Debug)] +pub struct Log { + pub timestamp: SystemTime, + pub item: String, + pub status: ::std::result::Result<String, (String, String)>, +} + +impl Log { + fn new(timestamp: i64, item: &str, message: &str, error: &str) -> Option<Self> { + let timestamp = from_unix(timestamp)?; + if message == "" { + None + } else { + if error == "" { + Some(Log{ + timestamp: timestamp, + item: item.into(), + status: Err((message.into(), error.into())), + }) + } else { + Some(Log{ + timestamp: timestamp, + item: item.into(), + status: Ok(message.into()), + }) + } + } + } + + /// Returns the message without context. + pub fn short(&self) -> String { + match self.status { + Ok(ref m) => m.clone(), + Err((ref m, ref e)) => format!("{}: {}", m, e), + } + } + + /// Returns the message without context. + pub fn string(&self) -> Result<String> { + Ok(match self.status { + Ok(ref m) => format!("{}: {}", format_system_time(&self.timestamp)?, m), + Err((ref m, ref e)) => format!("{}: {}: {}", format_system_time(&self.timestamp)?, m, e), + }) + } +} + /// Counter and timestamps. #[derive(Debug)] pub struct Stamps { @@ -798,6 +849,16 @@ impl Iterator for KeyIter { } } +/// XXX Use the correct time type. +/// +/// We should use time::Timespec and get rid of this function. +pub fn format_system_time(t: &SystemTime) -> Result<String> { + let tm = time::at(time::Timespec::new(t.duration_since(UNIX_EPOCH)?.as_secs() as i64, 0)); + Ok(time::strftime("%F %H:%M", &tm) + // Only parse errors can happen. + .unwrap()) +} + /* Error handling. */ /// Results for sequoia-store. @@ -879,6 +940,12 @@ impl From<capnp::NotInSchema> for Error { } } +impl From<SystemTimeError> for Error { + fn from(_: SystemTimeError) -> Self { + Error::ProtocolError + } +} + #[cfg(test)] mod store_test { use super::{core, Store, Error, TPK, Fingerprint}; diff --git a/store/src/macros.rs b/store/src/macros.rs index f460bcdc..0945af29 100644 --- a/store/src/macros.rs +++ b/store/src/macros.rs @@ -42,16 +42,23 @@ macro_rules! make_stats_request { let r = pry!(pry!(pry!(response.get()).get_result()).which()); let r = match r { /* The Result. */ - Which::Ok(Ok(s)) => Ok(Stats{ - created: from_unix(s.get_created()), - updated: from_unix(s.get_updated()), - encryption: Stamps::new(s.get_encryption_count(), - s.get_encryption_first(), - s.get_encryption_last()), - verification: Stamps::new(s.get_verification_count(), - s.get_verification_first(), - s.get_verification_last()), - }), + Which::Ok(Ok(s)) => { + let msg = pry!(s.get_message()); + Ok(Stats{ + created: from_unix(s.get_created()), + updated: from_unix(s.get_updated()), + message: Log::new(msg.get_timestamp(), + pry!(msg.get_item()), + pry!(msg.get_message()), + pry!(msg.get_error())), + encryption: Stamps::new(s.get_encryption_count(), + s.get_encryption_first(), + s.get_encryption_last()), + verification: Stamps::new(s.get_verification_count(), + s.get_verification_first(), + s.get_verification_last()), + }) + }, Which::Err(Ok(e)) => Err(e.into()), /* Protocol violations. */ Which::Ok(Err(e)) => Err(e.into()), diff --git a/store/src/store_protocol.capnp b/store/src/store_protocol.capnp index 6f11da0f..f895b856 100644 --- a/store/src/store_protocol.capnp +++ b/store/src/store_protocol.capnp @@ -67,12 +67,20 @@ interface Node { struct Stats { created @0 :Int64; updated @1 :Int64; - encryptionCount @2 :Int64; - encryptionFirst @3 :Int64; - encryptionLast @4 :Int64; - verificationCount @5 :Int64; - verificationFirst @6 :Int64; - verificationLast @7 :Int64; + message @2 :Log; + encryptionCount @3 :Int64; + encryptionFirst @4 :Int64; + encryptionLast @5 :Int64; + verificationCount @6 :Int64; + verificationFirst @7 :Int64; + verificationLast @8 :Int64; + } + + struct Log { + timestamp @0 :Int64; + item @1 :Text; + message @2 :Text; + error @3 :Text; } enum NetworkPolicy { |