RFE: tie FEATURE_CHANGE records to syscall

[rgbriggs]

Tie FEATURE_CHANGE records to a syscall since it is user attributable.

[pcmoore]

I'm currently of the opinion that we should connect as many records as possible when they are all part of the same event. So thumbs up from me.

[stevegrubb]

I'd like to ask why this issue exists at all? What problem does adding a SYSCALL record fix?

[rgbriggs]

On 2018-04-09 12:13, Steve Grubb wrote:

I'd like to ask why this issue exists at all? What problem does adding a SYSCALL record fix?

It collects all records from the same event into one event so that they aren't spread across multiple audit timestamps and serial numbers.

[rgbriggs]

On 2018-04-09 12:15, Richard Guy Briggs wrote:

On 2018-04-09 12:13, Steve Grubb wrote:

I'd like to ask why this issue exists at all? What problem does adding a SYSCALL record fix?

It collects all records from the same event into one event so that they aren't spread across multiple audit timestamps and serial numbers.

One future use case is the same container ID auxiliary record that would be added to both event instantiations of the same physical event.

[rgbriggs]

Test with ausearch -m feature_change, ausearch -ts recent -m feature_change to find the FEATURE_CHANGE record with feature=loginuid_immutable associated with a sendto SYSCALL.

[stevegrubb]

I still don't understand. The FEATURE_CHANGE event is complete. It has everything needed. So, I don't understand the comment about collecting all records into one event. Can you show me actual output of the current logs that illustrates the problem?

[rgbriggs]

On 2018-04-11 15:58, Steve Grubb wrote:

I still don't understand. The FEATURE_CHANGE event is complete. It has everything needed. So, I don't understand the comment about collecting all records into one event. Can you show me actual output of the current logs that illustrates the problem?

To avoid one event looking like two.

[stevegrubb]

To avoid one event looking like two.

Can you give me an example of how they look like two?

[pcmoore]

Can you give me an example of how they look like two?

If syscall records are being generated you will see a SYSCALL record with one timestamp and the FEATURE_CHANGE record with another.

[stevegrubb]

OK. Thanks. But how do I see this in my logs? There should be a reproducer or actual events so that we can see the actual problem. I just did:

ausearch --start today --raw > tmp.log

Using vi to search for FEATURE_CHANGE events, I find this:

node=x2 type=CONFIG_CHANGE msg=audit(1524055016.219:115): audit_backlog_limit=8192 old=8192 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 res=1^]AUID="unset" node=x2 type=CONFIG_CHANGE msg=audit(1524055016.219:116): audit_failure=1 old=1 auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 res=1^]AUID="unset" node=x2 type=FEATURE_CHANGE msg=audit(1524055016.219:117): ppid=906 pid=927 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="auditctl" exe="/usr/sbin/auditctl" subj=system_u:system_r:unconfined_service_t:s0 feature=loginuid_immutable old=0 new=1 old_lock=0 new_lock=1 res=1^]AUID="unset" UID="root" GID="root" EUID="root" SUID="root" FSUID="root" EGID="root" SGID="root" FSGID="root" node=x2 type=CONFIG_CHANGE msg=audit(1524055016.219:118): auid=4294967295 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 op=add_rule key="32bit-abi" list=4 res=1^]AUID="unset"

There is no SYSCALL record. So, what are we talking about? And if you look at the FEATURE_CHANGE event, it has complete subject information.

[pcmoore]

I kinda figured you of all people @stevegrubb would be able to setup audit to capture SYSCALL records, but here is a quick test that I did on my system, it should be trivial for you to reproduce.

First, for reference:

# uname -r
4.17.0-0.rc1.git1.1.1.secnext.fc29.x86_64
# rpm -q audit
audit-2.8.3-3.fc29.x86_64

Looking quickly at the auditctl sources it appears that it uses sendto(2) to talk netlink to the kernel, so starting with a freshly booted system I do the following to flush the default rules and add a filter for auditctl and sendto(2):

# auditctl -D
# auditctl -a always,exit -F arch=b64 -S sendto -F exe=/usr/sbin/auditctl
# auditctl -l
-a always,exit -F arch=b64 -S sendto -F exe=/usr/sbin/auditctl

With the filter rule in place I set the immutable loginuid/auid feature:

# auditctl --loginuid-immutable

... and if I look at the raw audit log I see the following records:

type=FEATURE_CHANGE msg=audit(1524068057.452:146):  ppid=631 pid=638 auid=0 uid=0 gid=0 
    euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="auditctl" 
    exe="/usr/sbin/auditctl" 
    subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 feature=loginuid_immutable old=0 
    new=1 old_lock=0 new_lock=1 res=1
