+++ This bug was initially created as a clone of Bug #1812121 +++

Description of problem:

Currently fapolicyd is silent, causing support members a hard life: when some issue is due to fapolicyd, it's hard to find what is going on, because no log is seen at all, so nobody thinks about fapolicyd being the potential culprit.
This makes us lose a lot of time investigating issues.

Additionally, running fapolicyd in "debug-deny" mode requires to hack the fapolicyd.service unit, as shown below:

Original (in /usr/lib/systemd/system):
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Type=forking
ExecStart=/usr/sbin/fapolicyd
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

Hacked to see denies (in /etc/systemd/system):
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
Type=simple
ExecStart=/usr/sbin/fapolicyd --debug-deny
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

The fapolicyd options should be read from /etc/sysconfig/fapolicyd or similar file and not require the daemon to be put in the foreground.

Version-Release number of selected component (if applicable):

fapolicyd-0.8.10-3.el8_1.1.x86_64

— Additional comment from Renaud Métrich on 2020-03-11 06:45:03 UTC —

For the first issue (not seeing denied), in fact the deny is seen in audit.log, but it's cryptic and not really useful (except at least detecting there is an issue):
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
time->Wed Mar 11 07:35:45 2020
type=PROCTITLE msg=audit(1583908545.548:109): proctitle=2F6C696236342F6C642D6C696E75782D7838362D36342E736F2E32002F62696E2F62617368
type=PATH msg=audit(1583908545.548:109): item=0 name="/lib64/libc.so.6" inode=50333113 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:lib_t:s0 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
type=CWD msg=audit(1583908545.548:109): cwd="/root"
type=SYSCALL msg=audit(1583908545.548:109): arch=c000003e syscall=257 success=no exit=-1 a0=ffffff9c a1=7ffdfa3b8af0 a2=80000 a3=0 items=1 ppid=1471 pid=1472 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=2 comm="ld-linux-x86-64" exe="/usr/lib64/ld-2.28.so" subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 key=(null)
type=FANOTIFY msg=audit(1583908545.548:109): resp=2
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

This was taken while executing "ldd /bin/bash".

From a previous conversation with Steve, I remember Kernel folks didn't want to add the "rule number" in the message.
Hence having fapolicyd directly write to the log would be useful (and less confusing than the message above).

— Additional comment from RHEL Program Management on 2020-05-14 07:31:08 UTC —

The keyword FutureFeature has been added. If this bug is not a FutureFeature, please remove from the Summary field any strings containing "RFE, rfe, FutureFeature, FEAT, Feat, feat".

— Additional comment from Dalibor Pospíšil on 2020-05-22 13:00:43 UTC —

The denials should be mostly audit logged. Did you check it? I'm not sure how much useful is the information from the audit messages.

I guess this is quite good UX POV and we should definitely improve it ASAP.

We should put together all the possibilities how to let the admin know what is happening wrong in the most descriptive way.

— Additional comment from Radovan Sroka on 2020-07-29 08:53:02 UTC —

