df08e45 · vibebox · git.iko.soy

git.iko.soy/vibebox

on main help sign in

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

df08e45robcholz8 months ago

src/config.rs+1−1

compare with main

unifiedsplit

@@ -279,6 +279,6 @@ fn validate_or_exit(config: &Config) {

279}

280

281fn die(message: &str) -> ! {

282− eprintln!("[vibebox] {message}");

282+ tracing::error!("{message}");

283 std::process::exit(1);

284}

src/instance.rs+55−29

@@ -26,7 +26,7 @@ use crate::{

26};

28const SSH_KEY_NAME: &str = "ssh_key";

29−pub(crate) const SERIAL_LOG_NAME: &str = "serial.log";

29+pub(crate) const VM_ROOT_LOG_NAME: &str = "vm_root.log";

30pub(crate) const DEFAULT_SSH_USER: &str = "vibecoder";

31const SSH_CONNECT_RETRIES: usize = 30;

32const SSH_CONNECT_DELAY_MS: u64 = 500;

@@ -118,7 +118,7 @@ pub(crate) fn ensure_ssh_keypair(

118 "vibebox",

119 ])

120 .stdin(Stdio::null())

121− .stdout(Stdio::null())

121+ .stdout(Stdio::inherit())

122 .stderr(Stdio::inherit())

123 .status()?;

124

