Merge pull request #113 from Burning1020/debug-log

Change some log printing

Makefile

@@ -23,15 +23,15 @@ bin/vmm-task:
 	@mkdir -p bin && cp vmm/task/target/${ARCH}-unknown-linux-musl/release/vmm-task bin/vmm-task
 
 bin/vmlinux.bin:
-	@bash -x vmm/scripts/kernel/${HYPERVISOR}/build.sh ${KERNEL_VERSION}
+	@bash vmm/scripts/kernel/${HYPERVISOR}/build.sh ${KERNEL_VERSION}
 	@mkdir -p bin && cp vmm/scripts/kernel/${HYPERVISOR}/vmlinux.bin bin/vmlinux.bin && rm vmm/scripts/kernel/${HYPERVISOR}/vmlinux.bin
 
 bin/kuasar.img:
-	@bash -x vmm/scripts/image/${GUESTOS_IMAGE}/build.sh image
+	@bash vmm/scripts/image/${GUESTOS_IMAGE}/build.sh image
 	@mkdir -p bin && cp /tmp/kuasar.img bin/kuasar.img && rm /tmp/kuasar.img
 
 bin/kuasar.initrd:
-	@bash -x vmm/scripts/image/${GUESTOS_IMAGE}/build.sh initrd
+	@bash vmm/scripts/image/${GUESTOS_IMAGE}/build.sh initrd
 	@mkdir -p bin && cp /tmp/kuasar.initrd bin/kuasar.initrd && rm /tmp/kuasar.initrd
 
 bin/wasm-sandboxer:

vmm/sandbox/config_clh.toml

@@ -11,9 +11,11 @@ initrd_path = ""
 kernel_params = ""
 hugepages = false
 entropy_source = "/dev/urandom"
-debug = true
+debug = false
+
 [hypervisor.task]
 debug = false
+
 [hypervisor.virtiofsd]
 path = "/usr/local/bin/virtiofsd"
 log_level = "info"

vmm/sandbox/src/client.rs

@@ -253,20 +253,21 @@ pub(crate) async fn client_update_routes(
     Ok(())
 }
 
