Improve Logging — heartwood

This patch evaluates the radicle-node family of crates that emit logs.

They are each evaluated for their use of warn! and error! and whether these can be downgraded to a lower log level.

This will make the logs of the running radicle-node less busy and work towards surfacing only interesting information.

 impl Drop for Keepfile {
     fn drop(&mut self) {
         if let Err(e) = fs::remove_file(&self.path) {
             log::warn!(target: "fetch", "Failed to remove {:?}: {e}", self.path);
             log::warn!("Failed to remove {:?}: {e}", self.path);
         }
     }
 }

         .map_err(Error::Protocol);
     log::debug!(
         target: "fetch",
         "Finished pull of {} ({}ms)",
         handle.repository().id(),
         start.elapsed().as_millis()

     match &result {
         Ok(_) => {
             log::debug!(
                 target: "fetch",
                 "Finished clone of {rid} from {remote} ({elapsed}ms)",
             );
             log::debug!("Finished clone of {rid} from {remote} ({elapsed}ms)",);
         }
         Err(e) => {
             log::debug!(
                 target: "fetch",
                 "Clone of {rid} from {remote} failed with '{e}' ({elapsed}ms)",
             );
             log::debug!("Clone of {rid} from {remote} failed with '{e}' ({elapsed}ms)",);
         }
     }
     result

 }
 fn handle_handshake_err(err: handshake::Error) -> HandshakeError {
     let err = match err {
     match err {
         handshake::Error::Transport(error) => match error {
             gix_transport::client::Error::Io(error) => HandshakeError::Io(error),
             err => HandshakeError::Gix(handshake::Error::Transport(err)),
         },
         err => {
             log::warn!(target: "fetch", "Failed to perform handshake: {err}");
             HandshakeError::Gix(err)
         }
     };
     log::warn!(target: "fetch", "{err}");
     err
         err => HandshakeError::Gix(err),
     }
 }

             .map_err(|err| error::Policy::FailedPolicy { rid, err })?;
         match entry.policy {
             SeedingPolicy::Block => {
                 log::error!(target: "fetch", "Attempted to fetch non-seeded repo {rid}");
                 log::info!("Attempted to fetch non-seeded repo {rid}");
                 Err(error::Policy::BlockedPolicy { rid })
             }
             SeedingPolicy::Allow { scope: Scope::All } => Ok(Self::All),

                     let node = match node {
                         Ok(policy) => policy,
                         Err(err) => {
                             log::error!(target: "fetch", "Failed to read follow policy for {rid}: {err}");
                             log::debug!("Failed to read follow policy for {rid}: {err}");
                             continue;
                         }
                     };

             let entry = match entry {
                 Ok(entry) => entry,
                 Err(err) => {
                     log::error!(target: "fetch", "Failed to read follow policy: {err}");
                     log::debug!("Failed to read follow policy: {err}");
                     continue;
                 }
             };

                 .collect::<Vec<_>>(),
             None => vec![],
         };
         log::trace!(target: "fetch", "Received refs {refs:?}");
         log::trace!("Received refs {refs:?}");
         step.pre_validate(&refs)?;
         let wants_haves = step.wants_haves(handle.repository(), &refs)?;

                     .fetch(wants_haves, handle.interrupt.clone(), handshake)?;
             self.keepfiles.extend(keepfile);
         } else {
             log::trace!(target: "fetch", "Nothing to fetch")
             log::trace!("Nothing to fetch")
         };
         let mut fetched = BTreeSet::new();

                     blocked: handle.blocked.clone(),
                     limit: limit.special,
                 };
                 log::trace!(target: "fetch", "{sigrefs_at:?}");
                 log::trace!("{sigrefs_at:?}");
                 self.run_stage(handle, handshake, &sigrefs_at)?;
                 let remotes = refs_at.iter().map(|r| &r.remote);

             }
             None => {
                 let followed = handle.allowed();
                 log::trace!(target: "fetch", "Followed nodes {followed:?}");
                 log::trace!("Followed nodes {followed:?}");
                 let special_refs = stage::SpecialRefs {
                     blocked: handle.blocked.clone(),
                     remote,

                     threshold,
                     limit: limit.special,
                 };
                 log::trace!(target: "fetch", "{special_refs:?}");
                 log::trace!("{special_refs:?}");
                 let fetched = self.run_stage(handle, handshake, &special_refs)?;
                 let signed_refs = sigrefs::RemoteRefs::load(

                 limit: limit.special,
             },
         )?;
         log::debug!(target: "fetch", "Fetched rad/id ({}ms)", start.elapsed().as_millis());
         log::debug!("Fetched rad/id ({}ms)", start.elapsed().as_millis());
         // N.b. The error case here should not happen. In the case of
         // a `clone` we have asked for refs/rad/id and ensured it was

             .map(|did| PublicKey::from(*did))
             .collect::<BTreeSet<_>>();
         log::trace!(target: "fetch", "Identity delegates {delegates:?}");
         log::trace!("Identity delegates {delegates:?}");
         // The local peer does not need to count towards the threshold
         // since they must be valid already.

         // We're finished fetching on this side, and all that's left
         // is validation.
         match handle.transport.done() {
             Ok(()) => log::debug!(target: "fetch", "Sent done signal to remote {remote}"),
             Ok(()) => log::debug!("Sent done signal to remote {remote}"),
             Err(err) => {
                 log::warn!(target: "fetch", "Attempted to send done to remote {remote}: {err}")
                 log::debug!("Failed to signal EOF to {remote}: {err}")
             }
         }

         // private function.
         for remote in signed_refs.keys() {
             if handle.is_blocked(remote) {
                 log::trace!(target: "fetch", "Skipping blocked remote {remote}");
                 log::trace!("Skipping blocked remote {remote}");
                 continue;
             }

                 .load(&self.as_cached(handle))?;
             match remote {
                 sigrefs::DelegateStatus::NonDelegate { remote, data: None } => {
                     log::debug!(target: "fetch", "Pruning non-delegate {remote} tips, missing 'rad/sigrefs'");
                     log::debug!("Pruning non-delegate {remote} tips, missing 'rad/sigrefs'");
                     failures.push(sigrefs::Validation::MissingRadSigRefs(remote));
                     self.prune(&remote);
                 }
                 sigrefs::DelegateStatus::Delegate { remote, data: None } => {
                     log::warn!(target: "fetch", "Pruning delegate {remote} tips, missing 'rad/sigrefs'");
                     log::debug!("Pruning delegate {remote} tips, missing 'rad/sigrefs'");
                     failures.push(sigrefs::Validation::MissingRadSigRefs(remote));
                     self.prune(&remote);
                     // This delegate has removed their `rad/sigrefs`.

                     {
                         let ancestry = repository::ancestry(handle.repository(), at, sigrefs.at)?;
                         if matches!(ancestry, repository::Ancestry::Behind) {
                             log::trace!(target: "fetch", "Advertised `rad/sigrefs` {} is behind {at} for {remote}", sigrefs.at);
                             log::trace!(
                                 "Advertised `rad/sigrefs` {} is behind {at} for {remote}",
                                 sigrefs.at
                             );
                             self.prune(&remote);
                             continue;
                         } else if matches!(ancestry, repository::Ancestry::Diverged) {

                     let mut fails =
                         sigrefs::validate(&cache, sigrefs)?.unwrap_or(Validations::default());
                     if !fails.is_empty() {
                         log::warn!(target: "fetch", "Pruning delegate {remote} tips, due to validation failures");
                         log::debug!("Pruning delegate {remote} tips, due to validation failures");
                         self.prune(&remote);
                         valid_delegates.remove(&remote);
                         failed_delegates.insert(remote);

                     .into_values()
                     .flat_map(|ups| ups.into_iter()),
             )?;
             log::debug!(target: "fetch", "Applied updates ({}ms)", start.elapsed().as_millis());
             log::debug!("Applied updates ({}ms)", start.elapsed().as_millis());
             Ok(FetchResult::Success {
                 applied,
                 remotes,

     /// Perform the handshake with the server side.
     #[allow(clippy::result_large_err)]
     pub(crate) fn handshake(&mut self) -> Result<handshake::Outcome, handshake::Error> {
         log::trace!(target: "fetch", "Performing handshake for {}", self.repo);
         log::trace!("Performing handshake for {}", self.repo);
         let (read, write) = self.stream.open();
         gix_protocol::fetch::handshake(
             &mut Connection::new(read, write, self.repo.clone()),

         handshake: &handshake::Outcome,
     ) -> Result<Option<Keepfile>, Error> {
         log::trace!(
             target: "fetch",
             "Running fetch wants={:?}, haves={:?}",
             wants_haves.wants,
             wants_haves.haves

         Ok(version) => version,
         Err(err) => {
             use radicle::git::VERSION_REQUIRED;
             log::warn!(target: "fetch", "The git version could not be determined: {err}");
             log::warn!(target: "fetch", "Pretending that we are on git version {VERSION_REQUIRED}.");
             log::debug!("The git version could not be determined: {err}");
             log::debug!("Pretending that we are on git version {VERSION_REQUIRED}.");
             VERSION_REQUIRED
         }
     };

     R: io::Read,
     W: io::Write,
 {
     log::trace!(target: "fetch", "Performing fetch");
     log::trace!("Performing fetch");
     if wants_haves.wants.is_empty() {
         return Err(Error::ReadRemainingBytes(io::Error::new(

         .and_then(packfile::Keepfile::new);
     out.pack = Some(pack_out);
     log::trace!(target: "fetch", "fetched refs: {:?}", out.refs);
     log::trace!("fetched refs: {:?}", out.refs);
     Ok(out)
 }

     R: io::Read,
     W: io::Write,
 {
     log::trace!(target: "fetch", "Performing ls-refs: {:?}", config.prefixes);
     log::trace!("Performing ls-refs: {:?}", config.prefixes);
     let handshake::Outcome {
         server_protocol_version: protocol,
         capabilities,

                 thread::spawn(&nid, "control", move || {
                     if let Err((e, mut stream)) = command(stream, handle) {
                         log::error!(target: "control", "Command returned error: {e}");
                         log::debug!(target: "control", "Command returned error: {e}");
                         CommandResult::error(e).to_writer(&mut stream).ok();

                     }
                 });
             }
             Err(e) => log::error!(target: "control", "Failed to accept incoming connection: {e}"),
             Err(e) => log::warn!(target: "control", "Failed to accept incoming connection: {e}"),
         }
     }
     log::debug!(target: "control", "Exiting control loop..");

     #[cfg(windows)]
     let signals = {
         let (_, signals) = chan::bounded(1);
         log::warn!(target: "node", "Signal handlers not installed.");
         log::info!(target: "node", "No signal handlers were installed, because this is not available on Windows.");
         signals
     };

             }
             if let Err(err) = res {
                 log::error!(target: "reactor", "Error during polling: {err}");
                 log::warn!(target: "reactor", "Failure during polling: {err}");
                 self.service.handle_error(Error::Poll(err));
             }

                     deregistered.push(token);
                 }
             } else if !deregistered.contains(&token) {
                 log::warn!(target: "reactor", token=token.0; "Event from unknown token {}: {:?}", token.0, event);
                 log::debug!(target: "reactor", token=token.0; "Event from unknown token {}: {:?}", token.0, event);
             }
         }

             // Deadlock may happen here if the service will generate events over and over
             // in the handle_* calls we may never get out of this loop
             if let Err(err) = self.handle_action(action, instant) {
                 log::error!(target: "reactor", "Error: {err}");
                 log::warn!(target: "reactor", "Failure: {err}");
                 self.service.handle_error(err);
             }
         }

                         }
                     }
                 } else {
                     log::error!(target: "reactor", token=token.0; "No transport with token {token:?} is known!");
                     log::debug!(target: "reactor", token=token.0; "No transport with token {token:?} is known!");
                 }
             }
             Action::SetTimer(duration) => {

     fn deregister_listener(&mut self, token: Token) -> Option<H::Listener> {
         let Some(mut source) = self.listeners.remove(&token) else {
             log::warn!(target: "reactor", token=token.0; "Deregistering non-registered listener with token {}", token.0);
             log::debug!(target: "reactor", token=token.0; "Deregistering non-registered listener with token {}", token.0);
             return None;
         };
         if let Err(err) = self.poll.registry().deregister(&mut source) {
             log::warn!(target: "reactor", token=token.0; "Failed to deregister listener with token {} from mio: {err}", token.0);
             log::debug!(target: "reactor", token=token.0; "Failed to deregister listener with token {} from mio: {err}", token.0);
         }
         Some(source)

     fn deregister_transport(&mut self, token: Token) -> Option<H::Transport> {
         let Some(mut source) = self.transports.remove(&token) else {
             log::warn!(target: "reactor", token=token.0; "Deregistering non-registered transport with token {}", token.0);
             log::debug!(target: "reactor", token=token.0; "Deregistering non-registered transport with token {}", token.0);
             return None;
         };
         if let Err(err) = self.poll.registry().deregister(&mut source) {
             log::warn!(target: "reactor", token=token.0; "Failed to deregister transport with token {} from mio: {err}", token.0);
             log::debug!(target: "reactor", token=token.0; "Failed to deregister transport with token {} from mio: {err}", token.0);
         }
         Some(source)