From 1b8b3da7339040e60fd3a0b87b1c1141ad1dacac Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Damir=20Jeli=C4=87?= Date: Thu, 19 Mar 2020 13:55:04 +0100 Subject: [PATCH] rust-sdk: Add initial tracing/logging setup. --- Cargo.toml | 18 ++++++++++++++---- examples/login.rs | 4 +++- src/async_client.rs | 44 ++++++++++++++++++++++++++++++++++++++----- src/base_client.rs | 3 +++ src/crypto/machine.rs | 28 ++++++++++++++++++++++++--- 5 files changed, 84 insertions(+), 13 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 11038126..cf3d9d64 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,20 +21,29 @@ reqwest = "0.10.4" http = "0.2.0" url = "2.1.1" +# Ruma dependencies js_int = "0.1.3" ruma-api = "0.14.0" ruma-client-api = { version = "0.6.0", git = "https://github.com/matrix-org/ruma-client-api/" } ruma-events = "0.17.0" ruma-identifiers = "0.14.1" -thiserror = "1.0.11" -zeroize = { version = "1.1.0", optional = true } -async-trait = { version = "0.1.24", optional = true } - +# Dependencies for the encryption support olm-rs = { path = "/home/poljar/werk/matrix/olm-rs", optional = true, features = ["serde"]} serde = { version = "1.0.104", optional = true, features = ["derive"] } serde_json = { version = "1.0.48", optional = true } cjson = { version = "0.1.0", optional = true } +zeroize = { version = "1.1.0", optional = true } + +# Misc dependencies +thiserror = "1.0.11" +async-trait = { version = "0.1.24", optional = true } +tracing = { version = "0.1.13" } + +[dependencies.tracing-futures] +version = "0.2.3" +default-features = false +features = ["std", "std-future"] [dependencies.tokio] version = "0.2.13" @@ -49,5 +58,6 @@ features = ["runtime-tokio", "sqlite"] [dev-dependencies] tokio = { version = "0.2.13", features = ["rt-threaded", "macros"] } +tracing-subscriber = "0.2.3" tempfile = "3.1.0" mockito = "0.23.3" diff --git a/examples/login.rs b/examples/login.rs index 8fda44ab..0dd83f8b 100644 --- a/examples/login.rs +++ b/examples/login.rs @@ -48,13 +48,15 @@ async fn login( client.add_event_callback(async_cb); client.login(username, password, None).await?; - let _response = client.sync(SyncSettings::new()).await?; + client.sync_forever(SyncSettings::new(), |_| async {}).await; Ok(()) } #[tokio::main] async fn main() -> Result<(), matrix_sdk::Error> { + tracing_subscriber::fmt::init(); + let (homeserver_url, username, password) = match (env::args().nth(1), env::args().nth(2), env::args().nth(3)) { (Some(a), Some(b), Some(c)) => (a, b, c), diff --git a/src/async_client.rs b/src/async_client.rs index c8afd107..7819fd0e 100644 --- a/src/async_client.rs +++ b/src/async_client.rs @@ -21,6 +21,7 @@ use std::sync::{Arc, Mutex, RwLock as SyncLock}; use std::time::{Duration, Instant}; use tokio::sync::RwLock; use tokio::time::delay_for as sleep; +use tracing::{debug, info, instrument, trace}; use http::Method as HttpMethod; use http::Response as HttpResponse; @@ -63,6 +64,12 @@ pub struct AsyncClient { event_callbacks: Arc>>, } +impl std::fmt::Debug for AsyncClient { + fn fmt(&self, fmt: &mut std::fmt::Formatter<'_>) -> StdResult<(), std::fmt::Error> { + write!(fmt, "AsyncClient {{ homeserver: {} }}", self.homeserver) + } +} + #[derive(Default, Debug)] /// Configuration for the creation of the `AsyncClient`. /// @@ -336,12 +343,15 @@ impl AsyncClient { /// not given the homeserver will create one. Can be an exising /// device_id from a previous login call. Note that this should be done /// only if the client also holds the encryption keys for this devcie. - pub async fn login>( + #[instrument(skip(password))] + pub async fn login + std::fmt::Debug>( &mut self, user: S, password: S, device_id: Option, ) -> Result { + info!("Logging in to {} as {:?}", self.homeserver, user); + let request = login::Request { user: login::UserInfo::MatrixId(user.into()), login_info: login::LoginInfo::Password { @@ -363,6 +373,7 @@ impl AsyncClient { /// # Arguments /// /// * `sync_settings` - Settings for the sync call. + #[instrument] pub async fn sync( &mut self, sync_settings: SyncSettings, @@ -478,6 +489,7 @@ impl AsyncClient { /// .await; /// }) /// ``` + #[instrument(skip(callback))] pub async fn sync_forever( &mut self, sync_settings: SyncSettings, @@ -534,7 +546,7 @@ impl AsyncClient { } } - async fn send( + async fn send( &self, request: Request, ) -> Result<::Incoming> @@ -551,6 +563,8 @@ impl AsyncClient { .join(url.path_and_query().unwrap().as_str()) .unwrap(); + trace!("Doing request {:?}", url); + let request_builder = match Request::METADATA.method { HttpMethod::GET => self.http_client.get(url), HttpMethod::POST => { @@ -577,12 +591,23 @@ impl AsyncClient { request_builder }; - let response = request_builder.send().await?; + let mut response = request_builder.send().await?; + + trace!("Got response: {:?}", response); let status = response.status(); + let mut http_response = HttpResponse::builder().status(status); + let headers = http_response.headers_mut().unwrap(); + + for (k, v) in response.headers_mut().drain() { + if let Some(key) = k { + headers.insert(key, v); + } + } + let body = response.bytes().await?.as_ref().to_owned(); - let response = HttpResponse::builder().status(status).body(body).unwrap(); - let response = ::Incoming::try_from(response)?; + let http_response = http_response.body(body).unwrap(); + let response = ::Incoming::try_from(http_response)?; Ok(response) } @@ -627,6 +652,8 @@ impl AsyncClient { /// Panics if the client isn't logged in, or if no encryption keys need to /// be uploaded. #[cfg(feature = "encryption")] + #[cfg_attr(docsrs, doc(cfg(feature = "encryption")))] + #[instrument] async fn keys_upload(&self) -> Result { let (device_keys, one_time_keys) = self .base_client @@ -635,6 +662,13 @@ impl AsyncClient { .keys_for_upload() .await .expect("Keys don't need to be uploaded"); + + debug!( + "Uploading encryption keys device keys: {}, one-time-keys: {}", + device_keys.is_some(), + one_time_keys.as_ref().map_or(0, |k| k.len()) + ); + let request = upload_keys::Request { device_keys, one_time_keys, diff --git a/src/base_client.rs b/src/base_client.rs index f7437c11..eac2c2f9 100644 --- a/src/base_client.rs +++ b/src/base_client.rs @@ -327,6 +327,7 @@ impl Client { /// Should account or one-time keys be uploaded to the server. #[cfg(feature = "encryption")] + #[cfg_attr(docsrs, doc(cfg(feature = "encryption")))] pub async fn should_upload_keys(&self) -> bool { let olm = self.olm.lock().await; @@ -340,6 +341,7 @@ impl Client { /// /// Returns an empty error if no keys need to be uploaded. #[cfg(feature = "encryption")] + #[cfg_attr(docsrs, doc(cfg(feature = "encryption")))] pub async fn keys_for_upload( &self, ) -> StdResult<(Option, Option), ()> { @@ -361,6 +363,7 @@ impl Client { /// # Panics /// Panics if the client hasn't been logged in. #[cfg(feature = "encryption")] + #[cfg_attr(docsrs, doc(cfg(feature = "encryption")))] pub async fn receive_keys_upload_response(&self, response: &KeysUploadResponse) -> Result<()> { let mut olm = self.olm.lock().await; diff --git a/src/crypto/machine.rs b/src/crypto/machine.rs index c451b85f..fec3e0b7 100644 --- a/src/crypto/machine.rs +++ b/src/crypto/machine.rs @@ -33,6 +33,7 @@ use olm_rs::utility::OlmUtility; use serde_json::json; use serde_json::Value; use tokio::sync::Mutex; +use tracing::{debug, info, instrument, warn}; use ruma_client_api::r0::keys::{ AlgorithmAndDeviceId, DeviceKeys, KeyAlgorithm, OneTimeKey, SignedKey, @@ -83,6 +84,7 @@ impl OlmMachine { } #[cfg(feature = "sqlite-cryptostore")] + #[instrument(skip(path, passphrase))] pub async fn new_with_sqlite_store>( user_id: &UserId, device_id: &str, @@ -94,8 +96,14 @@ impl OlmMachine { .await?; let account = match store.load_account().await? { - Some(a) => a, - None => Account::new(), + Some(a) => { + debug!("Restored account"); + a + } + None => { + debug!("Creating a new account"); + Account::new() + } }; Ok(OlmMachine { @@ -131,11 +139,15 @@ impl OlmMachine { /// /// * `response` - The keys upload response of the request that the client /// performed. + #[instrument] pub async fn receive_keys_upload_response( &mut self, response: &keys::upload_keys::Response, ) -> Result<()> { let mut account = self.account.lock().await; + if !account.shared { + debug!("Marking account as shared"); + } account.shared = true; let one_time_key_count = response @@ -143,6 +155,11 @@ impl OlmMachine { .get(&keys::KeyAlgorithm::SignedCurve25519); let count: u64 = one_time_key_count.map_or(0, |c| (*c).into()); + debug!( + "Updated uploaded one-time key count {} -> {}, marking keys as published", + self.uploaded_signed_key_count.as_ref().map_or(0, |c| *c), + count + ); self.uploaded_signed_key_count = Some(count); account.mark_keys_as_published(); @@ -374,7 +391,9 @@ impl OlmMachine { /// # Arguments /// /// * `event` - The to-device event that should be decrypted. + #[instrument] fn decrypt_to_device_event(&self, _: &ToDeviceEncrypted) -> StdResult { + info!("Decrypting to-device event"); Err(()) } @@ -386,6 +405,7 @@ impl OlmMachine { // TODO handle to-device verification events here. } + #[instrument] pub fn receive_sync_response(&mut self, response: &mut SyncResponse) { let one_time_key_count = response .device_one_time_keys_count @@ -399,10 +419,12 @@ impl OlmMachine { e } else { // Skip invalid events. - // TODO log here + warn!("Received an invalid to-device event {:?}", event); continue; }; + info!("Received a to-device event {:?}", event); + match event { ToDeviceEvent::RoomEncrypted(e) => { // TODO put the decrypted event into a vec so we can replace