From df08e45fae2f0ebb7d9a873ec0968db6cb45c5da Mon Sep 17 00:00:00 2001 From: robcholz <84130577+robcholz@users.noreply.github.com> Date: Sat, 7 Feb 2026 17:47:29 -0500 Subject: [PATCH] refactor: now uses log for everything and changed serial.log to vm_root.log --- src/config.rs | 2 +- src/instance.rs | 84 +++++++++++++++++++++++++++++++---------------- src/vm.rs | 20 +++++------ src/vm_manager.rs | 4 +-- 4 files changed, 68 insertions(+), 42 deletions(-) diff --git a/src/config.rs b/src/config.rs index 1c00d9b..0688c92 100644 --- a/src/config.rs +++ b/src/config.rs @@ -279,6 +279,6 @@ fn validate_or_exit(config: &Config) { } fn die(message: &str) -> ! { - eprintln!("[vibebox] {message}"); + tracing::error!("{message}"); std::process::exit(1); } diff --git a/src/instance.rs b/src/instance.rs index a652a86..8dc137f 100644 --- a/src/instance.rs +++ b/src/instance.rs @@ -26,7 +26,7 @@ use crate::{ }; const SSH_KEY_NAME: &str = "ssh_key"; -pub(crate) const SERIAL_LOG_NAME: &str = "serial.log"; +pub(crate) const VM_ROOT_LOG_NAME: &str = "vm_root.log"; pub(crate) const DEFAULT_SSH_USER: &str = "vibecoder"; const SSH_CONNECT_RETRIES: usize = 30; const SSH_CONNECT_DELAY_MS: u64 = 500; @@ -118,7 +118,7 @@ pub(crate) fn ensure_ssh_keypair( "vibebox", ]) .stdin(Stdio::null()) - .stdout(Stdio::null()) + .stdout(Stdio::inherit()) .stderr(Stdio::inherit()) .status()?; @@ -246,6 +246,8 @@ fn wait_for_vm_ipv4( timeout: Duration, ) -> Result<(), Box> { let start = Instant::now(); + let mut next_log_at = start + Duration::from_secs(10); + tracing::debug!("waiting for vm ipv4"); loop { let config = load_or_create_instance_config(instance_dir)?; if config.vm_ipv4.is_some() { @@ -254,8 +256,10 @@ fn wait_for_vm_ipv4( if start.elapsed() > timeout { return Err("Timed out waiting for VM IPv4".into()); } - if start.elapsed().as_secs() % 5 == 0 { - tracing::debug!("still waiting for vm ipv4"); + if Instant::now() >= next_log_at { + let waited = start.elapsed(); + tracing::debug!("still waiting for vm ipv4, {}s elapsed", waited.as_secs(),); + next_log_at += Duration::from_secs(10); } thread::sleep(Duration::from_millis(200)); } @@ -270,9 +274,13 @@ fn run_ssh_session( loop { attempts += 1; if !ssh_port_open(&ip) { - tracing::debug!(attempts, "ssh port not open yet"); - eprintln!( - "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" + tracing::debug!(attempts, "ssh port doesn't open yet"); + tracing::info!( + attempts, + ip = %ip, + "waiting for ssh port ({}/{})", + attempts, + SSH_CONNECT_RETRIES ); if attempts >= SSH_CONNECT_RETRIES { return Err( @@ -283,10 +291,14 @@ fn run_ssh_session( continue; } - eprintln!( - "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" + tracing::info!( + attempts, + user = %ssh_user, + ip = %ip, + "starting ssh ({}/{})", + attempts, + SSH_CONNECT_RETRIES ); - tracing::info!(attempts, user = %ssh_user, ip = %ip, "starting ssh"); let status = Command::new("ssh") .args([ "-i", @@ -319,21 +331,22 @@ fn run_ssh_session( match status { Ok(status) if status.success() => { - eprintln!("[vibebox] ssh exited with status: {status}"); + tracing::info!(status = %status, "ssh exited"); break; } Ok(status) if status.code() == Some(255) => { - eprintln!("[vibebox] ssh connection failed: {status}"); + tracing::warn!(status = %status, "ssh connection failed"); if attempts >= SSH_CONNECT_RETRIES { return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into()); } thread::sleep(Duration::from_millis(500)); } Ok(status) => { - eprintln!("[vibebox] ssh exited with status: {status}"); + tracing::info!(status = %status, "ssh exited"); break; } Err(err) => { + tracing::error!(error = %err, "failed to start ssh"); return Err(format!("failed to start ssh: {err}").into()); } } @@ -404,7 +417,7 @@ fn spawn_ssh_io( ) -> vm::IoContext { let io_control = vm::IoControl::new(); - let log_path = instance_dir.join(SERIAL_LOG_NAME); + let log_path = instance_dir.join(VM_ROOT_LOG_NAME); let log_file = fs::OpenOptions::new() .create(true) .write(true) @@ -458,7 +471,7 @@ fn spawn_ssh_io( if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) { cfg.vm_ipv4 = Some(ip.clone()); let _ = write_instance_config(&instance_path, &cfg); - eprintln!("[vibebox] detected vm IPv4: {ip}"); + tracing::info!(ip = %ip, "detected vm ipv4"); } } } @@ -466,7 +479,7 @@ fn spawn_ssh_io( if cleaned.contains("VIBEBOX_SSH_READY") { ssh_ready_for_output.store(true, Ordering::SeqCst); - eprintln!("[vibebox] sshd ready"); + tracing::info!("sshd ready"); } } }; @@ -517,7 +530,7 @@ fn spawn_ssh_io( break; } - eprintln!("[vibebox] starting ssh to {ssh_user}@{ip}"); + tracing::info!(user = %ssh_user, ip = %ip, "starting ssh"); io_control_for_thread.request_terminal_restore(); io_control_for_thread.set_forward_output(false); io_control_for_thread.set_forward_input(false); @@ -527,13 +540,19 @@ fn spawn_ssh_io( loop { attempts += 1; if !ssh_port_open(&ip) { - eprintln!( - "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" + tracing::info!( + attempts, + ip = %ip, + "waiting for ssh port ({}/{})", + attempts, + SSH_CONNECT_RETRIES ); if attempts >= SSH_CONNECT_RETRIES { ssh_connected_for_thread.store(false, Ordering::SeqCst); - eprintln!( - "[vibebox] ssh port not ready after {SSH_CONNECT_RETRIES} attempts" + tracing::warn!( + attempts, + "ssh port not ready after {} attempts", + SSH_CONNECT_RETRIES ); break; } @@ -541,8 +560,13 @@ fn spawn_ssh_io( continue; } - eprintln!( - "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" + tracing::info!( + attempts, + user = %ssh_user, + ip = %ip, + "starting ssh ({}/{})", + attempts, + SSH_CONNECT_RETRIES ); let status = Command::new("ssh") .args([ @@ -577,18 +601,20 @@ fn spawn_ssh_io( match status { Ok(status) if status.success() => { ssh_connected_for_thread.store(false, Ordering::SeqCst); - eprintln!("[vibebox] ssh exited with status: {status}"); + tracing::info!(status = %status, "ssh exited"); if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() { let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec())); } break; } Ok(status) if status.code() == Some(255) => { - eprintln!("[vibebox] ssh connection failed: {status}"); + tracing::warn!(status = %status, "ssh connection failed"); if attempts >= SSH_CONNECT_RETRIES { ssh_connected_for_thread.store(false, Ordering::SeqCst); - eprintln!( - "[vibebox] ssh failed after {SSH_CONNECT_RETRIES} attempts" + tracing::warn!( + attempts, + "ssh failed after {} attempts", + SSH_CONNECT_RETRIES ); break; } @@ -597,7 +623,7 @@ fn spawn_ssh_io( } Ok(status) => { ssh_connected_for_thread.store(false, Ordering::SeqCst); - eprintln!("[vibebox] ssh exited with status: {status}"); + tracing::info!(status = %status, "ssh exited"); if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() { let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec())); } @@ -605,7 +631,7 @@ fn spawn_ssh_io( } Err(err) => { ssh_connected_for_thread.store(false, Ordering::SeqCst); - eprintln!("[vibebox] failed to start ssh: {err}"); + tracing::error!(error = %err, "failed to start ssh"); break; } } diff --git a/src/vm.rs b/src/vm.rs index 43207d3..3dce637 100644 --- a/src/vm.rs +++ b/src/vm.rs @@ -429,7 +429,7 @@ fn ensure_base_image( if !base_compressed.exists() || std::fs::metadata(base_compressed).map(|m| m.len())? < DEBIAN_COMPRESSED_SIZE_BYTES { - println!("Downloading base image..."); + tracing::info!("downloading base image"); let status = Command::new("curl") .args([ "--continue-at", @@ -470,7 +470,7 @@ fn ensure_base_image( } } - println!("Decompressing base image..."); + tracing::info!("decompressing base image"); let status = Command::new("tar") .args([ "-xOf", @@ -499,7 +499,7 @@ fn ensure_default_image( ensure_base_image(base_raw, base_compressed)?; - println!("Configuring base image..."); + tracing::info!("configuring base image"); fs::copy(base_raw, default_raw)?; let provision_command = script_command_from_content(PROVISION_SCRIPT_NAME, PROVISION_SCRIPT)?; @@ -522,7 +522,7 @@ fn ensure_instance_disk( return Ok(()); } - println!("Creating instance disk from {}...", template_raw.display()); + tracing::info!(path = %template_raw.display(), "creating instance disk"); std::fs::create_dir_all(instance_raw.parent().unwrap())?; fs::copy(template_raw, instance_raw)?; Ok(()) @@ -961,7 +961,7 @@ fn spawn_login_actions_thread( let command = match script_command_from_path(&path, index) { Ok(command) => command, Err(err) => { - eprintln!("{err}"); + tracing::error!(error = %err, "failed to build login script command"); return; } }; @@ -1042,7 +1042,7 @@ where return Err("Timed out waiting for VM to start".into()); } - println!("VM booting..."); + tracing::info!("vm booting"); let output_monitor = Arc::new(OutputMonitor::default()); let io_ctx = io_handler(output_monitor.clone(), we_read_from, we_write_to); @@ -1111,7 +1111,7 @@ where unsafe { if vm.canRequestStop() { if let Err(err) = vm.requestStopWithError() { - eprintln!("Failed to request VM stop: {:?}", err); + tracing::error!(error = ?err, "failed to request VM stop"); } } else if vm.canStop() { let handler = RcBlock::new(|_error: *mut NSError| {}); @@ -1249,15 +1249,15 @@ pub fn ensure_signed() { match status { Ok(s) if s.success() => { let err = Command::new(&exe).args(std::env::args_os().skip(1)).exec(); - eprintln!("failed to re-exec after signing: {err}"); + tracing::error!(error = %err, "failed to re-exec after signing"); std::process::exit(1); } Ok(s) => { - eprintln!("codesign failed with status: {s}"); + tracing::error!(status = %s, "codesign failed"); std::process::exit(1); } Err(e) => { - eprintln!("failed to run codesign: {e}"); + tracing::error!(error = %e, "failed to run codesign"); std::process::exit(1); } } diff --git a/src/vm_manager.rs b/src/vm_manager.rs index 079adb0..1d0f479 100644 --- a/src/vm_manager.rs +++ b/src/vm_manager.rs @@ -17,7 +17,7 @@ use std::{ use crate::{ config::CONFIG_PATH_ENV, - instance::SERIAL_LOG_NAME, + instance::VM_ROOT_LOG_NAME, instance::{ DEFAULT_SSH_USER, InstanceConfig, build_ssh_login_actions, ensure_instance_dir, ensure_ssh_keypair, extract_ipv4, load_or_create_instance_config, write_instance_config, @@ -451,7 +451,7 @@ fn spawn_manager_io( vm_output_fd: std::os::unix::io::OwnedFd, vm_input_fd: std::os::unix::io::OwnedFd, ) -> vm::IoContext { - let log_path = instance_dir.join(SERIAL_LOG_NAME); + let log_path = instance_dir.join(VM_ROOT_LOG_NAME); let log_file = fs::OpenOptions::new() .create(true) .write(true)