feat: Add code instrumentation

Adds `log_instrument::instrument` attribute macros to functions.

Signed-off-by: Jonathan Woollett-Light <[email protected]>

Author: Jonathan Woollett-Light

src/api_server/src/lib.rs

@@ -43,6 +43,7 @@ pub struct ApiServer {
 }
 
 impl ApiServer {
+    #[log_instrument::instrument]
     /// Constructor for `ApiServer`.
     ///
     /// Returns the newly formed `ApiServer`.
@@ -59,6 +60,7 @@ impl ApiServer {
         }
     }
 
+    #[log_instrument::instrument]
     /// Runs the Api Server.
     ///
     /// # Arguments
@@ -128,6 +130,7 @@ impl ApiServer {
         }
     }
 
+    #[log_instrument::instrument]
     /// Handles an API request received through the associated socket.
     pub fn handle_request(
         &mut self,
@@ -158,6 +161,7 @@ impl ApiServer {
         }
     }
 
+    #[log_instrument::instrument]
     fn serve_vmm_action_request(
         &mut self,
         vmm_action: Box<VmmAction>,
@@ -199,13 +203,15 @@ impl ApiServer {
         response
     }
 
+    #[log_instrument::instrument]
     /// An HTTP response which also includes a body.
     pub(crate) fn json_response<T: Into<String> + Debug>(status: StatusCode, body: T) -> Response {
         let mut response = Response::new(Version::Http11, status);
         response.set_body(Body::new(body.into()));
         response
     }
 
+    #[log_instrument::instrument]
     fn json_fault_message<T: AsRef<str> + serde::Serialize + Debug>(msg: T) -> String {
         json!({ "fault_message": msg }).to_string()
     }

src/api_server/src/parsed_request.rs

@@ -41,13 +41,15 @@ pub(crate) struct ParsingInfo {
 }
 
 impl ParsingInfo {
+    #[log_instrument::instrument]
     pub fn append_deprecation_message(&mut self, message: &str) {
         match self.deprecation_message.as_mut() {
             None => self.deprecation_message = Some(message.to_owned()),
             Some(s) => (*s).push_str(message),
         }
     }
 
+    #[log_instrument::instrument]
     pub fn take_deprecation_message(&mut self) -> Option<String> {
         self.deprecation_message.take()
     }
@@ -61,6 +63,7 @@ pub(crate) struct ParsedRequest {
 
 impl TryFrom<&Request> for ParsedRequest {
     type Error = Error;
+    #[log_instrument::instrument]
     fn try_from(request: &Request) -> Result<Self, Self::Error> {
         let request_uri = request.uri().get_abs_path().to_string();
         log_received_api_request(describe(
@@ -121,21 +124,25 @@ impl TryFrom<&Request> for ParsedRequest {
 }
 
 impl ParsedRequest {
+    #[log_instrument::instrument]
     pub(crate) fn new(action: RequestAction) -> Self {
         Self {
             action,
             parsing_info: Default::default(),
         }
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn into_parts(self) -> (RequestAction, ParsingInfo) {
         (self.action, self.parsing_info)
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn parsing_info(&mut self) -> &mut ParsingInfo {
         &mut self.parsing_info
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn success_response_with_data<T>(body_data: &T) -> Response
     where
         T: ?Sized + Serialize + Debug,
@@ -146,6 +153,7 @@ impl ParsedRequest {
         response
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn success_response_with_mmds_value(body_data: &Value) -> Response {
         info!("The request was executed successfully. Status code: 200 OK.");
         let mut response = Response::new(Version::Http11, StatusCode::OK);
@@ -157,6 +165,7 @@ impl ParsedRequest {
         response
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn convert_to_response(
         request_outcome: &std::result::Result<VmmData, VmmActionError>,
     ) -> Response {
@@ -205,12 +214,14 @@ impl ParsedRequest {
         }
     }
 
+    #[log_instrument::instrument]
     /// Helper function to avoid boiler-plate code.
     pub(crate) fn new_sync(vmm_action: VmmAction) -> ParsedRequest {
         ParsedRequest::new(RequestAction::Sync(Box::new(vmm_action)))
     }
 }
 
+#[log_instrument::instrument]
 /// Helper function for writing the received API requests to the log.
 ///
 /// The `info` macro is used for logging.
@@ -219,6 +230,7 @@ fn log_received_api_request(api_description: String) {
     info!("The API server received a {}.", api_description);
 }
 
+#[log_instrument::instrument]
 /// Helper function for metric-logging purposes on API requests.
 ///
 /// # Arguments
@@ -246,6 +258,7 @@ fn describe(method: Method, path: &str, body: Option<&Body>) -> String {
     }
 }
 
+#[log_instrument::instrument]
 fn describe_with_body(method: Method, path: &str, payload_value: &Body) -> String {
     format!(
         "{:?} request on {:?} with body {:?}",
@@ -257,6 +270,7 @@ fn describe_with_body(method: Method, path: &str, payload_value: &Body) -> Strin
     )
 }
 
+#[log_instrument::instrument]
 /// Generates a `GenericError` for each request method.
 pub(crate) fn method_to_error(method: Method) -> Result<ParsedRequest, Error> {
     match method {
@@ -296,6 +310,7 @@ pub(crate) enum Error {
 
 // It's convenient to turn errors into HTTP responses directly.
 impl From<Error> for Response {
+    #[log_instrument::instrument]
     fn from(err: Error) -> Self {
         let msg = ApiServer::json_fault_message(format!("{}", err));
         match err {
@@ -309,6 +324,7 @@ impl From<Error> for Response {
 }
 
 // This function is supposed to do id validation for requests.
+#[log_instrument::instrument]
 pub(crate) fn checked_id(id: &str) -> Result<&str, Error> {
     // todo: are there any checks we want to do on id's?
     // not allow them to be empty strings maybe?
@@ -341,6 +357,7 @@ pub mod tests {
     use super::*;
 
     impl PartialEq for ParsedRequest {
+        #[log_instrument::instrument]
         fn eq(&self, other: &ParsedRequest) -> bool {
             if self.parsing_info.deprecation_message != other.parsing_info.deprecation_message {
                 return false;
@@ -355,13 +372,15 @@ pub mod tests {
         }
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn vmm_action_from_request(req: ParsedRequest) -> VmmAction {
         match req.action {
             RequestAction::Sync(vmm_action) => *vmm_action,
             _ => panic!("Invalid request"),
         }
     }
 
+    #[log_instrument::instrument]
     pub(crate) fn depr_action_from_req(req: ParsedRequest, msg: Option<String>) -> VmmAction {
         let (action_req, mut parsing_info) = req.into_parts();
         match action_req {
@@ -375,6 +394,7 @@ pub mod tests {
         }
     }
 
+    #[log_instrument::instrument]
     fn http_response(body: &str, status_code: i32) -> String {
         let header = format!(
             "HTTP/1.1 {} \r\nServer: Firecracker API\r\nConnection: keep-alive\r\n",
@@ -394,6 +414,7 @@ pub mod tests {
         }
     }
 
+    #[log_instrument::instrument]
     fn http_request(request_type: &str, endpoint: &str, body: Option<&str>) -> String {
         let req_no_body = format!(
             "{} {} HTTP/1.1\r\nContent-Type: application/json\r\n",

src/api_server/src/request/actions.rs

@@ -28,6 +28,7 @@ struct ActionBody {
     action_type: ActionType,
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_actions(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.actions_count.inc();
     let action_body = serde_json::from_slice::<ActionBody>(body.raw()).map_err(|err| {

src/api_server/src/request/balloon.rs

@@ -10,6 +10,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_get_balloon(path_second_token: Option<&str>) -> Result<ParsedRequest, Error> {
     match path_second_token {
         Some(stats_path) => match stats_path {
@@ -23,12 +24,14 @@ pub(crate) fn parse_get_balloon(path_second_token: Option<&str>) -> Result<Parse
     }
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_balloon(body: &Body) -> Result<ParsedRequest, Error> {
     Ok(ParsedRequest::new_sync(VmmAction::SetBalloonDevice(
         serde_json::from_slice::<BalloonDeviceConfig>(body.raw())?,
     )))
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_balloon(
     body: &Body,
     path_second_token: Option<&str>,

src/api_server/src/request/boot_source.rs

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_boot_source(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.boot_source_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::ConfigureBootSource(

src/api_server/src/request/cpu_configuration.rs

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_cpu_config(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.cpu_cfg_count.inc();
 

src/api_server/src/request/drive.rs

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{checked_id, Error, ParsedRequest};
 use crate::request::{Body, StatusCode};
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_drive(
     body: &Body,
     id_from_path: Option<&str>,
@@ -38,6 +39,7 @@ pub(crate) fn parse_put_drive(
     }
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_drive(
     body: &Body,
     id_from_path: Option<&str>,

src/api_server/src/request/entropy.rs

@@ -7,6 +7,7 @@ use vmm::vmm_config::entropy::EntropyDeviceConfig;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_entropy(body: &Body) -> Result<ParsedRequest, Error> {
     let cfg = serde_json::from_slice::<EntropyDeviceConfig>(body.raw())?;
     Ok(ParsedRequest::new_sync(VmmAction::SetEntropyDevice(cfg)))

src/api_server/src/request/instance_info.rs

@@ -6,6 +6,7 @@ use vmm::rpc_interface::VmmAction;
 
 use crate::parsed_request::{Error, ParsedRequest};
 
+#[log_instrument::instrument]
 pub(crate) fn parse_get_instance_info() -> Result<ParsedRequest, Error> {
     METRICS.get_api_requests.instance_info_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::GetVmInstanceInfo))

src/api_server/src/request/logger.rs

@@ -7,6 +7,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_logger(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.logger_count.inc();
     let res = serde_json::from_slice::<LoggerConfig>(body.raw());

src/api_server/src/request/machine_configuration.rs

@@ -8,11 +8,13 @@ use super::super::VmmAction;
 use crate::parsed_request::{method_to_error, Error, ParsedRequest};
 use crate::request::{Body, Method};
 
+#[log_instrument::instrument]
 pub(crate) fn parse_get_machine_config() -> Result<ParsedRequest, Error> {
     METRICS.get_api_requests.machine_cfg_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::GetVmMachineConfig))
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_machine_config(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.machine_cfg_count.inc();
     let config = serde_json::from_slice::<MachineConfig>(body.raw()).map_err(|err| {
@@ -27,6 +29,7 @@ pub(crate) fn parse_put_machine_config(body: &Body) -> Result<ParsedRequest, Err
     )))
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_machine_config(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.patch_api_requests.machine_cfg_count.inc();
     let config_update =

src/api_server/src/request/metrics.rs

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_metrics(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.put_api_requests.metrics_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::ConfigureMetrics(

src/api_server/src/request/mmds.rs

@@ -10,11 +10,13 @@ use vmm::vmm_config::mmds::MmdsConfig;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[log_instrument::instrument]
 pub(crate) fn parse_get_mmds() -> Result<ParsedRequest, Error> {
     METRICS.get_api_requests.mmds_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::GetMMDS))
 }
 
+#[log_instrument::instrument]
 fn parse_put_mmds_config(body: &Body) -> Result<ParsedRequest, Error> {
     let config: MmdsConfig = serde_json::from_slice(body.raw()).map_err(|err| {
         METRICS.put_api_requests.mmds_fails.inc();
@@ -35,6 +37,7 @@ fn parse_put_mmds_config(body: &Body) -> Result<ParsedRequest, Error> {
     Ok(parsed_request)
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_mmds(
     body: &Body,
     path_second_token: Option<&str>,
@@ -58,6 +61,7 @@ pub(crate) fn parse_put_mmds(
     }
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_mmds(body: &Body) -> Result<ParsedRequest, Error> {
     METRICS.patch_api_requests.mmds_count.inc();
     Ok(ParsedRequest::new_sync(VmmAction::PatchMMDS(

src/api_server/src/request/net.rs

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{checked_id, Error, ParsedRequest};
 use crate::request::{Body, StatusCode};
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_net(
     body: &Body,
     id_from_path: Option<&str>,
@@ -40,6 +41,7 @@ pub(crate) fn parse_put_net(
     )))
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_net(
     body: &Body,
     id_from_path: Option<&str>,

src/api_server/src/request/snapshot.rs

@@ -22,6 +22,7 @@ pub const MISSING_FIELD: &str =
 pub const TOO_MANY_FIELDS: &str =
     "too many fields: either `mem_backend` or `mem_file_path` exclusively is required";
 
+#[log_instrument::instrument]
 pub(crate) fn parse_put_snapshot(
     body: &Body,
     request_type_from_path: Option<&str>,
@@ -44,6 +45,7 @@ pub(crate) fn parse_put_snapshot(
     }
 }
 
+#[log_instrument::instrument]
 pub(crate) fn parse_patch_vm_state(body: &Body) -> Result<ParsedRequest, Error> {
     let vm = serde_json::from_slice::<Vm>(body.raw())?;
 
@@ -53,6 +55,7 @@ pub(crate) fn parse_patch_vm_state(body: &Body) -> Result<ParsedRequest, Error>
     }
 }
 
+#[log_instrument::instrument]
 fn parse_put_snapshot_load(body: &Body) -> Result<ParsedRequest, Error> {
     let snapshot_config = serde_json::from_slice::<LoadSnapshotConfig>(body.raw())?;