feat: Add code instrumentation

Adds code instrumentation. This opens support for tracing and
profiling via this instrumentation.

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

Author: Jonathan Woollett-Light

src/api_server/src/lib.rs

@@ -43,6 +43,10 @@ pub struct ApiServer {
 }
 
 impl ApiServer {
+    #[tracing::instrument(
+        level = "trace",
+        skip(api_request_sender, vmm_response_receiver, to_vmm_fd)
+    )]
     /// Constructor for `ApiServer`.
     ///
     /// Returns the newly formed `ApiServer`.
@@ -59,6 +63,10 @@ impl ApiServer {
         }
     }
 
+    #[tracing::instrument(
+        level = "trace",
+        skip(self, server, process_time_reporter, seccomp_filter, api_payload_limit)
+    )]
     /// Runs the Api Server.
     ///
     /// # Arguments
@@ -128,6 +136,7 @@ impl ApiServer {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(self, request, request_processing_start_us))]
     /// Handles an API request received through the associated socket.
     pub fn handle_request(
         &mut self,
@@ -158,6 +167,7 @@ impl ApiServer {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(self, vmm_action, request_processing_start_us))]
     fn serve_vmm_action_request(
         &mut self,
         vmm_action: Box<VmmAction>,
@@ -199,13 +209,15 @@ impl ApiServer {
         response
     }
 
+    #[tracing::instrument(level = "trace", skip(status, body))]
     /// 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
     }
 
+    #[tracing::instrument(level = "trace", skip(msg))]
     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 {
+    #[tracing::instrument(level = "trace", skip(self, message))]
     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),
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(self))]
     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;
+    #[tracing::instrument(level = "trace", skip(request))]
     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 {
+    #[tracing::instrument(level = "trace", skip(action))]
     pub(crate) fn new(action: RequestAction) -> Self {
         Self {
             action,
             parsing_info: Default::default(),
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn into_parts(self) -> (RequestAction, ParsingInfo) {
         (self.action, self.parsing_info)
     }
 
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn parsing_info(&mut self) -> &mut ParsingInfo {
         &mut self.parsing_info
     }
 
+    #[tracing::instrument(level = "trace", skip(body_data))]
     pub(crate) fn success_response_with_data<T>(body_data: &T) -> Response
     where
         T: ?Sized + Serialize + Debug,
@@ -146,6 +153,7 @@ impl ParsedRequest {
         response
     }
 
+    #[tracing::instrument(level = "trace", skip(body_data))]
     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
     }
 
+    #[tracing::instrument(level = "trace", skip(request_outcome))]
     pub(crate) fn convert_to_response(
         request_outcome: &std::result::Result<VmmData, VmmActionError>,
     ) -> Response {
@@ -205,12 +214,14 @@ impl ParsedRequest {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(vmm_action))]
     /// Helper function to avoid boiler-plate code.
     pub(crate) fn new_sync(vmm_action: VmmAction) -> ParsedRequest {
         ParsedRequest::new(RequestAction::Sync(Box::new(vmm_action)))
     }
 }
 
+#[tracing::instrument(level = "trace", skip(api_description))]
 /// 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);
 }
 
+#[tracing::instrument(level = "trace", skip(method, path, body))]
 /// Helper function for metric-logging purposes on API requests.
 ///
 /// # Arguments
@@ -246,6 +258,7 @@ fn describe(method: Method, path: &str, body: Option<&Body>) -> String {
     }
 }
 
+#[tracing::instrument(level = "trace", skip(method, path, payload_value))]
 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
     )
 }
 
+#[tracing::instrument(level = "trace", skip(method))]
 /// 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 {
+    #[tracing::instrument(level = "trace", skip(err))]
     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.
+#[tracing::instrument(level = "trace", skip(id))]
 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 {
+        #[tracing::instrument(level = "trace", skip(self, other))]
         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 {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(req))]
     pub(crate) fn vmm_action_from_request(req: ParsedRequest) -> VmmAction {
         match req.action {
             RequestAction::Sync(vmm_action) => *vmm_action,
             _ => panic!("Invalid request"),
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(req, msg))]
     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 {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(body, status_code))]
     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 {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip(request_type, endpoint, body))]
     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,
 }
 
+#[tracing::instrument(level = "trace", skip(body))]
 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;
 
+#[tracing::instrument(level = "trace", skip(path_second_token))]
 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
     }
 }
 
+#[tracing::instrument(level = "trace", skip(body))]
 pub(crate) fn parse_put_balloon(body: &Body) -> Result<ParsedRequest, Error> {
     Ok(ParsedRequest::new_sync(VmmAction::SetBalloonDevice(
         serde_json::from_slice::<BalloonDeviceConfig>(body.raw())?,
     )))
 }
 
+#[tracing::instrument(level = "trace", skip(body, path_second_token))]
 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;
 
+#[tracing::instrument(level = "trace", skip(body))]
 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;
 
+#[tracing::instrument(level = "trace", skip(body))]
 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};
 
+#[tracing::instrument(level = "trace", skip(body, id_from_path))]
 pub(crate) fn parse_put_drive(
     body: &Body,
     id_from_path: Option<&str>,
@@ -38,6 +39,7 @@ pub(crate) fn parse_put_drive(
     }
 }
 
+#[tracing::instrument(level = "trace", skip(body, id_from_path))]
 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;
 
+#[tracing::instrument(level = "trace", skip(body))]
 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};
 
+#[tracing::instrument(level = "trace", skip())]
 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

@@ -8,6 +8,7 @@ use super::super::VmmAction;
 use crate::parsed_request::{Error, ParsedRequest};
 use crate::request::Body;
 
+#[tracing::instrument(level = "trace", skip(body))]
 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());