commit 3e1716151601f0e8bff2f8d36c7e354c7e93f1f8
parent 7a5f0b4704f8403302bf1036a376df4a80e292a2
Author: triesap <tyson@radroots.org>
Date: Sat, 18 Apr 2026 00:27:48 +0000
app: harden launcher logging verification
Diffstat:
5 files changed, 305 insertions(+), 54 deletions(-)
diff --git a/Cargo.lock b/Cargo.lock
@@ -4667,6 +4667,7 @@ dependencies = [
"radroots_app_ui",
"thiserror 2.0.18",
"tracing",
+ "tracing-subscriber",
]
[[package]]
diff --git a/crates/launchers/desktop/Cargo.toml b/crates/launchers/desktop/Cargo.toml
@@ -21,5 +21,8 @@ radroots_app_ui.workspace = true
thiserror.workspace = true
tracing.workspace = true
+[dev-dependencies]
+tracing-subscriber.workspace = true
+
[lints]
workspace = true
diff --git a/crates/launchers/desktop/src/app.rs b/crates/launchers/desktop/src/app.rs
@@ -9,7 +9,7 @@ use thiserror::Error;
use tracing::{error, info};
use crate::menus::install_native_app_menu;
-use crate::runtime::DesktopAppRuntime;
+use crate::runtime::{DesktopAppRuntime, DesktopAppRuntimeSummary};
use crate::window::{home_titlebar_options, open_home_window};
#[derive(Debug, Error)]
@@ -26,17 +26,9 @@ pub fn launch() -> Result<(), AppLaunchError> {
let snapshot = AppRuntimeSnapshot::from_config(build, &runtime_config);
bootstrap_logging(&snapshot, runtime_config.local_log_root.as_path())?;
install_panic_hook();
- emit_launch_event(&snapshot);
let runtime = DesktopAppRuntime::bootstrap();
- if let Some(startup_issue) = runtime.summary().startup_issue {
- error!(
- target: "runtime",
- event = "runtime.degraded",
- startup_issue = %startup_issue,
- "desktop runtime degraded"
- );
- }
+ emit_runtime_events(&snapshot, &runtime.summary());
let app = Application::new().with_assets(gpui_component_assets::Assets);
@@ -126,3 +118,154 @@ fn emit_launch_event(snapshot: &AppRuntimeSnapshot) {
launch_event.message
);
}
+
+fn emit_runtime_events(snapshot: &AppRuntimeSnapshot, runtime: &DesktopAppRuntimeSummary) {
+ emit_launch_event(snapshot);
+
+ if let Some(startup_issue) = runtime.startup_issue.as_deref() {
+ emit_degraded_runtime_event(startup_issue);
+ }
+}
+
+fn emit_degraded_runtime_event(startup_issue: &str) {
+ error!(
+ target: "runtime",
+ event = "runtime.degraded",
+ startup_issue = %startup_issue,
+ "desktop runtime degraded"
+ );
+}
+
+#[cfg(test)]
+mod tests {
+ use std::sync::{Arc, Mutex};
+
+ use radroots_app_core::{
+ APP_PROJECTION_SOURCE, AppBuildIdentity, AppRuntimeCapture, AppRuntimeMode,
+ AppRuntimeSnapshot,
+ };
+ use radroots_app_models::TodayAgendaProjection;
+ use radroots_app_state::AppShellProjection;
+ use tracing::{
+ Event, Level, Subscriber,
+ field::{Field, Visit},
+ };
+ use tracing_subscriber::{Layer, layer::Context, prelude::*, registry::LookupSpan};
+
+ use crate::runtime::DesktopAppRuntimeSummary;
+
+ use super::emit_runtime_events;
+
+ #[derive(Clone, Debug, Eq, PartialEq)]
+ struct CapturedEvent {
+ level: Level,
+ target: String,
+ event: Option<String>,
+ message: Option<String>,
+ startup_issue: Option<String>,
+ }
+
+ #[derive(Default)]
+ struct EventFieldVisitor {
+ event: Option<String>,
+ message: Option<String>,
+ startup_issue: Option<String>,
+ }
+
+ struct CaptureLayer {
+ events: Arc<Mutex<Vec<CapturedEvent>>>,
+ }
+
+ impl EventFieldVisitor {
+ fn record_value(&mut self, field: &Field, value: String) {
+ match field.name() {
+ "event" => self.event = Some(value),
+ "message" => self.message = Some(value),
+ "startup_issue" => self.startup_issue = Some(value),
+ _ => {}
+ }
+ }
+ }
+
+ impl Visit for EventFieldVisitor {
+ fn record_str(&mut self, field: &Field, value: &str) {
+ self.record_value(field, value.to_owned());
+ }
+
+ fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+ self.record_value(field, format!("{value:?}").trim_matches('"').to_owned());
+ }
+ }
+
+ impl<S> Layer<S> for CaptureLayer
+ where
+ S: Subscriber + for<'lookup> LookupSpan<'lookup>,
+ {
+ fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
+ let mut visitor = EventFieldVisitor::default();
+ event.record(&mut visitor);
+ self.events
+ .lock()
+ .expect("capture lock")
+ .push(CapturedEvent {
+ level: *event.metadata().level(),
+ target: event.metadata().target().to_owned(),
+ event: visitor.event,
+ message: visitor.message,
+ startup_issue: visitor.startup_issue,
+ });
+ }
+ }
+
+ fn test_snapshot() -> AppRuntimeSnapshot {
+ AppRuntimeSnapshot::from_capture(
+ AppBuildIdentity {
+ package_name: "radroots_app".to_owned(),
+ package_version: "0.1.0".to_owned(),
+ build_profile: "debug".to_owned(),
+ target_triple: "aarch64-apple-darwin".to_owned(),
+ projection_source: APP_PROJECTION_SOURCE.to_owned(),
+ git_commit: None,
+ },
+ AppRuntimeMode::LocalhostDev,
+ AppRuntimeCapture {
+ host_locale: "en_US.UTF-8".to_owned(),
+ operating_system: "macos".to_owned(),
+ run_id: "app-localhost-dev-20260418T000000Z-deadbeefcafefeed".to_owned(),
+ },
+ )
+ }
+
+ #[test]
+ fn degraded_runtime_emits_launch_and_degraded_events() {
+ let events = Arc::new(Mutex::new(Vec::new()));
+ let subscriber = tracing_subscriber::registry().with(CaptureLayer {
+ events: Arc::clone(&events),
+ });
+ let summary = DesktopAppRuntimeSummary {
+ shell_projection: AppShellProjection::default(),
+ today_projection: TodayAgendaProjection::default(),
+ startup_issue: Some("desktop runtime roots require HOME for macos".to_owned()),
+ };
+
+ tracing::subscriber::with_default(subscriber, || {
+ emit_runtime_events(&test_snapshot(), &summary);
+ });
+
+ let events = events.lock().expect("events lock");
+ assert_eq!(events.len(), 2);
+ assert_eq!(events[0].event.as_deref(), Some("runtime.launch"));
+ assert_eq!(events[0].target, "bootstrap");
+ assert_eq!(events[1].event.as_deref(), Some("runtime.degraded"));
+ assert_eq!(events[1].level, Level::ERROR);
+ assert_eq!(events[1].target, "runtime");
+ assert_eq!(
+ events[1].startup_issue.as_deref(),
+ Some("desktop runtime roots require HOME for macos")
+ );
+ assert_eq!(
+ events[1].message.as_deref(),
+ Some("desktop runtime degraded")
+ );
+ }
+}
diff --git a/crates/shared/core/src/logging.rs b/crates/shared/core/src/logging.rs
@@ -238,7 +238,7 @@ pub fn init_logging(options: AppLoggingOptions) -> Result<(), AppLoggingError> {
info!(
target: "runtime",
event = "logging.initialized",
- file = %options.log_dir.join(format!("{}.jsonl", current_utc_day())).display(),
+ file = %current_day_log_path(&options.log_dir).display(),
stdout = options.stdout,
"logging initialized"
);
@@ -271,6 +271,10 @@ fn build_file_appender(log_dir: &Path) -> Result<RollingFileAppender, AppLogging
.build(log_dir)?)
}
+fn current_day_log_path(log_dir: &Path) -> PathBuf {
+ log_dir.join(format!("{}.jsonl", current_utc_day()))
+}
+
fn current_utc_day() -> String {
Utc::now().format("%Y-%m-%d").to_string()
}
@@ -298,7 +302,13 @@ fn prepare_latest_alias(log_dir: &Path) -> Result<(), AppLoggingError> {
}
#[cfg(unix)]
- std::os::unix::fs::symlink(format!("{}.jsonl", current_utc_day()), &latest_path)?;
+ std::os::unix::fs::symlink(
+ current_day_log_path(log_dir)
+ .file_name()
+ .map(|value| value.to_owned())
+ .unwrap_or_default(),
+ &latest_path,
+ )?;
#[cfg(not(unix))]
fs::write(&latest_path, [])?;
@@ -356,6 +366,7 @@ fn target_category(target: &str) -> String {
mod tests {
use std::{
fs,
+ io::Write,
path::{Path, PathBuf},
time::{SystemTime, UNIX_EPOCH},
};
@@ -369,7 +380,8 @@ mod tests {
};
use super::{
- APP_LOG_PRODUCT, APP_LOG_SCHEMA_VERSION, app_runtime_log_dir, prepare_latest_alias,
+ APP_LOG_PRODUCT, APP_LOG_SCHEMA_VERSION, app_runtime_log_dir, build_file_appender,
+ current_day_log_path, prepare_latest_alias,
};
fn temp_dir(name: &str) -> PathBuf {
@@ -432,6 +444,24 @@ mod tests {
}
#[test]
+ fn rolling_file_appender_writes_to_active_day_log_file() {
+ let dir = temp_dir("rolling-file");
+ fs::create_dir_all(&dir).expect("create dir");
+
+ let mut appender = build_file_appender(&dir).expect("build file appender");
+ writeln!(appender, "{{\"event\":\"runtime.launch\"}}").expect("write structured record");
+ appender.flush().expect("flush structured record");
+
+ let log_path = current_day_log_path(&dir);
+ let payload = fs::read_to_string(&log_path).expect("read current day log");
+
+ assert!(log_path.ends_with(format!("{}.jsonl", Utc::now().format("%Y-%m-%d"))));
+ assert!(payload.contains("\"event\":\"runtime.launch\""));
+
+ let _ = fs::remove_dir_all(&dir);
+ }
+
+ #[test]
fn structured_record_shape_remains_stable() {
let snapshot = test_snapshot();
let payload = serde_json::to_value(json!({
diff --git a/platforms/macos/Scripts/test-macos-host.sh b/platforms/macos/Scripts/test-macos-host.sh
@@ -18,6 +18,7 @@ require_command() {
require_command /usr/libexec/PlistBuddy
require_command mktemp
+require_command readlink
app_path="$("${script_dir}/build-macos-host.sh")"
plist_path="${app_path}/Contents/Info.plist"
@@ -67,11 +68,90 @@ release_app_path="$(
}
tmp_root="$(mktemp -d)"
+runner_pid=""
+degraded_runner_pid=""
+
+wait_for_log_event() {
+ local structured_log_file="$1"
+ local expected_event="$2"
+ local runner_pid="$3"
+ local event_verified=false
+
+ for _ in $(seq 1 150); do
+ if [[ -f "${structured_log_file}" ]] && grep -q "\"event\":\"${expected_event}\"" "${structured_log_file}" 2>/dev/null; then
+ event_verified=true
+ break
+ fi
+
+ if ! kill -0 "${runner_pid}" 2>/dev/null; then
+ wait "${runner_pid}"
+ exit $?
+ fi
+
+ sleep 0.1
+ done
+
+ [[ "${event_verified}" == "true" ]] || {
+ echo "${expected_event} was not recorded by run-macos-host.sh" >&2
+ exit 1
+ }
+}
+
+assert_latest_alias() {
+ local latest_log_path="$1"
+
+ [[ -e "${latest_log_path}" ]] || {
+ echo "missing latest structured log alias: ${latest_log_path}" >&2
+ exit 1
+ }
+
+ [[ "$(readlink "${latest_log_path}")" == "${date_utc}.jsonl" ]] || {
+ echo "latest structured log alias does not point at ${date_utc}.jsonl" >&2
+ exit 1
+ }
+}
+
+assert_raw_logs_exist() {
+ local stdout_file="$1"
+ local stderr_file="$2"
+
+ [[ -f "${stdout_file}" ]] || {
+ echo "missing raw stdout log: ${stdout_file}" >&2
+ exit 1
+ }
+
+ [[ -f "${stderr_file}" ]] || {
+ echo "missing raw stderr log: ${stderr_file}" >&2
+ exit 1
+ }
+}
+
+terminate_runner() {
+ local runner_pid="$1"
+
+ if [[ -n "${runner_pid}" ]] && kill -0 "${runner_pid}" 2>/dev/null; then
+ kill "${runner_pid}" 2>/dev/null || true
+ fi
+
+ set +e
+ wait "${runner_pid}"
+ local exit_code="$?"
+ set -e
+ [[ "${exit_code}" == "0" ]] || [[ "${exit_code}" == "143" ]] || [[ "${exit_code}" == "130" ]] || {
+ echo "unexpected runner exit code after termination: ${exit_code}" >&2
+ exit 1
+ }
+}
+
cleanup() {
if [[ -n "${runner_pid:-}" ]] && kill -0 "${runner_pid}" 2>/dev/null; then
kill "${runner_pid}" 2>/dev/null || true
wait "${runner_pid}" || true
fi
+ if [[ -n "${degraded_runner_pid:-}" ]] && kill -0 "${degraded_runner_pid}" 2>/dev/null; then
+ kill "${degraded_runner_pid}" 2>/dev/null || true
+ wait "${degraded_runner_pid}" || true
+ fi
rm -rf "${tmp_root}"
}
trap cleanup EXIT
@@ -100,48 +180,42 @@ RADROOTS_APP_RUNTIME_CONFIG_JSON="$(
"${script_dir}/run-macos-host.sh" &
runner_pid="$!"
-launch_verified=false
-for _ in $(seq 1 150); do
- if [[ -f "${structured_log_file}" ]] && grep -q '"event":"runtime.launch"' "${structured_log_file}" 2>/dev/null; then
- launch_verified=true
- break
- fi
-
- if ! kill -0 "${runner_pid}" 2>/dev/null; then
- wait "${runner_pid}"
- exit $?
- fi
-
- sleep 0.1
-done
-
-[[ "${launch_verified}" == "true" ]] || {
- echo "runtime.launch was not recorded by run-macos-host.sh" >&2
- exit 1
-}
-
-[[ -e "${latest_log_path}" ]] || {
- echo "missing latest structured log alias: ${latest_log_path}" >&2
- exit 1
-}
-
-[[ -f "${stdout_file}" ]] || {
- echo "missing raw stdout log: ${stdout_file}" >&2
- exit 1
-}
+wait_for_log_event "${structured_log_file}" "runtime.launch" "${runner_pid}"
+assert_latest_alias "${latest_log_path}"
+assert_raw_logs_exist "${stdout_file}" "${stderr_file}"
+terminate_runner "${runner_pid}"
+runner_pid=""
-[[ -f "${stderr_file}" ]] || {
- echo "missing raw stderr log: ${stderr_file}" >&2
- exit 1
-}
+degraded_run_id="$(radroots_app_run_id "${runtime_mode}")"
+degraded_log_root="${tmp_root}/degraded-logs"
+degraded_structured_log_file="${degraded_log_root}/apps/local/app/app-macos-native/${date_utc}.jsonl"
+degraded_latest_log_path="${degraded_log_root}/apps/local/app/app-macos-native/latest.jsonl"
+degraded_stdout_file="${degraded_log_root}/apps/local/app/app-macos-native/raw/stdout.${date_utc}.log"
+degraded_stderr_file="${degraded_log_root}/apps/local/app/app-macos-native/raw/stderr.${date_utc}.log"
+degraded_runtime_config_json="$(
+ radroots_app_build_runtime_config_json \
+ "${repo_root}" \
+ "${runtime_mode}" \
+ "${degraded_run_id}" \
+ "${bundle_identifier}" \
+ "${platform_name}" \
+ "${degraded_log_root}"
+)"
-kill "${runner_pid}" 2>/dev/null || true
-set +e
-wait "${runner_pid}"
-exit_code="$?"
-set -e
-[[ "${exit_code}" == "0" ]] || [[ "${exit_code}" == "143" ]] || [[ "${exit_code}" == "130" ]] || {
- echo "unexpected runner exit code after termination: ${exit_code}" >&2
+env -u HOME \
+ RADROOTS_APP_RUN_ID="${degraded_run_id}" \
+ RADROOTS_APP_LOCAL_LOG_ROOT="${degraded_log_root}" \
+ RADROOTS_APP_RUNTIME_CONFIG_JSON="${degraded_runtime_config_json}" \
+ "${script_dir}/run-macos-host.sh" &
+degraded_runner_pid="$!"
+
+wait_for_log_event "${degraded_structured_log_file}" "runtime.launch" "${degraded_runner_pid}"
+wait_for_log_event "${degraded_structured_log_file}" "runtime.degraded" "${degraded_runner_pid}"
+assert_latest_alias "${degraded_latest_log_path}"
+assert_raw_logs_exist "${degraded_stdout_file}" "${degraded_stderr_file}"
+grep -q '"startup_issue":"desktop runtime roots require HOME for macos"' "${degraded_structured_log_file}" || {
+ echo "runtime.degraded did not record the expected startup issue" >&2
exit 1
}
-runner_pid=""
+terminate_runner "${degraded_runner_pid}"
+degraded_runner_pid=""