-pub(crate) async fn client_sync_clock(client: &SandboxServiceClient) {
+pub(crate) async fn client_sync_clock(client: &SandboxServiceClient, id: &str) {
+    let id = id.to_string();
     let client = client.clone();
     let tolerance_nanos = Duration::from_millis(TIME_DIFF_TOLERANCE_IN_MS).as_nanos() as i64;
     let clock_id = ClockId::from_raw(nix::libc::CLOCK_REALTIME);
     tokio::spawn(async move {
         loop {
             tokio::time::sleep(Duration::from_secs(TIME_SYNC_PERIOD)).await;
-            debug!("sync_clock: start sync clock from host to guest");
+            debug!("sync_clock {}: start sync clock from host to guest", id);
 
             let mut req = SyncClockPacket::new();
             match clock_gettime(clock_id) {
                 Ok(ts) => req.ClientSendTime = ts.num_nanoseconds(),
                 Err(e) => {
-                    warn!("failed to get current clock: {}", e);
+                    warn!("sync_clock {}: failed to get current clock: {}", id, e);
                     continue;
                 }
             }
@@ -278,7 +279,7 @@ pub(crate) async fn client_sync_clock(client: &SandboxServiceClient) {
                     match clock_gettime(clock_id) {
                         Ok(ts) => p.ServerArriveTime = ts.num_nanoseconds(),
                         Err(e) => {
-                            warn!("failed to get current clock: {}", e);
+                            warn!("sync_clock {}: failed to get current clock: {}", id, e);
                             continue;
                         }
                     }
@@ -290,12 +291,12 @@ pub(crate) async fn client_sync_clock(client: &SandboxServiceClient) {
                             .sync_clock(with_timeout(Duration::from_secs(1).as_nanos() as i64), &p)
                             .await
                         {
-                            error!("sync clock set delta failed: {:?}", e);
+                            error!("sync_clock {}: sync clock set delta failed: {:?}", id, e);
                         }
                     }
                 }
                 Err(e) => {
-                    error!("sync clock get error: {:?}", e);
+                    error!("sync_clock {}: get error: {:?}", id, e);
                 }
             }
         }

vmm/sandbox/src/cloud_hypervisor/mod.rs

@@ -19,7 +19,7 @@ use std::{os::unix::io::RawFd, process::Stdio};
 use anyhow::anyhow;
 use async_trait::async_trait;
 use containerd_sandbox::error::{Error, Result};
-use log::{debug, error};
+use log::{debug, error, info};
 use serde::{Deserialize, Serialize};
 use time::OffsetDateTime;
 use tokio::{
@@ -137,7 +137,7 @@ impl CloudHypervisorVM {
         let pid = child
             .id()
             .ok_or(anyhow!("the virtiofsd has been polled to completion"))?;
-        spawn_wait(child, "virtiofsd".to_string(), None, None);
+        spawn_wait(child, format!("virtiofsd {}", self.id), None, None);
         Ok(pid)
     }
 
@@ -150,7 +150,6 @@ impl CloudHypervisorVM {
 #[async_trait]
 impl VM for CloudHypervisorVM {
     async fn start(&mut self) -> Result<u32> {
-        debug!("start vm {}", self.id);
         create_dir_all(&self.base_dir).await?;
         let virtiofsd_pid = self.start_virtiofsd().await?;
         let mut params = self.config.to_cmdline_params("--");
@@ -170,7 +169,7 @@ impl VM for CloudHypervisorVM {
         set_cmd_netns(&mut cmd, self.netns.to_string())?;
         cmd.stdout(Stdio::piped());
         cmd.stderr(Stdio::piped());
-        debug!("start cloud hypervisor with cmdline: {:?}", cmd);
+        info!("start cloud hypervisor with cmdline: {:?}", cmd);
         let child = cmd
             .spawn()
             .map_err(|e| anyhow!("failed to spawn cloud hypervisor command: {}", e))?;
@@ -179,7 +178,7 @@ impl VM for CloudHypervisorVM {
         let (tx, rx) = tokio::sync::watch::channel((0u32, 0i128));
         spawn_wait(
             child,
-            "cloud-hypervisor".to_string(),
+            format!("cloud-hypervisor {}", self.id),
             Some(pid_file),
             Some(tx),
         );

vmm/sandbox/src/network/mod.rs

@@ -19,7 +19,7 @@ use std::{fmt::Debug, os::unix::prelude::AsRawFd, path::Path};
 use anyhow::anyhow;
 use containerd_sandbox::error::Result;
 use futures_util::TryStreamExt;
-use log::{debug, error, warn};
+use log::{debug, error, info, warn};
 use nix::{
     fcntl::OFlag,
     sched::{setns, CloneFlags},
@@ -48,8 +48,9 @@ pub struct Network {
 impl Network {
     pub async fn new(config: NetworkConfig) -> Result<Self> {
         debug!("create network with config: {:?}", config);
+        let sandbox_id = config.sandbox_id.to_string();
         let network = Self::new_from_netns(config).await?;
-        debug!("network: {:?}", &network);
+        info!("network for sandbox {}: {:?}", sandbox_id, &network);
         Ok(network)
     }
 

vmm/sandbox/src/sandbox.rs

@@ -544,7 +544,7 @@ where
     pub(crate) async fn sync_clock(&self) {
         let client_guard = self.client.lock().await;
         if let Some(client) = &*client_guard {
-            client_sync_clock(client).await;
+            client_sync_clock(client, self.id.as_str()).await;
         }
     }
 

vmm/sandbox/src/storage/mod.rs

@@ -53,7 +53,10 @@ where
         }
 
         let id = format!("storage{}", self.increment_and_get_id());
-        debug!("attach storage for mount {:?} with id {}", m, id);
+        debug!(
+            "attach storage to container {} for mount {:?} with id {}",
+            container_id, m, id
+        );
 
         if is_block_device(&*m.source).await? {
             self.handle_block_device(&id, container_id, m).await?;

vmm/sandbox/src/utils.rs

@@ -30,7 +30,7 @@ use containerd_sandbox::{
     data::SandboxData,
     error::{Error, Result},
 };
-use log::{debug, error};
+use log::{error, info};
 use nix::{
     fcntl::{open, OFlag},
     libc::{dup2, fcntl, kill, setns, FD_CLOEXEC, F_GETFD, F_SETFD},
@@ -96,7 +96,6 @@ pub fn get_dns_config(data: &SandboxData) -> Option<&DnsConfig> {
     data.config.as_ref().and_then(|c| c.dns_config.as_ref())
 }
 
-#[allow(dead_code)]
 pub fn get_total_resources(data: &SandboxData) -> Option<LinuxContainerResources> {
     return data
         .config
@@ -114,7 +113,6 @@ pub fn get_total_resources(data: &SandboxData) -> Option<LinuxContainerResources
         });
 }
 
-#[allow(dead_code)]
 fn merge_resources(
     resource1: &LinuxContainerResources,
     resource2: &LinuxContainerResources,
@@ -148,25 +146,29 @@ fn merge_resources(
         }
     }
 
-    // merge cpuset_cpus, if error happend, log and use resource1
+    // merge cpuset_cpus, if error happened, log and use resource1
     let cpuset_cpus = if let Ok(c) = merge_cpusets(&resource1.cpuset_cpus, &resource2.cpuset_cpus) {
         c
     } else {
-        error!(
-            "failed to merge cpusets {} with {}",
-            resource1.cpuset_cpus, resource2.cpuset_cpus
-        );
+        if !resource1.cpuset_cpus.is_empty() {
+            error!(
+                "failed to merge cpuset cpus {} with {}",
+                resource1.cpuset_cpus, resource2.cpuset_cpus
+            );
+        }
         resource1.cpuset_cpus.to_string()
     };
 
-    // merge cpuset_mems, if error happend, log and use resource1
+    // merge cpuset_mems, if error happened, log and use resource1
     let cpuset_mems = if let Ok(c) = merge_cpusets(&resource1.cpuset_mems, &resource2.cpuset_mems) {
         c
     } else {
-        error!(
-            "failed to merge cpuset mems {} with {}",
-            resource1.cpuset_mems, resource2.cpuset_mems
-        );
+        if !resource1.cpuset_mems.is_empty() {
+            error!(
+                "failed to merge cpuset mems {} with {}",
+                resource1.cpuset_mems, resource2.cpuset_mems
+            );
+        }
         resource1.cpuset_mems.to_string()
     };
 
@@ -189,7 +191,6 @@ fn merge_resources(
     }
 }
 
-#[allow(dead_code)]
 fn merge_cpusets(cpusets1: &str, cpusets2: &str) -> Result<String> {
     let cpuset1_parts = cpuset_parts(cpusets1)?;
     let cpuset2_parts = cpuset_parts(cpusets2)?;
@@ -217,7 +218,6 @@ fn merge_cpusets(cpusets1: &str, cpusets2: &str) -> Result<String> {
         .join(","))
 }
 
-#[allow(dead_code)]
 fn merge_cpuset(base: (u32, u32), delta: (u32, u32)) -> (u32, u32) {
     let (mut low, mut high) = base;
     if delta.1 < low {
@@ -235,7 +235,6 @@ fn merge_cpuset(base: (u32, u32), delta: (u32, u32)) -> (u32, u32) {
     (low, high)
 }
 
-#[allow(dead_code)]
 fn cpuset_intersect(cpuset1: (u32, u32), cpuset2: (u32, u32)) -> bool {
     if cpuset2.1 < cpuset1.0 {
         return false;
@@ -246,7 +245,6 @@ fn cpuset_intersect(cpuset1: (u32, u32), cpuset2: (u32, u32)) -> bool {
     true
 }
 
-#[allow(dead_code)]
 fn cpuset_parts(cpuset: &str) -> Result<Vec<(u32, u32)>> {
     let mut cpuset1_parts = vec![];
     let c1 = cpuset.split(',');
@@ -256,7 +254,6 @@ fn cpuset_parts(cpuset: &str) -> Result<Vec<(u32, u32)>> {
     Ok(cpuset1_parts)
 }
 
-#[allow(dead_code)]
 fn cpuset_one_part(cpuset: &str) -> Result<(u32, u32)> {
     let parts = cpuset.split('-').collect::<Vec<&str>>();
     let low = parts[0]
@@ -273,7 +270,6 @@ fn cpuset_one_part(cpuset: &str) -> Result<(u32, u32)> {
     Ok((low, high))
 }
 
-#[allow(dead_code)]
 pub fn cpuset_tostring(cpuset: (u32, u32)) -> String {
     if cpuset.0 == cpuset.1 {
         return cpuset.0.to_string();
@@ -417,7 +413,7 @@ pub async fn read_std<T: AsyncRead + Unpin>(std: T, prefix: &str) -> Result<()>
                 if c == 0 {
                     return Ok(());
                 }
-                debug!("{}: {}", prefix, line.trim());
+                info!("{}: {}", prefix, line.trim());
             }
             Err(e) => {
                 error!("failed to read {} log {}", prefix, e);
@@ -491,6 +487,7 @@ pub fn init_logger(level: &str) {
     let log_level = log::LevelFilter::from_str(level).unwrap_or(log::LevelFilter::Info);
     env_logger::Builder::from_default_env()
         .format_timestamp_micros()
-        .filter_level(log_level)
+        .filter_module("containerd_sandbox", log_level)
+        .filter_module("vmm_sandboxer", log_level)
         .init();
 }

vmm/scripts/image/centos/build.sh

@@ -68,7 +68,7 @@ containerd)
 		--mount type=bind,src="${ROOTFS_DIR}",dst=/tmp/kuasar-rootfs,options=rbind:rw \
 		${IMAGE_NAME} \
 		${container_name} \
-		bash -x /kuasar/vmm/scripts/image/centos/build_rootfs.sh
+		bash /kuasar/vmm/scripts/image/centos/build_rootfs.sh
 	fn_check_result $? "ctr run ${container_name} return error!"
 	;;
 docker)
@@ -80,7 +80,7 @@ docker)
 		-v "${REPO_DIR}":/kuasar \
 		-v "${ROOTFS_DIR}":"/tmp/kuasar-rootfs" \
 		${IMAGE_NAME} \
-		bash -x /kuasar/vmm/scripts/image/centos/build_rootfs.sh
+		bash /kuasar/vmm/scripts/image/centos/build_rootfs.sh
 	fn_check_result $? "docker run ${container_name} return error!"
 	;;
 isulad)
@@ -93,7 +93,7 @@ isulad)
 		-v "${REPO_DIR}":/kuasar \
 		-v "${ROOTFS_DIR}":"/tmp/kuasar-rootfs" \
 		${IMAGE_NAME} \
-		bash -x /kuasar/vmm/scripts/image/centos/build_rootfs.sh
+		bash /kuasar/vmm/scripts/image/centos/build_rootfs.sh
 	fn_check_result $? "isula run ${container_name} return error!"
 	;;
 *)
@@ -109,7 +109,7 @@ fi
 
 case "$1" in
 image)
-	bash -x ${REPO_DIR}/vmm/scripts/image/build_image.sh
+	bash ${REPO_DIR}/vmm/scripts/image/build_image.sh
 	fn_check_result $? "build image failed!"
 	;;
 initrd)

vmm/scripts/image/centos/build_rootfs.sh

@@ -15,6 +15,8 @@
 
 set -e
 
+[ -n "${DEBUG}" ] && set -x
+
 golang_version="1.20.5"
 cert_file_path="/kuasar/proxy.crt"
 ARCH=$(uname -m)