Profiler fixes

[jw3]

Address a couple of bugs found in profiler after #770

Fixes a bug in the profiler reducer that only happened when there was env, regressed when env_dict was added to the state. This was causing silent crashes likely because the redux error handling isn't wired the best way. Will revisit this.

Fixes a bug on RHEL 8 where the fapolicyd output was not being written to file due to SELinux denial. After extensive trials the best approach was to drop systemd control and implement our own daemon control. Another benefit is that this avoids a couple bugs on the el8 systemd v239 that had to be worked around. This also avoids the somewhat suspect practice of writing the unit file on demand, though in hindsight we could of used systemd-run.

Add fapolicyd runtime log parsing that allows the profiler to wait until the fapolicyd service is ready before kicking off the target process. Even with the service integration mentioned in #531 the timing issues were not resolved. This is because the "up" status of the daemon does not mean "ready to observe events", there is a space between the two the duration of which depends on the size of the trust database. We were aware of this previously, it just got kicked down the road until now.

Closes #531 Closes #808

[jw3]

The silent failure observed in the env bug was due to a cast error in some generic python code. It was programmer error, cannot be triggered by user input if the code is correct.

Should investigate it with a unit test.

[tparchambault]

Env var PATH test example good to go...

Minor issue but RHEL8.6 rpm install shows subsection label in the Profiler Target Output pane that is incorrect relative to invoking fapolicyd --debug --permissive directly.

[jw3]

Using the systemd logging StandardOutput and StandardError has two challenges on el8 (1) the older systemd v239 available on el8 has a related bug that v240 fixes and (2) selinux restricts systemd writing log files.

Given both of these, trying to simply redirect the output from the unit ExecStart.

[jw3]

@tparchambault this is ready for another look :eyes:

[tparchambault]

Using the systemd logging StandardOutput and StandardError has two challenges on el8 (1) the older systemd v239 available on el8

That was my assumption w/the shipped Rhel8 fapolidyd version vs the latest fapd being another complicating factor.

Will test over Rhel86 later today.

[jw3]

I didnt notice that fapolicyd versions had any impact.

[jw3]

4. Default to home dir as pwd for non root users when pwd is not specified.

On the fence with implementing this now.

It does not appear to have been implemented previously.

https://github.com/ctc-oss/fapolicy-analyzer/issues/808#issuecomment-1458691712

[tparchambault]

Ran three trials w/o success unfortunately.

The first two trials attempted to run /tmp/my-ls -l as the user toma. No output observed in the Target Output pane with the following CL logging text:

