SELinux logging and auditing

May 30, 2021

SELinux developers understand that a security-oriented subsystem such as SELinux can only succeed if it is capable of enhanced logging and—even—debugging. Every action that SELinux takes, as part of the LSM hooks that it implements, should be auditable. Denials (actions that SELinux prevents) should always be logged so that administrators can take due action. SELinux tuning and changes, such as loading new policies or altering SELinux Booleans, should always result in an audit event.

Following audit events

By default, SELinux will send its messages to the Linux audit subsystem (assuming the Linux kernel is configured with the audit subsystem enabled through the CONFIG_AUDIT kernel configuration). There, the messages are picked up by the Linux audit daemon (auditd) and logged in the /var/log/audit/audit.log file. Distributions and administrators can define additional handling rules by configuring the audit dispatcher process (audisp), which picks up audit events and dispatches them to one or more separate processes. The SELinux troubleshooting daemon (setroubleshootd), an optional service to provide help with troubleshooting SELinux events, uses this to get access to audit events.

The audit event flow is shown in this diagram:

selinux logging

With SELinux enabled, (almost) every permission check that results in a denial is logged. When Linux auditing is enabled, these denials are logged by the audit daemon in the audit.log file by default. If the audit daemon is unavailable, the events are stored in the Linux kernel message buffer, which we can consult using the dmesg command. The events in the kernel message buffer are also often captured through the system logger.

If the SELinux troubleshooting daemon is installed, then the audit daemon will, alongside its logging, also dispatch the events through the audit dispatch system toward the sedispatch command. This command will further handle the event and send it through D-Bus (a system bus implementation popular on Linux systems) to the SELinux troubleshooting daemon. This daemon will analyze the event and might suggest one or more fixes to the administrator. We will cover the SELinux troubleshooting daemon in the Getting help with denials section.

Whenever SELinux verifies a particular access, it does not always go over the entire policy. Instead, it has an access vector cache (AVC), in which it stores the results of previous access attempts. This cache ensures that SELinux can quickly react to activities without having a huge impact on performance. We notice the abbreviation of this cache as the message type for most SELinux events, as shown at the beginning of the following example:

type=AVC msg=audit(03/22/2020 12:15:38.557:2331): avc: denied { read } for pid=12569 comm="dmesg" name="xterm-256color" dev="sdb2" ino=131523 scontext=sysadm_u:sysadm_r:dmesg_t:s0-s0:c0.c1023 tcontext=system_u:object_r:etc_t:s0 tclass=file permissive=0

When the Linux kernel checks a permission request, this request is represented as an access vector, and the cache is then consulted to quickly find the appropriate response. If the cache has the right access vector, then the decision is taken from the cache; otherwise, the SELinux subsystem consults the policy itself and updates the cache. Of course, SELinux invalidates the cache when a new policy is loaded or the policy is dynamically adjusted. This ensures that all permission checks are in line with the active policy.

This inner working of SELinux is less relevant to most administrators, but at least now we know where the term AVC comes from.

Tuning the AVC

The AVC can be slightly tuned, by setting the size of the cache or its related tables.

We can configure the cache size itself through the  /sys/fs/selinux/avc/cache_threshold  pseudo-file (available if the CONFIG_SECURITY_SELINUX_AVC_STATS kernel configuration is set). For instance, to increase the cache size to 768 entries (the default is 512), the following command would be used:

# echo 768 > /sys/fs/selinux/avc/cache_threshold

To confirm the cache threshold, read the file, as follows:

# cat /sys/fs/selinux/avc/cache_threshold
768

The AVC hash statistics are available through the hash_stats pseudo-file, as illustrated in the following code snippet:

$ cat /sys/fs/selinux/avc/hash_stats
entries: 506
buckets used: 233/512
longest chain: 5

If you suspect that lower system performance is due to SELinux, then we advise you to look at the longest chain output in hash_stats. If it is longer than 10, then some performance impact can be expected, and updating the cache size might help.

The avcstat command shows the evolution of the cache over time (the first number is the total since boot). When the number of cache misses is high or volatile, or the number of reclaims (obsoleting oldest cache entries and reusing them for new ones) is volatile, then the cache size might need to be increased. The command is illustrated in the following code snippet:

