[PATCH RESEND 2/2] selinux: provide matching audit timestamp in the AVC trace event

[Ondrej Mosnacek]

In order to make it possible for the users and tooling to associate an
SELinux AVC trace event with the corresponding audit event, make it
include the audit timestamp (including the "serial number") of the
event.

First make audit_log_start() include the timestamp in the audit_buffer
struct and add a public helper to retrieve it from an audit_buffer
instance. Then retrieve it in SELinux's avc_audit_post_callback() and
include it in the "avc:selinux_audited" trace event.

After this patch the even includes the numeric fields that make up the
timestamp and the text representation includes the timestamp in the same
format as used in the audit log - e.g. "audit_ts=1671454430.092:1671".

Signed-off-by: Ondrej Mosnacek <omosnace at redhat.com>
---
 include/linux/audit.h      |  8 ++++++++
 include/trace/events/avc.h | 25 +++++++++++++++++--------
 kernel/audit.c             | 15 +++++++++++----
 security/selinux/avc.c     |  4 +++-
 4 files changed, 39 insertions(+), 13 deletions(-)

diff --git a/include/linux/audit.h b/include/linux/audit.h
index 788ab93c3be4..d6d7acc1b623 100644
--- a/include/linux/audit.h
+++ b/include/linux/audit.h
@@ -162,6 +162,9 @@ extern __printf(4, 5)
 void audit_log(struct audit_context *ctx, gfp_t gfp_mask, int type,
 	       const char *fmt, ...);
 
+extern void audit_buffer_get_timestamp(struct audit_buffer *ab,
+				       struct audit_timestamp *ts);
+
 extern struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask, int type);
 extern __printf(2, 3)
 void audit_log_format(struct audit_buffer *ab, const char *fmt, ...);
@@ -218,6 +221,11 @@ static inline __printf(4, 5)
 void audit_log(struct audit_context *ctx, gfp_t gfp_mask, int type,
 	       const char *fmt, ...)
 { }
+static inline void audit_buffer_get_timestamp(struct audit_buffer *ab,
+					      struct audit_timestamp *ts)
+{
+	*ts = (struct audit_timestamp){};
+}
 static inline struct audit_buffer *audit_log_start(struct audit_context *ctx,
 						   gfp_t gfp_mask, int type)
 {
diff --git a/include/trace/events/avc.h b/include/trace/events/avc.h
index b55fda2e0773..8cac14ae22ae 100644
--- a/include/trace/events/avc.h
+++ b/include/trace/events/avc.h
@@ -16,34 +16,43 @@ TRACE_EVENT(selinux_audited,
 	TP_PROTO(struct selinux_audit_data *sad,
 		char *scontext,
 		char *tcontext,
-		const char *tclass
+		const char *tclass,
+		const struct audit_timestamp *ts
 	),
 
-	TP_ARGS(sad, scontext, tcontext, tclass),
+	TP_ARGS(sad, scontext, tcontext, tclass, ts),
 
 	TP_STRUCT__entry(
 		__field(u32, requested)
 		__field(u32, denied)
 		__field(u32, audited)
 		__field(int, result)
+		__field(u64, audit_stamp_sec)
+		__field(u32, audit_stamp_msec)
+		__field(u32, audit_stamp_serial)
 		__string(scontext, scontext)
 		__string(tcontext, tcontext)
 		__string(tclass, tclass)
 	),
 
 	TP_fast_assign(
-		__entry->requested	= sad->requested;
-		__entry->denied		= sad->denied;
-		__entry->audited	= sad->audited;
-		__entry->result		= sad->result;
+		__entry->requested		= sad->requested;
+		__entry->denied			= sad->denied;
+		__entry->audited		= sad->audited;
+		__entry->result			= sad->result;
+		__entry->audit_stamp_sec	= ts->t.tv_sec;
+		__entry->audit_stamp_msec	= ts->t.tv_nsec / 1000000;
+		__entry->audit_stamp_serial	= ts->serial;
 		__assign_str(tcontext, tcontext);
 		__assign_str(scontext, scontext);
 		__assign_str(tclass, tclass);
 	),
 
-	TP_printk("requested=0x%x denied=0x%x audited=0x%x result=%d scontext=%s tcontext=%s tclass=%s",
+	TP_printk("requested=0x%x denied=0x%x audited=0x%x result=%d scontext=%s tcontext=%s tclass=%s audit_ts=%llu.%03u:%u",
 		__entry->requested, __entry->denied, __entry->audited, __entry->result,
-		__get_str(scontext), __get_str(tcontext), __get_str(tclass)
+		__get_str(scontext), __get_str(tcontext), __get_str(tclass),
+		__entry->audit_stamp_sec, __entry->audit_stamp_msec,
+		__entry->audit_stamp_serial
 	)
 );
 
diff --git a/kernel/audit.c b/kernel/audit.c
index aded2d69ea69..ad21d148704a 100644
--- a/kernel/audit.c
+++ b/kernel/audit.c
@@ -199,6 +199,7 @@ static struct audit_ctl_mutex {
 struct audit_buffer {
 	struct sk_buff       *skb;	/* formatted skb ready to send */
 	struct audit_context *ctx;	/* NULL or associated context */
+	struct audit_timestamp ts;	/* the timestamp of this record */
 	gfp_t		     gfp_mask;
 };
 
@@ -1826,6 +1827,12 @@ static inline void audit_get_stamp(struct audit_context *ctx,
 	}
 }
 
+void audit_buffer_get_timestamp(struct audit_buffer *ab,
+				struct audit_timestamp *ts)
+{
+	*ts = ab->ts;
+}
+
 /**
  * audit_log_start - obtain an audit buffer
  * @ctx: audit_context (may be NULL)
@@ -1845,7 +1852,6 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 				     int type)
 {
 	struct audit_buffer *ab;
-	struct audit_timestamp ts;
 
 	if (audit_initialized != AUDIT_INITIALIZED)
 		return NULL;
@@ -1900,13 +1906,14 @@ struct audit_buffer *audit_log_start(struct audit_context *ctx, gfp_t gfp_mask,
 		return NULL;
 	}
 
-	audit_get_stamp(ab->ctx, &ts);
+	audit_get_stamp(ab->ctx, &ab->ts);
 	/* cancel dummy context to enable supporting records */
 	if (ctx)
 		ctx->dummy = 0;
 	audit_log_format(ab, "audit(%llu.%03lu:%u): ",
-			 (unsigned long long)ts.t.tv_sec, ts.t.tv_nsec/1000000,
-			 ts.serial);
+			 (unsigned long long)ab->ts.t.tv_sec,
+			 ab->ts.t.tv_nsec/1000000,
+			 ab->ts.serial);
 
 	return ab;
 }
diff --git a/security/selinux/avc.c b/security/selinux/avc.c
index 9a43af0ebd7d..e59c91eb3228 100644
--- a/security/selinux/avc.c
+++ b/security/selinux/avc.c
@@ -708,6 +708,7 @@ 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;
+	struct audit_timestamp ts;
 	char *scontext = NULL;
 	char *tcontext = NULL;
 	const char *tclass = NULL;
@@ -735,7 +736,8 @@ static void avc_audit_post_callback(struct audit_buffer *ab, void *a)
 	if (sad->denied)
 		audit_log_format(ab, " permissive=%u", sad->result ? 0 : 1);
 
-	trace_selinux_audited(sad, scontext, tcontext, tclass);
+	audit_buffer_get_timestamp(ab, &ts);
+	trace_selinux_audited(sad, scontext, tcontext, tclass, &ts);
 	kfree(tcontext);
 	kfree(scontext);
 
-- 
2.38.1