daemon: use tracing crate and improve logging

We replace the `log` crate with `tracing` for `daemon` and clean up some
logging statements.

Signed-off-by: Thomas Scholtes <[email protected]>

daemon/Cargo.toml

@@ -11,7 +11,7 @@ async-stream = "0.3"
 either = "1.6"
 futures = { version = "0.3", features = [ "compat" ] }
 lazy_static = "1.4"
-log = "0.4"
+tracing = "0.1"
 nonempty = "0.6"
 serde = { version = "1.0", features = [ "derive" ] }
 serde_millis = "0.1"
@@ -39,7 +39,6 @@ path = "../git-helpers"
 [dev-dependencies]
 assert_matches = "1.3"
 pretty_assertions = "0.6"
-pretty_env_logger = "0.3"
 tempfile = "3.1"
 tracing = "0.1"
 tracing-subscriber = "0.2"

daemon/src/config.rs

@@ -120,7 +120,7 @@ impl discovery::Discovery for StreamDiscovery {
                 match self.seeds_receiver.changed().await {
                     Ok(_) => {},
                     Err(_) => {
-                        log::warn!("Peer discovery stream dropped");
+                        tracing::warn!("Peer discovery stream dropped");
                         break;
                     }
                 }

daemon/src/peer.rs

@@ -206,11 +206,11 @@ where
                             .expect("subroutines is gone");
                         let (_, run) = net::protocol::accept(bound, disco.clone().discover());
                         if let Err(e) = run.await {
-                            log::error!("accept error: {}", e);
+                            tracing::error!(error = ?e, "accept error");
                         }
                     },
                     Err(e) => {
-                        log::error!("bound error: {}", e);
+                        tracing::error!(error = ?e, "bound error");
                         return Err(Error::Bootstrap(e));
                     },
                 }

daemon/src/peer/gossip.rs

@@ -26,8 +26,8 @@ where
         rev: rev.map(|rev| Rev::Git(rev.into())),
         origin: None,
     }) {
-        Ok(()) => log::trace!("successfully announced for urn=`{}`, rev=`{:?}`", urn, rev),
-        Err(_payload) => log::warn!("failed to announce for urn=`{}`, rev=`{:?}`", urn, rev),
+        Ok(()) => tracing::trace!(%urn, ?rev, "successfully announced URN"),
+        Err(_payload) => tracing::warn!(%urn, ?rev, "failed to announce URN"),
     }
 }
 
@@ -41,11 +41,7 @@ where
         rev: None,
         origin,
     }) {
-        Ok(()) => log::trace!(
-            "successfully queried for urn=`{}`, origin=`{:?}`",
-            urn,
-            origin
-        ),
-        Err(_payload) => log::warn!("failed to query for urn=`{}`, origin=`{:?}`", urn, origin),
+        Ok(()) => tracing::trace!(%urn, ?origin, "successfully queried URN"),
+        Err(_payload) => tracing::warn!(%urn, "failed to query URN"),
     };
 }

daemon/src/peer/include.rs

