Repository: ctc-oss/fapolicy-analyzer
Issue category: Performance Issue

Issue:
Detect systemd service start/stop events to replace hard coded delays
The original implementation used conservative hard coded delays to sync fapolicyd starts/stops {via dbus} with the invocation and termination of the Profiling target executables. The focus at that time was correct functionality however it's time for a quick first pass optimization to improve the end-user experience. We can totally eliminate or minimize the hard coded delays if we wait/block while monitoring systemd's journal for fapolicyd events of interest e.g. wait after starting the fapolicyd profiling instance until journalctl reports that the fapd_profiling.service has started, then invoke the profiling target executable. 

This is not a blocker to the systemd profiler work, and will be done in parallel.
Profiler testing over Rhel86 observations
## Summary ##

1. Directly invoking `fapolicyd --debug --permissive` outputs to stderr not stdout wrt Profiler Tool Target Output pane section titles.
2. Specifying a `user` w/o specifying a `working directory` sets the working directory to the `root` user's HOME.
3. Specifying only the basename of a target binary while specifying a working directory, and a `PATH` env var results in no output in the Profiler Tool Target Output pane

Please see https://github.com/ctc-oss/fapolicy-analyzer/pull/770 for details and images.


Hints:
This should be able to be done on the backend with a few aditions.