$ avcstat 5
lookups	hits		misses	allocs	reclaims	frees
58396334	58382324	14010		14010		10736		13511
591		591		0		0		0		0
1657		1653		4		4		0		0

Recent kernels also allow the number of buckets used through a kernel configuration parameter to be set (CONFIG_SECURITY_SELINUX_SIDTAB_HASH_BITS), and its cache statistics can be viewed through the /sys/fs/selinux/ss/sidtab_hash_stats pseudo-file, as illustrated in the following code snippet:

$ cat /sys/fs/selinux/ss/sidtab_hash_stats
entries: 285
buckets use: 55/512
longest chain: 3

Another performance parameter is the size of the internal session ID (SID) (the internal identifier used to represent contexts) to the string cache. Sadly, we can only configure this parameter at kernel build time, using the CONFIG_SECURITY_SELINUX_SID2STR_CACHE_SIZE setting.

Uncovering more logging

There is an important SELinux policy directive that provides control over what is (not) audited, and that is dontaudit. A dontaudit rule in the SELinux policy tells SELinux that an access denial should not be logged. This is the only example where SELinux won’t log a denial—the SELinux policy writer has explicitly disabled the auditing of events. This is usually done to remove clutter from the logs and hide cosmetic denials that have no influence on the security of the system.

The seinfo utility can tell us how many of these rules, as well as its sibling rule auditallow (log events, even though they are allowed by the policy), are currently active, as illustrated in the following code snippet:

$ seinfo | grep -i audit
Auditallow:	1	Dontaudit:		5559
Auditallowxperm:	0	Dontauditxperm:	   0

Luckily, we can disable these dontaudit rules at will. Through the following semodule command, these rules are removed from the active policy:

# semodule –-disable_dontaudit –-build

The arguments can also be abbreviated to -D and -B, respectively. To re-enable the dontaudit rules, just rebuild the policy like so:

# semodule -B

Disabling the dontaudit rules can sometimes help in troubleshooting failures that do not result in any useful audit event. Generally speaking, though, audit events that policy writers mark as cosmetic are not the cause of a failure.

Configuring Linux auditing

SELinux will try to use the audit subsystem when available and will fall back to regular system logging when it isn’t. This can either be because the Linux kernel audit subsystem is not configured or because the Linux audit daemon itself is not running.

For a Linux audit, we usually do not need to configure anything as SELinux AVC denials are logged by default. You will find the denials in the audit log file (/var/log/audit/audit.log), usually together with the system call and other event messages related to the same action, as illustrated in the following code snippet:

type=PROCTITLE msg=audit(...) : proctitle=ping 8.8.8.8 
type=SYSCALL msg=audit(...) : arch=x86_64 syscall=socket success=no exit=EACCES(Permission denied) a0=inet a1=SOCK_DGRAM a2=icmp a3=0x7fffac013050 items=0 ppid=2685 pid=17292 auid=admin uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=tty1 ses=1 comm=ping exe=/bin/ping subj=sysadm_u:sysadm_r:ping_t:s0-s0:c0.c1023 key=(null) 
 type=AVC msg=audit(...) : avc: denied { create } for pid=17292 comm=ping scontext=sysadm_u:sysadm_r:ping_t:s0-s0:c0.c1023 tcontext=sysadm_u:sysadm_r:ping_t:s0-s0:c0.c1023 tclass=icmp_socket permissive=0 

To configure the target log file for the audit system, use the log_file parameter in /etc/audit/auditd.conf.

To enable remote audit logging (to centralize audit events from multiple hosts on a single system), you have the option of either enabling syslog forwarding or enabling the audisp-remote plugin.

With syslog forwarding, the audit dispatch daemon is configured to send audit events to the local system logger as well. It is then up to the administrator to configure the local system logger to pass on events toward a remote system.

Edit the /etc/audit/plugins.d/syslog.conf file and set active to yes, as follows:

# vi /etc/audit/plugins.d/syslog.conf
active = yes
direction = out
path = /sbin/audisp-syslog
type = always
args = LOG_INFO
format = string

Using the system logger to centralize audit events might not be the best option though, as system loggers generally use unencrypted—and often not even guaranteed—data delivery. With the audisp-remote plugin, we can even use an encrypted channel to send the audit events, and provide guaranteed delivery to a remote auditd server.