@@ -246,6 +246,8 @@ fn wait_for_vm_ipv4(

246 timeout: Duration,

247) -> Result<(), Box<dyn std::error::Error>> {

248 let start = Instant::now();

249+ let mut next_log_at = start + Duration::from_secs(10);

250+ tracing::debug!("waiting for vm ipv4");

249 loop {

251 loop {

250 let config = load_or_create_instance_config(instance_dir)?;

252 let config = load_or_create_instance_config(instance_dir)?;

251 if config.vm_ipv4.is_some() {

253 if config.vm_ipv4.is_some() {

@@ -254,8 +256,10 @@ fn wait_for_vm_ipv4(

254 if start.elapsed() > timeout {

256 if start.elapsed() > timeout {

255 return Err("Timed out waiting for VM IPv4".into());

257 return Err("Timed out waiting for VM IPv4".into());

256 }

258 }

259+ if Instant::now() >= next_log_at {

257− if start.elapsed().as_secs() % 5 == 0 {

260+ let waited = start.elapsed();

258− tracing::debug!("still waiting for vm ipv4");

261+ tracing::debug!("still waiting for vm ipv4, {}s elapsed", waited.as_secs(),);

262+ next_log_at += Duration::from_secs(10);

259 }

263 }

260 thread::sleep(Duration::from_millis(200));

264 thread::sleep(Duration::from_millis(200));

261 }

265 }

@@ -270,9 +274,13 @@ fn run_ssh_session(

270 loop {

274 loop {

271 attempts += 1;

275 attempts += 1;

272 if !ssh_port_open(&ip) {

276 if !ssh_port_open(&ip) {

273− tracing::debug!(attempts, "ssh port not open yet");

277+ tracing::debug!(attempts, "ssh port doesn't open yet");

274− eprintln!(

278+ tracing::info!(

279+ attempts,

280+ ip = %ip,

281+ "waiting for ssh port ({}/{})",

282+ attempts,

275− "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"

283+ SSH_CONNECT_RETRIES

276 );

284 );

277 if attempts >= SSH_CONNECT_RETRIES {

285 if attempts >= SSH_CONNECT_RETRIES {

278 return Err(

286 return Err(

@@ -283,10 +291,14 @@ fn run_ssh_session(

283 continue;

291 continue;

284 }

292 }

285

293

286− eprintln!(

294+ tracing::info!(

295+ attempts,

296+ user = %ssh_user,

297+ ip = %ip,

298+ "starting ssh ({}/{})",

299+ attempts,

287− "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"

300+ SSH_CONNECT_RETRIES

288 );

301 );

289− tracing::info!(attempts, user = %ssh_user, ip = %ip, "starting ssh");

290 let status = Command::new("ssh")

302 let status = Command::new("ssh")

291 .args([

303 .args([

292 "-i",

304 "-i",

@@ -319,21 +331,22 @@ fn run_ssh_session(

319

331

320 match status {

332 match status {

321 Ok(status) if status.success() => {

333 Ok(status) if status.success() => {

322− eprintln!("[vibebox] ssh exited with status: {status}");

334+ tracing::info!(status = %status, "ssh exited");

323 break;

335 break;

324 }

336 }

325 Ok(status) if status.code() == Some(255) => {

337 Ok(status) if status.code() == Some(255) => {

326− eprintln!("[vibebox] ssh connection failed: {status}");

338+ tracing::warn!(status = %status, "ssh connection failed");

327 if attempts >= SSH_CONNECT_RETRIES {

339 if attempts >= SSH_CONNECT_RETRIES {

328 return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into());

340 return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into());

329 }

341 }

330 thread::sleep(Duration::from_millis(500));

342 thread::sleep(Duration::from_millis(500));

331 }

343 }

332 Ok(status) => {

344 Ok(status) => {

333− eprintln!("[vibebox] ssh exited with status: {status}");

345+ tracing::info!(status = %status, "ssh exited");

334 break;

346 break;

335 }

347 }

336 Err(err) => {

348 Err(err) => {

349+ tracing::error!(error = %err, "failed to start ssh");

337 return Err(format!("failed to start ssh: {err}").into());

350 return Err(format!("failed to start ssh: {err}").into());

338 }

351 }

339 }

352 }

@@ -404,7 +417,7 @@ fn spawn_ssh_io(

404) -> vm::IoContext {

417) -> vm::IoContext {

405 let io_control = vm::IoControl::new();

418 let io_control = vm::IoControl::new();

406

419

407− let log_path = instance_dir.join(SERIAL_LOG_NAME);

420+ let log_path = instance_dir.join(VM_ROOT_LOG_NAME);

408 let log_file = fs::OpenOptions::new()

421 let log_file = fs::OpenOptions::new()

409 .create(true)

422 .create(true)

410 .write(true)

423 .write(true)

@@ -458,7 +471,7 @@ fn spawn_ssh_io(

458 if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) {

471 if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) {

459 cfg.vm_ipv4 = Some(ip.clone());

472 cfg.vm_ipv4 = Some(ip.clone());

460 let _ = write_instance_config(&instance_path, &cfg);

473 let _ = write_instance_config(&instance_path, &cfg);

461− eprintln!("[vibebox] detected vm IPv4: {ip}");

474+ tracing::info!(ip = %ip, "detected vm ipv4");

462 }

475 }

463 }

476 }

464 }

477 }

@@ -466,7 +479,7 @@ fn spawn_ssh_io(

466

479

467 if cleaned.contains("VIBEBOX_SSH_READY") {

480 if cleaned.contains("VIBEBOX_SSH_READY") {

468 ssh_ready_for_output.store(true, Ordering::SeqCst);

481 ssh_ready_for_output.store(true, Ordering::SeqCst);

469− eprintln!("[vibebox] sshd ready");

482+ tracing::info!("sshd ready");

470 }

483 }

471 }

484 }

472 };

485 };

@@ -517,7 +530,7 @@ fn spawn_ssh_io(

517 break;

530 break;

518 }

531 }

519

532

520− eprintln!("[vibebox] starting ssh to {ssh_user}@{ip}");

533+ tracing::info!(user = %ssh_user, ip = %ip, "starting ssh");

521 io_control_for_thread.request_terminal_restore();

534 io_control_for_thread.request_terminal_restore();

522 io_control_for_thread.set_forward_output(false);

535 io_control_for_thread.set_forward_output(false);

523 io_control_for_thread.set_forward_input(false);

536 io_control_for_thread.set_forward_input(false);

@@ -527,13 +540,19 @@ fn spawn_ssh_io(

527 loop {

540 loop {

528 attempts += 1;

541 attempts += 1;

529 if !ssh_port_open(&ip) {

542 if !ssh_port_open(&ip) {

530− eprintln!(

543+ tracing::info!(

544+ attempts,

545+ ip = %ip,

546+ "waiting for ssh port ({}/{})",

547+ attempts,

531− "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"

548+ SSH_CONNECT_RETRIES

532 );

549 );

533 if attempts >= SSH_CONNECT_RETRIES {

550 if attempts >= SSH_CONNECT_RETRIES {

534 ssh_connected_for_thread.store(false, Ordering::SeqCst);

551 ssh_connected_for_thread.store(false, Ordering::SeqCst);

535− eprintln!(

552+ tracing::warn!(

553+ attempts,

536− "[vibebox] ssh port not ready after {SSH_CONNECT_RETRIES} attempts"

554+ "ssh port not ready after {} attempts",

555+ SSH_CONNECT_RETRIES

537 );

556 );

538 break;

557 break;

539 }

558 }

@@ -541,8 +560,13 @@ fn spawn_ssh_io(

541 continue;

560 continue;

542 }

561 }

543

562

544− eprintln!(

563+ tracing::info!(

564+ attempts,

565+ user = %ssh_user,

566+ ip = %ip,

567+ "starting ssh ({}/{})",

568+ attempts,

545− "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"

569+ SSH_CONNECT_RETRIES

546 );

570 );

547 let status = Command::new("ssh")

571 let status = Command::new("ssh")

548 .args([

572 .args([

@@ -577,18 +601,20 @@ fn spawn_ssh_io(

577 match status {

601 match status {

578 Ok(status) if status.success() => {

602 Ok(status) if status.success() => {

579 ssh_connected_for_thread.store(false, Ordering::SeqCst);

603 ssh_connected_for_thread.store(false, Ordering::SeqCst);

580− eprintln!("[vibebox] ssh exited with status: {status}");

604+ tracing::info!(status = %status, "ssh exited");

581 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {

605 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {

582 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));

606 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));

583 }

607 }

584 break;

608 break;

585 }

609 }

586 Ok(status) if status.code() == Some(255) => {

610 Ok(status) if status.code() == Some(255) => {

587− eprintln!("[vibebox] ssh connection failed: {status}");

611+ tracing::warn!(status = %status, "ssh connection failed");

588 if attempts >= SSH_CONNECT_RETRIES {

612 if attempts >= SSH_CONNECT_RETRIES {

589 ssh_connected_for_thread.store(false, Ordering::SeqCst);

613 ssh_connected_for_thread.store(false, Ordering::SeqCst);

590− eprintln!(

614+ tracing::warn!(

615+ attempts,

591− "[vibebox] ssh failed after {SSH_CONNECT_RETRIES} attempts"

616+ "ssh failed after {} attempts",

617+ SSH_CONNECT_RETRIES

592 );

618 );

593 break;

619 break;

594 }

620 }

@@ -597,7 +623,7 @@ fn spawn_ssh_io(

597 }

623 }

598 Ok(status) => {

624 Ok(status) => {

599 ssh_connected_for_thread.store(false, Ordering::SeqCst);

625 ssh_connected_for_thread.store(false, Ordering::SeqCst);

600− eprintln!("[vibebox] ssh exited with status: {status}");

626+ tracing::info!(status = %status, "ssh exited");

601 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {

627 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {

602 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));

628 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));

603 }

629 }

@@ -605,7 +631,7 @@ fn spawn_ssh_io(

605 }

631 }

606 Err(err) => {

632 Err(err) => {

607 ssh_connected_for_thread.store(false, Ordering::SeqCst);

633 ssh_connected_for_thread.store(false, Ordering::SeqCst);

608− eprintln!("[vibebox] failed to start ssh: {err}");

634+ tracing::error!(error = %err, "failed to start ssh");

609 break;

635 break;

610 }

636 }

611 }

637 }

src/vm.rs+10−10

@@ -429,7 +429,7 @@ fn ensure_base_image(

429 if !base_compressed.exists()

430 || std::fs::metadata(base_compressed).map(|m| m.len())? < DEBIAN_COMPRESSED_SIZE_BYTES

431 {

432− println!("Downloading base image...");

432+ tracing::info!("downloading base image");

433 let status = Command::new("curl")

434 .args([

435 "--continue-at",

@@ -470,7 +470,7 @@ fn ensure_base_image(

470 }

471 }

472

473− println!("Decompressing base image...");

473+ tracing::info!("decompressing base image");

474 let status = Command::new("tar")

475 .args([

476 "-xOf",

@@ -499,7 +499,7 @@ fn ensure_default_image(

499

500 ensure_base_image(base_raw, base_compressed)?;

501

502− println!("Configuring base image...");

502+ tracing::info!("configuring base image");

503 fs::copy(base_raw, default_raw)?;

504

505 let provision_command = script_command_from_content(PROVISION_SCRIPT_NAME, PROVISION_SCRIPT)?;

@@ -522,7 +522,7 @@ fn ensure_instance_disk(

522 return Ok(());

523 }

524

525− println!("Creating instance disk from {}...", template_raw.display());

525+ tracing::info!(path = %template_raw.display(), "creating instance disk");

526 std::fs::create_dir_all(instance_raw.parent().unwrap())?;

527 fs::copy(template_raw, instance_raw)?;

528 Ok(())

@@ -961,7 +961,7 @@ fn spawn_login_actions_thread(

961 let command = match script_command_from_path(&path, index) {

962 Ok(command) => command,

963 Err(err) => {

964− eprintln!("{err}");

964+ tracing::error!(error = %err, "failed to build login script command");

965 return;

966 }

967 };

@@ -1042,7 +1042,7 @@ where

1042 return Err("Timed out waiting for VM to start".into());

1043 }

1044

1045− println!("VM booting...");

1045+ tracing::info!("vm booting");

1046

1047 let output_monitor = Arc::new(OutputMonitor::default());

1048 let io_ctx = io_handler(output_monitor.clone(), we_read_from, we_write_to);

@@ -1111,7 +1111,7 @@ where

1111 unsafe {

1112 if vm.canRequestStop() {

1113 if let Err(err) = vm.requestStopWithError() {

1114− eprintln!("Failed to request VM stop: {:?}", err);

1114+ tracing::error!(error = ?err, "failed to request VM stop");

1115 }

1116 } else if vm.canStop() {

1117 let handler = RcBlock::new(|_error: *mut NSError| {});

@@ -1249,15 +1249,15 @@ pub fn ensure_signed() {

1249 match status {

1250 Ok(s) if s.success() => {

1251 let err = Command::new(&exe).args(std::env::args_os().skip(1)).exec();

1252− eprintln!("failed to re-exec after signing: {err}");

1252+ tracing::error!(error = %err, "failed to re-exec after signing");

1253 std::process::exit(1);

1254 }

1255 Ok(s) => {

1256− eprintln!("codesign failed with status: {s}");

1256+ tracing::error!(status = %s, "codesign failed");

1257 std::process::exit(1);

1258 }

1259 Err(e) => {

1260− eprintln!("failed to run codesign: {e}");

1260+ tracing::error!(error = %e, "failed to run codesign");

1261 std::process::exit(1);

1262 }

1263 }

src/vm_manager.rs+2−2

@@ -17,7 +17,7 @@ use std::{

18use crate::{

19 config::CONFIG_PATH_ENV,

20− instance::SERIAL_LOG_NAME,

20+ instance::VM_ROOT_LOG_NAME,

21 instance::{

22 DEFAULT_SSH_USER, InstanceConfig, build_ssh_login_actions, ensure_instance_dir,

23 ensure_ssh_keypair, extract_ipv4, load_or_create_instance_config, write_instance_config,

@@ -451,7 +451,7 @@ fn spawn_manager_io(

451 vm_output_fd: std::os::unix::io::OwnedFd,

452 vm_input_fd: std::os::unix::io::OwnedFd,

453) -> vm::IoContext {

454− let log_path = instance_dir.join(SERIAL_LOG_NAME);

454+ let log_path = instance_dir.join(VM_ROOT_LOG_NAME);

455 let log_file = fs::OpenOptions::new()

456 .create(true)

457 .write(true)