fix: tracing::instrument

Adds function instrumentation.

Signed-off-by: Jonathan Woollett-Light <jcawl@amazon.co.uk>

Author: Jonathan Woollett-Light

src/api_server/src/lib.rs

@@ -61,6 +61,11 @@ impl ApiServer {
     /// Constructor for `ApiServer`.
     ///
     /// Returns the newly formed `ApiServer`.
+    #[tracing::instrument(
+        level = "debug",
+        ret(skip),
+        skip(api_request_sender, vmm_response_receiver, to_vmm_fd)
+    )]
     pub fn new(
         api_request_sender: mpsc::Sender<ApiRequest>,
         vmm_response_receiver: mpsc::Receiver<ApiResponse>,
@@ -145,6 +150,18 @@ impl ApiServer {
     /// let mut buf: [u8; 100] = [0; 100];
     /// assert!(sock.read(&mut buf[..]).unwrap() > 0);
     /// ```
+    #[tracing::instrument(
+        level = "debug",
+        ret(skip),
+        skip(
+            self,
+            path,
+            process_time_reporter,
+            seccomp_filter,
+            api_payload_limit,
+            socket_ready
+        )
+    )]
     pub fn bind_and_run(
         &mut self,
         path: &PathBuf,
@@ -221,6 +238,11 @@ impl ApiServer {
     }
 
     /// Handles an API request received through the associated socket.
+    #[tracing::instrument(
+        level = "debug",
+        ret(skip),
+        skip(self, request, request_processing_start_us)
+    )]
     pub fn handle_request(
         &mut self,
         request: &Request,
@@ -250,6 +272,11 @@ impl ApiServer {
         }
     }
 
+    #[tracing::instrument(
+        level = "debug",
+        ret(skip),
+        skip(self, vmm_action, request_processing_start_us)
+    )]
     fn serve_vmm_action_request(
         &mut self,
         vmm_action: Box<VmmAction>,
@@ -292,12 +319,14 @@ impl ApiServer {
     }
 
     /// An HTTP response which also includes a body.
+    #[tracing::instrument(level = "debug", ret(skip), skip(status, 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), skip(action))]
     pub(crate) fn new(action: RequestAction) -> Self {
         Self {
             action,
             parsing_info: Default::default(),
         }
     }
 
+    #[tracing::instrument(level = "debug", ret(skip), skip(self))]
     pub(crate) fn into_parts(self) -> (RequestAction, ParsingInfo) {
         (self.action, self.parsing_info)
     }
 
+    #[tracing::instrument(level = "debug", skip(self))]
     pub(crate) fn parsing_info(&mut self) -> &mut ParsingInfo {
         &mut self.parsing_info
     }
 
+    #[tracing::instrument(level = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), skip(request_outcome))]
     pub(crate) fn convert_to_response(
         request_outcome: &std::result::Result<VmmData, VmmActionError>,
     ) -> Response {
@@ -206,6 +215,7 @@ impl ParsedRequest {
     }
 
     /// Helper function to avoid boiler-plate code.
+    #[tracing::instrument(level = "debug", ret(skip), skip(vmm_action))]
     pub(crate) fn new_sync(vmm_action: VmmAction) -> ParsedRequest {
         ParsedRequest::new(RequestAction::Sync(Box::new(vmm_action)))
     }
@@ -215,6 +225,7 @@ impl ParsedRequest {
 ///
 /// The `info` macro is used for logging.
 #[inline]
+#[tracing::instrument(level = "debug", ret(skip), skip(api_description))]
 fn log_received_api_request(api_description: String) {
     info!("The API server received a {}.", api_description);
 }
@@ -226,6 +237,7 @@ fn log_received_api_request(api_description: String) {
 /// * `method` - one of `GET`, `PATCH`, `PUT`
 /// * `path` - path of the API request
 /// * `body` - body of the API request
+#[tracing::instrument(level = "debug", ret(skip), skip(method, path, body))]
 fn describe(method: Method, path: &str, body: Option<&Body>) -> String {
     match (path, body) {
         ("/mmds", Some(_)) | (_, None) => format!("{:?} request on {:?}", method, path),
@@ -234,6 +246,7 @@ fn describe(method: Method, path: &str, body: Option<&Body>) -> String {
     }
 }
 
+#[tracing::instrument(level = "debug", ret(skip), skip(method, path, payload_value))]
 fn describe_with_body(method: Method, path: &str, payload_value: &Body) -> String {
     format!(
         "{:?} request on {:?} with body {:?}",
@@ -246,6 +259,7 @@ fn describe_with_body(method: Method, path: &str, payload_value: &Body) -> Strin
 }
 
 /// Generates a `GenericError` for each request method.
+#[tracing::instrument(level = "debug", ret(skip), skip(method))]
 pub(crate) fn method_to_error(method: Method) -> Result<ParsedRequest, Error> {
     match method {
         Method::Get => Err(Error::Generic(
@@ -284,6 +298,7 @@ pub(crate) enum Error {
 
 // It's convenient to turn errors into HTTP responses directly.
 impl From<Error> for Response {
+    #[tracing::instrument(level = "debug", ret(skip), skip(err))]
     fn from(err: Error) -> Self {
         let msg = ApiServer::json_fault_message(format!("{}", err));
         match err {
@@ -297,6 +312,7 @@ impl From<Error> for Response {
 }
 
 // This function is supposed to do id validation for requests.
+#[tracing::instrument(level = "debug", ret(skip), 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?
@@ -329,6 +345,7 @@ pub mod tests {
     use super::*;
 
     impl PartialEq for ParsedRequest {
+        #[tracing::instrument(level = "debug", ret(skip), skip(self, other))]
         fn eq(&self, other: &ParsedRequest) -> bool {
             if self.parsing_info.deprecation_message != other.parsing_info.deprecation_message {
                 return false;
@@ -343,13 +360,15 @@ pub mod tests {
         }
     }
 
+    #[tracing::instrument(level = "debug", ret(skip), 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 = "debug", ret(skip), 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 {
@@ -363,6 +382,7 @@ pub mod tests {
         }
     }
 
+    #[tracing::instrument(level = "debug", ret(skip), 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",
@@ -382,6 +402,7 @@ pub mod tests {
         }
     }
 
+    #[tracing::instrument(level = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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 = "debug", ret(skip), 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());