diff mbox series

[2/2] selinux: add attributes to avc tracepoint

Message ID 20200806080358.3124505-2-tweek@google.com (mailing list archive)
State Superseded
Delegated to: Paul Moore
Headers show
Series [1/2] selinux: add tracepoint on denials | expand

Commit Message

Thiébaud Weksteen Aug. 6, 2020, 8:03 a.m. UTC
From: Peter Enderborg <peter.enderborg@sony.com>

Add further attributes to filter the trace events from AVC.

Signed-off-by: Peter Enderborg <peter.enderborg@sony.com>
Reviewed-by: Thiébaud Weksteen <tweek@google.com>
---
 include/trace/events/avc.h | 41 ++++++++++++++++++++++++++++----------
 security/selinux/avc.c     | 22 +++++++++++---------
 2 files changed, 44 insertions(+), 19 deletions(-)

Comments

Stephen Smalley Aug. 6, 2020, 12:11 p.m. UTC | #1
On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:

> From: Peter Enderborg <peter.enderborg@sony.com>
>
> Add further attributes to filter the trace events from AVC.

Please include sample usage and output in the description.
Peter Enderborg Aug. 6, 2020, 12:24 p.m. UTC | #2
On 8/6/20 2:11 PM, Stephen Smalley wrote:
> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
>
>> From: Peter Enderborg <peter.enderborg@sony.com>
>>
>> Add further attributes to filter the trace events from AVC.
>
> Please include sample usage and output in the description.
>
>
Im not sure where you want it to be.

In the commit message or in a Documentation/trace/events-avc.rst ?
Stephen Smalley Aug. 6, 2020, 12:32 p.m. UTC | #3
On 8/6/20 8:24 AM, peter enderborg wrote:

> On 8/6/20 2:11 PM, Stephen Smalley wrote:
>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
>>
>>> From: Peter Enderborg <peter.enderborg@sony.com>
>>>
>>> Add further attributes to filter the trace events from AVC.
>> Please include sample usage and output in the description.
>>
>>
> Im not sure where you want it to be.
>
> In the commit message or in a Documentation/trace/events-avc.rst ?

I was just asking for it in the commit message / patch description.  I 
don't know what is typical for Documentation/trace.
Stephen Smalley Aug. 6, 2020, 1:45 p.m. UTC | #4
On 8/6/20 8:32 AM, Stephen Smalley wrote:

> On 8/6/20 8:24 AM, peter enderborg wrote:
>
>> On 8/6/20 2:11 PM, Stephen Smalley wrote:
>>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
>>>
>>>> From: Peter Enderborg <peter.enderborg@sony.com>
>>>>
>>>> Add further attributes to filter the trace events from AVC.
>>> Please include sample usage and output in the description.
>>>
>>>
>> Im not sure where you want it to be.
>>
>> In the commit message or in a Documentation/trace/events-avc.rst ?
>
> I was just asking for it in the commit message / patch description.  I 
> don't know what is typical for Documentation/trace.

For example, I just took the patches for a spin, running the 
selinux-testsuite under perf like so:

sudo perf record -e avc:selinux_audited -g make test

and then ran:

sudo perf report -g

and a snippet of sample output included:

      6.40%     6.40%  requested=0x800000 denied=0x800000 
audited=0x800000 result=-13 ssid=922 tsid=922 
scontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023 
tcontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023 
tclass=capability
             |
             ---0x495641000028933d
                __libc_start_main
                |
                |--4.60%--__GI___ioctl
                |          entry_SYSCALL_64
                |          do_syscall_64
                |          __x64_sys_ioctl
                |          ksys_ioctl
                |          binder_ioctl
                |          binder_set_nice
                |          can_nice
                |          capable
                |          security_capable
                |          cred_has_capability.isra.0
                |          slow_avc_audit
                |          common_lsm_audit
                |          avc_audit_post_callback
                |          avc_audit_post_callback
                |