(In reply to Renaud Métrich from comment #0)
> Description of problem:
>
> Currently fapolicyd is silent, causing support members a hard life: when
> some issue is due to fapolicyd, it's hard to find what is going on, because
> no log is seen at all, so nobody thinks about fapolicyd being the potential
> culprit.
> This makes us lose a lot of time investigating issues.
>
> Additionally, running fapolicyd in "debug-deny" mode requires to hack the
> fapolicyd.service unit, as shown below:
>
> Original (in /usr/lib/systemd/system):
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
> Type=forking
> ExecStart=/usr/sbin/fapolicyd
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
>
> Hacked to see denies (in /etc/systemd/system):
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
> Type=simple
> ExecStart=/usr/sbin/fapolicyd --debug-deny
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
>
>
> The fapolicyd options should be read from /etc/sysconfig/fapolicyd or
> similar file and not require the daemon to be put in the foreground.
>
>
> Version-Release number of selected component (if applicable):
>
> fapolicyd-0.8.10-3.el8_1.1.x86_64

Hello Renaud,

there is a new syslog_format option for fapolicyd.conf in RHEL8.3 beta. Is it helpful?
Is the latest fapolicyd more convenient?
Can we actually close this bug?

— Additional comment from Renaud Métrich on 2020-08-05 07:06:40 UTC —

Hi Radovan,

I can see indeed that there is a new syslog_format option but I do not see any change.
Having a deny doesn't show anything either in audit or other log file.

Am I missing something?

— Additional comment from RHEL Program Management on 2020-09-30 10:12:47 UTC —

pm_ack is no longer used for this product. The flag has been reset.

See https://issues.redhat.com/browse/PTT-1821 for additional details or contact lmiksik@redhat.com if you have any questions.

— Additional comment from Radovan Sroka on 2020-10-13 08:05:45 UTC —

(In reply to Renaud Métrich from comment #5)
> Hi Radovan,
>
> I can see indeed that there is a new syslog_format option but I do not see
> any change.
> Having a deny doesn't show anything either in audit or other log file.
>
> Am I missing something?

Hello Renaud,

there is ongoing work on kernel and fapolicyd so there will be some debugging info available...

https://marc.info/?l=linux-fsdevel&m=160148235110009&w=2
https://github.com/stevegrubb/fapolicyd/commit/d09619f8ca976642b2794a132be79655862180a7.patch

It should get into 8.4.

— Additional comment from Steve Grubb on 2020-11-10 18:12:44 UTC —

You should not use a deny in the rule, use a deny_audit or deny_syslog to get something recorded. The shipped rules do this by default. So, there shouldn't need to be the need to do anything else.

— Additional comment from Renaud Métrich on 2020-11-13 08:24:42 UTC —

Hi Steve,

With default rules shipped by fapolicyd-1.0-3.el8_3.2 (RHEL8.3), I do not see any deny at all in the audit log.
I still need to use --debug-deny to see something useful.

Reproducer:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

1. cp /bin/true /tmp/
2. useradd foo
3. su - foo

$ /tmp/true
-bash: /tmp/true: Operation not permitted
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

--> Nothing printed in audit.log, nor in daemon output

After enabling "--debug-deny", I see the rule being hit in daemon output:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
fapolicyd[28317]: rule=13 dec=deny_audit perm=execute auid=0 pid=28456 exe=/usr/bin/bash : path=/tmp/true ftype=application/x-executable
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

— Additional comment from Steve Grubb on 2020-11-13 13:08:27 UTC —

use: ausearch --start today -m fanotify -i

also, execution in /tmp may be blocked by mount permissions and not fapolicyd. It's better to test against the homedir.

— Additional comment from Renaud Métrich on 2020-11-13 13:20:43 UTC —

"ausearch --start today -m fanotify -i" doesn't work.

There is just no FANOTIFY message in the audit log at all.

I tested, stopping fapolicyd "fixes" the problem, so /tmp is not culprit here (it's actually / on my system).

— Additional comment from Steve Grubb on 2020-11-13 13:44:22 UTC —

Is the audit daemon running? Are you on the 8.3 kernel?

— Additional comment from Renaud Métrich on 2020-11-13 14:14:58 UTC —

Yes, 8.3 and auditd running.

— Additional comment from Steve Grubb on 2020-11-13 14:27:27 UTC —

I suspect that maybe there are no audit rules loaded? If so, the audit system suppresses some events. I think this may be a kernel problem.

cp /usr/share/audit/sample-rules/43-module-load.rules /etc/audit/rules.d/
service auditd stop
service auditd start

Should be all better.

— Additional comment from Renaud Métrich on 2020-11-13 14:54:58 UTC —

Exact! I had no rule.

With sample rules, this know works:

type=PROCTITLE msg=audit(11/13/2020 15:49:48.108:185) : proctitle=-bash
type=PATH msg=audit(11/13/2020 15:49:48.108:185) : item=0 name=/tmp/true inode=16797947 dev=fd:00 mode=file,755 ouid=root ogid=root rdev=00:00 obj=unconfined_u:object_r:user_tmp_t:s0 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=CWD msg=audit(11/13/2020 15:49:48.108:185) : cwd=/home/user
type=SYSCALL msg=audit(11/13/2020 15:49:48.108:185) : arch=x86_64 syscall=execve success=no exit=EPERM(Operation not permitted) a0=0x561984a521f0 a1=0x561984a51040 a2=0x561984a4e470 a3=0x8 items=1 ppid=2073 pid=2117 auid=root uid=user gid=user euid=user suid=user fsuid=user egid=user sgid=user fsgid=user tty=pts0 ses=4 comm=bash exe=/usr/bin/bash subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 key=(null)
type=FANOTIFY msg=audit(11/13/2020 15:49:48.108:185) : resp=deny

But well, this doesn't help finding which rule is hit.

— Additional comment from Steve Grubb on 2020-11-13 15:32:10 UTC —

Upstream commit b6da9dc adds a note to the rules man page about needing an audit rule.

You are step by step recreating this upstream issue:

https://github.com/linux-application-whitelisting/fapolicyd/issues/84

Hopefully a fix for this can land in 8.4 if the upstream kernel maintainers approve the patch.

— Additional comment from Thorsten Scherf on 2020-11-19 15:26:04 UTC —

This BZ is related:
https://bugzilla.redhat.com/show_bug.cgi?id=1898964

The idea was to make 'fanotify' messages available by default in sosreports. This is now fixed upstream: https://github.com/sosreport/sos/pull/2314/commits/afb2251a463f0fa8941561929522901bd40ba7d1

But of course this requires that 'fanotify' are stored in audit.log. I guess that's not the case with every customer so my patch probably won't help too much. I'd also like to see 'fanotify' messages showing up in audit.log even when no audit rule is loaded. Similar to what we see with 'avc' messages.

— Additional comment from Radovan Sroka on 2021-01-06 08:16:03 UTC —

(In reply to Radovan Sroka from comment #7)
> (In reply to Renaud Métrich from comment #5)
> > Hi Radovan,
> >
> > I can see indeed that there is a new syslog_format option but I do not see
> > any change.
> > Having a deny doesn't show anything either in audit or other log file.
> >
> > Am I missing something?
>
> Hello Renaud,
>
> there is ongoing work on kernel and fapolicyd so there will be some
> debugging info available...
>
> https://marc.info/?l=linux-fsdevel&m=160148235110009&w=2
> https://github.com/stevegrubb/fapolicyd/commit/
> d09619f8ca976642b2794a132be79655862180a7.patch
>
> It should get into 8.4.

The patch was not merged yet. Setting ITM16.

— Additional comment from Radovan Sroka on 2021-01-06 08:20:25 UTC —

Does it make sense to ship our own dummy audit rule so this audit logging will be on automatically after fapolicyd installation?

— Additional comment from Steve Grubb on 2021-01-06 13:52:00 UTC —

Since we are already linking against libaudit, we can query the kernel to see if any rules are loaded and issue a warning via syslog. We would need to do this before dropping capabilities, though. I'm not sure we want to set a precedent of installing rules. Not even auditd does that except for the basic rule that sets the backlog size from the default of 64. And then we have the Fedora mandate that audit must be disabled by default per FESCO orders.

— Additional comment from Dalibor Pospíšil on 2021-01-08 09:02:27 UTC —

So what exactly will be the scope here?
I guess, we need to deliver the fix in fapolicyd to include the rule number to the response and probably just document the necessity of setting up some audit rule to make auditd to stand logging.

The kernel part should be probably tracked by a kernel BZ.

Are even able to deliver it within 8.4.0 if we depend on kernel?

— Additional comment from Steve Grubb on 2021-01-08 17:35:04 UTC —

It seems to me that there are 3 issues: not getting audit events, user space needs to describe what failed, the kernel needs to carry that indication through to the results.

The first has been immedately solved by updating documentation. We can also add a technical solution to detect that auditing is desired and the kernel is misconfigured. The second and third items can actually be solved today by switching to deny_syslog. However, another solution has been proposed so that this may be accomplished by the audit logs. Upstream wanted a solution that substantially differs from what has been proposed and more research needs to be done. Doing this by audit will likely be an 8.5 target. So, I'd suggest the customer use deny_syslog today.

— Additional comment from Radovan Sroka on 2021-01-11 10:24:46 UTC —

(In reply to Steve Grubb from comment #22)
> It seems to me that there are 3 issues: not getting audit events, user space
> needs to describe what failed, the kernel needs to carry that indication
> through to the results.
>
> The first has been immedately solved by updating documentation. We can also
> add a technical solution to detect that auditing is desired and the kernel
> is misconfigured. The second and third items can actually be solved today by
> switching to deny_syslog. However, another solution has been proposed so
> that this may be accomplished by the audit logs. Upstream wanted a solution
> that substantially differs from what has been proposed and more research
> needs to be done. Doing this by audit will likely be an 8.5 target. So, I'd
> suggest the customer use deny_syslog today.

So I propose to document "not getting audit events" part in the rebase bugzilla.

This bugzilla will be postponed to 8.5.0 where the user space and the kernel patch
will be available. Therefore ACs cover "getting the information what failed" part
via syslog and via audit.

Do we want to test the "getting the information what failed" via syslog in 8.4.0?
If yes, the AC could be part of the rebase bugzilla as well.

What do you think?

— Additional comment from Dalibor Pospíšil on 2021-01-11 17:58:53 UTC —

(In reply to Radovan Sroka from comment #23)
> So I propose to document "not getting audit events" part in the rebase
> bugzilla.

This might deserve even some KB article as this is quite generic issue. There might be some already so we may refer to it.

>
> This bugzilla will be postponed to 8.5.0 where the user space and the kernel
> patch
> will be available. Therefore ACs cover "getting the information what failed"
> part
> via syslog and via audit.
>
> Do we want to test the "getting the information what failed" via syslog in
> 8.4.0?
> If yes, the AC could be part of the rebase bugzilla as well.

Yes, this makes sense as the deny_syslog is not much tested.

>
> What do you think?

So we can postpone this one and mark it as known issue in the doc field and describe in the doc text possibly with the reference to the KB?.

— Additional comment from Steve Grubb on 2021-01-11 19:58:17 UTC —

FYI, deny_syslog is essentially the debug mode. The only difference is LOG_INFO vs LOG_DEBUG. The only issue that I know of that was fixed after 1.0 was released is this:
https://github.com/linux-application-whitelisting/fapolicyd/commit/8738bde663e7c0c7c93acc49beec5d168503cfd1

Logging obj_trust is not done by default, so most people won't see it.

— Additional comment from RHEL Program Management on 2021-02-15 10:05:30 UTC —

The keyword FutureFeature has been added. If this bug is not a FutureFeature, please remove from the Summary field any strings containing "RFE, rfe, FutureFeature, FEAT, Feat, feat".

— Additional comment from Dalibor Pospíšil on 2021-06-17 09:21:50 UTC —

Actually, there's no plan to deliver an update in 8.5 at all.

— Additional comment from RHEL Program Management on 2022-03-08 08:41:23 UTC —

860ITRStrip 900ITRStrip AtFullFreeze

Attention assignees: This BZ was automatically returned to the backlog by changing the Internal Target Release (ITR) to '---'. The change was made because the final release+ deadline was passed and no request for an exception, blocker, or zstream was made. Please consult with your PO and team to decide what action to take next with this BZ:

1. Important changes that cannot wait for the next minor release should request an exception or blocker (Reset ITR/ITM, set exception? or blocker?, save, then follow the instructions appended to the BZ).

2. Bug fixes that may be best managed post-release can start following the z-stream process (Set ZTR, ITR, and zstream? flag)

3. Changes that can wait for a future release can have their ITR/ITM set to the optimal release target. Acks are preserved and release+ will again be added.

If you are unsure of what action to take it is safe to leave this BZ in the backlog for the time being. You may wish to unset your acks in this case.

— Additional comment from Thorsten Scherf on 2022-10-30 20:20:54 UTC —

May I ask what is the current status with this request?

There is a similar BZ that was recently opened by a different customer:

https://bugzilla.redhat.com/show_bug.cgi?id=2138082

— Additional comment from Radovan Sroka on 2022-10-31 09:54:05 UTC —

(In reply to Thorsten Scherf from comment #29)
> May I ask what is the current status with this request?
>
> There is a similar BZ that was recently opened by a different customer:
>
> https://bugzilla.redhat.com/show_bug.cgi?id=2138082

It is blocked by https://bugzilla.redhat.com/show_bug.cgi?id=2008229.

— Additional comment from Richard on 2023-05-16 14:23:38 UTC —

Any chance of this coming the RHEL 8 soon? Troubleshooting fapolicyd is really a pain without proper logging.

— Additional comment from Dalibor Pospíšil on 2023-05-16 19:24:58 UTC —

Yeah, I'm afraid we will be still blocked on the kernel bits. As a workaround for the troubleshooting one can use syslog logging where you can get much more detailed information.

Acceptance Criteria:

• the audit messages contain the rule number which caused the actual decision