refactor: now uses log for everything and changed serial.log to vm_root.log

This commit is contained in:
robcholz
2026-02-07 17:47:29 -05:00
parent 402f37bae4
commit df08e45fae
4 changed files with 68 additions and 42 deletions
+1 -1
View File
@@ -279,6 +279,6 @@ fn validate_or_exit(config: &Config) {
} }
fn die(message: &str) -> ! { fn die(message: &str) -> ! {
eprintln!("[vibebox] {message}"); tracing::error!("{message}");
std::process::exit(1); std::process::exit(1);
} }
+55 -29
View File
@@ -26,7 +26,7 @@ use crate::{
}; };
const SSH_KEY_NAME: &str = "ssh_key"; 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"; pub(crate) const DEFAULT_SSH_USER: &str = "vibecoder";
const SSH_CONNECT_RETRIES: usize = 30; const SSH_CONNECT_RETRIES: usize = 30;
const SSH_CONNECT_DELAY_MS: u64 = 500; const SSH_CONNECT_DELAY_MS: u64 = 500;
@@ -118,7 +118,7 @@ pub(crate) fn ensure_ssh_keypair(
"vibebox", "vibebox",
]) ])
.stdin(Stdio::null()) .stdin(Stdio::null())
.stdout(Stdio::null()) .stdout(Stdio::inherit())
.stderr(Stdio::inherit()) .stderr(Stdio::inherit())
.status()?; .status()?;
@@ -246,6 +246,8 @@ fn wait_for_vm_ipv4(
timeout: Duration, timeout: Duration,
) -> Result<(), Box<dyn std::error::Error>> { ) -> Result<(), Box<dyn std::error::Error>> {
let start = Instant::now(); let start = Instant::now();
let mut next_log_at = start + Duration::from_secs(10);
tracing::debug!("waiting for vm ipv4");
loop { loop {
let config = load_or_create_instance_config(instance_dir)?; let config = load_or_create_instance_config(instance_dir)?;
if config.vm_ipv4.is_some() { if config.vm_ipv4.is_some() {
@@ -254,8 +256,10 @@ fn wait_for_vm_ipv4(
if start.elapsed() > timeout { if start.elapsed() > timeout {
return Err("Timed out waiting for VM IPv4".into()); return Err("Timed out waiting for VM IPv4".into());
} }
if start.elapsed().as_secs() % 5 == 0 { if Instant::now() >= next_log_at {
tracing::debug!("still waiting for vm ipv4"); 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)); thread::sleep(Duration::from_millis(200));
} }
@@ -270,9 +274,13 @@ fn run_ssh_session(
loop { loop {
attempts += 1; attempts += 1;
if !ssh_port_open(&ip) { if !ssh_port_open(&ip) {
tracing::debug!(attempts, "ssh port not open yet"); tracing::debug!(attempts, "ssh port doesn't open yet");
eprintln!( tracing::info!(
"[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" attempts,
ip = %ip,
"waiting for ssh port ({}/{})",
attempts,
SSH_CONNECT_RETRIES
); );
if attempts >= SSH_CONNECT_RETRIES { if attempts >= SSH_CONNECT_RETRIES {
return Err( return Err(
@@ -283,10 +291,14 @@ fn run_ssh_session(
continue; continue;
} }
eprintln!( tracing::info!(
"[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" 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") let status = Command::new("ssh")
.args([ .args([
"-i", "-i",
@@ -319,21 +331,22 @@ fn run_ssh_session(
match status { match status {
Ok(status) if status.success() => { Ok(status) if status.success() => {
eprintln!("[vibebox] ssh exited with status: {status}"); tracing::info!(status = %status, "ssh exited");
break; break;
} }
Ok(status) if status.code() == Some(255) => { 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 { if attempts >= SSH_CONNECT_RETRIES {
return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into()); return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into());
} }
thread::sleep(Duration::from_millis(500)); thread::sleep(Duration::from_millis(500));
} }
Ok(status) => { Ok(status) => {
eprintln!("[vibebox] ssh exited with status: {status}"); tracing::info!(status = %status, "ssh exited");
break; break;
} }
Err(err) => { Err(err) => {
tracing::error!(error = %err, "failed to start ssh");
return Err(format!("failed to start ssh: {err}").into()); return Err(format!("failed to start ssh: {err}").into());
} }
} }
@@ -404,7 +417,7 @@ fn spawn_ssh_io(
) -> vm::IoContext { ) -> vm::IoContext {
let io_control = vm::IoControl::new(); 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() let log_file = fs::OpenOptions::new()
.create(true) .create(true)
.write(true) .write(true)
@@ -458,7 +471,7 @@ fn spawn_ssh_io(
if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) { if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) {
cfg.vm_ipv4 = Some(ip.clone()); cfg.vm_ipv4 = Some(ip.clone());
let _ = write_instance_config(&instance_path, &cfg); 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") { if cleaned.contains("VIBEBOX_SSH_READY") {
ssh_ready_for_output.store(true, Ordering::SeqCst); 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; 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.request_terminal_restore();
io_control_for_thread.set_forward_output(false); io_control_for_thread.set_forward_output(false);
io_control_for_thread.set_forward_input(false); io_control_for_thread.set_forward_input(false);
@@ -527,13 +540,19 @@ fn spawn_ssh_io(
loop { loop {
attempts += 1; attempts += 1;
if !ssh_port_open(&ip) { if !ssh_port_open(&ip) {
eprintln!( tracing::info!(
"[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" attempts,
ip = %ip,
"waiting for ssh port ({}/{})",
attempts,
SSH_CONNECT_RETRIES
); );
if attempts >= SSH_CONNECT_RETRIES { if attempts >= SSH_CONNECT_RETRIES {
ssh_connected_for_thread.store(false, Ordering::SeqCst); ssh_connected_for_thread.store(false, Ordering::SeqCst);
eprintln!( tracing::warn!(
"[vibebox] ssh port not ready after {SSH_CONNECT_RETRIES} attempts" attempts,
"ssh port not ready after {} attempts",
SSH_CONNECT_RETRIES
); );
break; break;
} }
@@ -541,8 +560,13 @@ fn spawn_ssh_io(
continue; continue;
} }
eprintln!( tracing::info!(
"[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})" attempts,
user = %ssh_user,
ip = %ip,
"starting ssh ({}/{})",
attempts,
SSH_CONNECT_RETRIES
); );
let status = Command::new("ssh") let status = Command::new("ssh")
.args([ .args([
@@ -577,18 +601,20 @@ fn spawn_ssh_io(
match status { match status {
Ok(status) if status.success() => { Ok(status) if status.success() => {
ssh_connected_for_thread.store(false, Ordering::SeqCst); 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() { if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {
let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec())); let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));
} }
break; break;
} }
Ok(status) if status.code() == Some(255) => { 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 { if attempts >= SSH_CONNECT_RETRIES {
ssh_connected_for_thread.store(false, Ordering::SeqCst); ssh_connected_for_thread.store(false, Ordering::SeqCst);
eprintln!( tracing::warn!(
"[vibebox] ssh failed after {SSH_CONNECT_RETRIES} attempts" attempts,
"ssh failed after {} attempts",
SSH_CONNECT_RETRIES
); );
break; break;
} }
@@ -597,7 +623,7 @@ fn spawn_ssh_io(
} }
Ok(status) => { Ok(status) => {
ssh_connected_for_thread.store(false, Ordering::SeqCst); 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() { if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {
let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec())); let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));
} }
@@ -605,7 +631,7 @@ fn spawn_ssh_io(
} }
Err(err) => { Err(err) => {
ssh_connected_for_thread.store(false, Ordering::SeqCst); ssh_connected_for_thread.store(false, Ordering::SeqCst);
eprintln!("[vibebox] failed to start ssh: {err}"); tracing::error!(error = %err, "failed to start ssh");
break; break;
} }
} }
+10 -10
View File
@@ -429,7 +429,7 @@ fn ensure_base_image(
if !base_compressed.exists() if !base_compressed.exists()
|| std::fs::metadata(base_compressed).map(|m| m.len())? < DEBIAN_COMPRESSED_SIZE_BYTES || 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") let status = Command::new("curl")
.args([ .args([
"--continue-at", "--continue-at",
@@ -470,7 +470,7 @@ fn ensure_base_image(
} }
} }
println!("Decompressing base image..."); tracing::info!("decompressing base image");
let status = Command::new("tar") let status = Command::new("tar")
.args([ .args([
"-xOf", "-xOf",
@@ -499,7 +499,7 @@ fn ensure_default_image(
ensure_base_image(base_raw, base_compressed)?; ensure_base_image(base_raw, base_compressed)?;
println!("Configuring base image..."); tracing::info!("configuring base image");
fs::copy(base_raw, default_raw)?; fs::copy(base_raw, default_raw)?;
let provision_command = script_command_from_content(PROVISION_SCRIPT_NAME, PROVISION_SCRIPT)?; let provision_command = script_command_from_content(PROVISION_SCRIPT_NAME, PROVISION_SCRIPT)?;
@@ -522,7 +522,7 @@ fn ensure_instance_disk(
return Ok(()); 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())?; std::fs::create_dir_all(instance_raw.parent().unwrap())?;
fs::copy(template_raw, instance_raw)?; fs::copy(template_raw, instance_raw)?;
Ok(()) Ok(())
@@ -961,7 +961,7 @@ fn spawn_login_actions_thread(
let command = match script_command_from_path(&path, index) { let command = match script_command_from_path(&path, index) {
Ok(command) => command, Ok(command) => command,
Err(err) => { Err(err) => {
eprintln!("{err}"); tracing::error!(error = %err, "failed to build login script command");
return; return;
} }
}; };
@@ -1042,7 +1042,7 @@ where
return Err("Timed out waiting for VM to start".into()); 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 output_monitor = Arc::new(OutputMonitor::default());
let io_ctx = io_handler(output_monitor.clone(), we_read_from, we_write_to); let io_ctx = io_handler(output_monitor.clone(), we_read_from, we_write_to);
@@ -1111,7 +1111,7 @@ where
unsafe { unsafe {
if vm.canRequestStop() { if vm.canRequestStop() {
if let Err(err) = vm.requestStopWithError() { 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() { } else if vm.canStop() {
let handler = RcBlock::new(|_error: *mut NSError| {}); let handler = RcBlock::new(|_error: *mut NSError| {});
@@ -1249,15 +1249,15 @@ pub fn ensure_signed() {
match status { match status {
Ok(s) if s.success() => { Ok(s) if s.success() => {
let err = Command::new(&exe).args(std::env::args_os().skip(1)).exec(); 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); std::process::exit(1);
} }
Ok(s) => { Ok(s) => {
eprintln!("codesign failed with status: {s}"); tracing::error!(status = %s, "codesign failed");
std::process::exit(1); std::process::exit(1);
} }
Err(e) => { Err(e) => {
eprintln!("failed to run codesign: {e}"); tracing::error!(error = %e, "failed to run codesign");
std::process::exit(1); std::process::exit(1);
} }
} }
+2 -2
View File
@@ -17,7 +17,7 @@ use std::{
use crate::{ use crate::{
config::CONFIG_PATH_ENV, config::CONFIG_PATH_ENV,
instance::SERIAL_LOG_NAME, instance::VM_ROOT_LOG_NAME,
instance::{ instance::{
DEFAULT_SSH_USER, InstanceConfig, build_ssh_login_actions, ensure_instance_dir, DEFAULT_SSH_USER, InstanceConfig, build_ssh_login_actions, ensure_instance_dir,
ensure_ssh_keypair, extract_ipv4, load_or_create_instance_config, write_instance_config, 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_output_fd: std::os::unix::io::OwnedFd,
vm_input_fd: std::os::unix::io::OwnedFd, vm_input_fd: std::os::unix::io::OwnedFd,
) -> vm::IoContext { ) -> 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() let log_file = fs::OpenOptions::new()
.create(true) .create(true)
.write(true) .write(true)