type=SYSCALL msg=audit(1524068057.452:147): arch=c000003e syscall=44 success=yes exit=32 
    a0=3 a1=7ffdd6a0c9c0 a2=20 a3=0 items=0 ppid=631 pid=638 auid=0 uid=0 gid=0 euid=0 suid=0 
    fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=1 comm="auditctl" exe="/usr/sbin/auditctl" 
    subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 key=(null)
type=SOCKADDR msg=audit(1524068057.452:147): saddr=100000000000000000000000
type=PROCTITLE msg=audit(1524068057.452:147): 
    proctitle=617564697463746C002D2D6C6F67696E7569642D696D6D757461626C65

... if we look closely at the timestamps we can see that these records are grouped into two distinct audit events (which is not correct). This is confirmed by two quick searches with ausearch:

# ausearch -i -m FEATURE_CHANGE
----
type=FEATURE_CHANGE msg=audit(04/18/2018 12:14:17.452:146) :  ppid=631 pid=638 auid=root 
    uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts0 ses=1 
    comm=auditctl exe=/usr/sbin/auditctl subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 
    feature=loginuid_immutable old=0 new=1 old_lock=0 new_lock=1 res=yes 
# ausearch -i -m SYSCALL
----
type=PROCTITLE msg=audit(04/18/2018 12:14:17.452:147) : proctitle=auditctl --loginuid-immutable 
type=SOCKADDR msg=audit(04/18/2018 12:14:17.452:147) : saddr={ fam=netlink nlnk-fam=16 nlnk- 
    pid=0 } 
type=SYSCALL msg=audit(04/18/2018 12:14:17.452:147) : arch=x86_64 syscall=sendto success=yes 
    exit=32 a0=0x3 a1=0x7ffdd6a0c9c0 a2=0x20 a3=0x0 items=0 ppid=631 pid=638 auid=root uid=root 
    gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts0 ses=1 
    comm=auditctl exe=/usr/sbin/auditctl subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 
    key=(null)

I would expect all of these records to be shown as a single event, and I expect most everyone would agree.

[stevegrubb]

I think we are mixing things. The configuration change events are called out by common criteria to occur with or without syscall auditing rules loaded. All of the configuration events are simple events. Meaning that they do not have syscalls and are self contained. These events need to have subject, object, results, action, old value, and new value. The syscall events are caused by syscall rules in order to meet the selective audit rules called out for by common criteria. The syscall events are always compound events which means they have multiple records collected by various parts of the kernel as the syscall is handled.

It has never been expected or required that both of these separate requirements be coordinated by a syscall. In fact, its harmful. It adds unnecessary information, wastes disk space, adds more to process, increases network traffic for remote logging, etc. The FEATURE_CHANGE event is a complete event. It is a statement that the configuration has been changed. If the syscall has a key attached to it, then that is a separate statement about something happening. If these are combined, one of the two meanings will get dropped.

Its like this, while someone may audit sendto, I would never expect to see a user space originating event like USER_START pickup a syscall. They are doing the same thing. pam issues a sendto syscall on netlink with the audit event. And right now, we really cannot do audit by executable for networking syscalls because we pick up unwanted events like this netlink event. What they really want is TCP/IP syscall events.

In summary, FEATURE_CHANGE is a complete simple event. It should not add a syscall record. By combining them, meaning is lost. Configuration changes are big enough they should stand on their own without being obscured by syscall records.

[pcmoore]

Your last comment confuses records and events. An audit event can be composed of multiple records that are all part of a single event. In this particular example, we change an audit subsystem feature which is a single event that generates PROCTITLE, SYSCALL, SOCKADDR, and FEATURE_CHANGE records. All of these records are triggered by a single user event.

@rgbriggs please respin that patch soon so I can merge it and we can end this debate.

[stevegrubb]

There is no confusion. FEATURE_CHANGE is a complete event. By this logic, are we going to tie user space originating events to a syscall? How about LOGIN? Or how about SECCOMP events? We have simple events for a reason. They are designed to be self contained, fast to process, and save disk space.

Next question, has any testing been done with the proposed change? ausearch-test, format text, and format csv.

[pcmoore]

By this logic, are we going to tie user space originating events to a syscall?

If we could safely tie records from userspace to other records then yes, but I suspect that would be close to impossible due to how those records are generated.

How about LOGIN?

Why not.

Or how about SECCOMP events?

Also, why not, it just makes sense.

Next question, has any testing been done with the proposed change? ausearch-test, format text, and format csv.

If there are any test failures I would consider that to be a problem with the test and not the kernel change.

[pcmoore]

Merged via d96f92f4aae1132482ce0a584c4bc3ce32c796ea, thanks @rgbriggs.