@@ -14,8 +14,7 @@ pub async fn update<S>(peer: Peer<S>, urn: Urn)
 where
     S: Clone + Signer,
 {
-    match state::update_include(&peer, urn.clone()).await {
-        Ok(path) => log::debug!("Updated include file @ {}", path.display()),
-        Err(err) => log::debug!("Failed to update include file for `{}`: {}", urn, err),
+    if let Err(err) = state::update_include(&peer, urn.clone()).await {
+        tracing::error!(%urn, error = ?err, "Failed to update include file");
     }
 }

daemon/src/peer/run_state.rs

@@ -199,7 +199,7 @@ impl RunState {
     /// new state and in some cases produes commands which should be
     /// executed in the appropriate subroutines.
     pub fn transition(&mut self, input: Input) -> Vec<Command> {
-        log::trace!("TRANSITION START: {:?} {:?}", input, self.status);
+        tracing::trace!(?input, status = ?self.status, "transition start");
 
         let cmds = match input {
             Input::Announce(announce_input) => self.handle_announce(announce_input),
@@ -211,7 +211,7 @@ impl RunState {
             Input::Stats(stats_input) => self.handle_stats(stats_input),
         };
 
-        log::trace!("TRANSITION END: {:?} {:?}", self.status, cmds);
+        tracing::trace!(?cmds, status = ?self.status, "transition end");
 
         cmds
     }
@@ -356,7 +356,7 @@ impl RunState {
                     urn,
                 },
             ) => {
-                log::warn!("Cloning failed with: {}", reason);
+                tracing::warn!(?reason, "cloning failed");
                 self.waiting_room
                     .cloning_failed(&urn, remote_peer, SystemTime::now(), reason)
             },

daemon/src/peer/run_state/running_waiting_room.rs

@@ -328,7 +328,7 @@ impl RunningWaitingRoom {
             },
             // FIXME(alexjg): Figure out how to report this error to the client
             Err(error) => {
-                log::warn!("WaitingRoom::Error : {}", error);
+                tracing::warn!(?error, "waiting room error");
                 Vec::new()
             },
         }

daemon/src/peer/subroutines.rs

@@ -88,7 +88,7 @@ where
         };
         let waiting_room = match waiting_room::load(&store) {
             Err(err) => {
-                log::warn!("Failed to load waiting room: {}", err);
+                tracing::warn!(?err, "Failed to load waiting room");
                 WaitingRoom::new(request::waiting_room::Config {
                     delta: config::DEFAULT_WAITING_ROOM_TIMEOUT,
                     ..request::waiting_room::Config::default()
@@ -121,7 +121,7 @@ where
                         match res {
                             Ok(ev) => Some(Input::Protocol(ev)),
                             Err(err) => {
-                                log::warn!("receive error: {}", err);
+                                tracing::warn!(?err, "receive error");
                                 None
                             },
                         }
@@ -276,7 +276,7 @@ where
     }
 
     fn handle_input(&mut self, input: Input) {
-        log::debug!("handling subroutine input: {:?}", input);
+        tracing::debug!(?input, "handling subroutine input");
 
         let old_status = self.run_state.status.clone();
 
@@ -344,7 +344,7 @@ where
                 .ok();
         },
         Err(err) => {
-            log::error!("announce error: {:?}", err);
+            tracing::error!(?err, "announce error");
             sender
                 .send(Input::Announce(input::Announce::Failed))
                 .await
@@ -381,8 +381,8 @@ where
 #[allow(clippy::unused_async)]
 async fn persist_waiting_room(waiting_room: WaitingRoom<SystemTime, Duration>, store: kv::Store) {
     match waiting_room::save(&store, waiting_room) {
-        Ok(()) => log::debug!("Successfully persisted the waiting room"),
-        Err(err) => log::debug!("Error while persisting the waiting room: {}", err),
+        Ok(()) => tracing::debug!("Successfully persisted the waiting room"),
+        Err(err) => tracing::debug!(?err, "Error while persisting the waiting room"),
     }
 }
 
@@ -405,7 +405,7 @@ where
                 .ok();
         },
         Err(err) => {
-            log::error!("sync error for {}: {:?}", peer_id, err);
+            tracing::error!(%peer_id, ?err, "sync error");
             sender
                 .send(Input::PeerSync(input::Sync::Failed(peer_id)))
                 .await
@@ -456,11 +456,11 @@ async fn clone<S>(
             gossip::announce(&peer, &urn, None);
         },
         Err(err) => {
-            log::warn!(
-                "an error occurred for the command 'Clone' for the URN '{}' from {}:\n{}",
-                urn,
-                remote_peer,
-                err,
+            tracing::warn!(
+                %urn,
+                %remote_peer,
+                ?err,
+                "an error occurred for the command 'Clone'",
             );
             sender
                 .send(Input::Request(input::Request::Failed {

daemon/src/peer/sync.rs

@@ -17,7 +17,7 @@ pub async fn sync<S>(peer: &Peer<S>, remote_peer: PeerId) -> Result<(), Error>
 where
     S: Clone + Signer,
 {
-    log::debug!("Starting sync from {}", remote_peer);
+    tracing::debug!(%remote_peer, "Starting sync");
 
     let urns = state::list_projects(peer)
         .await?
@@ -26,18 +26,18 @@ where
         .collect::<Vec<_>>();
 
     for urn in urns {
-        log::debug!("Starting fetch of {} from {}", urn, remote_peer);
+        tracing::debug!(%urn, %remote_peer, "starting fetch");
         match state::fetch(peer, urn.clone(), remote_peer, vec![], None).await {
             Ok(result) => {
-                log::debug!(
-                    "Finished fetch of {} from {} with the result {:?}",
-                    urn,
-                    remote_peer,
-                    result.updated_tips
+                tracing::debug!(
+                    %urn,
+                    %remote_peer,
+                    updated_tips = ?result.updated_tips,
+                    "finished fetch",
                 );
                 include::update(peer.clone(), urn).await;
             },
-            Err(e) => log::debug!("Fetch of {} from {} errored: {}", urn, remote_peer, e),
+            Err(error) => tracing::error!(%urn, %remote_peer, ?error, "fetch error"),
         }
     }
 

daemon/src/project/checkout.rs

@@ -112,7 +112,7 @@ where
     remote.save(&repo)?;
     for (reference, oid) in remote.fetch(storage, &repo, LocalFetchspec::Configured)? {
         let msg = format!("Fetched `{}->{}`", reference, oid);
-        log::debug!("{}", msg);
+        tracing::debug!("{}", msg);
 
         // FIXME(finto): we should ignore refs that don't start with heads to avoid
         // unintended side-effects.

daemon/src/project/create/validation.rs

@@ -233,10 +233,7 @@ impl Repository {
                 url,
                 default_branch,
             } => {
-                log::debug!(
-                    "Setting up existing repository @ '{}'",
-                    repo.path().display()
-                );
+                tracing::debug!(path = ?repo.path(), "Setting up existing repository");
                 Self::setup_remote(&repo, open_storage, url, &default_branch)?;
                 Ok(repo)
             },
@@ -248,7 +245,7 @@ impl Repository {
                 signature,
             } => {
                 let path = path.join(name);
-                log::debug!("Setting up new repository @ '{}'", path.display());
+                tracing::debug!(?path, "Setting up new repository",);
                 let repo = Self::initialise(path, description, &default_branch)?;
                 Self::initial_commit(
                     &repo,
@@ -284,7 +281,7 @@ impl Repository {
         description: &str,
         default_branch: &OneLevel,
     ) -> Result<git2::Repository, git2::Error> {
-        log::debug!("Setting up new repository @ '{}'", path.display());
+        tracing::debug!(?path, "Setting up new repository");
         let mut options = git2::RepositoryInitOptions::new();
         options.no_reinit(true);
         options.mkpath(true);
@@ -336,7 +333,7 @@ impl Repository {
     {
         let _default_branch_ref = Self::existing_branch(repo, default_branch)?;
 
-        log::debug!("Creating rad remote");
+        tracing::debug!("Creating rad remote");
 
         let fetchspec = Refspec {
             src: refspec_pattern!("refs/heads/*"),
@@ -359,7 +356,7 @@ impl Repository {
                 force: Force::True,
             },
         )? {
-            log::debug!("Pushed local branch `{}`", pushed);
+            tracing::debug!(branch = ?pushed, "Pushed local branch");
         }
         Ok(git_remote)
     }
@@ -383,10 +380,7 @@ impl Repository {
     ) -> Result<Option<Remote<LocalUrl>>, Error> {
         match Remote::<LocalUrl>::find(repo, reflike!("rad")) {
             Err(remote::FindError::ParseUrl(_)) => {
-                log::warn!("an old/invalid URL was found when trying to load the `rad` remote");
-                log::warn!(
-                    "we are going to rename the remote to `rad_old` and create a new `rad` remote"
-                );
+                tracing::warn!("renaming invalid rad URL");
                 repo.remote_rename("rad", "rad_old")?;
                 Ok(None)
             },

daemon/src/state.rs

@@ -482,10 +482,10 @@ where
         })
         .await??;
 
-    log::debug!(
-        "Created project '{}#{}'",
-        project.urn(),
-        project.subject().name
+    tracing::debug!(
+        urn = ?project.urn(),
+        name = ?project.subject().name,
+        "created project",
     );
 
     let repo = spawn_blocking({
@@ -555,8 +555,7 @@ where
     }
 
     gossip::query(peer, &urn, Some(remote_peer));
-    let path = update_include(peer, urn).await?;
-    log::debug!("Updated include path @ `{}`", path.display());
+    update_include(peer, urn).await?;
     Ok(())
 }
 
@@ -577,8 +576,7 @@ where
 
     // Only need to update if we did untrack an existing peer
     if res {
-        let path = update_include(peer, urn).await?;
-        log::debug!("Updated include path @ `{}`", path.display());
+        update_include(peer, urn).await?;
     }
     Ok(res)
 }
@@ -725,18 +723,16 @@ where
         include_path,
     };
 
-    log::debug!("Determing Owner");
     let ownership = match peer_id {
         None => crate::project::checkout::Ownership::Local(peer.peer_id()),
         Some(remote) => {
             let handle = {
                 let rad_self =
                     Urn::try_from(Reference::rad_self(Namespace::from(urn.clone()), peer_id))
                         .expect("namespace is set");
-                log::debug!("Monorepo: {}", monorepo(peer).display());
                 let person = peer
                     .using_storage(move |store| {
-                        log::debug!("Urn -> {}", rad_self);
+                        tracing::debug!(?rad_self, "cloning from peer");
                         person::get(store, &rad_self)?.ok_or(Error::PersonNotFound(rad_self))
                     })
                     .await??;
@@ -753,7 +749,6 @@ where
     };
 
     let settings = settings(peer);
-    log::debug!("Cloning");
     let path = spawn_blocking(move || checkout.run(settings, ownership)).await??;
 
     Ok(path)
@@ -791,7 +786,7 @@ where
     })
     .await??;
     let include_path = include.file_path();
-    log::info!("creating include file @ '{:?}'", include_path);
+    tracing::debug!(path = ?include_path, "updaing include");
     include.save()?;
 
     Ok(include_path)