denied capability logged only after profile load

[Jamie Strandboge]

Recently I was debugging a fsetid denial in snap-confine and I noticed that the kernel audit subsystem would not always log the denial when it should have. This seems to be related to the profile load. I've always felt that capability logging was sporadic (but never looked into it until now) and feel this might affect more than just fsetid.

Eg consider this profile:

$ cat ./p
#include <tunables/global>

profile test {
  #include <abstractions/base>
  #include <abstractions/bash>
  #include <abstractions/consoles>
  #include <abstractions/nameservice>
  #include <abstractions/wutmp>

  /bin/bash ixr,

  /bin/chmod ixr,
  /bin/chown ixr,
  /bin/ls ixr,
  /bin/mkdir ixr,
  /bin/mktemp ixr,
  /bin/rm ixr,
  /usr/bin/id ixr,

  /usr/bin/newgrp ixr,
  /usr/bin/sg ixr,
  network raw,
  owner @{PROC}/@{pid}/loginuid r,
  /etc/{,g}shadow r,
  /etc/login.defs r,
  owner @{PROC}/@{pid}/status r,
  capability audit_write,
  capability setuid,
  capability setgid,

  /tmp/test.sh r,

  /tmp/tmp.*/ rw,
  /tmp/tmp.*/tst/ rw,

# capability fsetid,
}

and this test script:
$ cat ./test.sh
#!/bin/sh
set -e

tmpdir=
cleanup() {
    if [ -d "$tmpdir" ]; then
        rm -rf "$tmpdir"
    fi
}

if [ -z "$SUDO_USER" ]; then
    echo "Must run this script under sudo as root"
    exit 1
fi

tmpdir=$(mktemp -d)
trap "cleanup" EXIT HUP INT QUIT TERM

# simulate fsetid denial with snap-confine
tstdir="$tmpdir/tst"
sg "$SUDO_USER" -c "mkdir '$tstdir'"
chmod 7777 "$tstdir"
ls -ld "$tstdir"
chown root:root "$tstdir"
ls -ld "$tstdir"

myuid=$(sg "$SUDO_USER" -c "id -u")
mygid=$(sg "$SUDO_USER" -c "id -g")
echo "running chmod --reference=/var/lib with uid=$myuid,gid=$mygid"
sg "$SUDO_USER" -c "chmod --reference=/var/lib '$tstdir'"
ls -ld "$tstdir"
exit 0

