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

Mon May 16 07:38:25 UTC 2016

On 05/15/2016 07:27 PM, apparmor at raf.org wrote:
> 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).
> 
Indeed those don't look spliced, and if you are getting more than the odd
one it wouldn't be a splicing problem either.

> 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.
> 
Well that's both good and bad, I happy that it is working for you but I
hate phantom bugs, they are so hard to track down.

If this hits again, grab all the info you can ps-tree, ps -Z etc and let
us know so we can work on figuring this out.