[apparmor] Understanding log messages (when prof != comm)

[apparmor at raf.org]

Hi,

Sorry for the delay in responding.

John Johansen wrote:

> On 05/10/2016 10:32 PM, apparmor at raf.org wrote:
> 
> <<snip>>
> 
> >>
> >>> There is a separate profile for each postfix executable.
> >>>
> >> okay
> >>
> >>> The profile /etc/apparmor.d/usr.lib.postfix.master contains:
> >>>
> >>>   /usr/lib/postfix/smtp Px,
> >>>
> >>> The profile /etc/apparmor.d/usr.lib.postfix.smtp contains:
> >>>
> >>>   /{var/spool/postfix/,}active/[0-9A-F]* rwk,
> >>>
> >> ah, another potential point of confusion. The name of the file
> >> containing the profile is arbitrary. It is just there to help
> >> humans find the various profiles. The file can even contain
> >> multiple profiles.
> >>
> >> You could have a single postfix file which contained the
> >> profiles
> >>   profile /usr/lib/postfix/smp { }
> >>   profile /usr/lib/postfix/foobar { }
> >>   ...
> > 
> > Sorry I didn't mention it before but the debian package that contains
> > these postfix profiles each contain a single profile with no "profile"
> > keyword and so the attachment defaults to the profile name which is
> > indicated by the name of the file (with slashes instead of fullstops/periods).
> > I haven't changed that structure. I have only added a few rules where
> > needed. Other profiles in that debian have multiple profiles per file
> > but not the postfix ones.
> 
> okay thanks
> 
> >> now with that said back to the rule and the log message
> >>
> >>> I'm seeing apparmor log messages that contain:
> >>>
> >>>   profile="/usr/lib/postfix/master"
> >>>   op="file_lock"
> >>>   name="/var/spool/postfix/active/01FBB1FA73"
> >>>   comm="smtp"
> >>>   req="k"
> >>>   denied="k"
> >>>
> >>> This makes me think that the profile for master needs to have
> >>> a rule added like the above rule for smtp but the comm="smtp"
> >>> makes me think that this log message is about smtp, not master,
> >>> but smtp already has this rule.
> >>>
> >>> What am I not understanding here? Why is the profile for master
> >>> being mentioned in the log message rather than the profile for smtp?
> >>> Is it master or smtp that is trying to lock the file in question?
> >>> Which profile needs a new rule? Does the master profile needs the
> >>> same rule as the smtp profile, or is the rule in the smtp profile
> >>> incorrect?
> >>
> >> the rule from the /etc/apparmor.d/usr.lib.postfix.smtp
> >> profile should allow that denial, however from the
> >> profile= entry we can see that the application is NOT
> >> being confined by the /etc/apparmor.d/usr.lib.postfix.smtp
> >> profile it is being confined by the 
> >>   /usr/lib/postfix/master profile.
> >>
> >> and the comm is smtp
> >>
> >> So why would this happen? First up I am assuming you don't
> >> have any custom attachments defined for those profiles.
> > 
> > That's correct.
> > 
> >> The first thing that comes to my mind is that the smtp
> >> program was not run from /usr/lib/postfix/smtp which would
> >> mean the Px rule was not applied.
> > 
> > I don't understand how that is possible. Since the master profile
> > is in effect, master must have started smtp and it wouldn't start
> > any smtp other than /usr/lib/postfix/smtp and, even if it tried,
> > there is no rule to allow it to do so. It can only start the
> > binaries that apparmor allows it to.
> > 
> > And /usr/lib/postfix/smtp is the only executable named smtp
> > on the host.
> > 
> Well I was thinking another none postix process could have started
> it. Eg was aa-exec but something else could have. Not saying that
> did happen, just a possibility to look into
> 
> >> Other potential reasons would be postfix is using change_onexec
> >> to override the rule. This is unlikely as I am unaware of any
> >> such modification to postfix, and the postfix/master profile
> >> would also need the correct change_profile rules.
> > 
> > And I certainly didn't make any such modification. :-)
> > 
> >> Another possibility is that smtp was run via something that
> >> is confined by a different profile. Eg from the terminal I
> >> can do
> >>
> >>   aa-exec -p /usr/lib/postfix/master -- smtp ...
> >>
> >> and it will run under the postfix/master profile
> > 
> > I'd remember if I had done that. :-)
> 
> Well I would hope so :)
> 
> >> you need to check where the smtp profile is in the filesystem
> >> to make sure the attachment is correct.
> > 
> > The smtp profile is in /etc/apparmor.d/usr.lib.postfix.smtp
> > and the profile name and attachment are both "/usr/lib/postfix/smtp".
> 
> okay
> 
> >> And you should check
> >> the parent pid and comm/confinement (ps -Z for the profile
> >> information), to ensure it is being started by the postfix/master
> >> profile.
> > 
> > pstree tells me that the smtp processes were all started by master.
> > I would have thought that the profile field in the log message also
> > indicates this (barring manual use of aa-exec of course).
> > 
> sure the profile field certainly hints at that but, the message is
> odd in more than one way so its worth checking
> 
> With pstree is showing smtp processes are all started by master,
> what are their security fields showing
> 
>   ps aux -Z | grep smtp
> 
> should do the trick. Do any of them show that they are confined
> by the wrong profile?

