audit userspace problems with io_uring async ops

[Paul Moore]

Hi all,

We just recently started picking up audit-testsuite failures with the
latest upstream kernels and I tracked it down to a change in how the
IORING_OP_OPENAT operation is handled, and how Steve's audit userspace
displays async io_uring ops.  It appears that when ausearch is used to
look for events it doesn't display async io_uring events (URINGOP
records/events without an associated SYSCALL record/event).  Take the
following snippet from /var/log/audit/audit.log:

--- 287 ---
type=SYSCALL msg=audit(1677618568.199:287): arch=c000003e syscall=426
  success=yes exit=1 a0=4 a1=1 a2=0 a3=0 items=1 ppid=1498 pid=1499
  auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
  tty=pts1 ses=3 comm="iouring" exe="/.../iouring"
  subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
  key="testsuite-1677618568-WJBbDxKg"ARCH=x86_64 SYSCALL=io_uring_enter ...
type=CWD msg=audit(1677618568.199:287):
  cwd="/root/sources/audit-testsuite/tests/io_uring"
type=PATH msg=audit(1677618568.199:287): item=0
  name="/tmp/iouring.4.txt" nametype=UNKNOWN ...
type=PROCTITLE msg=audit(1677618568.199:287):
  proctitle=2E2F696F7572696E670074315F6368696C64
--- 288 ---
type=URINGOP msg=audit(1677618568.199:288): uring_op=18 success=yes exit=0
  items=1 ppid=1498 pid=1499
  uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
  subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
  key="testsuite-1677618568-WJBbDxKg"URING_OP=openat ...
type=CWD msg=audit(1677618568.199:288):
  cwd="/root/sources/audit-testsuite/tests/io_uring"
type=PATH msg=audit(1677618568.199:288): item=0 name="/tmp/iouring.4.txt"
  inode=33 dev=00:22 mode=0100644 ouid=0 ogid=0 rdev=00:00
  obj=unconfined_u:object_r:user_tmp_t:s0 nametype=NORMAL ...
--- 289 ---
type=SYSCALL msg=audit(1677618568.199:289): arch=c000003e syscall=426
  success=yes exit=0 a0=4 a1=0 a2=1 a3=1 items=0 ppid=1498 pid=1499
  auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
  tty=pts1 ses=3 comm="iouring" exe="/.../iouring"
  subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
  key="testsuite-1677618568-WJBbDxKg"ARCH=x86_64 SYSCALL=io_uring_enter ...
type=PROCTITLE msg=audit(1677618568.199:289):
  proctitle=2E2F696F7572696E670074315F6368696C64

... and the matching ausearch output:

% ausearch -i -k "testsuite-1677618568-WJBbDxKg"
----
type=PROCTITLE msg=audit(02/28/2023 16:09:28.199:287) :
  proctitle=./iouring t1_child
type=PATH msg=audit(02/28/2023 16:09:28.199:287) : item=0
  name=/tmp/iouring.4.txt nametype=UNKNOWN ...
type=CWD msg=audit(02/28/2023 16:09:28.199:287) :
  cwd=/root/sources/audit-testsuite/tests/io_uring
type=SYSCALL msg=audit(02/28/2023 16:09:28.199:287) : arch=x86_64
 syscall=io_uring_enter success=yes exit=1 a0=0x4 a1=0x1 a2=0x0 a3=0x0 items=1
 ppid=1498 pid=1499 auid=root uid=root gid=root euid=root suid=root fsuid=root
 egid=root sgid=root fsgid=root tty=pts1 ses=3 comm=iouring exe=/.../iouring
 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
 key=testsuite-1677618568-WJBbDxKg
----
type=PROCTITLE msg=audit(02/28/2023 16:09:28.199:289) :
 proctitle=./iouring t1_child
type=SYSCALL msg=audit(02/28/2023 16:09:28.199:289) : arch=x86_64
 syscall=io_uring_enter success=yes exit=0 a0=0x4 a1=0x0 a2=0x1 a3=0x1 items=0
 ppid=1498 pid=1499 auid=root uid=root gid=root euid=root suid=root fsuid=root
 egid=root sgid=root fsgid=root tty=pts1 ses=3 comm=iouring exe=/.../iouring
 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
 key=testsuite-1677618568-WJBbDxKg
----

... if you look closely you'll notice that the #289 event (the async
URINGOP) is missing from the ausearch output.

The good news is that this is easily reproducible on current upstream
kernels and Steve's v3.1 audit userspace release using the
audit-testsuite io_uring tests.  This can also be seen in Rawhide with
current packages:

% uname -r
6.3.0-0.rc0.20230228gitae3419fb.9.1.secnext.fc39.x86_64
% rpm -q audit
audit-3.1-2.fc39.x86_64
% pwd
/root/sources/audit-testsuite/tests/io_uring
% git log --oneline | head -n 1
44c933e tests/filter_exclude: euid filtering now possible in exclude filter

Once ausearch is fixed we will also need to update the audit-testsuite
to add an explicit io_uring filter for the IORING_OP_OPENAT op.  The
patch below is untested (blocked on ausearch), but I expect it to
resolve the issue in the test suite:

>>>
diff --git a/tests/io_uring/test b/tests/io_uring/test
index 9eb427a..df13af0 100755
--- a/tests/io_uring/test
+++ b/tests/io_uring/test
@@ -49,6 +49,7 @@ system("auditctl -D >& /dev/null");
 # set our io_uring filters
 system("auditctl -a exit,always -F arch=b$abi_bits -S io_uring_setup -k $key");
 system("auditctl -a exit,always -F arch=b$abi_bits -S io_uring_enter -k $key");
+system("auditctl -a io_uring,always -S openat -k $key");

 # run the "t1" test
 system("$basedir/iouring t1");
>>>

For the kernel folks, the relevant commit is likely 0ffae640ad83
("io_uring: always go async for unsupported open flags").  I believe
what happened in the past is we caught the initial failing/-EAGAIN
io_uring op with the syscall record, e.g. #287 in the example above,
but now that IORING_OP_OPENAT goes straight to an async/io_wq op we
don't "see" it as ausearch isn't showing that (maybe needs to learn to
search URINGOP records too? dunno.).  Arguably this was always a
problem with the test, we just got a bit lucky because io_uring would
attempt to do IORING_OP_OPENAT synchronously at first.

-- 
paul-moore.com