Stephen Smalley Aug. 6, 2020, 1:49 p.m. UTC | #5
On Thu, Aug 6, 2020 at 9:45 AM Stephen Smalley
<stephen.smalley.work@gmail.com> wrote:
>
> On 8/6/20 8:32 AM, Stephen Smalley wrote:
>
> > On 8/6/20 8:24 AM, peter enderborg wrote:
> >
> >> On 8/6/20 2:11 PM, Stephen Smalley wrote:
> >>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
> >>>
> >>>> From: Peter Enderborg <peter.enderborg@sony.com>
> >>>>
> >>>> Add further attributes to filter the trace events from AVC.
> >>> Please include sample usage and output in the description.
> >>>
> >>>
> >> Im not sure where you want it to be.
> >>
> >> In the commit message or in a Documentation/trace/events-avc.rst ?
> >
> > I was just asking for it in the commit message / patch description.  I
> > don't know what is typical for Documentation/trace.
>
> For example, I just took the patches for a spin, running the
> selinux-testsuite under perf like so:
>
> sudo perf record -e avc:selinux_audited -g make test
>
> and then ran:
>
> sudo perf report -g
>
> and a snippet of sample output included:
>
>       6.40%     6.40%  requested=0x800000 denied=0x800000
> audited=0x800000 result=-13 ssid=922 tsid=922
> scontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
> tcontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
> tclass=capability

