diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 664169ae..50d62846 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -23,7 +23,7 @@ jobs: sudo apt-get update sudo apt-get install -y libbpf-dev libbpfcc-dev clang llvm - uses: Swatinem/rust-cache@v2 - - uses: dtolnay/rust-toolchain@stable + - uses: dtolnay/rust-toolchain@1.95.0 with: components: rustfmt clippy - run: cargo fmt --all -- --check -l @@ -31,7 +31,7 @@ jobs: run: cargo clippy -- -D warnings - name: cargo-audit run: | - cargo install cargo-audit + cargo install cargo-audit --locked cargo-audit audit win_lint: @@ -39,7 +39,7 @@ jobs: steps: - uses: actions/checkout@v4 - uses: Swatinem/rust-cache@v2 - - uses: dtolnay/rust-toolchain@stable + - uses: dtolnay/rust-toolchain@1.95.0 with: components: rustfmt clippy - run: cargo fmt --all -- --check -l @@ -47,7 +47,7 @@ jobs: run: cargo clippy -- -D warnings - name: cargo-audit run: | - cargo install cargo-audit + cargo install cargo-audit --locked cargo-audit audit build: diff --git a/proxy_agent/src/common/helpers.rs b/proxy_agent/src/common/helpers.rs index 518555cd..0469773c 100644 --- a/proxy_agent/src/common/helpers.rs +++ b/proxy_agent/src/common/helpers.rs @@ -18,6 +18,6 @@ pub fn write_startup_event( ) -> String { let message = START.write_event(task, method_name, module_name, logger_key); #[cfg(not(windows))] - crate::common::logger::write_serial_console_log(message.clone()); + crate::common::logger::write_serial_console_log(message.clone(), None); message } diff --git a/proxy_agent/src/common/logger.rs b/proxy_agent/src/common/logger.rs index a83c390b..63900920 100644 --- a/proxy_agent/src/common/logger.rs +++ b/proxy_agent/src/common/logger.rs @@ -42,9 +42,10 @@ fn log(log_level: LoggerLevel, message: String) { } #[cfg(not(windows))] -pub fn write_serial_console_log(message: String) { +pub fn write_serial_console_log(message: String, serial_console_log_path: Option) { use proxy_agent_shared::{current_info, misc_helpers}; - use std::io::Write; + use std::os::unix::fs::OpenOptionsExt; + use std::time::Duration; let message = format!( "{} {}_{}({}) - {}\n", @@ -55,18 +56,141 @@ pub fn write_serial_console_log(message: String) { message ); - const SERIAL_CONSOLE_PATH: &str = "/dev/console"; + let serial_console_path = serial_console_log_path.unwrap_or_else(|| "/dev/console".to_string()); match std::fs::OpenOptions::new() .write(true) - .open(SERIAL_CONSOLE_PATH) + // O_NONBLOCK makes a stalled console return `WouldBlock` instead of blocking the write; + // the write helper retries it with a bounded timeout. + // O_CLOEXEC prevents a child process from retaining this /dev/console descriptor after it executes an external program. + .custom_flags(libc::O_NONBLOCK | libc::O_CLOEXEC) + .open(serial_console_path) { Ok(mut serial_console) => { - if serial_console.write_all(message.as_bytes()).is_err() { - eprintln!("Failed to write to serial console: {message}"); + if let Err(e) = write_all_with_timeout( + &mut serial_console, + message.as_bytes(), + Duration::from_secs(2), + ) { + write_warning(format!( + "write_serial_console_log::Failed to write to serial console: {e}" + )); } } Err(e) => { - eprintln!("Failed to open serial console: {e}"); + write_warning(format!( + "write_serial_console_log::Failed to open serial console: {e}" + )); } } } + +#[cfg(not(windows))] +fn write_all_with_timeout( + file: &mut std::fs::File, + mut buffer: &[u8], + timeout: std::time::Duration, +) -> std::io::Result<()> { + use std::io::Write; + use std::os::fd::AsRawFd; + + let deadline = std::time::Instant::now() + timeout; + while !buffer.is_empty() { + match file.write(buffer) { + Ok(0) => { + return Err(std::io::Error::new( + std::io::ErrorKind::WriteZero, + "failed to write serial console message", + )); + } + Ok(written) => buffer = &buffer[written..], + Err(e) if e.kind() == std::io::ErrorKind::Interrupted => continue, + Err(e) if e.kind() == std::io::ErrorKind::WouldBlock => { + let remaining = deadline.saturating_duration_since(std::time::Instant::now()); + if remaining.is_zero() { + return Err(std::io::Error::new( + std::io::ErrorKind::TimedOut, + "serial console write timed out", + )); + } + + let timeout_ms = remaining.as_millis().min(libc::c_int::MAX as u128) as libc::c_int; + let mut poll_fd = libc::pollfd { + fd: file.as_raw_fd(), + events: libc::POLLOUT, + revents: 0, + }; + // SAFETY: poll_fd points to one valid pollfd for the duration of this call. + let result = unsafe { libc::poll(&mut poll_fd, 1, timeout_ms) }; + if result == 0 { + return Err(std::io::Error::new( + std::io::ErrorKind::TimedOut, + "serial console write timed out", + )); + } + if result < 0 { + let poll_error = std::io::Error::last_os_error(); + if poll_error.kind() != std::io::ErrorKind::Interrupted { + return Err(poll_error); + } + } + } + Err(e) => return Err(e), + } + } + + Ok(()) +} + +#[cfg(all(test, not(windows)))] +mod tests { + use super::{write_all_with_timeout, write_serial_console_log}; + use std::io::Write; + use std::os::fd::FromRawFd; + use std::time::Duration; + + #[test] + fn write_serial_console_log_writes_to_supplied_path() { + let log_path = std::env::temp_dir().join(format!( + "azure-proxy-agent-console-{}-{}.log", + std::process::id(), + proxy_agent_shared::misc_helpers::get_date_time_unix_nano() + )); + std::fs::File::create(&log_path).expect("create serial console test log"); + + write_serial_console_log( + "serial console test message".to_string(), + Some(log_path.to_string_lossy().into_owned()), + ); + + let contents = std::fs::read_to_string(&log_path).expect("read serial console test log"); + std::fs::remove_file(log_path).expect("remove serial console test log"); + assert!(contents.ends_with(" - serial console test message\n")); + } + + #[test] + fn write_all_with_timeout_times_out_when_file_is_not_writable() { + let mut pipe_fds = [0; 2]; + // SAFETY: pipe_fds points to storage for the two descriptors returned by pipe2. + assert_eq!( + unsafe { libc::pipe2(pipe_fds.as_mut_ptr(), libc::O_NONBLOCK | libc::O_CLOEXEC) }, + 0 + ); + // SAFETY: pipe2 returned two owned descriptors that are each converted exactly once. + let _read_end = unsafe { std::fs::File::from_raw_fd(pipe_fds[0]) }; + // SAFETY: pipe2 returned two owned descriptors that are each converted exactly once. + let mut write_end = unsafe { std::fs::File::from_raw_fd(pipe_fds[1]) }; + let fill_buffer = [0_u8; 4096]; + loop { + match write_end.write(&fill_buffer) { + Ok(_) => {} + Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => break, + Err(error) => panic!("failed to fill nonblocking pipe: {error}"), + } + } + + let error = write_all_with_timeout(&mut write_end, b"blocked", Duration::from_millis(200)) + .expect_err("full pipe should time out"); + + assert_eq!(error.kind(), std::io::ErrorKind::TimedOut); + } +} diff --git a/proxy_agent/src/provision.rs b/proxy_agent/src/provision.rs index 6f12a725..f8f3ce28 100644 --- a/proxy_agent/src/provision.rs +++ b/proxy_agent/src/provision.rs @@ -465,9 +465,9 @@ async fn write_provision_state( #[cfg(not(windows))] { if failed_state_message.is_empty() { - logger::write_serial_console_log("Provision finished successfully".to_string()); + logger::write_serial_console_log("Provision finished successfully".to_string(), None); } else { - logger::write_serial_console_log(failed_state_message.clone()); + logger::write_serial_console_log(failed_state_message.clone(), None); } } diff --git a/proxy_agent/src/service.rs b/proxy_agent/src/service.rs index 12564739..b1a0c1b6 100644 --- a/proxy_agent/src/service.rs +++ b/proxy_agent/src/service.rs @@ -65,7 +65,7 @@ pub async fn start_service(shared_state: SharedState) { ); logger::write_information(start_message.clone()); #[cfg(not(windows))] - logger::write_serial_console_log(start_message); + logger::write_serial_console_log(start_message, None); #[cfg(windows)] start_etw_listener();