Sorry for the delay. The below looks fine but I had disabled the
profiles for awhile and have just re-enabled them and restarted
apparmor and restarted postfix before running the command below.

I hadn't restarted anything before because I hadn't changed any
profiles yet except to put them into complain mode. The new
behaviour started happening and the strange log message
started appearing.

  $ ps aux -Z | grep [s]mtp
  /usr/lib/postfix/smtpd postfix 32431 0.0 0.5 44860 5656 ? S 10:52 0:00 smtpd -n smtp ...
  /usr/lib/postfix/smtp  postfix 32434 0.0 0.3 42724 4088 ? S 10:52 0:00 smtp -n smtp-a...
  /usr/lib/postfix/smtpd postfix 32437 0.0 0.5 42788 5548 ? S 10:52 0:00 smtpd -n 127.0...
  /usr/lib/postfix/smtp  postfix 32438 0.0 0.3 42556 3988 ? S 10:52 0:00 smtp -n relay ...

> >> Oh and you didn't mention what the attachment/profile name
> >> of the /etc/apparmor.d/usr.lib.postfix.smtp profile actually
> >> is. Check there as well to make sure it is correct
> > 
> > The attachment and profile name are both "/usr/lib/postfix/smtp".
> > 
> > Here are all of the postfix-related profiles/attachments and
> > the exec rules that they contain:
> > 
> >   [...snip...]
> > 
> > So the only profiles that allow smtp to be executed are
> > master and smtp itself.
> > 
> > Thanks for all of your explanations. It was quite a heroic effort.
> > But I'm still at a loss to explain this log message or what to do
> > about it. :-(
> > 
> thanks. Though your answers didn't really make me happy :)
> 
> This is quite weird, some more info would be useful
> 
> version of apparmor?  apparmor_parser -V
> kernel version? Any custom patches on it?

 $ apparmor_parser -V
 AppArmor parser version 2.9.0
 Copyright (C) 1999-2008 Novell Inc.
 Copyright 2009-2012 Canonical Ltd.

 $ uname -a
 Linux s1 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt25-2 (2016-04-08) x86_64 GNU/Linux

No custom patches here, but possibly Debian-8 patches.

> Oh and was the message straight from dmesg, or a logging daemon, and
> if so which one auditd?, syslog? ...
> 
> We have had cases in the past where there was ring buffer overflow
> causing 2 log messages to be spliced together? So the full original
> log message, unedited might help in checking for splicing etc.
> 
> Not that we have seen that recently but it was a problem in the past

There were many instances of similar messages so it doesn't look like
a ring buffer overflow. There were 88 for comm="smtp", 694 for comm="smtpd",
427 for comm="trivial-rewrite", 149 for comm="pickup" and 25 for comm="cleanup"
on May 2.

But what I showed was an abbreviated version.

Here's a full version:

  May  2 15:06:09 s1 kernel: [385560.467958] audit:
  type=1400 audit(1462165569.115:16396):
  apparmor="ALLOWED" operation="open"
  profile="/usr/lib/postfix/master"
  name="/var/spool/postfix/active/01FBB1FA73"
  pid=31128 comm="smtp" requested_mask="rw"
  denied_mask="rw" fsuid=109 ouid=109

  May  2 15:06:09 s1 kernel: [385560.467964] audit:
  type=1400 audit(1462165569.115:16397):
  apparmor="ALLOWED" operation="file_lock"
  profile="/usr/lib/postfix/master"
  name="/var/spool/postfix/active/01FBB1FA73"
  pid=31128 comm="smtp" requested_mask="k"
  denied_mask="k" fsuid=109 ouid=109

They are from /var/log/messages (via rsyslog).

Interestingly, after re-enabling the profiles and restarting apparmor and
postfix today, the same sort of messages have not appeared. Maybe whatever
it is is over.

cheers,
raf