DEBUG:root:disposing of subscription for class SystemTrustDatabaseAdmin INFO:root:validateArgs() DEBUG:root:validateArgs({'cmd': '/tmp/my-ls', 'arg': '-l', 'uid': 'toma', 'pwd': '/tmp', 'env': None} DEBUG:root:Processing current working dir: /tmp DEBUG:root:FaProfSession::validateArgs() --> pwd verified DEBUG:root:Entry text = {'cmd': '/tmp/my-ls', 'arg': '-l', 'uid': 'toma', 'pwd': '/tmp', 'env': None, 'env_dict': None} DEBUG:root:dispatch( START_PROFILING_REQUEST ) waiting on daemon to be Active... daemon is now Active thread '' panicked at 'fapolicyd ready: NotReady', crates/pyo3/src/profiler.rs:179:74 note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

Trial 2: Identical result to Trial 1 unfortunately.

[jw3]

@tparchambault hmm I was able to recreate the first reports, but using the same args as you against this current PR results in success on my el 8.6.

I am going to work some additional error handling around some of these spots into this PR, might help see what the issue is on your machine.

[tparchambault]

The third trial was executed w/RUST_BACKTRACE=1 however the Rust bt was not displayed. I suspect that the pkexec environment spawned a restricted environment. I'll modify the wrapper to pass in the RUST_BACKTRACE env var tomorrow AM. Using the distro provided /usr/bin/ls for simplicity with the same result.

INFO:root:validateArgs() DEBUG:root:validateArgs({'cmd': '/usr/bin/ls', 'arg': None, 'uid': None, 'pwd': '/tmp', 'env': None} DEBUG:root:Processing current working dir: /tmp DEBUG:root:FaProfSession::validateArgs() --> pwd verified DEBUG:root:Entry text = {'cmd': '/usr/bin/ls', 'arg': None, 'uid': None, 'pwd': '/tmp', 'env': None, 'env_dict': None} DEBUG:root:dispatch( START_PROFILING_REQUEST ) thread '' panicked at 'fapolicyd ready: NotReady', crates/pyo3/src/profiler.rs:179:74 note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

[jw3]

@tparchambault

thread '' panicked at 'fapolicyd ready: NotReady', crates/pyo3/src/profiler.rs:179:74

NotReady indicates that the profiler fapolicyd (aka fapolicyp) was never observed as coming online. You could check /usr/lib/systemd/system/fapolicyp.service, try to start it manually and see what happens.

[jw3]

Rust backtrace will not help. The panic message says enough.

[jw3]

See if you can find out what the fapolicyp service is doing, thats where it is going wrong.

Here is a sample unit file if it got cleaned up.

[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=sh -c 'exec /usr/sbin/fapolicyd --debug --permissive --no-details 2> /tmp/fapolicyp.test'

[tparchambault]

fapolicyp service was running:

[toma@son-o-wimpy ~]$ sudo systemctl status fapolicyp.service [sudo] password for toma: Sorry, try again. [sudo] password for toma: ● fapolicyp.service - File Access Profiling Daemon Loaded: loaded (/usr/lib/systemd/system/fapolicyp.service; disabled; vendor > Active: active (running) since Tue 2023-03-07 18:06:49 EST; 1h 7min ago Main PID: 7765 (fapolicyd) Tasks: 4 (limit: 23516) Memory: 902.5M CGroup: /system.slice/fapolicyp.service └─7765 /usr/sbin/fapolicyd --debug --permissive --no-details

Mar 07 18:06:49 son-o-wimpy systemd[1]: Started File Access Profiling Daemon.

[tparchambault]

Mystery solved. Thx.

[tparchambault]

Still seeing the same panic. Will pursue tomorrow morning after a reboot and update this thread.

See if you can find out what the fapolicyp service is doing, thats where it is going wrong.

The fapolicyp service is not getting shutdown but that's probably because of the panic. I stop it w/systemctl between trials now and still seeing the same line number. The RUST_BACKTRACE=FULL is currently useless w/mostly address = frames.

Does a template fapolicyp.service file get installed by the package or do you create it on the fly? I'll dig deeper tomorrow.

[tparchambault]

Thx for your help man.

[jw3]

The template is included in the source code.

I pushed a commit that should clean up better around this panic. The panic is important, the cleanup after it is lacking. The last commit improves the situation to where it restores the system to a good state after failing to start.

[jw3]

Recreating my 8.6 vm in case I have some fix in the system making it work for me.

[tparchambault]

Recreating my 8.6 vm in case I have some fix in the system making it work for me.

Ditto at this end.

[jw3]

@tparchambault

I can recreate and have tested a bit.

Looks like it comes down to the redirected output not being written to the target file. This can be recreated both in the app and with the standalone unit file.

[jw3]

To help debug I added a hook into alternative service template. If /tmp/profiler.service is present it will be used rather than the static version from build time.

[jw3]

Looks like selinux sees fapolicyd as the subject of the write, through the io redirect, and rejects it due to fapolicyd not having access to the target object.

[tparchambault]

That's good work man.

I'll give your latest CI action RPM a spin on a rollbacked Rhel86.

[jw3]

I added a hook into alternative service template

This no longer exists. Neither does systemd control of the profiler service.

The current version works well here. Give it a spin @tparchambault

[jw3]

https://lists.fedoraproject.org/archives/list/selinux@lists.fedoraproject.org/thread/JQKHEKRJRRWOIRXRTBOOAB735AVBS3NP/

Similar issue - attempt to redirect produces empty file, selinux denials in the log for subject:fapolicyd object:our-log-path.

[tparchambault]

Tested over VBox RHEL 8.6 VM. Things look good from here also.

08 March 2023 Testing

Profiler Testing: /tmp/my-ls -l as the user toma in /tmp/

No obvious issues observed

Profiler Testing: my-ls -l as the user toma in /tmp/ with PATH

No obvious issues observed.

Profiler Testing: /tmp/my-ls -l as the user toma w/o a specified Working Directory

No obvious issues observed, other than working directory is root's HOME. Researching via prior Profiler rpms addressing JW's above comment currently in progress. Otherwise all systems go.

[tparchambault]

4. Default to home dir as pwd for non root users when pwd is not specified.

On the fence with implementing this now.

It does not appear to have been implemented previously.

#808 (comment)

Verified that @jw3 's observation is correct. Tested one of the final rpms w/the python subprocess based implementation of the Profiling functionality. If the Working Directory is not specified the pwd is root's HOME directory.

[jw3]

Thanks @tparchambault , appreciate the reviews 👍