Merge pull request #223 from soywod/tracing

Logs contributed by @soywod - thanks so much!!

.github/workflows/ci.yaml

@@ -35,6 +35,8 @@ jobs:
         run: cargo clippy -- -D warnings
 
       - name: Build and Test
+        env:
+          RUST_LOG: debug
         run: cargo test --features=apple-native,windows-native --verbose
 
       - name: Build the CLI release
@@ -85,6 +87,8 @@ jobs:
         run: gnome-keyring-daemon --components=secrets --daemonize --unlock <<< 'foobar'
 
       - name: Run tests
+        env:
+          RUST_LOG: debug
         # run tests single-threaded to avoid dbus race conditions
         run: cargo test --features=${{ matrix.features }} -- --test-threads=1
 

Cargo.toml

@@ -26,6 +26,7 @@ async-io = ["zbus?/async-io"]
 vendored = ["dbus-secret-service?/vendored", "openssl?/vendored"]
 
 [dependencies]
+log = "0.4.22"
 openssl = { version = "0.10.55", optional = true }
 
 [target.'cfg(any(target_os = "macos", target_os = "ios"))'.dependencies]  # see issue #190
@@ -63,10 +64,11 @@ path = "examples/cli.rs"
 [dev-dependencies]
 base64 = "0.22"
 clap = { version = "4", features = ["derive", "wrap_help"] }
+doc-comment = "0.3"
+env_logger = "0.11.5"
+rand = "0.8"
 rpassword = "7"
 rprompt = "2"
-rand = "0.8"
-doc-comment = "0.3"
 whoami = "1"
 
 [package.metadata.docs.rs]

src/lib.rs

@@ -173,9 +173,11 @@ Service, accesses from multiple threads (and even the same thread very quickly)
 are not recommended, as they may cause the RPC mechanism to fail.
  */
 
+use log::debug;
+use std::collections::HashMap;
+
 pub use credential::{Credential, CredentialBuilder};
 pub use error::{Error, Result};
-use std::collections::HashMap;
 
 pub mod mock;
 
