BIND (named) denied hourly by apparmor querying IPv6 interfaces

Asked by Ian McMichael on 2009-06-20

I'm running 8.10 server and every hour I am getting the following logged to kern.log:

Jun 20 15:21:03 roobarb kernel: [3301249.704162] type=1503 audit(1245507663.022:952): operation="inode_permission" requested_mask="::r" denied_mask="::r" fsuid=105 name="/proc/5509/net/if_inet6" pid=5510 profile="/usr/sbin/named"

Bind (named) is running as process 5509. Clearly something else tries to access it each hour. The PID of the process causing the log entry changes each hour. I can never catch the process running to find out what it is.

Here is /etc/apparmor.d/usr.sbin.named, which I believe is the standard file:

# vim:syntax=apparmor
# Last Modified: Fri Jun 1 16:43:22 2007
#include <tunables/global>

/usr/sbin/named {
  #include <abstractions/base>
  #include <abstractions/nameservice>

  capability net_bind_service,
  capability setgid,
  capability setuid,
  capability sys_chroot,

  # /etc/bind should be read-only for bind
  # /var/lib/bind is for dynamically updated zone (and journal) files.
  # /var/cache/bind is for slave/stub data, since we're not the origin of it.
  # See /usr/share/doc/bind9/README.Debian.gz
  /etc/bind/** r,
  /var/lib/bind/** rw,
  /var/lib/bind/ rw,
  /var/cache/bind/** rw,
  /var/cache/bind/ rw,

  # dnscvsutil package
  /var/lib/dnscvsutil/compiled/** rw,

  /proc/net/if_inet6 r,
  /usr/sbin/named mr,
  /var/run/bind/run/named.pid w,
  # support for resolvconf
  /var/run/bind/named.options r,
}

Can I increase apparmor's logging somehow to tell me the command line of the process that is running? Is there another way to track process activation on Linux? I've checked obvious things like the crontab but cannot work out what is causing the issue.

Thanks in advance,

Ian.

Question information

Language:
English Edit question
Status:
Solved
For:
Ubuntu apparmor Edit question
Assignee:
No assignee Edit question
Solved by:
Steven Danna
Solved:
2009-06-21
Last query:
2009-06-21
Last reply:
2009-06-20

This question was reopened

ps -ef | grep 5509

in your example. If the system gives a different pid you can search for it and kill the process or whatever is required

Ian McMichael (ian-sigma-uk) said : #2

Thanks for the reply. As I said above, named is running as PID 5509. You can see this from the path the other process is trying to access, IE. /proc/5509/net/if_inet6. What I am trying to work out is what runs for a moment as PID 5510, in this example, and changes each hour when it runs.

As the process only runs for a split second I'm never able to catch it. Any ideas how I can track what is running and, if possible, the command line it is using?

Thanks again,

Ian.

Steven Danna (ssd7) said : #3

Given the fact that (a) the process ID of the process being restricted by AppArmor is 5510 and the PID of named is 5509 and (b) that the process is being restricted by the AppArmor profile for named, it is fairly safe to say that whatever is being denied access to "/proc/5509/net/if_inet6" is a child process of /usr/bin/named. It make sense that read access to this file is being denied, since the profile for /usr/bin/named doesn't include a line allowing access to it.

If you want more information about process 5510, there are a number of ways to get more info about it using ps.

For instance, you can get the command line for a given process ID by doing something like this:

ps -o user,pid,ppid,command -p 5510

Also, and this may be of interest to you, you can get see the child processes of a given process, like 5509 by doing something like this:

ps -ely | awk " { if ( \$4 == 5509 ) {print}}"

Also, if you want to know the current PID of named (so that you can use the command above) you can do something like this:

ps -C named

There are tons of different options of ps to explore if you are looking for information about a process.

Ian McMichael (ian-sigma-uk) said : #4

Hi Steven,

Thanks for your assistance. I'm reasonably good with the ps command but certainly not up to your level.

I agree that this is probably a sub-process of named, otherwise the profile should be restricting it. However, my issue is that it runs for a fleeting moment once an hour. All the command you gave me are great if I can guess the process ID and run it at exactly the right millisecond.

Is there any way of auditing process start-up to a log file on Linux? A kernel setting somewhere, maybe? I'm looking for a clue as to what would be causing this.

On another interesting note, how would I allow this in an apparmor profile if I needed to? Clearly I can't add /proc/5509/net/if_inet6 as the process ID of named will change each time I start it.

It only happens on one of several Ubuntu servers I run and so there is clearly something different/wrong on this one. I'd just like to find out what is being denied before it bites me...

Thanks again,

Ian.

Steven Danna (ssd7) said : #5

I realized shortly after sending that answer that it likely wouldn't be
helpful if those child processes weren't sticking around. I don't know
much about apparmor to know if you can get more logging information.

One idea I had was to use tail -f on the log in question and then using
something like grep, awk, and sed to get the process id very quickly and
passing it to ps, but I don't know (a) if this would even work and (b)
be quick enough to get info before the process died. I haven't been
able to test such a solution because I don't have any apparmor entries
to test it against. Maybe something like this:

 ps -p $(sudo tail -f /var/log/kern.log | grep -i type=1503 | sed -r
"s/.*pid=(.*).*?/\1/" )

Obviously that would all be on one line. Like I said, I'm not even sure
if something like that would work, I'm sure the regex could be better.
Hopefully somebody with some more information about apparmor and process
monitoring can help. I'd be happy to "think this out" with you if that
would help.

You might want to respond to this message just to get the question back
into an "Open" state so that others who see it aren't discouraged from
pitching in.

Ian McMichael (ian-sigma-uk) said : #6

Thanks Steve. That's a great suggestion and certainly worth a shot.

I'm working down an alternative path at the moment. Having concluded it must be something named related I've turned up the trace level and am currently waiting for the next occurrence. Hopefully in the next 25 minutes or so I'll have a lot more to go on...

In the meantime, if you or anyone else happens to be a BIND expert, is the implied default setting below likely to be to blame?

options {
 interface-interval 60;
};

I believe this will cause the network interfaces to be scanned every hour for changes and named to bind (not BIND!) to any new ones it finds. This could well attempt to access /proc/<pid>/net/if_inet6 to check the bindings. Does this sound likely? If so, why am I only seeing it on one box and why has no-one else complained?

More when I have the BIND log...

Ian.

Ian McMichael (ian-sigma-uk) said : #7

Marked solved by accident! Ooops - see above...

Ian McMichael (ian-sigma-uk) said : #8

OK, here is what happens:

20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 0.in-addr.arpa/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 127.in-addr.arpa/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 254.169.IN-ADDR.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 2.0.192.IN-ADDR.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone <internal lan>.in-addr.arpa/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 255.in-addr.arpa/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 255.255.255.255.IN-ADDR.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.964 dns_zone_dialup: zone 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone D.F.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone 8.E.F.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone 9.E.F.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone A.E.F.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone B.E.F.IP6.ARPA/IN/internal: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone localhost/IN/internal: notify = 0, refresh = 0
<various internal zones removed for privacy>
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone <identity protected>/IN/external: notify = 0, refresh = 0
<various external zones removed for privacy>
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone authors.bind/CH: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone hostname.bind/CH: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone version.bind/CH: notify = 0, refresh = 0
20-Jun-2009 19:21:02.986 dns_zone_dialup: zone id.server/CH: notify = 0, refresh = 0

That was logged with debug level set to 10. Do any BIND experts know what it is doing and why it should upset apparmor? It looks like it is simply checking all the zone files for changes every hour.

Does anyone else run internal/external views with dynamic zones on their internal view? If so, are you seeing similar apparmor denials every hour in your log?

Not sure where to go next, so I'll probably try again with a higher debug level...

Ian.

Best Steven Danna (ssd7) said : #9

I found a bug report that seems related to this. According to that bug report, a fix for the issue should have already been released:

https://bugs.launchpad.net/ubuntu/+source/bind9/+bug/289060

Basically, the only thing that is wrong is the apparmor profile was incorrectly made. To fix it the following lines should be added:

/proc/**/net/if_inet6 r

There are other changes that can also be made. The bug report has a diff that shows all the changes.

Hope this helps!

Ian McMichael (ian-sigma-uk) said : #10

Thanks Steve. That bug does indeed appear to fix the issue. Looking at the Jaunty bind 9.6 package, I can see the line has actually been updated (amongst others) to:

/proc/*/net/if_inet6 r

This is more secure as the double asterisk allows the entire rest of the tree, if I am not mistaken? Anyway, it works with the single asterisk, so that's what I have gone with. I've also updated the bug asking if it can be released for those of us not yet running Jaunty.

Thanks again for helping track this one down. Shame my initial search on Google didn't turn up the bug report or I wouldn't have needed you assistance...

Ian McMichael (ian-sigma-uk) said : #11

Thanks Steven Danna, that solved my question.