Sanitise debug and trace logging. Closes: #89

src/commons/api/admin.rs

@@ -553,6 +553,21 @@ impl UpdateChildRequest {
     }
 }
 
+impl fmt::Display for UpdateChildRequest {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        if self.id_cert.is_some() {
+            write!(f, "new id cert ")?;
+        }
+        if let Some(resources) = &self.resources {
+            write!(f, "new resources: {} ", resources)?;
+        }
+        if self.force {
+            write!(f, "<forced>")?;
+        }
+        Ok(())
+    }
+}
+
 //------------ Tests ---------------------------------------------------------
 
 #[cfg(test)]

src/commons/api/rrdp.rs

@@ -222,7 +222,7 @@ impl Notification {
     }
 
     pub fn write_xml(&self, path: &PathBuf) -> Result<(), io::Error> {
-        debug!("Writing notification file: {}", path.to_string_lossy());
+        trace!("Writing notification file: {}", path.to_string_lossy());
         let mut file = file::create_file_with_path(&path)?;
 
         XmlWriter::encode_to_file(&mut file, |w| {
@@ -490,6 +490,7 @@ impl Snapshot {
     }
 
     pub fn write_xml(&self, path: &PathBuf) -> Result<HexEncodedHash, io::Error> {
+        trace!("Writing snapshot file: {}", path.to_string_lossy());
         let vec = XmlWriter::encode_vec(|w| {
             let a = [
                 ("xmlns", NS),
@@ -626,6 +627,7 @@ impl Delta {
     }
 
     pub fn write_xml(&self, path: &PathBuf) -> Result<HexEncodedHash, io::Error> {
+        trace!("Writing delta file: {}", path.to_string_lossy());
         let vec = XmlWriter::encode_vec(|w| {
             let a = [
                 ("xmlns", NS),

src/commons/eventsourcing/agg_store.rs

@@ -113,7 +113,7 @@ impl<A: Aggregate> DiskAggregateStore<A> {
     }
 
     fn get_latest_no_lock(&self, handle: &Handle) -> StoreResult<Arc<A>> {
-        debug!("Trying to load aggregate id: {}", handle);
+        trace!("Trying to load aggregate id: {}", handle);
         match self.cache_get(handle) {
             None => match self.store.get_aggregate(handle)? {
                 None => {
@@ -123,7 +123,7 @@ impl<A: Aggregate> DiskAggregateStore<A> {
                 Some(agg) => {
                     let arc: Arc<A> = Arc::new(agg);
                     self.cache_update(handle, arc.clone());
-                    debug!("Loaded aggregate id: {} from disk", handle);
+                    trace!("Loaded aggregate id: {} from disk", handle);
                     Ok(arc)
                 }
             },
@@ -132,7 +132,7 @@ impl<A: Aggregate> DiskAggregateStore<A> {
                     let agg = Arc::make_mut(&mut arc);
                     self.store.update_aggregate(handle, agg)?;
                 }
-                debug!("Loaded aggregate id: {} from memory", handle);
+                trace!("Loaded aggregate id: {} from memory", handle);
                 Ok(arc)
             }
         }
@@ -169,6 +169,7 @@ impl<A: Aggregate> AggregateStore<A> for DiskAggregateStore<A> {
         {
             // Verify whether there is a concurrency issue
             if prev.version() != latest.version() {
+                // TODO: Print history (last X events) and conflict to log.
                 return Err(AggregateStoreError::ConcurrentModification(handle.clone()));
             }
 

src/commons/eventsourcing/store.rs

@@ -173,12 +173,12 @@ impl KeyStore for DiskKeyStore {
                     Err(KeyStoreError::JsonError(e))
                 }
                 Ok(v) => {
-                    debug!("Deserialized json at: {}", path_str);
+                    trace!("Deserialized json at: {}", path_str);
                     Ok(Some(v))
                 }
             }
         } else {
-            debug!("Could not find file at: {}", path_str);
+            trace!("Could not find file at: {}", path_str);
             Ok(None)
         }
     }
@@ -196,12 +196,12 @@ impl KeyStore for DiskKeyStore {
                     Err(KeyStoreError::JsonError(e))
                 }
                 Ok(v) => {
-                    debug!("Deserialized event at: {}", path_str);
+                    trace!("Deserialized event at: {}", path_str);
                     Ok(Some(v))
                 }
             }
         } else {
-            debug!("No more events at: {}", path_str);
+            trace!("No more events at: {}", path_str);
             Ok(None)
         }
     }

src/commons/remote/proxy.rs

@@ -194,7 +194,7 @@ impl ProxyServer {
     /// Retrieves the QueryMessage contained in the SignedMessage and
     /// converts into the (json) equivalent request for the API.
     fn convert_to_json_request(&self, msg: &SignedMessage) -> Result<PublishRequest, Error> {
-        debug!("Convert contained message to Json equivalent");
+        trace!("Convert contained message to Json equivalent");
         let msg = rfc8181::Message::from_signed_message(&msg)?;
         let msg = msg.into_query()?;
         Ok(msg.into_publish_request())

src/commons/util/file.rs

@@ -123,7 +123,7 @@ pub fn clean_file_and_path(path: &PathBuf) -> Result<(), io::Error> {
         while parent_opt.is_some() {
             let parent = parent_opt.unwrap();
             if parent.read_dir()?.count() == 0 {
-                debug!("Will delete {}", parent.to_string_lossy().to_string());
+                trace!("Will delete {}", parent.to_string_lossy().to_string());
                 fs::remove_dir(parent)?;
             }
 

src/daemon/auth.rs

@@ -112,7 +112,7 @@ impl FromRequest for Auth {
 
     fn from_request(req: &HttpRequest, payload: &mut Payload) -> Self::Future {
         if let Some(identity) = Identity::from_request(req, payload)?.identity() {
-            debug!("Found user: {}", &identity);
+            trace!("Found user: {}", &identity);
             Ok(Auth::User(identity))
         } else if let Some(header) = req.headers().get("Authorization") {
             let token =

src/daemon/ca/certauth.rs

@@ -827,10 +827,12 @@ impl<S: Signer> CertAuth<S> {
         rc: &ResourceClass,
         signer: &S,
     ) -> Result<Vec<Evt>> {
+        let parent_class_name = entitlement.class_name().clone();
         let req_details_list = rc.make_request_events(entitlement, &self.base_repo, signer)?;
 
         let mut res = vec![];
         for details in req_details_list.into_iter() {
+            debug!("Updating Entitlements for CA: {}, Request for RC: {}", &self.handle, &parent_class_name);
             res.push(StoredEvent::new(&self.handle, *version, details));
             *version += 1;
         }
@@ -908,6 +910,8 @@ impl<S: Signer> CertAuth<S> {
             let delta = rc.withdraw(&self.base_repo);
             let revocations = rc.revoke(signer.deref())?;
 
+            debug!("Updating Entitlements for CA: {}, Removing RC: {}", &self.handle, &name);
+
             res.push(EvtDet::resource_class_removed(
                 &self.handle,
                 version,
@@ -960,6 +964,7 @@ impl<S: Signer> CertAuth<S> {
                     );
                     let rc_add_version = version;
                     version += 1;
+                    debug!("Updating Entitlements for CA: {}, adding RC: {}", &self.handle, &rcn);
 
                     let signer = signer.read().unwrap();
                     let mut request_events =

src/daemon/ca/server.rs

@@ -165,7 +165,7 @@ impl<S: Signer> CaServer<S> {
         parent: &ParentHandle,
         child: &ChildHandle,
     ) -> ServerResult<Option<ChildCaInfo>, S> {
-        debug!("Finding details for CA: {} under parent: {}", child, parent);
+        trace!("Finding details for CA: {} under parent: {}", child, parent);
 
         let ca = self.get_ca(parent)?;
         let child_opt = match ca.get_child(child) {
@@ -184,8 +184,8 @@ impl<S: Signer> CaServer<S> {
         req: UpdateChildRequest,
     ) -> ServerResult<(), S> {
         debug!(
-            "Updating details for CA: {} under parent: {}",
-            child, parent
+            "Updating details for CA: {} under parent: {} to: {}",
+            child, parent, req
         );
         let mut ca = self.get_ca(parent)?;
 
@@ -216,20 +216,27 @@ impl<S: Signer> CaServer<S> {
 /// # CA support
 ///
 impl<S: Signer> CaServer<S> {
+    /// Gets a CA by the given handle, returns an `Err(ServerError::UnknownCA)` if it
+    /// does not exist.
     pub fn get_ca(&self, handle: &Handle) -> ServerResult<Arc<CertAuth<S>>, S> {
         self.ca_store
             .get_latest(handle)
             .map_err(|_| ServerError::UnknownCa(handle.to_string()))
     }
 
+    /// Checks whether a CA by the given handle exists.
+    pub fn has_ca(&self, handle: &Handle) -> bool {
+        self.ca_store.has(handle)
+    }
+
     /// Verifies an RFC6492 message and returns the child handle, token,
     /// and content of the request, so that the simple 'list' and 'issue'
     /// functions can be called.
     pub fn rfc6492(&self, ca_handle: &Handle, msg: SignedMessage) -> ServerResult<Bytes, S> {
-        debug!("RFC6492 Request: will check");
+        trace!("RFC6492 Request: will check");
         let ca = self.ca_store.get_latest(ca_handle)?;
         let content = ca.verify_rfc6492(msg)?;
-        debug!("RFC6492 Request: verified");
+        trace!("RFC6492 Request: verified");
 
         let (child, recipient, content) = content.unwrap();
 
@@ -258,7 +265,7 @@ impl<S: Signer> CaServer<S> {
         handle: &Handle,
         msg: rfc6492::Message,
     ) -> ServerResult<Bytes, S> {
-        debug!("RFC6492 Response wrapping for {}", handle);
+        trace!("RFC6492 Response wrapping for {}", handle);
         self.get_ca(handle)?
             .sign_rfc6492_response(msg, self.signer.read().unwrap().deref())
             .map_err(ServerError::<S>::CertAuth)
@@ -763,7 +770,7 @@ impl<S: Signer> CaServer<S> {
         // send to the server
         let uri = parent_res.service_uri().to_string();
         debug!(
-            "Sending to parent: {}\n{}",
+            "Sending RFC6492 message to parent: {}\n{}",
             &uri,
             base64::encode(&signed.as_bytes())
         );
@@ -773,7 +780,10 @@ impl<S: Signer> CaServer<S> {
 
         // unpack and validate response
         let msg = match SignedMessage::decode(res.as_ref(), false).map_err(ServerError::custom) {
-            Ok(msg) => msg,
+            Ok(msg) => {
+                debug!("Received syntactically correct RFC6492 response.");
+                msg
+            },
             Err(e) => {
                 error!("Could not parse response: {}", base64::encode(res.as_ref()));
                 return Err(e);

src/daemon/config.rs

@@ -167,7 +167,7 @@ impl Config {
         let data_dir = data_dir.clone();
         let rsync_base = ConfigDefaults::rsync_base();
         let service_uri = ConfigDefaults::service_uri();
-        let log_level = LevelFilter::Info;
+        let log_level = LevelFilter::Debug;
         let log_type = LogType::Stderr;
         let mut log_file = data_dir.clone();
         log_file.push("krill.log");

src/daemon/endpoints.rs

@@ -187,7 +187,7 @@ pub fn handle_delta(
 ) -> HttpResponse {
     let handle = handle.into_inner();
     let delta = delta.into_inner();
-    debug!("Received delta request for {}", &handle);
+    trace!("Received delta request for {}", &handle);
     if_publication_allowed(&server, &handle, &auth, || {
         render_empty_res(server.read().handle_delta(delta, &handle))
     })
@@ -197,7 +197,7 @@ pub fn handle_delta(
 #[allow(clippy::needless_pass_by_value)]
 pub fn handle_list(server: web::Data<AppServer>, auth: Auth, handle: Path<Handle>) -> HttpResponse {
     let handle = handle.into_inner();
-    debug!("Received list request for {}", &handle);
+    trace!("Received list request for {}", &handle);
     if_publication_allowed(&server, &handle, &auth, || {
         match server.read().handle_list(&handle) {
             Ok(list) => render_json(list),

src/daemon/krillserver.rs

@@ -99,7 +99,9 @@ impl KrillServer {
 
         if config.use_ta() {
             let ta_handle = ta_handle();
-            if caserver.get_ca(&ta_handle).is_err() {
+            if !caserver.has_ca(&ta_handle) {
+                info!("Creating embedded Trust Anchor");
+
                 let repo_info = pubserver.repo_info_for(&ta_handle)?;
 
                 let ta_uri = config.ta_cert_uri();
@@ -125,7 +127,6 @@ impl KrillServer {
                 // Force initial  publication
                 caserver.republish(&ta_handle)?;
 
-                info!("Created embedded Trust Anchor");
             }
         }
 
@@ -179,7 +180,7 @@ impl KrillServer {
         };
 
         if allowed {
-            debug!("Access to publication api allowed")
+            trace!("Access to publication api allowed")
         } else {
             warn!(
                 "Access to publication api disallowed for handle: {}, and auth: {}",

src/daemon/mq.rs

@@ -63,7 +63,7 @@ impl<S: Signer> eventsourcing::EventListener<CertAuth<S>> for EventQueueListener
         use crate::commons::eventsourcing::Event;
 
         let json = serde_json::to_string_pretty(&event).unwrap();
-        debug!("Seen CertAuth event: {}", json);
+        trace!("Seen CertAuth event: {}", json);
 
         let handle = event.handle();
         match event.details() {

src/daemon/scheduler.rs

@@ -65,7 +65,7 @@ fn make_event_sh(
                         .send_revoke_requests(&handle, &parent, revocations)
                         .is_err()
                     {
-                        info!("Could not revoke key for removed resource class. This is not \
+                        debug!("Could not revoke key for removed resource class. This is not \
                         an issue, because typically the parent will revoke our keys pro-actively, \
                         just before removing the resource class entitlements.");
                     }
@@ -101,10 +101,9 @@ fn make_republish_sh(caserver: Arc<CaServer<OpenSslSigner>>) -> ScheduleHandle {
 }
 
 fn publish(handle: &Handle, delta: PublishDelta, pubserver: &PubServer) {
-    debug!("Triggered publishing for CA: {}", handle);
-    match pubserver.publish(handle, delta) {
-        Ok(()) => debug!("Published for CA: {}", handle),
-        Err(e) => error!("Failed to publish for CA: {}, error: {}", handle, e),
+    trace!("Asking CA: {} if it wants to publish", handle);
+    if let Err(e) = pubserver.publish(handle, delta) {
+        error!("Failed to publish for CA: {}, error: {}", handle, e);
     }
 }