So then the question becomes how do you use the above information,
e.g. is that sufficient to correlate it to an actual avc: denied
message, how do you decode the requested/denied/audited fields (or
should the code do that for you and just report the string name(s) of
the permission(s), do you need all three of those fields separately,
is it useful to log the ssid/tsid at all given that you have the
contexts and sids are dynamically assigned, etc.

>              |
>              ---0x495641000028933d
>                 __libc_start_main
>                 |
>                 |--4.60%--__GI___ioctl
>                 |          entry_SYSCALL_64
>                 |          do_syscall_64
>                 |          __x64_sys_ioctl
>                 |          ksys_ioctl
>                 |          binder_ioctl
>                 |          binder_set_nice
>                 |          can_nice
>                 |          capable
>                 |          security_capable
>                 |          cred_has_capability.isra.0
>                 |          slow_avc_audit
>                 |          common_lsm_audit
>                 |          avc_audit_post_callback
>                 |          avc_audit_post_callback
Peter Enderborg Aug. 6, 2020, 2:51 p.m. UTC | #6
On 8/6/20 3:49 PM, Stephen Smalley wrote:
> On Thu, Aug 6, 2020 at 9:45 AM Stephen Smalley
> <stephen.smalley.work@gmail.com> wrote:
>> On 8/6/20 8:32 AM, Stephen Smalley wrote:
>>
>>> On 8/6/20 8:24 AM, peter enderborg wrote:
>>>
>>>> On 8/6/20 2:11 PM, Stephen Smalley wrote:
>>>>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
>>>>>
>>>>>> From: Peter Enderborg <peter.enderborg@sony.com>
>>>>>>
>>>>>> Add further attributes to filter the trace events from AVC.
>>>>> Please include sample usage and output in the description.
>>>>>
>>>>>
>>>> Im not sure where you want it to be.
>>>>
>>>> In the commit message or in a Documentation/trace/events-avc.rst ?
>>> I was just asking for it in the commit message / patch description.  I
>>> don't know what is typical for Documentation/trace.
>> For example, I just took the patches for a spin, running the
>> selinux-testsuite under perf like so:
>>
>> sudo perf record -e avc:selinux_audited -g make test
>>
>> and then ran:
>>
>> sudo perf report -g
>>
>> and a snippet of sample output included:
>>
>>       6.40%     6.40%  requested=0x800000 denied=0x800000
>> audited=0x800000 result=-13 ssid=922 tsid=922
>> scontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
>> tcontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
>> tclass=capability
> So then the question becomes how do you use the above information,
> e.g. is that sufficient to correlate it to an actual avc: denied
> message, how do you decode the requested/denied/audited fields (or
> should the code do that for you and just report the string name(s) of
> the permission(s), do you need all three of those fields separately,
> is it useful to log the ssid/tsid at all given that you have the
> contexts and sids are dynamically assigned, etc.
>
>>              |
>>              ---0x495641000028933d
>>                 __libc_start_main
>>                 |
>>                 |--4.60%--__GI___ioctl
>>                 |          entry_SYSCALL_64
>>                 |          do_syscall_64
>>                 |          __x64_sys_ioctl
>>                 |          ksys_ioctl
>>                 |          binder_ioctl
>>                 |          binder_set_nice
>>                 |          can_nice
>>                 |          capable
>>                 |          security_capable
>>                 |          cred_has_capability.isra.0
>>                 |          slow_avc_audit
>>                 |          common_lsm_audit
>>                 |          avc_audit_post_callback
>>                 |          avc_audit_post_callback

The real cool thing happen when you enable "user-stack-trace" too.

           <...>-4820  [007] .... 85878.897553: selinux_audited: requested=0x4000000 denied=0x4000000 audited=0x4000000 result=-13 ssid=341 tsid=61 scontext=system_u:system_r:ntpd_t:s0 tcontext=system_u:object_r:bin_t:s0 tclass=file
           <...>-4820  [007] .... 85878.897572: <user stack trace>
 =>  <00007f07d99bb45b>
 =>  <0000555ecd89ca57>

The fields are useful for filter what you what to see and what you can ignore.  Having the ssid and text was from the part where it is called.
The numeric can be used for two things. When you dont have any context. Same same reason as in post_callback. We need to be static
in format so it need  be there if it ever can happen. And it is also useful for faster filtering.

You can do "ssid!=42 && ssid!=43 && tsid==666".  From my view it would be good to have all fields there. But they need to right typed to be able
to use the filter mechanism. There must me some trade-off too where the argument filtering get bigger than the processing, but I think we can
add a lot more before we reach that threshold.
Stephen Smalley Aug. 6, 2020, 3:03 p.m. UTC | #7
On Thu, Aug 6, 2020 at 10:51 AM peter enderborg
<peter.enderborg@sony.com> wrote:
>
> On 8/6/20 3:49 PM, Stephen Smalley wrote:
> > On Thu, Aug 6, 2020 at 9:45 AM Stephen Smalley
> > <stephen.smalley.work@gmail.com> wrote:
> >> On 8/6/20 8:32 AM, Stephen Smalley wrote:
> >>
> >>> On 8/6/20 8:24 AM, peter enderborg wrote:
> >>>
> >>>> On 8/6/20 2:11 PM, Stephen Smalley wrote:
> >>>>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
> >>>>>
> >>>>>> From: Peter Enderborg <peter.enderborg@sony.com>
> >>>>>>
> >>>>>> Add further attributes to filter the trace events from AVC.
> >>>>> Please include sample usage and output in the description.
> >>>>>
> >>>>>
> >>>> Im not sure where you want it to be.
> >>>>
> >>>> In the commit message or in a Documentation/trace/events-avc.rst ?
> >>> I was just asking for it in the commit message / patch description.  I
> >>> don't know what is typical for Documentation/trace.
> >> For example, I just took the patches for a spin, running the
> >> selinux-testsuite under perf like so:
> >>
> >> sudo perf record -e avc:selinux_audited -g make test
> >>
> >> and then ran:
> >>
> >> sudo perf report -g
> >>
> >> and a snippet of sample output included:
> >>
> >>       6.40%     6.40%  requested=0x800000 denied=0x800000
> >> audited=0x800000 result=-13 ssid=922 tsid=922
> >> scontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
> >> tcontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
> >> tclass=capability
> > So then the question becomes how do you use the above information,
> > e.g. is that sufficient to correlate it to an actual avc: denied
> > message, how do you decode the requested/denied/audited fields (or
> > should the code do that for you and just report the string name(s) of
> > the permission(s), do you need all three of those fields separately,
> > is it useful to log the ssid/tsid at all given that you have the
> > contexts and sids are dynamically assigned, etc.
> >
> >>              |
> >>              ---0x495641000028933d
> >>                 __libc_start_main
> >>                 |
> >>                 |--4.60%--__GI___ioctl
> >>                 |          entry_SYSCALL_64
> >>                 |          do_syscall_64
> >>                 |          __x64_sys_ioctl
> >>                 |          ksys_ioctl
> >>                 |          binder_ioctl
> >>                 |          binder_set_nice
> >>                 |          can_nice
> >>                 |          capable
> >>                 |          security_capable
> >>                 |          cred_has_capability.isra.0
> >>                 |          slow_avc_audit
> >>                 |          common_lsm_audit
> >>                 |          avc_audit_post_callback
> >>                 |          avc_audit_post_callback
>
> The real cool thing happen when you enable "user-stack-trace" too.
>
>            <...>-4820  [007] .... 85878.897553: selinux_audited: requested=0x4000000 denied=0x4000000 audited=0x4000000 result=-13 ssid=341 tsid=61 scontext=system_u:system_r:ntpd_t:s0 tcontext=system_u:object_r:bin_t:s0 tclass=file
>            <...>-4820  [007] .... 85878.897572: <user stack trace>
>  =>  <00007f07d99bb45b>
>  =>  <0000555ecd89ca57>
>
> The fields are useful for filter what you what to see and what you can ignore.  Having the ssid and text was from the part where it is called.
> The numeric can be used for two things. When you dont have any context. Same same reason as in post_callback. We need to be static
> in format so it need  be there if it ever can happen. And it is also useful for faster filtering.
>
> You can do "ssid!=42 && ssid!=43 && tsid==666".  From my view it would be good to have all fields there. But they need to right typed to be able
> to use the filter mechanism. There must me some trade-off too where the argument filtering get bigger than the processing, but I think we can
> add a lot more before we reach that threshold.

I don't think the SIDs are useful because they are dynamically
assigned (aside from the initial SIDs for bootstrapping before policy
load) and are not exported to userspace (userspace has no way to look
them up).  It is probably a mistake that we even fall back to logging
them in the existing code and may just be a legacy of when SIDs were
exported to userspace (ancient history, before mainline merge of
SELinux).

In any event, if you were to include the sample usage and output I
provided as part of the commit message / patch description (or replace
with your own example), that would be helpful I think.  Even better
would be to also provide some hint as to how people are expected to
decode the requested/denied/audited fields (I know how to do that but
not everyone will, and ideally one would have a script or something
for doing so).
Peter Enderborg Aug. 6, 2020, 3:59 p.m. UTC | #8
On 8/6/20 5:03 PM, Stephen Smalley wrote:
> On Thu, Aug 6, 2020 at 10:51 AM peter enderborg
> <peter.enderborg@sony.com> wrote:
>> On 8/6/20 3:49 PM, Stephen Smalley wrote:
>>> On Thu, Aug 6, 2020 at 9:45 AM Stephen Smalley
>>> <stephen.smalley.work@gmail.com> wrote:
>>>> On 8/6/20 8:32 AM, Stephen Smalley wrote:
>>>>
>>>>> On 8/6/20 8:24 AM, peter enderborg wrote:
>>>>>
>>>>>> On 8/6/20 2:11 PM, Stephen Smalley wrote:
>>>>>>> On 8/6/20 4:03 AM, Thiébaud Weksteen wrote:
>>>>>>>
>>>>>>>> From: Peter Enderborg <peter.enderborg@sony.com>
>>>>>>>>
>>>>>>>> Add further attributes to filter the trace events from AVC.
>>>>>>> Please include sample usage and output in the description.
>>>>>>>
>>>>>>>
>>>>>> Im not sure where you want it to be.
>>>>>>
>>>>>> In the commit message or in a Documentation/trace/events-avc.rst ?
>>>>> I was just asking for it in the commit message / patch description.  I
>>>>> don't know what is typical for Documentation/trace.
>>>> For example, I just took the patches for a spin, running the
>>>> selinux-testsuite under perf like so:
>>>>
>>>> sudo perf record -e avc:selinux_audited -g make test
>>>>
>>>> and then ran:
>>>>
>>>> sudo perf report -g
>>>>
>>>> and a snippet of sample output included:
>>>>
>>>>       6.40%     6.40%  requested=0x800000 denied=0x800000
>>>> audited=0x800000 result=-13 ssid=922 tsid=922
>>>> scontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
>>>> tcontext=unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023
>>>> tclass=capability
>>> So then the question becomes how do you use the above information,
>>> e.g. is that sufficient to correlate it to an actual avc: denied
>>> message, how do you decode the requested/denied/audited fields (or
>>> should the code do that for you and just report the string name(s) of
>>> the permission(s), do you need all three of those fields separately,
>>> is it useful to log the ssid/tsid at all given that you have the
>>> contexts and sids are dynamically assigned, etc.
>>>
>>>>              |
>>>>              ---0x495641000028933d
>>>>                 __libc_start_main
>>>>                 |
>>>>                 |--4.60%--__GI___ioctl
>>>>                 |          entry_SYSCALL_64
>>>>                 |          do_syscall_64
>>>>                 |          __x64_sys_ioctl
>>>>                 |          ksys_ioctl
>>>>                 |          binder_ioctl
>>>>                 |          binder_set_nice
>>>>                 |          can_nice
>>>>                 |          capable
>>>>                 |          security_capable
>>>>                 |          cred_has_capability.isra.0
>>>>                 |          slow_avc_audit
>>>>                 |          common_lsm_audit
>>>>                 |          avc_audit_post_callback
>>>>                 |          avc_audit_post_callback
>> The real cool thing happen when you enable "user-stack-trace" too.
>>
>>            <...>-4820  [007] .... 85878.897553: selinux_audited: requested=0x4000000 denied=0x4000000 audited=0x4000000 result=-13 ssid=341 tsid=61 scontext=system_u:system_r:ntpd_t:s0 tcontext=system_u:object_r:bin_t:s0 tclass=file
>>            <...>-4820  [007] .... 85878.897572: <user stack trace>
>>  =>  <00007f07d99bb45b>
>>  =>  <0000555ecd89ca57>
>>
>> The fields are useful for filter what you what to see and what you can ignore.  Having the ssid and text was from the part where it is called.
>> The numeric can be used for two things. When you dont have any context. Same same reason as in post_callback. We need to be static
>> in format so it need  be there if it ever can happen. And it is also useful for faster filtering.
>>
>> You can do "ssid!=42 && ssid!=43 && tsid==666".  From my view it would be good to have all fields there. But they need to right typed to be able
>> to use the filter mechanism. There must me some trade-off too where the argument filtering get bigger than the processing, but I think we can
>> add a lot more before we reach that threshold.
> I don't think the SIDs are useful because they are dynamically
> assigned (aside from the initial SIDs for bootstrapping before policy
> load) and are not exported to userspace (userspace has no way to look
> them up).  It is probably a mistake that we even fall back to logging
> them in the existing code and may just be a legacy of when SIDs were
> exported to userspace (ancient history, before mainline merge of
> SELinux).
>
> In any event, if you were to include the sample usage and output I
> provided as part of the commit message / patch description (or replace
> with your own example), that would be helpful I think.  Even better
> would be to also provide some hint as to how people are expected to
> decode the requested/denied/audited fields (I know how to do that but
> not everyone will, and ideally one would have a script or something
> for doing so).

But they are always the same until load off a new policy? And they can be mapped while debugging.

You see one event and then you "know" it. This is for developers so it is a different mindset than for the
netlink type that is for administrators.  Features for speeding things up are useful.

Im doing a update on commit message, will send it to Weksteen for a review round first.
Steven Rostedt Aug. 6, 2020, 4:37 p.m. UTC | #9
On Thu, 6 Aug 2020 08:32:38 -0400
Stephen Smalley <stephen.smalley.work@gmail.com> wrote:

> >
> > In the commit message or in a Documentation/trace/events-avc.rst ?  
> 
> I was just asking for it in the commit message / patch description.  I 
> don't know what is typical for Documentation/trace.

No, the Documentation/trace is for generic tracing documentation. Not
for individual events.

-- Steve
Paul Moore Aug. 7, 2020, 2:22 a.m. UTC | #10
On Thu, Aug 6, 2020 at 12:37 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> On Thu, 6 Aug 2020 08:32:38 -0400
> Stephen Smalley <stephen.smalley.work@gmail.com> wrote:
> > >
> > > In the commit message or in a Documentation/trace/events-avc.rst ?
> >
> > I was just asking for it in the commit message / patch description.  I
> > don't know what is typical for Documentation/trace.
>
> No, the Documentation/trace is for generic tracing documentation. Not
> for individual events.

As I've said many times in the past, I've never rejected a patch
because the patch description was too verbose, but I have rejected
patches where the description hasn't provided enough useful
information.

I would really like to see the commit description show an example
where you setup/load/etc. the event into the kernel, trigger and
capture the event information, and then show how the event output can
be parsed/processed into something meaningful by a user.  I'm
essentially looking for a "hello world" version of the SELinux
tracepoint, does that make sense?
diff mbox series

Patch

diff --git a/include/trace/events/avc.h b/include/trace/events/avc.h
index 07c058a9bbcd..ac5ef2e1c2c5 100644
--- a/include/trace/events/avc.h
+++ b/include/trace/events/avc.h
@@ -1,6 +1,7 @@ 
 /* SPDX-License-Identifier: GPL-2.0 */
 /*
- * Author: Thiébaud Weksteen <tweek@google.com>
+ * Authors:	Thiébaud Weksteen <tweek@google.com>
+ *		Peter Enderborg <Peter.Enderborg@sony.com>
  */
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM avc
@@ -12,23 +13,43 @@ 
 
 TRACE_EVENT(selinux_audited,
 
-	TP_PROTO(struct selinux_audit_data *sad),
+	TP_PROTO(struct selinux_audit_data *sad,
+		char *scontext,
+		char *tcontext,
+		const char *tclass
+	),
 
-	TP_ARGS(sad),
+	TP_ARGS(sad, scontext, tcontext, tclass),
 
 	TP_STRUCT__entry(
-		__field(unsigned int, tclass)
-		__field(unsigned int, audited)
+		__field(u32, requested)
+		__field(u32, denied)
+		__field(u32, audited)
+		__field(int, result)
+		__string(scontext, scontext)
+		__string(tcontext, tcontext)
+		__string(tclass, tclass)
+		__field(u32, ssid)
+		__field(u32, tsid)
 	),
 
 	TP_fast_assign(
-		__entry->tclass = sad->tclass;
-		__entry->audited = sad->audited;
+		__entry->requested	= sad->requested;
+		__entry->denied		= sad->denied;
+		__entry->audited	= sad->audited;
+		__entry->result		= sad->result;
+		__entry->ssid		= sad->ssid;
+		__entry->tsid		= sad->tsid;
+		__assign_str(tcontext, tcontext);
+		__assign_str(scontext, scontext);
+		__assign_str(tclass, tclass);
 	),
 
-	TP_printk("tclass=%u audited=%x",
-		__entry->tclass,
-		__entry->audited)
+	TP_printk("requested=0x%x denied=0x%x audited=0x%x result=%d ssid=%u tsid=%u scontext=%s tcontext=%s tclass=%s",
+		__entry->requested, __entry->denied, __entry->audited, __entry->result,
+		__entry->ssid, __entry->tsid, __get_str(scontext), __get_str(tcontext),
+		__get_str(tclass)
+	)
 );
 
 #endif
diff --git a/security/selinux/avc.c b/security/selinux/avc.c
index b0a0af778b70..7de5cc5169af 100644
--- a/security/selinux/avc.c
+++ b/security/selinux/avc.c
@@ -705,35 +705,39 @@  static void avc_audit_post_callback(struct audit_buffer *ab, void *a)
 {
 	struct common_audit_data *ad = a;
 	struct selinux_audit_data *sad = ad->selinux_audit_data;
-	char *scontext;
+	char *scontext = NULL;
+	char *tcontext = NULL;
+	const char *tclass = NULL;
 	u32 scontext_len;
+	u32 tcontext_len;
 	int rc;
 
-	trace_selinux_audited(sad);
-
 	rc = security_sid_to_context(sad->state, sad->ssid, &scontext,
 				     &scontext_len);
 	if (rc)
 		audit_log_format(ab, " ssid=%d", sad->ssid);
 	else {
 		audit_log_format(ab, " scontext=%s", scontext);
-		kfree(scontext);
 	}
 
-	rc = security_sid_to_context(sad->state, sad->tsid, &scontext,
-				     &scontext_len);
+	rc = security_sid_to_context(sad->state, sad->tsid, &tcontext,
+				     &tcontext_len);
 	if (rc)
 		audit_log_format(ab, " tsid=%d", sad->tsid);
 	else {
-		audit_log_format(ab, " tcontext=%s", scontext);
-		kfree(scontext);
+		audit_log_format(ab, " tcontext=%s", tcontext);
 	}
 
-	audit_log_format(ab, " tclass=%s", secclass_map[sad->tclass-1].name);
+	tclass = secclass_map[sad->tclass-1].name;
+	audit_log_format(ab, " tclass=%s", tclass);
 
 	if (sad->denied)
 		audit_log_format(ab, " permissive=%u", sad->result ? 0 : 1);
 
+	trace_selinux_audited(sad, scontext, tcontext, tclass);
+	kfree(tcontext);
+	kfree(scontext);
+
 	/* in case of invalid context report also the actual context string */
 	rc = security_sid_to_context_inval(sad->state, sad->ssid, &scontext,
 					   &scontext_len);