@@ -328,18 +330,25 @@ impl Entry {
     /// will panic. If you encounter this, and especially if you can reproduce it, please report a bug with the
     /// details (and preferably a backtrace) so the developers can investigate.
     pub fn new(service: &str, user: &str) -> Result<Entry> {
-        build_default_credential(None, service, user)
+        debug!("creating entry with service {service}, user {user}, and no target");
+        let entry = build_default_credential(None, service, user)?;
+        debug!("created entry {:?}", entry.inner);
+        Ok(entry)
     }
 
     /// Create an entry for the given target, service, and user.
     ///
     /// The default credential builder is used.
     pub fn new_with_target(target: &str, service: &str, user: &str) -> Result<Entry> {
-        build_default_credential(Some(target), service, user)
+        debug!("creating entry with service {service}, user {user}, and target {target}");
+        let entry = build_default_credential(Some(target), service, user)?;
+        debug!("created entry {:?}", entry.inner);
+        Ok(entry)
     }
 
     /// Create an entry that uses the given platform credential for storage.
     pub fn new_with_credential(credential: Box<Credential>) -> Entry {
+        debug!("create entry from {credential:?}");
         Entry { inner: credential }
     }
 
@@ -351,6 +360,7 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn set_password(&self, password: &str) -> Result<()> {
+        debug!("set password for entry {:?}", self.inner);
         self.inner.set_password(password)
     }
 
@@ -362,6 +372,7 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn set_secret(&self, secret: &[u8]) -> Result<()> {
+        debug!("set secret for entry {:?}", self.inner);
         self.inner.set_secret(secret)
     }
 
@@ -375,6 +386,7 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn get_password(&self) -> Result<String> {
+        debug!("get password from entry {:?}", self.inner);
         self.inner.get_password()
     }
 
@@ -388,6 +400,7 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn get_secret(&self) -> Result<Vec<u8>> {
+        debug!("get secret from entry {:?}", self.inner);
         self.inner.get_secret()
     }
 
@@ -405,6 +418,7 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn get_attributes(&self) -> Result<HashMap<String, String>> {
+        debug!("get attributes from entry {:?}", self.inner);
         self.inner.get_attributes()
     }
 
@@ -424,6 +438,10 @@ impl Entry {
     /// on some platforms, and then only if a third-party
     /// application wrote the ambiguous credential.
     pub fn update_attributes(&self, attributes: &HashMap<&str, &str>) -> Result<()> {
+        debug!(
+            "update attributes for entry {:?} from map {attributes:?}",
+            self.inner
+        );
         self.inner.update_attributes(attributes)
     }
 
@@ -441,6 +459,7 @@ impl Entry {
     /// structure, which is controlled by Rust.  It only
     /// affects the underlying credential store.
     pub fn delete_credential(&self) -> Result<()> {
+        debug!("delete entry {:?}", self.inner);
         self.inner.delete_credential()
     }
 
@@ -555,7 +574,9 @@ mod tests {
     pub fn generate_random_string_of_len(len: usize) -> String {
         // from the Rust Cookbook:
         // https://rust-lang-nursery.github.io/rust-cookbook/algorithms/randomness.html
-        use rand::{distributions::Alphanumeric, thread_rng, Rng};
+        #[allow(unused_imports)]
+        use rand::Rng;
+        use rand::{distributions::Alphanumeric, thread_rng};
         thread_rng()
             .sample_iter(&Alphanumeric)
             .take(len)

tests/basic.rs

@@ -1,10 +1,12 @@
-use common::generate_random_string;
+use common::{generate_random_string, init_logger};
 use keyring::{Entry, Error};
 
 mod common;
 
 #[test]
 fn test_missing_entry() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     assert!(
@@ -16,6 +18,8 @@ fn test_missing_entry() {
 #[test]
 #[cfg(all(target_os = "linux", not(feature = "linux-native")))]
 fn test_empty_password() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let in_pass = "";
@@ -36,6 +40,8 @@ fn test_empty_password() {
 
 #[test]
 fn test_round_trip_ascii_password() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let password = "test ascii password";
@@ -58,6 +64,8 @@ fn test_round_trip_ascii_password() {
 
 #[test]
 fn test_round_trip_non_ascii_password() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let password = "このきれいな花は桜です";
@@ -80,6 +88,8 @@ fn test_round_trip_non_ascii_password() {
 
 #[test]
 fn test_round_trip_random_secret() {
+    init_logger();
+
     use rand::{rngs::OsRng, Rng};
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
@@ -102,6 +112,8 @@ fn test_round_trip_random_secret() {
 
 #[test]
 fn test_update() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let password = "test ascii password";

tests/common/mod.rs

@@ -18,3 +18,7 @@ pub fn generate_random_string_of_len(len: usize) -> String {
 pub fn generate_random_string() -> String {
     generate_random_string_of_len(30)
 }
+
+pub fn init_logger() {
+    let _ = env_logger::builder().is_test(true).try_init();
+}

tests/threading.rs

@@ -1,10 +1,12 @@
-use common::generate_random_string;
+use common::{generate_random_string, init_logger};
 use keyring::{Entry, Error};
 
 mod common;
 
 #[test]
 fn test_create_then_move() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).unwrap();
     let test = move || {
@@ -40,6 +42,8 @@ fn test_create_then_move() {
 
 #[test]
 fn test_simultaneous_create_then_move() {
+    init_logger();
+
     let mut handles = vec![];
     for i in 0..10 {
         let name = format!("{}-{}", generate_random_string(), i);
@@ -69,6 +73,8 @@ fn test_simultaneous_create_then_move() {
 #[test]
 #[cfg(not(target_os = "windows"))]
 fn test_create_set_then_move() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let password = "test ascii password";
@@ -96,6 +102,8 @@ fn test_create_set_then_move() {
 #[test]
 #[cfg(not(target_os = "windows"))]
 fn test_simultaneous_create_set_then_move() {
+    init_logger();
+
     let mut handles = vec![];
     for i in 0..10 {
         let name = format!("{}-{}", generate_random_string(), i);
@@ -124,6 +132,8 @@ fn test_simultaneous_create_set_then_move() {
 
 #[test]
 fn test_simultaneous_independent_create_set() {
+    init_logger();
+
     let mut handles = vec![];
     for i in 0..10 {
         let name = format!("thread_entry{i}");
@@ -153,6 +163,8 @@ fn test_simultaneous_independent_create_set() {
 #[test]
 #[cfg(any(target_os = "macos", target_os = "windows", feature = "linux-native"))]
 fn test_multiple_create_delete_single_thread() {
+    init_logger();
+
     let name = generate_random_string();
     let entry = Entry::new(&name, &name).expect("Can't create entry");
     let repeats = 10;
@@ -176,6 +188,8 @@ fn test_multiple_create_delete_single_thread() {
 #[test]
 #[cfg(any(target_os = "macos", target_os = "windows", feature = "linux-native"))]
 fn test_simultaneous_multiple_create_delete_single_thread() {
+    init_logger();
+
     let mut handles = vec![];
     for t in 0..10 {
         let name = generate_random_string();