From 4ccf95b8ea2c55edaf55937c452b0441683239b2 Mon Sep 17 00:00:00 2001 From: nzbr Date: Fri, 6 Dec 2024 20:44:08 +0100 Subject: [PATCH 1/4] shell-wrapper: log to kmsg when running as root for early boot logging --- utils/Cargo.toml | 2 +- utils/src/shell_wrapper.rs | 10 +++++++++- 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/utils/Cargo.toml b/utils/Cargo.toml index 2a170680..a682f4dd 100644 --- a/utils/Cargo.toml +++ b/utils/Cargo.toml @@ -7,7 +7,7 @@ rust-version = "1.69.0" [dependencies] anyhow = { version = "1.0.82", features = ["backtrace"] } -nix = { version = "0.29.0", features = ["mount", "process"] } +nix = { version = "0.29.0", features = ["mount", "process", "user"] } log = "0.4.21" kernlog = "0.3.1" systemd-journal-logger = "2.1.1" diff --git a/utils/src/shell_wrapper.rs b/utils/src/shell_wrapper.rs index 5bfdb73a..f0b29a65 100644 --- a/utils/src/shell_wrapper.rs +++ b/utils/src/shell_wrapper.rs @@ -112,7 +112,15 @@ fn main() { .context("When installing journal logger") }) { - warn!("Error while setting up journal logger: {:?}", err); + if nix::unistd::geteuid().is_root() { + // Journal isn't available during early boot. Try to use kmsg instead + if let Err(err) = kernlog::init().context("When initializing kernel logger") { + warn!("Error while setting up kernel logger: {:?}", err); + } + } else { + // Users can't access the kernel log + warn!("Error while setting up journal logger: {:?}", err); + } } log::set_max_level(LevelFilter::Info); From 9169a78d1abb040ba79e2754fbefba69fed1ddf6 Mon Sep 17 00:00:00 2001 From: nzbr Date: Fri, 6 Dec 2024 20:46:40 +0100 Subject: [PATCH 2/4] shell-wrapper: wait for activation script to mitigate race condition --- utils/src/shell_wrapper.rs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/utils/src/shell_wrapper.rs b/utils/src/shell_wrapper.rs index f0b29a65..80b62607 100644 --- a/utils/src/shell_wrapper.rs +++ b/utils/src/shell_wrapper.rs @@ -3,7 +3,10 @@ use log::{error, info, warn, LevelFilter}; use nix::libc::{sigaction, PT_NULL, SIGCHLD, SIG_IGN}; use std::mem::MaybeUninit; use std::os::unix::process::CommandExt; +use std::path::Path; use std::process::Command; +use std::thread; +use std::time::Duration; use std::{env, fs::read_link}; use systemd_journal_logger::JournalLog; @@ -17,6 +20,13 @@ fn real_main() -> anyhow::Result<()> { // Therefore we dereference our symlink to get whatever it was originally. let shell = read_link(exe_dir.join("shell")).context("when locating the wrapped shell")?; + if shell.starts_with("/run/current-system/sw/bin/") { + while !Path::new("/run/current-system/sw/bin").exists() { + warn!("Activation script has not finished! Waiting for /run/current-system/sw/bin to exist"); + thread::sleep(Duration::from_secs(3)); + } + } + // Set the SHELL environment variable to the wrapped shell instead of the wrapper let shell_env = env::var_os("SHELL"); if shell_env == Some(exe.into()) { From 9b71eccd3ec501cc33b10b2640681a8732917d04 Mon Sep 17 00:00:00 2001 From: nzbr Date: Tue, 10 Dec 2024 17:34:51 +0100 Subject: [PATCH 3/4] shell-wrapper: wait for inotify events instead of fixed delay --- utils/Cargo.toml | 2 +- utils/src/shell_wrapper.rs | 26 ++++++++++++++++++++------ 2 files changed, 21 insertions(+), 7 deletions(-) diff --git a/utils/Cargo.toml b/utils/Cargo.toml index a682f4dd..1db16223 100644 --- a/utils/Cargo.toml +++ b/utils/Cargo.toml @@ -7,7 +7,7 @@ rust-version = "1.69.0" [dependencies] anyhow = { version = "1.0.82", features = ["backtrace"] } -nix = { version = "0.29.0", features = ["mount", "process", "user"] } +nix = { version = "0.29.0", features = ["mount", "process", "user", "inotify"] } log = "0.4.21" kernlog = "0.3.1" systemd-journal-logger = "2.1.1" diff --git a/utils/src/shell_wrapper.rs b/utils/src/shell_wrapper.rs index 80b62607..b259ccbe 100644 --- a/utils/src/shell_wrapper.rs +++ b/utils/src/shell_wrapper.rs @@ -1,12 +1,11 @@ use anyhow::{anyhow, Context}; use log::{error, info, warn, LevelFilter}; use nix::libc::{sigaction, PT_NULL, SIGCHLD, SIG_IGN}; +use nix::sys::inotify::{AddWatchFlags, InitFlags, Inotify}; use std::mem::MaybeUninit; use std::os::unix::process::CommandExt; use std::path::Path; use std::process::Command; -use std::thread; -use std::time::Duration; use std::{env, fs::read_link}; use systemd_journal_logger::JournalLog; @@ -20,10 +19,25 @@ fn real_main() -> anyhow::Result<()> { // Therefore we dereference our symlink to get whatever it was originally. let shell = read_link(exe_dir.join("shell")).context("when locating the wrapped shell")?; - if shell.starts_with("/run/current-system/sw/bin/") { - while !Path::new("/run/current-system/sw/bin").exists() { - warn!("Activation script has not finished! Waiting for /run/current-system/sw/bin to exist"); - thread::sleep(Duration::from_secs(3)); + if shell.starts_with("/run/current-system/sw/bin/") + && !Path::new("/run/current-system").exists() + { + let inotify = Inotify::init(InitFlags::empty()).context("When initializing inotify")?; + + // Watch changes in /run to re-check if the activation script has finished + let wd = inotify.add_watch("/run", AddWatchFlags::IN_CREATE).unwrap(); + + let mut warning = false; + + // Check if the activation script has finished by now + while !Path::new("/run/current-system").exists() { + if (!warning) { + warning = true; + warn!("Activation script has not finished! Waiting for /run/current-system/sw/bin to exist"); + } + let events = inotify + .read_events() + .context("When reading inotify events")?; } } From d75f47966c7482af396053c6f3af48f79342105c Mon Sep 17 00:00:00 2001 From: nzbr Date: Tue, 10 Dec 2024 17:43:21 +0100 Subject: [PATCH 4/4] test(shell-wrapper): add a test for long running activation scripts --- tests/slow-activation/delay-activation.nix | 14 ++++++++++++ .../slow-activation/slow-activation.Tests.ps1 | 22 +++++++++++++++++++ 2 files changed, 36 insertions(+) create mode 100644 tests/slow-activation/delay-activation.nix create mode 100644 tests/slow-activation/slow-activation.Tests.ps1 diff --git a/tests/slow-activation/delay-activation.nix b/tests/slow-activation/delay-activation.nix new file mode 100644 index 00000000..6fbdfb66 --- /dev/null +++ b/tests/slow-activation/delay-activation.nix @@ -0,0 +1,14 @@ +{ pkgs, lib, ... }: + +{ + imports = [ + + ]; + + wsl.enable = true; + + system.activationScripts."00-delay" = '' + echo "Delaying activation for 15 seconds..." + sleep 15s + ''; +} diff --git a/tests/slow-activation/slow-activation.Tests.ps1 b/tests/slow-activation/slow-activation.Tests.ps1 new file mode 100644 index 00000000..f6caaf94 --- /dev/null +++ b/tests/slow-activation/slow-activation.Tests.ps1 @@ -0,0 +1,22 @@ +BeforeAll { + . $PSScriptRoot/../lib/lib.ps1 +} + +Describe "Slow Activation Script" { + BeforeAll { + $distro = [Distro]::new() + } + + It "should not cause starting a shell to fail" { + $distro.InstallConfig("$PSScriptRoot/delay-activation.nix", "boot") + $distro.Shutdown() + + $distro.Launch("echo 'TEST'") | Select-Object -Last 1 | Tee-Object -Variable output + $output | Should -BeExactly "TEST" + $LASTEXITCODE | Should -Be 0 + } + + AfterAll { + $distro.Uninstall() + } +}