First, configure the audit daemon on the target (log) server to accept audit logs from remote hosts by enabling the audit daemon to listen on port 60. We also change the event formatting to an enriched value and add hostnames to the events so that we can distinguish events from multiple hosts, as follows:

auditd.conf

# vi /etc/audit/auditd.conf
tcp_listen_port = 60
log_format = ENRICHED
name_format = HOSTNAME

Next, on the source systems, configure auditd.conf as shown in the previous code snippet, but without the port setting. Then, configure the audisp-remote plugin to connect to the target server’s audit daemon, as follows:

audisp-remote.conf

# vi /etc/audit/audisp-remote.conf
remote_server = <targethostname>
port = 60

Finally, enable the audisp-remote plugin, as follows:

au-remote.conf

# vi /etc/audit/plugins.d/au-remote.conf
active = yes

Don’t forget to restart the audit daemon so that the changes take effect.

We can only recommend you always use the Linux audit subsystem. Not only does it integrate nicely with troubleshooting utilities; it also allows administrators to use the audit tools to query the audit logs or even generate reports, such as with aureport, as illustrated in the following code snippet:

aureport

# aureport --avc --start recent
AVC Report
===============================================================
# date time comm subj syscall class permission obj result event
===============================================================
...
7. 03/21/2020 19:40:55 sudo sysadm_u:sysadm_r:sysadm_sudo_t:s0-s0:c0.c1023 257 dir search sysadm_u:sysadm_r:sysadm_t:s0-s0:c0.c1023 denied 1067
...
10. 03/21/2020 19:48:19 dmesg sysadm_u:sysadm_r:dmesg_t:s0-s0:c0.c1023 21 file read system_u:object_r:etc_t:s0 denied 1080

The Linux audit system is an important aide for Linux administrators, and not just for SELinux troubleshooting. But next to the Linux audit system, events can also be directed toward the local system logger, as explained next.

Configuring the local system logger

When auditing is not enabled, or the Linux audit daemon is not running, then the system logger is responsible for capturing SELinux events. The system logger will log these events through the kernel logging facility (kern.*). Most system loggers will save these kernel log events in a general log file, such as /var/log/messages.

We can configure the system logger to direct SELinux AVC messages into its own log file, such as /var/log/avc.log. For instance, for the rsyslog system logger, we can add in a configuration entry under /etc/rsyslog.d named 99-selinux.conf, with the following content:

99-selinux.conf

# vi /etc/rsyslog.d/99-selinux.conf
:msg, contains, "avc: "	-/var/log/avc.log

After restarting the system logger, the AVC-related messages will show up in the /var/log/avc.log file.

When the local system logger handles SELinux logging, an easy method to quickly obtain the latest AVC denials (or other messages) is through the dmesg command, as illustrated in the following code snippet:

# dmesg | grep avc | tail

Be aware, though, that unlike the audit logs, many systems allow the dmesg content to be read by regular users. This might result in some information leakage to untrusted users. For this reason, some SELinux policies do not allow regular users to access the kernel ring buffer (and, as such, use dmesg) unless the user_dmesg SELinux Boolean is set to on, as illustrated in the following code snippet:

# setsebool user_dmesg on

The user_dmesg SELinux Boolean is not available on CentOS, though. There, only the standard unconfined user type and the administrative user type have access to the kernel ring buffer. To prevent other users from reading this information, you need to map these users to non-administrative SELinux users, such as user_u or (x)guest_u .

Reading SELinux denials

The one thing every one of us will have to do several times with SELinux systems is to read and interpret SELinux denial information. When SELinux prohibits access and there is no dontaudit rule in place to hide it, SELinux will log it. If nothing is logged, it was probably not SELinux that was responsible for the failure. Remember: SELinux comes after Linux discretionary access control (DAC) checks, so if a regular permission doesn’t allow a certain activity then SELinux is never consulted.

SELinux denial messages are logged the moment SELinux prevents some access from occurring. When SELinux is in enforcing mode, the application usually returns a Permission denied error, although sometimes it might be a bit more obscure. An example of this can be seen in the following code snippet:

$ ls /proc/1
ls: cannot access '/proc/1': Permission denied
# ls -ldZ /proc/1
dr-xr-xr-x. 9 root system_u:system_r:init_t:s0 0 Mar 21 10:54 /proc/1

So, what does a denial message look like? The following command output shows a denial from the audit subsystem, which we can query through the ausearch command:

# ausearch -m avc -ts recent -i
type=AVC msg=audit(03/22/2020 12:15:38.557:2331): avc: denied { read } for pid=12569 comm="dmesg" name="xterm-256color" dev="sdb2" ino=131523 scontext=sysadm_u:sysadm_r:dmesg_t:s0-s0:c0.c1023 tcontext=system_u:object_r:etc_t:s0 tclass=file permissive=0

Let’s break up this denial into its individual components. The following list gives more information about each part of the preceding denials. As an administrator, knowing how to read denials is extremely important, so take enough time for this:

  • SELinux action: The action that SELinux took or would take if run in enforcing mode. This is usually denied, although some actions are explicitly marked to be audited as well and would result in granted. Example: denied
  • Permissions: The checked permissions (action initiated by the process). This is usually a single permission, although it can sometimes be a set of permissions. Example: { read }
  • Process ID (PID): The ID of the process that was performing the action. Example: pid=12569
  • Process name: The process name (command). It doesn’t display any arguments to the command, though. Example: comm="dmesg"
  • Target name: The name of the target (resource) that the process is performing an action on. If the target is a file, then the name is usually the filename or directory. Example: name="xterm-256color"
  • Target device: The device on which the target resource resides. Together with the next field (inode number) this allows us to uniquely identify the resource on a system. Example: dev="sdb2"
  • Target file inode number: The inode number of the target file or directory. Together with the device, this allows us to find the file on the filesystem.Example: ino=131523
  • Source context: The context in which the process resides (the domain of the process). Example: scontext=sysadm_u:sysadm_r:dmesg_t:s0-s0:c0.c1023
  • Target context: The context of the target resources. Example: tcontext=system_u:object_r:etc_t:s0
  • Object class: The class of the target object—for instance, a directory, file, socket, node, pipe, file descriptor, filesystem, or capability. Example: tclass=file
  • Permissive mode: The mode the domain was in when the action was executed. If set to 0, then SELinux was in enforcing mode; otherwise, it was permissive (either for the system or for the given domain).Example: permissive=0

We can interpret the previous denial like so: SELinux has denied the dmesg command to read a file named “xterm-256color“. The file has inode number 131523 on device /dev/sdb2 and is labeled as etc_t. The dmesg command has PID 12569 and is labeled as dmesg_t. The dmesg_t domain was not in permissive mode.

Depending on the action and the target class, SELinux uses different fields to give all the information we need to troubleshoot a problem. Consider the following denial:

type=AVC msg=audit(03/22/20 18:12:52.177:2326): avc: denied { name_bind } for pid=15983 comm="nginx" src=89 scontext=system_u:system_r:httpd_t:s0 tcontext=system_u:object_r:reserved_port_t:s0 tclass=tcp_socket permissive=0

The preceding denial came up because the nginx web server was configured to listen on a non-default port (89 instead of the default 80).

Identifying the problem is a matter of understanding how the operations work and properly reading the denials. The denial logs give us enough to get us started, giving a clear idea of what was denied.

Administrators might want to update the SELinux policy to allow a specific action (by adding an allow rule to the SELinux policy, as described further on in this book). This is, however, not always the right approach because other options exist and are usually better, such as these:

  • Providing the right label on the target resource (usually the case when the target is a non-default port, non-default location, and so on)
  • Switching Booleans (flags that manipulate the SELinux policy) to allow additional privileges
  • Providing the right label on the source process (often the case when the acting application is not installed by the distribution package manager)
  • Using the application as intended instead of through other means (as SELinux only allows expected behavior), such as starting a daemon through a service (init script or systemd unit) instead of through a command-line operation

If the preceding nginx example were a wanted configuration (using a non-default port), then we should label this port as a HyperText Transfer Protocol (HTTP) port and not allow the httpd_t domain to bind on (many) other ports.

Other SELinux-related event types

Although most SELinux log events are AVC-related, they aren’t the sole event types an administrator will have to deal with. Most audit events will show SELinux information as part of the event, even though SELinux has little to do with the event itself, but a few audit event types are directly concerned with SELinux.

Note:

A full list of all possible audit events is available in the linux/audit.h header file, located in /usr/include.

USER_AVC

A USER_AVC event resembles regular AVC audit events, but now the source is a user space object manager. These are applications that use SELinux policy rules, but they enforce these rules themselves rather than through the kernel.

The following example is such an event, generated by D-Bus:

type=USER_AVC msg=audit(03/22/2020 11:25:56.123:154) : pid=540 uid=dbus auid=unset ses=unset subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: denied { acquire_svc } for service=com.redhat.tuned spid=1460 scontext=system_u:system_r:tuned_t:s0 tcontext=system_u:system_r:tunned_t:s0 tclass=dbus permissive=0 exe=/usr/bin/dbus-daemon sauid=dbus hostname=? addr=? terminal=?'

The event has two parts. Everything up to the msg= string is information about the user space object manager that generated the event, and is the first part of the event. The true event itself (which is the second part) is stored within the msg= part and includes similar fields, as we already know from regular AVCs.

SELINUX_ERR

An SELINUX_ERR event comes up when SELinux detects a general policy violation rather than an access control violation. It cannot be resolved by SELinux policy writers by just allowing the operation. These events usually point to a misuse of applications and services that the policy is not tailored to accomplish, and an example is shown in the following code snippet:

type=PATH msg=audit(03/22/2020 12:25:53.104:2364) : item=0 name=/usr/sbin/rpc.nfsd inode=3019958 dev=08:12 mode=file,755 ouid=root ogid=root rdev=00:00 obj=system_u:object_r:nfsd_exec_t:s0 nametype=NORMAL cap_fp=none cap_fi=none cap_fe=0 cap_fver=0 cap_frootid=0
type=SELINUX_ERR msg=audit(03/22/2020 12:25:53.104:2364) : op=security_compute_sid invalid_context=sysadm_u:sysadm_r:nfsd_t:s0-s0:c0.c1023 scontext=sysadm_u:sysadm_r:sysadm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:nfsd_exec_t:s0 tclass=process 

In the preceding example, a user (running in the sysadm_t domain) was executing rpc.nfsd (with nfsd_exec_t as the label), and the policy wanted to transition to the nfsd_t domain. However, that resulted in a full context of sysadm_u:sysadm_r:nfsd_t:s0-s0:c0.c1023, which is not a valid context. The sysadm_r SELinux role does not support the nfsd_t domain.

MAC_POLICY_LOAD

MAC_POLICY_LOAD event occurs whenever the system loads a new SELinux policy in memory. This occurs when the administrator loads a new or updated SELinux policy module, rebuilds the policy with the dontaudit rules disabled, or toggles an SELinux Boolean that the administrator wants to persist across reboots. Such an event is illustrated in the following code snippet:

type=MAC_POLICY_LOAD msg=audit(03/22/2020 12:28:17.077:2368) : auid=admin ses=1 lsm=selinux res=yes

When a MAC_POLICY_LOAD event occurs, you might notice a subsequent USER_MAC_POLICY_LOAD event. This occurs when a user space object manager detects an update on the SELinux policy and takes action. Note that not all user space object managers will send out this event: some object managers will query the live policy and, as such, do not need to act when a new policy loads.

MAC_CONFIG_CHANGE

When an SELinux Boolean changes but doesn’t persist, then a MAC_CONFIG_CHANGE event will be dispatched. This tells the administrator that the active policy has been instructed to change its behavior slightly, but within the bounds of the existing loaded policy. Such an event is illustrated in the following code snippet:

type=MAC_CONFIG_CHANGE msg=audit(03/22/2020 12:29:49.564:2370) : bool=virt_use_nfs val=0 old_val=1 auid=admin ses=1

In the preceding example, the virt_use_nfs SELinux Boolean was changed from the value 1 (on) to 0 (off).

MAC_STATUS

MAC_STATUS event shows up when the SELinux enforcement state has been changed. For instance, when an administrator uses setenforce 0 to put SELinux in permissive mode, then the following event occurs:

type=MAC_STATUS msg=audit(03/22/2020 12:30:45.200:2372) : enforcing=0 old_enforcing=1 auid=admin ses=1 enabled=1 old-enabled=1 lsm=selinux res=yes

