rust-sdk: Add initial tracing/logging setup.

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"
+# Dependencies for the encryption support
-zeroize = { version = "1.1.0", optional = true }
-async-trait = { version = "0.1.24", optional = true }
-
 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"

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),

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<Mutex<Vec<RoomEventCallback>>>,
 }
 
+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<S: Into<String>>(
+    #[instrument(skip(password))]
+    pub async fn login<S: Into<String> + std::fmt::Debug>(
         &mut self,
         user: S,
         password: S,
         device_id: Option<S>,
     ) -> Result<login::Response> {
+        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<C>(
         &mut self,
         sync_settings: SyncSettings,
@@ -534,7 +546,7 @@ impl AsyncClient {
         }
     }
 
-    async fn send<Request: Endpoint>(
+    async fn send<Request: Endpoint + std::fmt::Debug>(
         &self,
         request: Request,
     ) -> Result<<Request::Response as Outgoing>::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 http_response = http_response.body(body).unwrap();
-        let response = <Request::Response as Outgoing>::Incoming::try_from(response)?;
+        let response = <Request::Response as Outgoing>::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<upload_keys::Response> {
         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,

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<DeviceKeys>, Option<OneTimeKeys>), ()> {
@@ -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;
 

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<P: AsRef<Path>>(
         user_id: &UserId,
         device_id: &str,
@@ -94,8 +96,14 @@ impl OlmMachine {
                 .await?;
 
         let account = match store.load_account().await? {
-            Some(a) => a,
+            Some(a) => {
-            None => Account::new(),
+                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<ToDeviceEvent, ()> {
+        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