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