MAC_STATUS is also used to inform administrators when the SELinux state itself (enabled or disabled) is altered.

NetLabel events

NetLabel is a Linux kernel project to support labeled network packets, allowing security contexts such as SELinux contexts to be passed on between hosts. One of the protocols that the NetLabel implementation supports in Linux is Common IP Security Option (CIPSO) labeling.

The following audit events are related to the NetLabel capability:

  • MAC_UNLBL_STCADD and MAC_UNLBL_STCDEL events are triggered when a static label is added or removed. Static labeling means that if a packet is received or sent and it does not have a label, then this “default” static label is assigned.
  • MAC_MAP_ADD and MAC_MAP_DEL events are triggered when a mapping between a labeling protocol (such as CIPSO) and its parameters against an LSM (SELinux) domain is added or removed from the configuration.
  • MAC_CIPSOV4_ADD and MAC_CIPSOV4_DEL events are triggered when a CIPSO (IPv4) configuration is added or removed.

Labeled IPsec events

Another labeled network protocol that Linux supports is labeled IPsec, where IPsec is short for Information Protocol Security. Through this, the SELinux context of the source process (which is communicating over the IPsec tunnel toward a target resource) is known by the IPsec daemons at both ends of the tunnel. Furthermore, SELinux will contain rules about which domains can communicate over an IPsec tunnel and which domains can communicate with each other network-wise.

The following audit events are related to IPsec:

  • MAC_IPSEC_ADDSA and MAC_IPSEC_DELSA events are used when a security association is added or removed (new IPsec tunnels are defined or deleted).
  • MAC_IPSEC_ADDSPD and MAC_IPSEC_DELSPD events are used when a security policy definition is added or removed. Security policies generally describe whether network packets need to be handled by IPsec and, if so, through which security association.
  • A MAC_IPSEC_EVENT event is a generic event for IPsec audit messages.

Using ausearch

The ausearch command, part of the Linux audit framework, is a frequently used command for querying audit events stored on the system. We already briefly covered it when taking a first look at an AVC denial, but only briefly mentioning it won’t do it justice.

With ausearch, we can search for events that originated during or after a selected time period. We used the -ts recent (time start) option in the past, which displays events that occurred during the past 10 minutes. The argument can also be a timestamp. Other supported shorthand values are listed as follows:

  • today, meaning starting at 1 second past midnight on the current day
  • yesterday, meaning starting at 1 second past midnight the previous day
  • this-week, this-month, or this-year, meaning starting at 1 second past midnight on the first day of the current week, current month, or current year
  • checkpoint, which uses the timestamp mentioned in a checkpoint file created in a previous run
  • boot, which implies only events since the system booted should be shown
  • week-ago, meaning starting at 1 second after midnight exactly 7 days ago

The use of checkpoint is particularly useful when troubleshooting SELinux issues as it allows us to show denials (and other SELinux events) since the last invocation of the ausearch command. This is illustrated in the following code snippet:

# ausearch --checkpoint /root/ausearch-checkpoint.txt -ts checkpoint

This allows administrators to perform minor tweaks and reproduce the problem and only see the events since then, instead of going through all events over and over again.

By default, the ausearch command displays all events stored in the audit log. On busy systems, this can be very verbose and may result in unwanted events being displayed as well. Luckily, users can limit the type of events queried through the ausearch command.

For SELinux troubleshooting, using avc,user_avc,selinux_err limits the events nicely to those needed for the job, as illustrated in the following code snippet:

# ausearch -m avc,user_avc,selinux_err -ts recent

If the numeric display of fields such as user IDs and timestamps is too confusing, then it is possible for ausearch to look up and translate user IDs to usernames and timestamps to formatted time fields. Add the -i option to ausearch to have it interpret these fields and display the interpreted values instead.

In this article, we’ve seen how SELinux notifies the system about its actions through log events, and where these log events are stored. In the next section, we’ll look at how to act upon these events.

Related Articles

No Results Found

The page you requested could not be found. Try refining your search, or use the navigation above to locate the post.

Lorem ipsum dolor sit amet consectetur

0 Comments

Submit a Comment

Your email address will not be published. Required fields are marked *

18 − three =