1. Listen for dbus events; would look similar to [this](https://github.com/diwic/dbus-rs/blob/master/dbus/examples/unity_focused_window.rs)
2. Register a Python callback with the backend
3. Callback when state changes

We don't have any examples of 2 yet but it should be straightforward.

I'll take a look at this in milestone 8.


Patch:
diff --git a/Cargo.lock b/Cargo.lock
index 3b02a7962..126cb87a7 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -287,7 +287,6 @@ dependencies = [
  "fapolicy-trust",
  "pyo3",
  "similar",
- "tempfile",
 ]
 
 [[package]]
diff --git a/crates/daemon/src/error.rs b/crates/daemon/src/error.rs
index b289208db..044582d5e 100644
--- a/crates/daemon/src/error.rs
+++ b/crates/daemon/src/error.rs
@@ -29,4 +29,10 @@ pub enum Error {
 
     #[error("FileIO error: {0}")]
     IOError(#[from] io::Error),
+
+    #[error("failed to observe fapolicyd ready state")]
+    NotReady,
+
+    #[error("failed to observe fapolicyd shutdown")]
+    NotStopped,
 }
diff --git a/crates/daemon/src/fapolicyd.rs b/crates/daemon/src/fapolicyd.rs
index 15d9092dc..79ea20d8c 100644
--- a/crates/daemon/src/fapolicyd.rs
+++ b/crates/daemon/src/fapolicyd.rs
@@ -8,6 +8,16 @@
 
 // todo;; tracking the fapolicyd specific bits in here to determine if bindings are worthwhile
 
+use crate::error::Error;
+use std::fs::File;
+use std::io::Read;
+use std::path::{Path, PathBuf};
+use std::process::{Child, Command, Stdio};
+use std::sync::atomic::{AtomicBool, Ordering};
+use std::sync::Arc;
+use std::time::Duration;
+use std::{io, thread};
+
 pub const TRUST_LMDB_PATH: &str = "/var/lib/fapolicyd";
 pub const TRUST_LMDB_NAME: &str = "trust.db";
 pub const TRUST_DIR_PATH: &str = "/etc/fapolicyd/trust.d";
@@ -16,9 +26,142 @@ pub const RULES_FILE_PATH: &str = "/etc/fapolicyd/rules.d";
 pub const COMPILED_RULES_PATH: &str = "/etc/fapolicyd/compiled.rules";
 pub const RPM_DB_PATH: &str = "/var/lib/rpm";
 pub const FIFO_PIPE: &str = "/run/fapolicyd/fapolicyd.fifo";
+pub const START_POLLING_EVENTS_MESSAGE: &str = "Starting to listen for events";
 
 #[derive(Clone, Debug)]
 pub enum Version {
     Unknown,
     Release { major: u8, minor: u8, patch: u8 },
 }
+
+/// A fapolicyd runner
+pub struct Daemon {
+    pub name: String,
+    alive: Arc<AtomicBool>,
+    term: Arc<AtomicBool>,
+}
+
+impl Daemon {
+    pub fn new(name: &str) -> Self {
+        Self {
+            name: name.to_string(),
+            alive: Default::default(),
+            term: Default::default(),
+        }
+    }
+
+    pub fn active(&self) -> bool {
+        self.alive.load(Ordering::Relaxed)
+    }
+
+    pub fn stop(&self) {
+        self.term.store(true, Ordering::Relaxed)
+    }
+
+    pub fn start(&self, events_log: Option<&PathBuf>) -> io::Result<()> {
+        let (mut cmd, _) = build(
+            "/usr/sbin/fapolicyd --debug --permissive --no-details",
+            events_log,
+        );
+        let alive: Arc<AtomicBool> = self.alive.clone();
+        let term: Arc<AtomicBool> = self.term.clone();
+
+        thread::spawn(move || {
+            let mut execd = Execd::new(cmd.spawn().unwrap());
+
+            // the process is now alive
+            alive.store(true, Ordering::Relaxed);
+
+            while let Ok(true) = execd.running() {
+                thread::sleep(Duration::from_secs(1));
+                if term.load(Ordering::Relaxed) {
+                    execd.kill().expect("kill daemon");
+                    break;
+                }
+            }
+
+            // we need to wait on the process to die, instead of just blocking
+            // this loop provides the ability to add a harder stop impl, abort
+            term.store(false, Ordering::Relaxed);
+            while let Ok(true) = execd.running() {
+                if term.load(Ordering::Relaxed) {
+                    execd.kill().expect("abort daemon");
+                    break;
+                }
+                thread::sleep(Duration::from_secs(1));
+            }
+
+            // no longer alive
+            alive.store(false, Ordering::Relaxed);
+        });
+
+        Ok(())
+    }
+}
+
+type CmdArgs = (Command, String);
+fn build(args: &str, out: Option<&PathBuf>) -> CmdArgs {
+    let opts: Vec<&str> = args.split(' ').collect();
+    let (target, opts) = opts.split_first().expect("invalid cmd string");
+
+    let mut cmd = Command::new(target);
+
+    if let Some(path) = out {
+        let f = File::create(path).unwrap();
+        cmd.stderr(Stdio::from(f));
+    }
+
+    cmd.args(opts);
+    (cmd, args.to_string())
+}
+
+/// Internal struct used to inspect a running process
+struct Execd {
+    proc: Option<Child>,
+}
+
+impl Execd {
+    fn new(proc: Child) -> Execd {
+        Execd { proc: Some(proc) }
+    }
+
+    /// Is process is still running?, never blocks
+    fn running(&mut self) -> io::Result<bool> {
+        match self.proc.as_mut().unwrap().try_wait() {
+            Ok(Some(_)) => Ok(false),
+            Ok(None) => Ok(true),
+            Err(e) => Err(e),
+        }
+    }
+
+    /// Cancel the process, without blocking
+    fn kill(&mut self) -> io::Result<()> {
+        self.proc.as_mut().unwrap().kill()
+    }
+}
+
+/// watch a fapolicyd log at the specified path for the
+/// message it prints when ready to start polling events
+pub fn wait_until_ready(path: &Path) -> Result<(), Error> {
+    let mut f = File::open(path)?;
+    for _ in 0..10 {
+        thread::sleep(Duration::from_secs(1));
+        let mut s = String::new();
+        f.read_to_string(&mut s)?;
+        if s.contains(START_POLLING_EVENTS_MESSAGE) {
+            return Ok(());
+        }
+    }
+    Err(Error::NotReady)
+}
+
+/// wait for the daemon process to shutdown
+pub fn wait_until_shutdown(daemon: &Daemon) -> Result<(), Error> {
+    for _ in 0..10 {
+        thread::sleep(Duration::from_secs(1));
+        if !daemon.alive.load(Ordering::Relaxed) {
+            return Ok(());
+        }
+    }
+    Err(Error::NotStopped)
+}
diff --git a/crates/daemon/src/lib.rs b/crates/daemon/src/lib.rs
index d27f0d094..d741aaef5 100644
--- a/crates/daemon/src/lib.rs
+++ b/crates/daemon/src/lib.rs
@@ -8,9 +8,8 @@
 
 pub mod error;
 pub mod fapolicyd;
-
-pub use version::fapolicyd_version as version;
-
 pub mod profiler;
 pub mod svc;
 pub mod version;
+
+pub use version::fapolicyd_version as version;
diff --git a/crates/daemon/src/profiler.rs b/crates/daemon/src/profiler.rs
index ca6cd3ee9..90dcf0326 100644
--- a/crates/daemon/src/profiler.rs
+++ b/crates/daemon/src/profiler.rs
@@ -7,8 +7,6 @@
  */
 
 use std::fs;
-use std::fs::File;
-use std::io::Write;
 use std::path::PathBuf;
 
 use tempfile::NamedTempFile;
@@ -17,25 +15,26 @@ use fapolicy_rules::db::DB;
 use fapolicy_rules::write;
 
 use crate::error::Error;
-use crate::fapolicyd::COMPILED_RULES_PATH;
-use crate::svc::{daemon_reload, wait_for_daemon, Handle, State};
+use crate::fapolicyd::{Daemon, COMPILED_RULES_PATH};
+use crate::svc::State;
+use crate::{fapolicyd, svc};
 
-const PROFILER_UNIT_NAME: &str = "fapolicyp";
+const PROFILER_NAME: &str = "fapolicyp";
 
 pub struct Profiler {
-    pub name: String,
+    fapolicyp: Daemon,
     prev_state: Option<State>,
     prev_rules: Option<NamedTempFile>,
-    pub stdout_log: Option<PathBuf>,
+    pub events_log: Option<PathBuf>,
 }
 
 impl Default for Profiler {
     fn default() -> Self {
         Profiler {
-            name: PROFILER_UNIT_NAME.to_string(),
             prev_state: None,
             prev_rules: None,
-            stdout_log: None,
+            events_log: None,
+            fapolicyp: Daemon::new(PROFILER_NAME),
         }
     }
 }
@@ -45,13 +44,8 @@ impl Profiler {
         Default::default()
     }
 
-    fn handle(&self) -> Handle {
-        Handle::new(&self.name)
-    }
-
-    pub fn is_active(&self) -> Result<bool, Error> {
-        let handle = self.handle();
-        Ok(handle.valid() && handle.active()?)
+    pub fn is_active(&self) -> bool {
+        self.fapolicyp.active()
     }
 
     pub fn activate(&mut self) -> Result<State, Error> {
@@ -59,15 +53,15 @@ impl Profiler {
     }
 
     pub fn activate_with_rules(&mut self, db: Option<&DB>) -> Result<State, Error> {
-        let daemon = Handle::default();
-        if !self.is_active()? {
-            // 1. preserve daemon state
-            self.prev_state = Some(daemon.state()?);
-            // 2. stop daemon if running
+        let fapolicyd = svc::Handle::default();
+        if !self.is_active() {
+            // 1. preserve fapolicyd daemon state
+            self.prev_state = Some(fapolicyd.state()?);
+            // 2. stop fapolicyd daemon if running
             if let Some(State::Active) = self.prev_state {
                 // todo;; probably need to ensure its not in
                 //        a state like restart, init or some such
-                daemon.stop()?
+                fapolicyd.stop()?
             }
             // 3. swap the rules file if necessary
             if let Some(db) = db {
@@ -82,67 +76,38 @@ impl Profiler {
                 eprintln!("rules backed up to {:?}", backup.path());
                 self.prev_rules = Some(backup);
             }
-            // 4. write the profiler unit file
-            write_service(self.stdout_log.as_ref())?;
-            // 5. start the profiler
-            self.handle().start()?;
-            // 6. wait for the profiler to become active
-            wait_for_daemon(&self.handle(), State::Active, 10)?;
+            // 5. start the profiler daemon
+            self.fapolicyp.start(self.events_log.as_ref())?;
+            // 6. wait for the profiler daemon to become active
+            if let Some(log) = self.events_log.as_ref() {
+                if fapolicyd::wait_until_ready(log).is_err() {
+                    eprintln!("wait_until_ready failed");
+                };
+            }
         }
-        daemon.state()
+        fapolicyd.state()
     }
 
     pub fn deactivate(&mut self) -> Result<State, Error> {
-        let daemon = Handle::default();
-        if self.is_active()? {
-            // 1. stop the daemon
-            self.handle().stop()?;
-            // 2. wait for the profiler to become inactive
-            wait_for_daemon(&self.handle(), State::Inactive, 10)?;
+        let fapolicyd = svc::Handle::default();
+        if self.is_active() {
+            // 1. stop the profiler daemon
+            self.fapolicyp.stop();
+            // 2. wait for the profiler daemon to become inactive
+            fapolicyd::wait_until_shutdown(&self.fapolicyp)?;
             // 3. swap original rules back in if they were changed
             if let Some(f) = self.prev_rules.take() {
                 // persist the temp file as the compiled rules
                 f.persist(COMPILED_RULES_PATH).map_err(|e| e.error)?;
             }
-            // 4. start daemon if it was previously active
+            // 4. start fapolicyd daemon if it was previously active
             if let Some(State::Active) = self.prev_state {
                 eprintln!("restarting daemon");
-                daemon.start()?;
+                fapolicyd.start()?;
             }
         }
         // clear the prev state
         self.prev_state = None;
-        // delete the service file
-        delete_service()?;
-        daemon.state()
-    }
-}
-
-fn service_path() -> String {
-    format!("/usr/lib/systemd/system/{}.service", PROFILER_UNIT_NAME)
-}
-
-fn write_service(stdout: Option<&PathBuf>) -> Result<(), Error> {
-    let mut unit_file = File::create(service_path())?;
-    let mut service_def = include_str!("profiler.service").to_string();
-    if let Some(stdout_path) = stdout {
-        // append? it appears that a bug pre v240 forces append here - systemd#10944
-        service_def = format!(
-            "{}\nStandardOutput=append:{}",
-            service_def,
-            stdout_path.display()
-        );
+        fapolicyd.state()
     }
-    unit_file.write_all(service_def.as_bytes())?;
-
-    // reload the daemon to ensure profiler unit is visible
-    daemon_reload()?;
-
-    Ok(())
-}
-
-fn delete_service() -> Result<(), Error> {
-    fs::remove_file(PathBuf::from(service_path()))?;
-    daemon_reload()?;
-    Ok(())
 }
diff --git a/crates/daemon/src/profiler.service b/crates/daemon/src/profiler.service
deleted file mode 100644
index b9bac1c95..000000000
--- a/crates/daemon/src/profiler.service
+++ /dev/null
@@ -1,12 +0,0 @@
-[Unit]
-Description=File Access Profiling Daemon
-DefaultDependencies=no
-After=local-fs.target systemd-tmpfiles-setup.service
-
-[Install]
-WantedBy=multi-user.target
-
-[Service]
-Type=simple
-PIDFile=/run/fapolicyp.pid
-ExecStart=/usr/sbin/fapolicyd --debug --permissive --no-details
diff --git a/crates/daemon/src/svc.rs b/crates/daemon/src/svc.rs
index 11ee3b7e2..de2fb8437 100644
--- a/crates/daemon/src/svc.rs
+++ b/crates/daemon/src/svc.rs
@@ -156,22 +156,22 @@ impl Handle {
     }
 }
 
-pub fn wait_for_daemon(handle: &Handle, target_state: State, seconds: usize) -> Result<(), Error> {
+pub fn wait_for_service(handle: &Handle, target_state: State, seconds: usize) -> Result<(), Error> {
     for _ in 0..seconds {
-        eprintln!("waiting on daemon to be {target_state:?}...");
+        eprintln!("waiting on {} to be {target_state:?}...", handle.name);
         sleep(Duration::from_secs(1));
         if handle
             .state()
             .map(|state| target_state.can_be(state))
             .unwrap_or(false)
         {
-            eprintln!("daemon is now {target_state:?}");
+            eprintln!("{} is now {target_state:?}", handle.name);
             return Ok(());
         }
     }
 
     let actual_state = handle.state()?;
-    eprintln!("done waiting, daemon is {target_state:?}");
+    eprintln!("done waiting, {} is {target_state:?}", handle.name);
 
     if target_state.can_be(actual_state) {
         Ok(())
diff --git a/crates/pyo3/Cargo.toml b/crates/pyo3/Cargo.toml
index eacd4ad33..cdce68aec 100644
--- a/crates/pyo3/Cargo.toml
+++ b/crates/pyo3/Cargo.toml
@@ -11,8 +11,7 @@ crate-type = ["cdylib"]
 [dependencies]
 pyo3 = { version = "0.15", features = ["abi3-py36", "auto-initialize"] }
 similar = "2.1"
-chrono = "0.4.22"
-tempfile = "3.3"
+chrono = "0.4"
 
 fapolicy-analyzer = { version = "*", path = "../analyzer" }
 fapolicy-app = { version = "*", path = "../app" }
diff --git a/crates/pyo3/src/daemon.rs b/crates/pyo3/src/daemon.rs
index ca1fa699d..1431d2cc1 100644
--- a/crates/pyo3/src/daemon.rs
+++ b/crates/pyo3/src/daemon.rs
@@ -9,7 +9,7 @@
 use crate::system::PySystem;
 use fapolicy_daemon::fapolicyd::Version;
 use fapolicy_daemon::svc::State::{Active, Inactive};
-use fapolicy_daemon::svc::{wait_for_daemon, Handle};
+use fapolicy_daemon::svc::{wait_for_service, Handle};
 use pyo3::exceptions::PyRuntimeError;
 use pyo3::prelude::*;
 
@@ -77,13 +77,13 @@ impl PyHandle {
 
     #[args(timeout = 15)]
     pub fn wait_until_active(&self, timeout: usize) -> PyResult<()> {
-        wait_for_daemon(&self.rs, Active, timeout)
+        wait_for_service(&self.rs, Active, timeout)
             .map_err(|e| PyRuntimeError::new_err(format!("{:?}", e)))
     }
 
     #[args(timeout = 15)]
     pub fn wait_until_inactive(&self, timeout: usize) -> PyResult<()> {
-        wait_for_daemon(&self.rs, Inactive, timeout)
+        wait_for_service(&self.rs, Inactive, timeout)
             .map_err(|e| PyRuntimeError::new_err(format!("{:?}", e)))
     }
 }
diff --git a/crates/pyo3/src/profiler.rs b/crates/pyo3/src/profiler.rs
index 1206ea7c4..b662e9023 100644
--- a/crates/pyo3/src/profiler.rs
+++ b/crates/pyo3/src/profiler.rs
@@ -6,7 +6,9 @@
  * file, You can obtain one at https://mozilla.org/MPL/2.0/.
  */
 
+use chrono::Utc;
 use fapolicy_analyzer::users::read_users;
+use fapolicy_daemon::fapolicyd::wait_until_ready;
 use pyo3::exceptions::PyRuntimeError;
 use pyo3::prelude::*;
 use pyo3::{PyResult, Python};
@@ -18,9 +20,8 @@ use std::path::PathBuf;
 use std::process::{Child, Command, Output, Stdio};
 use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::Arc;
-use std::thread;
 use std::time::{Duration, SystemTime};
-use tempfile::{NamedTempFile, PersistError};
+use std::{io, thread};
 
 use fapolicy_daemon::profiler::Profiler;
 use fapolicy_rules::read::load_rules_db;
@@ -47,7 +48,7 @@ impl PyProfiler {
     #[new]
     fn new() -> Self {
         Self {
-            log_dir: Some("/tmp".to_string()),
+            log_dir: Some("/var/tmp".to_string()),
             ..Default::default()
         }
     }
@@ -153,7 +154,7 @@ impl PyProfiler {
 
         // set the daemon stdout log, aka the events log
         if let Some((_, path)) = events_log.as_ref() {
-            rs.stdout_log = Some(path.clone());
+            rs.events_log = Some(path.clone());
         }
 
         // build the target commands
@@ -171,99 +172,111 @@ impl PyProfiler {
 
         // outer thread is responsible for daemon control
         thread::spawn(move || {
-            rs.activate_with_rules(db.as_ref())
-                .expect("activate profiler");
-
-            // inner thread is responsible for target execution
-            let inner = thread::spawn(move || {
-                for (mut cmd, args) in targets {
-                    if term.load(Ordering::Relaxed) {
-                        break;
-                    }
-
-                    // start the process, wrapping in the execd helper
-                    let mut execd = Execd::new(cmd.spawn().unwrap());
-
-                    // the process is now alive
-                    alive.store(true, Ordering::Relaxed);
-
-                    let pid = execd.pid().expect("pid");
-                    let handle = ExecHandle::new(
-                        pid,
-                        args,
-                        term.clone(),
-                        // todo;; clean this up...
-                        events_log.as_ref().map(|x| x.1.display().to_string()),
-                        stdout_log.as_ref().map(|x| x.1.display().to_string()),
-                        stderr_log.as_ref().map(|x| x.1.display().to_string()),
-                    );
-                    let start = SystemTime::now();
-
-                    if let Some(cb) = cb_exec.as_ref() {
-                        Python::with_gil(|py| {
-                            if cb.call1(py, (handle.clone(),)).is_err() {
-                                eprintln!("'exec' callback failed");
-                            }
-                        });
-                    }
-
-                    // loop on target completion status, providing opportunity to interrupt
-                    while let Ok(true) = execd.running() {
-                        thread::sleep(Duration::from_secs(1));
+            // start the daemon and wait until it is ready
+            let start_profiling_daemon = rs
+                .activate_with_rules(db.as_ref())
+                .and_then(|_| wait_until_ready(&events_log.as_ref().unwrap().1))
+                .map_err(|e| e.to_string());
+
+            // if profiling daemon is not ready do not spawn target threads
+            let profiling_res = if start_profiling_daemon.is_ok() {
+                // inner thread is responsible for target execution
+                let target_thread = thread::spawn(move || {
+                    for (mut cmd, args) in targets {
                         if term.load(Ordering::Relaxed) {
-                            execd.kill().expect("kill fail (term)");
                             break;
                         }
-                        if let Some(cb) = cb_tick.as_ref() {
-                            let t = SystemTime::now()
-                                .duration_since(start)
-                                .expect("system time")
-                                .as_secs();
+
+                        // start the process, wrapping in the execd helper
+                        let mut execd = Execd::new(cmd.spawn().unwrap());
+
+                        // the process is now alive
+                        alive.store(true, Ordering::Relaxed);
+
+                        let pid = execd.pid().expect("pid");
+                        let handle = ExecHandle::new(
+                            pid,
+                            args,
+                            term.clone(),
+                            // todo;; clean this up...
+                            events_log.as_ref().map(|x| x.1.display().to_string()),
+                            stdout_log.as_ref().map(|x| x.1.display().to_string()),
+                            stderr_log.as_ref().map(|x| x.1.display().to_string()),
+                        );
+                        let start = SystemTime::now();
+
+                        if let Some(cb) = cb_exec.as_ref() {
                             Python::with_gil(|py| {
-                                if cb.call1(py, (handle.clone(), t)).is_err() {
-                                    eprintln!("'tick' callback failed");
+                                if cb.call1(py, (handle.clone(),)).is_err() {
+                                    eprintln!("'exec' callback failed");
                                 }
                             });
                         }
-                    }
 
-                    // we need to wait on the process to die, instead of just blocking
-                    // this loop provides the ability to add a harder stop impl, abort
-                    term.store(false, Ordering::Relaxed);
-                    while let Ok(true) = execd.running() {
-                        if term.load(Ordering::Relaxed) {
-                            execd.abort().expect("abort fail (term)");
-                            break;
+                        // loop on target completion status, providing opportunity to interrupt
+                        while let Ok(true) = execd.running() {
+                            thread::sleep(Duration::from_secs(1));
+                            if term.load(Ordering::Relaxed) {
+                                execd.kill().expect("kill fail (term)");
+                                break;
+                            }
+                            if let Some(cb) = cb_tick.as_ref() {
+                                let t = SystemTime::now()
+                                    .duration_since(start)
+                                    .expect("system time")
+                                    .as_secs();
+                                Python::with_gil(|py| {
+                                    if cb.call1(py, (handle.clone(), t)).is_err() {
+                                        eprintln!("'tick' callback failed");
+                                    }
+                                });
+                            }
+                        }
+
+                        // we need to wait on the process to die, instead of just blocking
+                        // this loop provides the ability to add a harder stop impl, abort
+                        term.store(false, Ordering::Relaxed);
+                        while let Ok(true) = execd.running() {
+                            if term.load(Ordering::Relaxed) {
+                                execd.abort().expect("abort fail (term)");
+                                break;
+                            }
+                            thread::sleep(Duration::from_secs(1));
                         }
-                        thread::sleep(Duration::from_secs(1));
-                    }
 
-                    // no longer alive
-                    alive.store(false, Ordering::Relaxed);
+                        // no longer alive
+                        alive.store(false, Ordering::Relaxed);
 
-                    // write the target stdout/stderr if configured
-                    let output: Output = execd.into();
-                    if let Some((ref mut f, _)) = stdout_log {
-                        f.write_all(&output.stdout).unwrap();
-                    }
-                    if let Some((ref mut f, _)) = stderr_log {
-                        f.write_all(&output.stderr).unwrap();
+                        // write the target stdout/stderr if configured
+                        let output: Output = execd.into();
+                        if let Some((ref mut f, _)) = stdout_log {
+                            f.write_all(&output.stdout).unwrap();
+                        }
+                        if let Some((ref mut f, _)) = stderr_log {
+                            f.write_all(&output.stderr).unwrap();
+                        }
                     }
-                }
-            });
+                });
 
-            if let Some(e) = inner.join().err() {
-                eprintln!("exec thread panic {:?}", e);
-            }
+                // outer thread waits on the target thread to complete
+                target_thread.join().map_err(|e| format!("{:?}", e))
+            } else {
+                start_profiling_daemon
+            };
 
-            rs.deactivate().expect("deactivate profiler");
+            // attempt to deactivate if active
+            if rs.is_active() && rs.deactivate().is_err() {
+                eprintln!("profiler deactivate failed");
+            }
 
-            // callback when all targets are completed / cancelled / failed
-            // callback failure here is considered fatal due to the
-            // transactional completion nature of this call
+            // done; all targets are completed / cancelled / failed
             if let Some(cb) = cb_done.as_ref() {
-                Python::with_gil(|py| cb.call0(py).expect("done callback failed"));
+                if Python::with_gil(|py| cb.call0(py)).is_err() {
+                    eprintln!("'done' callback failed");
+                }
             }
+
+            profiling_res.expect("profiling failure");
         });
 
         Ok(proc_handle)
@@ -272,21 +285,22 @@ impl PyProfiler {
 
 type LogPath = Option<(File, PathBuf)>;
 type LogPaths = (LogPath, LogPath, LogPath);
-fn create_log_files(log_dir: Option<&String>) -> Result<LogPaths, PersistError> {
+fn create_log_files(log_dir: Option<&String>) -> Result<LogPaths, io::Error> {
     if let Some(log_dir) = log_dir {
-        let event_log = make_log_path(log_dir)?;
-        let target_stdout = make_log_path(log_dir)?;
-        let target_stderr = make_log_path(log_dir)?;
+        let t = Utc::now().timestamp();
+
+        let event_log = make_log_path(log_dir, t, "events")?;
+        let target_stdout = make_log_path(log_dir, t, "stdout")?;
+        let target_stderr = make_log_path(log_dir, t, "stderr")?;
         return Ok((event_log, target_stdout, target_stderr));
     }
     Ok((None, None, None))
 }
 
-fn make_log_path(log_dir: &str) -> Result<LogPath, PersistError> {
-    NamedTempFile::new_in(log_dir)
-        .ok()
-        .map(|f| f.keep())
-        .transpose()
+fn make_log_path(log_dir: &str, t: i64, suffix: &str) -> Result<LogPath, io::Error> {
+    let path = PathBuf::from(format!("{log_dir}/.fapa{t}.{suffix}"));
+    let file = File::create(&path)?;
+    Ok(Some((file, path)))
 }
 
 /// Terminable process handle returned to python after starting profiling
diff --git a/crates/tools/src/fapolicy_profiler.rs b/crates/tools/src/fapolicy_profiler.rs
index e32322f6f..4feb71e7a 100644
--- a/crates/tools/src/fapolicy_profiler.rs
+++ b/crates/tools/src/fapolicy_profiler.rs
@@ -65,7 +65,7 @@ fn main() -> Result<(), Box<dyn Error>> {
             );
             std::fs::remove_file(&path)?;
         }
-        profiler.stdout_log = Some(path);
+        profiler.events_log = Some(path);
     }
 
     profiler.activate_with_rules(db.as_ref())?;
diff --git a/fapolicy_analyzer/ui/features/profiler_feature.py b/fapolicy_analyzer/ui/features/profiler_feature.py
index f9e786f25..770830ba4 100644
--- a/fapolicy_analyzer/ui/features/profiler_feature.py
+++ b/fapolicy_analyzer/ui/features/profiler_feature.py
@@ -16,6 +16,7 @@
 from typing import Callable, Dict
 
 import gi
+import logging
 from rx import of
 from rx.core.pipe import pipe
 from rx.operators import catch, map
@@ -119,15 +120,17 @@ def on_done():
             # set user, pwd, envs
             p.user = args.get("uid", None)
             p.pwd = args.get("pwd", None)
-            p.env = args.get("env", None)
-        except RuntimeError:
+            p.env = args.get("env_dict", None)
+        except RuntimeError as e:
+            logging.error(f"profiler init failed {e}")
             dispatch(profiler_initialization_error(PROFILER_INIT_ERROR))
             return profiler_done()
 
         # execute and dispatch
         try:
             _handle = p.profile(cmd)
-        except RuntimeError:
+        except RuntimeError as e:
+            logging.error(f"profiler exec failed {e}")
             dispatch(profiler_execution_error(PROFILER_EXEC_ERROR))
             return profiler_done()
 
diff --git a/fapolicy_analyzer/ui/profiler_page.py b/fapolicy_analyzer/ui/profiler_page.py
index 2f3e04369..43057c0b1 100644
--- a/fapolicy_analyzer/ui/profiler_page.py
+++ b/fapolicy_analyzer/ui/profiler_page.py
@@ -117,7 +117,7 @@ def handle_done(self, state: ProfilerState):
         self.display_log_output([
             (f"`{state.cmd}` stdout", state.stdout_log),
             (f"`{state.cmd}` stderr", state.stderr_log),
-            ("fapolicyd stdout", state.events_log),
+            ("fapolicyd", state.events_log),
         ])
         self.analysis_file = state.events_log
         self.terminating = False
diff --git a/fapolicy_analyzer/ui/reducers/profiler_reducer.py b/fapolicy_analyzer/ui/reducers/profiler_reducer.py
index 0619a86f5..4bc787564 100644
--- a/fapolicy_analyzer/ui/reducers/profiler_reducer.py
+++ b/fapolicy_analyzer/ui/reducers/profiler_reducer.py
@@ -104,7 +104,7 @@ def handle_start_profiling_request(state: ProfilerState, action: Action) -> Prof
     args: Dict[str, str] = action.payload
     uid = args.get("uid", None)
     pwd = args.get("pwd", None)
-    env = args.get("env_dict", None)
+    env = args.get("env", None)
     return derive_profiler_state(ProfilerState, state, uid=uid, pwd=pwd, env=env)
 
 


Test patch: