Skip to content

Commit

Permalink
fix(csi/controller): increase info level logging
Browse files Browse the repository at this point in the history 
This will trace most requests and their completions as info.

Signed-off-by: Tiago Castro <[email protected]>
  • Loading branch information
@tiagolobocastro
tiagolobocastro committed Dec 4, 2024
1 parent e03a827 commit aaf7d3c
Show file tree
Hide file tree
Showing 3 changed files with 94 additions and 54 deletions.
99 changes: 45 additions & 54 deletions control-plane/csi-driver/src/bin/controller/controller.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -254,9 +254,25 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<CreateVolumeRequest>,
) -> Result<tonic::Response<CreateVolumeResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(request = ?args);

let _permit = self.create_volume_permit().await?;

// k8s uses names pvc-{uuid} and we use uuid further as ID in SPDK so we
// must require it.
let re = Regex::new(VOLUME_NAME_PATTERN).unwrap();
let volume_uuid = match re.captures(&args.name) {
Some(captures) => captures.get(1).unwrap().as_str().to_string(),
None => {
return Err(Status::invalid_argument(format!(
"Expected the volume name in pvc-<UUID> format: {}",
args.name
)))
}
};
tracing::Span::current().record("volume.uuid", volume_uuid.as_str());

let req = csi_driver::trace::CsiRequest::new_info("Create Volume");

let volume_content_source = if let Some(source) = &args.volume_content_source {
match &source.r#type {
Some(Type::Snapshot(snapshot_source)) => {
Expand Down Expand Up @@ -284,20 +300,6 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
None
};

// k8s uses names pvc-{uuid} and we use uuid further as ID in SPDK so we
// must require it.
let re = Regex::new(VOLUME_NAME_PATTERN).unwrap();
let volume_uuid = match re.captures(&args.name) {
Some(captures) => captures.get(1).unwrap().as_str().to_string(),
None => {
return Err(Status::invalid_argument(format!(
"Expected the volume name in pvc-<UUID> format: {}",
args.name
)))
}
};
tracing::Span::current().record("volume.uuid", volume_uuid.as_str());

check_volume_capabilities(&args.volume_capabilities)?;

// Check volume size.
Expand Down Expand Up @@ -342,8 +344,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
Ok(volume) => {
check_existing_volume(&volume, replica_count, size, thin)?;
debug!(
"Volume {} already exists and is compatible with requested config",
volume_uuid
"Volume {volume_uuid} already exists and is compatible with requested config"
);
}
// If the volume doesn't exist, create it.
Expand Down Expand Up @@ -412,6 +413,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
accessible_topology: vt_mapper.volume_accessible_topology(),
};

req.info_ok();
Ok(Response::new(CreateVolumeResponse {
volume: Some(volume),
}))
Expand All @@ -422,21 +424,22 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<DeleteVolumeRequest>,
) -> Result<tonic::Response<DeleteVolumeResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(volume.uuid = %args.volume_id, request = ?args);
let req = csi_driver::trace::CsiRequest::new_info("Delete Volume");
let volume_uuid = Uuid::parse_str(&args.volume_id).map_err(|_e| {
Status::invalid_argument(format!("Malformed volume UUID: {}", args.volume_id))
})?;
let _guard = csi_driver::limiter::VolumeOpGuard::new(volume_uuid)?;
RestApiClient::get_client()
.delete_volume(&volume_uuid)
.await
.map_err(|e| {
.map_err(|error| {
Status::internal(format!(
"Failed to delete volume {}, error = {:?}",
args.volume_id, e
"Failed to delete volume {}, error = {error:?}",
args.volume_id
))
})?;

req.info_ok();
Ok(Response::new(DeleteVolumeResponse {}))
}

Expand All @@ -446,7 +449,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<ControllerPublishVolumeRequest>,
) -> Result<tonic::Response<ControllerPublishVolumeResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(volume.uuid = %args.volume_id, request = ?args);
let req = csi_driver::trace::CsiRequest::new_info("Publish Volume");
if args.readonly {
return Err(Status::invalid_argument(
"Read-only volumes are not supported",
Expand Down Expand Up @@ -489,8 +492,8 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
Some(target) => {
if target.protocol != Some(protocol) {
let m = format!(
"Volume {} already shared via different protocol: {:?}",
volume_id, target.protocol,
"Volume {volume_id} already shared via different protocol: {:?}",
target.protocol,
);
error!("{}", m);
return Err(Status::failed_precondition(m));
Expand Down Expand Up @@ -548,10 +551,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
.await?;

if let Some((node, uri)) = get_volume_share_location(&v) {
debug!(
"Volume {} successfully published on node {} via {}",
volume_id, node, uri
);
debug!("Volume {volume_id} successfully published on node {node} via {uri}");
uri
} else {
let m = format!(
Expand All @@ -565,22 +565,18 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {

publish_context.insert("uri".to_string(), uri);

debug!(
"Publish context for volume {}: {:?}",
volume_id, publish_context
);
tracing::info!(?publish_context, "{}", req.log_str());
Ok(Response::new(ControllerPublishVolumeResponse {
publish_context,
}))
}

#[instrument(err, fields(volume.uuid = %request.get_ref().volume_id), skip(self))]
async fn controller_unpublish_volume(
&self,
request: tonic::Request<ControllerUnpublishVolumeRequest>,
) -> Result<tonic::Response<ControllerUnpublishVolumeResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(volume.uuid = %args.volume_id, request = ?args);
let req = csi_driver::trace::CsiRequest::new_info("Unpublish Volume");

let volume_uuid = Uuid::parse_str(&args.volume_id).map_err(|_e| {
Status::invalid_argument(format!("Malformed volume UUID: {}", args.volume_id))
Expand Down Expand Up @@ -619,7 +615,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
)),
})?;

debug!("Volume {} successfully unpublished", args.volume_id);
req.info_ok();
Ok(Response::new(ControllerUnpublishVolumeResponse {}))
}

Expand All @@ -629,9 +625,8 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<ValidateVolumeCapabilitiesRequest>,
) -> Result<tonic::Response<ValidateVolumeCapabilitiesResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(volume.uuid = %args.volume_id, request = ?args);
let _ = csi_driver::trace::CsiRequest::new_dbg("Validate Volume Capabilities");

debug!("Request to validate volume capabilities: {:?}", args);
let volume_uuid = Uuid::parse_str(&args.volume_id).map_err(|_e| {
Status::invalid_argument(format!("Malformed volume UUID: {}", args.volume_id))
})?;
Expand Down Expand Up @@ -681,8 +676,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<ListVolumesRequest>,
) -> Result<tonic::Response<ListVolumesResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(request = ?args);

let req = csi_driver::trace::CsiRequest::new_trace("List Volumes");
let max_entries = args.max_entries;
if max_entries < 0 {
return Err(Status::invalid_argument("max_entries can't be negative"));
Expand Down Expand Up @@ -714,8 +708,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
})
.collect();

debug!("Available k8s volumes: {:?}", entries);

tracing::trace!(?entries, "{}", req.log_str());
Ok(Response::new(ListVolumesResponse {
entries,
next_token: volumes.next_token.map_or("".to_string(), |v| v.to_string()),
Expand All @@ -728,7 +721,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<GetCapacityRequest>,
) -> Result<tonic::Response<GetCapacityResponse>, tonic::Status> {
let args = request.into_inner();
tracing::trace!(request = ?args);
let _ = csi_driver::trace::CsiRequest::new_trace("Get Node(s) Capacity");

// Check capabilities.
check_volume_capabilities(&args.volume_capabilities)?;
Expand All @@ -741,7 +734,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
};

let pools: Vec<Pool> = if let Some(node) = node {
debug!("Calculating pool capacity for node {}", node);
debug!("Calculating pool capacity for node {node}");
RestApiClient::get_client()
.get_node_pools(node)
.await
Expand All @@ -755,9 +748,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
RestApiClient::get_client()
.list_pools()
.await
.map_err(|e| {
Status::internal(format!("Failed to list all pools, error = {e:?}",))
})?
.map_err(|e| Status::internal(format!("Failed to list all pools, error = {e:?}")))?
};

let available_capacity: i64 = pools.into_iter().fold(0, |acc, p| match p.state {
Expand Down Expand Up @@ -814,7 +805,6 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
request: tonic::Request<CreateSnapshotRequest>,
) -> Result<tonic::Response<CreateSnapshotResponse>, tonic::Status> {
let request = request.into_inner();
tracing::trace!(volume.uuid = %request.source_volume_id, snapshot.uuid = %request.name, ?request);

let volume_uuid = Uuid::parse_str(&request.source_volume_id).map_err(|_e| {
Status::invalid_argument(format!(
Expand All @@ -839,6 +829,8 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
let snap_uuid = Uuid::parse_str(&snapshot_uuid_str).map_err(|_e| {
Status::invalid_argument(format!("Malformed snapshot ID: {}", request.name))
})?;

let req = csi_driver::trace::CsiRequest::new_info("Create Snapshot");
let create_params = CreateSnapshotParams::try_from(&request.parameters)?;

// Get the volume object. Extract the app node endpoint if quiesce is requested.
Expand Down Expand Up @@ -915,6 +907,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
snapshot_creation_result
}?;

req.info_ok();
Ok(tonic::Response::new(CreateSnapshotResponse {
snapshot: Some(snapshot_to_csi(snapshot)),
}))
Expand All @@ -925,8 +918,8 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
&self,
request: tonic::Request<DeleteSnapshotRequest>,
) -> Result<tonic::Response<DeleteSnapshotResponse>, tonic::Status> {
let req = csi_driver::trace::CsiRequest::new_info("Delete Snapshot");
let args = request.into_inner();
tracing::trace!(snapshot.uuid = %args.snapshot_id, ?args);

let snapshot_uuid = Uuid::parse_str(&args.snapshot_id).map_err(|_e| {
Status::invalid_argument(format!("Malformed snapshot UUID: {}", args.snapshot_id))
Expand All @@ -942,6 +935,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
))
})?;

req.info_ok();
Ok(Response::new(DeleteSnapshotResponse {}))
}

Expand Down Expand Up @@ -985,13 +979,13 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
}))
}

#[instrument(err, skip(self))]
#[instrument(err, fields(volume.uuid = request.get_ref().volume_id), skip(self))]
async fn controller_expand_volume(
&self,
request: Request<ControllerExpandVolumeRequest>,
) -> Result<Response<ControllerExpandVolumeResponse>, Status> {
let args = request.into_inner();
trace!(volume.uuid = %args.volume_id, request = ?args);
let req = csi_driver::trace::CsiRequest::new_info("Expand Volume");

let vol_uuid = Uuid::parse_str(&args.volume_id).map_err(|error| {
Status::invalid_argument(format!(
Expand Down Expand Up @@ -1039,10 +1033,7 @@ impl rpc::csi::controller_server::Controller for CsiControllerSvc {
error => Status::from(error),
})?;

debug!(
size_bytes = requested_size,
"Expansion succeeded for volume {vol_uuid}"
);
tracing::info!(size_bytes = requested_size, "{}", req.log_str());
Ok(tonic::Response::new(ControllerExpandVolumeResponse {
capacity_bytes: vol.spec.size as i64,
node_expansion_required,
Expand Down
2 changes: 2 additions & 0 deletions control-plane/csi-driver/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -71,3 +71,5 @@ pub mod limiter;
/// Contains tools to advertise the same set of capabilities across different
/// CSI microservices.
pub mod plugin_capabilities;
/// Request Tracing.
pub mod trace;
47 changes: 47 additions & 0 deletions control-plane/csi-driver/src/trace.rs
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,47 @@
/// A csi request which can be traced.
pub struct CsiRequest<'a> {
request: &'a str,
start: std::time::Instant,
}

impl<'a> CsiRequest<'a> {
/// Add new request and info trace it.
pub fn new_info(request: &'a str) -> Self {
tracing::info!("[ CSI ] {request} Request started");

Self::new(request)
}
/// Add new request and debug trace it.
pub fn new_dbg(request: &'a str) -> Self {
tracing::debug!("[ CSI ] {request} Request started");

Self::new(request)
}
/// Add new request and trace trace it.
pub fn new_trace(request: &'a str) -> Self {
tracing::trace!("[ CSI ] {request} Request started");

Self::new(request)
}

fn new(request: &'a str) -> Self {
Self {
request,
start: std::time::Instant::now(),
}
}

/// Get completion log message.
pub fn log_str(self) -> String {
format!(
"[ CSI ] {} Request completed successfully after {:?}",
self.request,
self.start.elapsed()
)
}

/// Log completion info.
pub fn info_ok(self) {
tracing::info!("{}", self.log_str())
}
}

0 comments on commit aaf7d3c

Please sign in to comment.