@@ -26,7 +26,7 @@ use crate::{
2626};
2727
2828const 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";
3030pub(crate) const DEFAULT_SSH_USER: &str = "vibecoder";
3131const SSH_CONNECT_RETRIES: usize = 30;
3232const SSH_CONNECT_DELAY_MS: u64 = 500;
@@ -72,7 +72,6 @@ pub fn run_with_ssh(manager_conn: UnixStream) -> Result<(), Box<dyn std::error::
7272 tracing::debug!(ssh_user = %ssh_user, "loaded instance config");
7373
7474 let _manager_conn = manager_conn;
75− tracing::debug!("waiting for vm ipv4");
7675 wait_for_vm_ipv4(&instance_dir, Duration::from_secs(120))?;
7776
7877 let ip = load_or_create_instance_config(&instance_dir)?
@@ -118,7 +117,7 @@ pub(crate) fn ensure_ssh_keypair(
118117 "vibebox",
119118 ])
120119 .stdin(Stdio::null())
121− .stdout(Stdio::null())
120+ .stdout(Stdio::inherit())
122121 .stderr(Stdio::inherit())
123122 .status()?;
124123
@@ -246,6 +245,9 @@ fn wait_for_vm_ipv4(
246245 timeout: Duration,
247246) -> Result<(), Box<dyn std::error::Error>> {
248247 let start = Instant::now();
248+ let mut next_log_at = start + Duration::from_secs(10);
249+ tracing::info!("waiting for vm ipv4");
250+ let mut once_hint = false;
249251 loop {
250252 let config = load_or_create_instance_config(instance_dir)?;
251253 if config.vm_ipv4.is_some() {
@@ -254,8 +256,16 @@ fn wait_for_vm_ipv4(
254256 if start.elapsed() > timeout {
255257 return Err("Timed out waiting for VM IPv4".into());
256258 }
257− if start.elapsed().as_secs() % 5 == 0 {
258− tracing::debug!("still waiting for vm ipv4");
259+ if Instant::now() >= next_log_at {
260+ let waited = start.elapsed();
261+ if waited.as_secs() > 15 && !once_hint {
262+ tracing::info!(
263+ "if vibebox is just initialized in this directory, it might take up to 1 minutes depending on your machine, and then you can enjoy the speed vibecoding! go pack!"
264+ );
265+ once_hint = true;
266+ }
267+ tracing::info!("still waiting for vm ipv4, {}s elapsed", waited.as_secs(),);
268+ next_log_at += Duration::from_secs(10);
259269 }
260270 thread::sleep(Duration::from_millis(200));
261271 }
@@ -270,9 +280,13 @@ fn run_ssh_session(
270280 loop {
271281 attempts += 1;
272282 if !ssh_port_open(&ip) {
273− tracing::debug!(attempts, "ssh port not open yet");
274− eprintln!(
275− "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"
283+ tracing::debug!(attempts, "ssh port doesn't open yet");
284+ tracing::info!(
285+ attempts,
286+ ip = %ip,
287+ "waiting for ssh port ({}/{})",
288+ attempts,
289+ SSH_CONNECT_RETRIES
276290 );
277291 if attempts >= SSH_CONNECT_RETRIES {
278292 return Err(
@@ -283,10 +297,14 @@ fn run_ssh_session(
283297 continue;
284298 }
285299
286− eprintln!(
287− "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"
300+ tracing::info!(
301+ attempts,
302+ user = %ssh_user,
303+ ip = %ip,
304+ "starting ssh ({}/{})",
305+ attempts,
306+ SSH_CONNECT_RETRIES
288307 );
289− tracing::info!(attempts, user = %ssh_user, ip = %ip, "starting ssh");
290308 let status = Command::new("ssh")
291309 .args([
292310 "-i",
@@ -319,21 +337,22 @@ fn run_ssh_session(
319337
320338 match status {
321339 Ok(status) if status.success() => {
322− eprintln!("[vibebox] ssh exited with status: {status}");
340+ tracing::info!(status = %status, "ssh exited");
323341 break;
324342 }
325343 Ok(status) if status.code() == Some(255) => {
326− eprintln!("[vibebox] ssh connection failed: {status}");
344+ tracing::warn!(status = %status, "ssh connection failed");
327345 if attempts >= SSH_CONNECT_RETRIES {
328346 return Err(format!("ssh failed after {SSH_CONNECT_RETRIES} attempts").into());
329347 }
330348 thread::sleep(Duration::from_millis(500));
331349 }
332350 Ok(status) => {
333− eprintln!("[vibebox] ssh exited with status: {status}");
351+ tracing::info!(status = %status, "ssh exited");
334352 break;
335353 }
336354 Err(err) => {
355+ tracing::error!(error = %err, "failed to start ssh");
337356 return Err(format!("failed to start ssh: {err}").into());
338357 }
339358 }
@@ -404,7 +423,7 @@ fn spawn_ssh_io(
404423) -> vm::IoContext {
405424 let io_control = vm::IoControl::new();
406425
407− let log_path = instance_dir.join(SERIAL_LOG_NAME);
426+ let log_path = instance_dir.join(VM_ROOT_LOG_NAME);
408427 let log_file = fs::OpenOptions::new()
409428 .create(true)
410429 .write(true)
@@ -458,7 +477,7 @@ fn spawn_ssh_io(
458477 if cfg.vm_ipv4.as_deref() != Some(ip.as_str()) {
459478 cfg.vm_ipv4 = Some(ip.clone());
460479 let _ = write_instance_config(&instance_path, &cfg);
461− eprintln!("[vibebox] detected vm IPv4: {ip}");
480+ tracing::info!(ip = %ip, "detected vm ipv4");
462481 }
463482 }
464483 }
@@ -466,7 +485,7 @@ fn spawn_ssh_io(
466485
467486 if cleaned.contains("VIBEBOX_SSH_READY") {
468487 ssh_ready_for_output.store(true, Ordering::SeqCst);
469− eprintln!("[vibebox] sshd ready");
488+ tracing::info!("sshd ready");
470489 }
471490 }
472491 };
@@ -517,7 +536,7 @@ fn spawn_ssh_io(
517536 break;
518537 }
519538
520− eprintln!("[vibebox] starting ssh to {ssh_user}@{ip}");
539+ tracing::info!(user = %ssh_user, ip = %ip, "starting ssh");
521540 io_control_for_thread.request_terminal_restore();
522541 io_control_for_thread.set_forward_output(false);
523542 io_control_for_thread.set_forward_input(false);
@@ -527,13 +546,19 @@ fn spawn_ssh_io(
527546 loop {
528547 attempts += 1;
529548 if !ssh_port_open(&ip) {
530− eprintln!(
531− "[vibebox] waiting for ssh port on {ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"
549+ tracing::info!(
550+ attempts,
551+ ip = %ip,
552+ "waiting for ssh port ({}/{})",
553+ attempts,
554+ SSH_CONNECT_RETRIES
532555 );
533556 if attempts >= SSH_CONNECT_RETRIES {
534557 ssh_connected_for_thread.store(false, Ordering::SeqCst);
535− eprintln!(
536− "[vibebox] ssh port not ready after {SSH_CONNECT_RETRIES} attempts"
558+ tracing::warn!(
559+ attempts,
560+ "ssh port not ready after {} attempts",
561+ SSH_CONNECT_RETRIES
537562 );
538563 break;
539564 }
@@ -541,8 +566,13 @@ fn spawn_ssh_io(
541566 continue;
542567 }
543568
544− eprintln!(
545− "[vibebox] starting ssh to {ssh_user}@{ip} (attempt {attempts}/{SSH_CONNECT_RETRIES})"
569+ tracing::info!(
570+ attempts,
571+ user = %ssh_user,
572+ ip = %ip,
573+ "starting ssh ({}/{})",
574+ attempts,
575+ SSH_CONNECT_RETRIES
546576 );
547577 let status = Command::new("ssh")
548578 .args([
@@ -577,18 +607,20 @@ fn spawn_ssh_io(
577607 match status {
578608 Ok(status) if status.success() => {
579609 ssh_connected_for_thread.store(false, Ordering::SeqCst);
580− eprintln!("[vibebox] ssh exited with status: {status}");
610+ tracing::info!(status = %status, "ssh exited");
581611 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {
582612 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));
583613 }
584614 break;
585615 }
586616 Ok(status) if status.code() == Some(255) => {
587− eprintln!("[vibebox] ssh connection failed: {status}");
617+ tracing::warn!(status = %status, "ssh connection failed");
588618 if attempts >= SSH_CONNECT_RETRIES {
589619 ssh_connected_for_thread.store(false, Ordering::SeqCst);
590− eprintln!(
591− "[vibebox] ssh failed after {SSH_CONNECT_RETRIES} attempts"
620+ tracing::warn!(
621+ attempts,
622+ "ssh failed after {} attempts",
623+ SSH_CONNECT_RETRIES
592624 );
593625 break;
594626 }
@@ -597,7 +629,7 @@ fn spawn_ssh_io(
597629 }
598630 Ok(status) => {
599631 ssh_connected_for_thread.store(false, Ordering::SeqCst);
600− eprintln!("[vibebox] ssh exited with status: {status}");
632+ tracing::info!(status = %status, "ssh exited");
601633 if let Some(tx) = input_tx_holder_for_thread.lock().unwrap().clone() {
602634 let _ = tx.send(VmInput::Bytes(b"systemctl poweroff\n".to_vec()));
603635 }
@@ -605,7 +637,7 @@ fn spawn_ssh_io(
605637 }
606638 Err(err) => {
607639 ssh_connected_for_thread.store(false, Ordering::SeqCst);
608− eprintln!("[vibebox] failed to start ssh: {err}");
640+ tracing::error!(error = %err, "failed to start ssh");
609641 break;
610642 }
611643 }