If on the remote machine I disable rate-limiting and use journalctl (which I've found drops fewer denials):
$ ssh -tt sec-artful-amd64.vm 'sudo sysctl -w kernel.printk_ratelimit=0 ; journalctl --follow | grep apparmor'
kernel.printk_ratelimit = 0

Then, in another terminal if I scp these over to the same machine, load the profile and execute the script, I can get a denial every time:
$ scp ./* sec-artful-amd64.vm:/tmp && ssh -tt sec-artful-amd64.vm 'sudo apparmor_parser -r /tmp/p && sudo aa-exec -p test -- /tmp/test.sh'
p 100% 672 1.6MB/s 00:00
test.sh 100% 656 2.0MB/s 00:00
drwsrwxrwt 2 root jamie 4096 Jul 31 15:06 /tmp/tmp.GspqwYMrVg/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:06 /tmp/tmp.GspqwYMrVg/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:06 /tmp/tmp.GspqwYMrVg/tst
Connection to sec-artful-amd64.vm closed.

The denial is:
Jul 31 15:06:07 sec-artful-amd64 kernel: audit: type=1400 audit(1501531567.266:81): apparmor="DENIED" operation="capable" profile="test" pid=5625 comm="chmod" capability=4 capname="fsetid"

However, if I subsequently run the script as many times as I want, I get no denial:
$ ssh -tt sec-artful-amd64.vm 'sudo aa-exec -p test -- /tmp/test.sh'
drwsrwxrwt 2 root jamie 4096 Jul 31 15:07 /tmp/tmp.rZcDS2NPGr/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:07 /tmp/tmp.rZcDS2NPGr/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:07 /tmp/tmp.rZcDS2NPGr/tst
Connection to sec-artful-amd64.vm closed.

If I load the profile but don't scp, I get a denial every time:
$ ssh -tt sec-artful-amd64.vm 'sudo apparmor_parser -r /tmp/p && sudo aa-exec -p test -- /tmp/test.sh'
drwsrwxrwt 2 root jamie 4096 Jul 31 15:08 /tmp/tmp.3A9SYTIwXm/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:08 /tmp/tmp.3A9SYTIwXm/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:08 /tmp/tmp.3A9SYTIwXm/tst
Connection to sec-artful-amd64.vm closed.

If I only scp and run the script (profile was previously loaded), I don't get a denial: {{{
$ scp ./* sec-artful-amd64.vm:/tmp && ssh -tt sec-artful-amd64.vm 'sudo aa-exec -p test -- /tmp/test.sh'
p 100% 672 1.7MB/s 00:00
test.sh 100% 656 5.9MB/s 00:00
drwsrwxrwt 2 root jamie 4096 Jul 31 15:09 /tmp/tmp.hrHkpuxcAI/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:09 /tmp/tmp.hrHkpuxcAI/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:09 /tmp/tmp.hrHkpuxcAI/tst
Connection to sec-artful-amd64.vm closed.
}}}

The above is with 'aa-exec -p test', so I then tried with binary attachment.

With scp, profile load and run the script, I get a reliable denial:
$ scp ./* sec-artful-amd64.vm:/tmp && ssh -tt sec-artful-amd64.vm 'sudo apparmor_parser -r /tmp/p.bin && sudo /tmp/test.sh'
p 100% 672 1.9MB/s 00:00
p.bin 100% 672 3.6MB/s 00:00
test.sh 100% 656 4.5MB/s 00:00
drwsrwxrwt 2 root jamie 4096 Jul 31 15:11 /tmp/tmp.nQHhfLPTX6/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:11 /tmp/tmp.nQHhfLPTX6/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:11 /tmp/tmp.nQHhfLPTX6/tst
Connection to sec-artful-amd64.vm closed.

If I subsequently run the script as many times as I want, I don't get a denial: {{{
$ ssh -tt sec-artful-amd64.vm 'sudo /tmp/test.sh'
drwsrwxrwt 2 root jamie 4096 Jul 31 15:13 /tmp/tmp.XEZJRclaBa/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:13 /tmp/tmp.XEZJRclaBa/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:13 /tmp/tmp.XEZJRclaBa/tst
Connection to sec-artful-amd64.vm closed.
}}}

If I load the profile but don't scp, I get a denial every time:
$ ssh -tt sec-artful-amd64.vm 'sudo apparmor_parser -r /tmp/p.bin && sudo /tmp/test.sh'
drwsrwxrwt 2 root jamie 4096 Jul 31 15:14 /tmp/tmp.QLKnCPK2ig/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:14 /tmp/tmp.QLKnCPK2ig/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:14 /tmp/tmp.QLKnCPK2ig/tst
Connection to sec-artful-amd64.vm closed.

If I only scp and run the script (profile was previously loaded), I don't get a denial: {{{
$ scp ./* sec-artful-amd64.vm:/tmp && ssh -tt sec-artful-amd64.vm 'sudo /tmp/test.sh'
p 100% 672 2.8MB/s 00:00
p.bin 100% 672 4.4MB/s 00:00
test.sh 100% 656 5.1MB/s 00:00
drwsrwxrwt 2 root jamie 4096 Jul 31 15:15 /tmp/tmp.I7HJ5wc3oh/tst
drwsrwxrwt 2 root root 4096 Jul 31 15:15 /tmp/tmp.I7HJ5wc3oh/tst
running chmod --reference=/var/lib with uid=0,gid=1000
drwxr-xr-x 2 root root 4096 Jul 31 15:15 /tmp/tmp.I7HJ5wc3oh/tst
Connection to sec-artful-amd64.vm closed.

I also tried changing the inode number of test.sh (eg, via a cp, rm and cp back) to see if it made a difference with binary attachment (it didn't).

With the above I've demonstrated that we can only get a reliable denial by doing a profile load, then running the script once. Running it subsequent times result in no denial until we load the profile again, then we can run the script once and see a denial. I don't know if at some point a subsequent run would pop out a denial (ie, it is just less likely to log) or if it will never log.

[Seth Arnold (seth-arnold)]

The profile given here doesn't have an attachment specification:

profile test {

Did you add one for the test sections that don't use aa-exec?

Thanks

[Jamie Strandboge (jdstrand)]

@Seth, the first test cases use 'aa-exec -p test' and therefore didn't need anything else. I omitted the binary attachment profile since it simply changes this:

  profile test {

to

  /tmp/test.sh {

Sorry if that wasn't clear.

[John Johansen (jjohansen)]

AppArmor has a small deduplication LRU cache in its capability audit logging. Its pretty basic just using a profile capability pair, which will prevent further logging of capability requests for the profile capability pair in question while the entry remains in the cache.

The cache is necessarily because many capabilities are checked multiple times for a single syscall resulting in a flooding of the audit subsystem.

We can (and should) certainly extend the cache to take more than just the profile and capability into account. This would likely fix the majority of your issues.

[Jamie Strandboge (jdstrand)]

Thanks John, that sounds wonderful.

IME, as a profiler, an implementation default that was one denial per invocation of the profiled application (including children and threads) would be the ideal: ie, we'd never miss a denial (kernel rate limiting notwithstanding), but we'd have the minimum number of log entries. I'm not sure if that is strictly possible, but maybe striving towards this goal will help in designing the future improvements. Having additional knobs to alter the default behavior might be handy too.

Thanks again!