Add timeout for write_serial_console_log function.

.github/workflows/ci.yml

@@ -23,31 +23,31 @@ 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
       - name: Clippy
         run: cargo clippy -- -D warnings
       - name: cargo-audit
         run: | 
-          cargo install cargo-audit
+          cargo install cargo-audit --locked
           cargo-audit audit
 
   win_lint:
     runs-on: windows-2022
     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
       - name: Clippy
         run: cargo clippy -- -D warnings
       - name: cargo-audit
         run: | 
-          cargo install cargo-audit
+          cargo install cargo-audit --locked
           cargo-audit audit
 
   build:

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
 }

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<String>) {
     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);
+    }
+}

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);
         }
     }
 

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();