support micro time for advanced audit

staging/src/k8s.io/apiserver/pkg/apis/audit/types.go

@@ -77,15 +77,10 @@ const (
 // Event captures all the information that can be included in an API audit log.
 type Event struct {
 	metav1.TypeMeta
-	// ObjectMeta is included for interoperability with API infrastructure.
-	// +optional
-	metav1.ObjectMeta
 
 	// AuditLevel at which event was generated
 	Level Level
 
-	// Time the request reached the apiserver.
-	Timestamp metav1.Time
 	// Unique audit ID, generated for each request.
 	AuditID types.UID
 	// Stage of the request handling when this event instance was generated.
@@ -125,6 +120,11 @@ type Event struct {
 	// at Response Level.
 	// +optional
 	ResponseObject *runtime.Unknown
+
+	// Time the request reached the apiserver.
+	RequestReceivedTimestamp metav1.MicroTime
+	// Time the request reached current audit stage.
+	StageTimestamp metav1.MicroTime
 }
 
 // +k8s:deepcopy-gen:interfaces=k8s.io/apimachinery/pkg/runtime.Object

staging/src/k8s.io/apiserver/pkg/apis/audit/v1alpha1/conversion.go

@@ -19,6 +19,7 @@ package v1alpha1
 import (
 	"strings"
 
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/conversion"
 	"k8s.io/apiserver/pkg/apis/audit"
 )
@@ -52,3 +53,26 @@ func Convert_v1alpha1_ObjectReference_To_audit_ObjectReference(in *ObjectReferen
 	}
 	return nil
 }
+
+func Convert_v1alpha1_Event_To_audit_Event(in *Event, out *audit.Event, s conversion.Scope) error {
+	if err := autoConvert_v1alpha1_Event_To_audit_Event(in, out, s); err != nil {
+		return err
+	}
+	if out.StageTimestamp.IsZero() {
+		out.StageTimestamp = metav1.NewMicroTime(in.CreationTimestamp.Time)
+	}
+	if out.RequestReceivedTimestamp.IsZero() {
+		out.RequestReceivedTimestamp = metav1.NewMicroTime(in.Timestamp.Time)
+	}
+	return nil
+}
+
+func Convert_audit_Event_To_v1alpha1_Event(in *audit.Event, out *Event, s conversion.Scope) error {
+	if err := autoConvert_audit_Event_To_v1alpha1_Event(in, out, s); err != nil {
+		return err
+	}
+	out.CreationTimestamp = metav1.NewTime(in.StageTimestamp.Time)
+	out.Timestamp = metav1.NewTime(in.RequestReceivedTimestamp.Time)
+	return nil
+
+}

staging/src/k8s.io/apiserver/pkg/apis/audit/v1alpha1/conversion_test.go

@@ -19,7 +19,9 @@ package v1alpha1
 import (
 	"reflect"
 	"testing"
+	"time"
 
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	auditinternal "k8s.io/apiserver/pkg/apis/audit"
@@ -36,7 +38,7 @@ func init() {
 	RegisterConversions(scheme)
 }
 
-func TestConversion(t *testing.T) {
+func TestConversionObjectReference(t *testing.T) {
 	scheme.Log(t)
 
 	testcases := []struct {
@@ -92,3 +94,114 @@ func TestConversion(t *testing.T) {
 		})
 	}
 }
+
+func TestConversionEventToInternal(t *testing.T) {
+	scheme.Log(t)
+
+	time1 := time.Now()
+	time2 := time.Now()
+	testcases := []struct {
+		desc     string
+		old      *Event
+		expected *auditinternal.Event
+	}{
+		{
+			"StageTimestamp is empty",
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(time1),
+				},
+			},
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(time1),
+			},
+		},
+		{
+			"StageTimestamp is not empty",
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(time1),
+				},
+				StageTimestamp: metav1.NewMicroTime(time2),
+			},
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(time2),
+			},
+		},
+		{
+			"RequestReceivedTimestamp is empty",
+			&Event{
+				Timestamp: metav1.NewTime(time1),
+			},
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(time1),
+			},
+		},
+		{
+			"RequestReceivedTimestamp is not empty",
+			&Event{
+				Timestamp:                metav1.NewTime(time1),
+				RequestReceivedTimestamp: metav1.NewMicroTime(time2),
+			},
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(time2),
+			},
+		},
+	}
+	for _, tc := range testcases {
+		t.Run(tc.desc, func(t *testing.T) {
+			internal := &auditinternal.Event{}
+			if err := scheme.Convert(tc.old, internal, nil); err != nil {
+				t.Errorf("unexpected error: %v", err)
+			}
+			if !reflect.DeepEqual(internal, tc.expected) {
+				t.Errorf("expected\n\t%#v, got \n\t%#v", tc.expected, internal)
+			}
+		})
+	}
+}
+
+func TestConversionInternalToEvent(t *testing.T) {
+	scheme.Log(t)
+
+	now := time.Now()
+	testcases := []struct {
+		desc     string
+		old      *auditinternal.Event
+		expected *Event
+	}{
+		{
+			"convert stageTimestamp",
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(now),
+			},
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(now),
+				},
+				StageTimestamp: metav1.NewMicroTime(now),
+			},
+		},
+		{
+			"convert RequestReceivedTimestamp",
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(now),
+			},
+			&Event{
+				Timestamp:                metav1.NewTime(now),
+				RequestReceivedTimestamp: metav1.NewMicroTime(now),
+			},
+		},
+	}
+	for _, tc := range testcases {
+		t.Run(tc.desc, func(t *testing.T) {
+			event := &Event{}
+			if err := scheme.Convert(tc.old, event, nil); err != nil {
+				t.Errorf("unexpected error: %v", err)
+			}
+			if !reflect.DeepEqual(event, tc.expected) {
+				t.Errorf("expected\n\t%#v, got \n\t%#v", tc.expected, event)
+			}
+		})
+	}
+}

staging/src/k8s.io/apiserver/pkg/apis/audit/v1alpha1/types.go

@@ -126,6 +126,12 @@ type Event struct {
 	// at Response Level.
 	// +optional
 	ResponseObject *runtime.Unknown `json:"responseObject,omitempty" protobuf:"bytes,14,opt,name=responseObject"`
+	// Time the request reached the apiserver.
+	// +optional
+	RequestReceivedTimestamp metav1.MicroTime `json:"requestReceivedTimestamp" protobuf:"bytes,15,opt,name=requestReceivedTimestamp"`
+	// Time the request reached current audit stage.
+	// +optional
+	StageTimestamp metav1.MicroTime `json:"stageTimestamp" protobuf:"bytes,16,opt,name=stageTimestamp"`
 }
 
 // +k8s:deepcopy-gen:interfaces=k8s.io/apimachinery/pkg/runtime.Object

staging/src/k8s.io/apiserver/pkg/apis/audit/v1beta1/conversion.go

@@ -0,0 +1,45 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package v1beta1
+
+import (
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/conversion"
+	"k8s.io/apiserver/pkg/apis/audit"
+)
+
+func Convert_v1beta1_Event_To_audit_Event(in *Event, out *audit.Event, s conversion.Scope) error {
+	if err := autoConvert_v1beta1_Event_To_audit_Event(in, out, s); err != nil {
+		return err
+	}
+	if out.StageTimestamp.IsZero() {
+		out.StageTimestamp = metav1.NewMicroTime(in.CreationTimestamp.Time)
+	}
+	if out.RequestReceivedTimestamp.IsZero() {
+		out.RequestReceivedTimestamp = metav1.NewMicroTime(in.Timestamp.Time)
+	}
+	return nil
+}
+
+func Convert_audit_Event_To_v1beta1_Event(in *audit.Event, out *Event, s conversion.Scope) error {
+	if err := autoConvert_audit_Event_To_v1beta1_Event(in, out, s); err != nil {
+		return err
+	}
+	out.CreationTimestamp = metav1.NewTime(in.StageTimestamp.Time)
+	out.Timestamp = metav1.NewTime(in.RequestReceivedTimestamp.Time)
+	return nil
+}

staging/src/k8s.io/apiserver/pkg/apis/audit/v1beta1/conversion_test.go

@@ -0,0 +1,150 @@
+/*
+Copyright 2017 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package v1beta1
+
+import (
+	"reflect"
+	"testing"
+	"time"
+
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/runtime"
+	"k8s.io/apimachinery/pkg/runtime/schema"
+	auditinternal "k8s.io/apiserver/pkg/apis/audit"
+)
+
+var scheme = runtime.NewScheme()
+
+func init() {
+	addKnownTypes(scheme)
+	internalGV := schema.GroupVersion{Group: auditinternal.GroupName, Version: runtime.APIVersionInternal}
+	scheme.AddKnownTypes(internalGV,
+		&auditinternal.Event{},
+	)
+	RegisterConversions(scheme)
+}
+
+func TestConversionEventToInternal(t *testing.T) {
+	scheme.Log(t)
+
+	time1 := time.Now()
+	time2 := time.Now()
+	testcases := []struct {
+		desc     string
+		old      *Event
+		expected *auditinternal.Event
+	}{
+		{
+			"StageTimestamp is empty",
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(time1),
+				},
+			},
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(time1),
+			},
+		},
+		{
+			"StageTimestamp is not empty",
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(time1),
+				},
+				StageTimestamp: metav1.NewMicroTime(time2),
+			},
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(time2),
+			},
+		},
+		{
+			"RequestReceivedTimestamp is empty",
+			&Event{
+				Timestamp: metav1.NewTime(time1),
+			},
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(time1),
+			},
+		},
+		{
+			"RequestReceivedTimestamp is not empty",
+			&Event{
+				Timestamp:                metav1.NewTime(time1),
+				RequestReceivedTimestamp: metav1.NewMicroTime(time2),
+			},
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(time2),
+			},
+		},
+	}
+	for _, tc := range testcases {
+		t.Run(tc.desc, func(t *testing.T) {
+			internal := &auditinternal.Event{}
+			if err := scheme.Convert(tc.old, internal, nil); err != nil {
+				t.Errorf("unexpected error: %v", err)
+			}
+			if !reflect.DeepEqual(internal, tc.expected) {
+				t.Errorf("expected\n\t%#v, got \n\t%#v", tc.expected, internal)
+			}
+		})
+	}
+}
+
+func TestConversionInternalToEvent(t *testing.T) {
+	scheme.Log(t)
+
+	now := time.Now()
+	testcases := []struct {
+		desc     string
+		old      *auditinternal.Event
+		expected *Event
+	}{
+		{
+			"convert stageTimestamp",
+			&auditinternal.Event{
+				StageTimestamp: metav1.NewMicroTime(now),
+			},
+			&Event{
+				ObjectMeta: metav1.ObjectMeta{
+					CreationTimestamp: metav1.NewTime(now),
+				},
+				StageTimestamp: metav1.NewMicroTime(now),
+			},
+		},
+		{
+			"convert RequestReceivedTimestamp",
+			&auditinternal.Event{
+				RequestReceivedTimestamp: metav1.NewMicroTime(now),
+			},
+			&Event{
+				Timestamp:                metav1.NewTime(now),
+				RequestReceivedTimestamp: metav1.NewMicroTime(now),
+			},
+		},
+	}
+	for _, tc := range testcases {
+		t.Run(tc.desc, func(t *testing.T) {
+			event := &Event{}
+			if err := scheme.Convert(tc.old, event, nil); err != nil {
+				t.Errorf("unexpected error: %v", err)
+			}
+			if !reflect.DeepEqual(event, tc.expected) {
+				t.Errorf("expected\n\t%#v, got \n\t%#v", tc.expected, event)
+			}
+		})
+	}
+}

staging/src/k8s.io/apiserver/pkg/apis/audit/v1beta1/types.go

@@ -73,12 +73,15 @@ type Event struct {
 	metav1.TypeMeta `json:",inline"`
 	// ObjectMeta is included for interoperability with API infrastructure.
 	// +optional
+	// DEPRECATED: Use StageTimestamp which supports micro second instead of ObjectMeta.CreateTimestamp
+	// and the rest of the object is not used
 	metav1.ObjectMeta `json:"metadata,omitempty" protobuf:"bytes,1,opt,name=metadata"`
 
 	// AuditLevel at which event was generated
 	Level Level `json:"level" protobuf:"bytes,2,opt,name=level,casttype=Level"`
 
 	// Time the request reached the apiserver.
+	// DEPRECATED: Use RequestReceivedTimestamp which supports micro second instead.
 	Timestamp metav1.Time `json:"timestamp" protobuf:"bytes,3,opt,name=timestamp"`
 	// Unique audit ID, generated for each request.
 	AuditID types.UID `json:"auditID" protobuf:"bytes,4,opt,name=auditID,casttype=k8s.io/apimachinery/pkg/types.UID"`
@@ -119,6 +122,12 @@ type Event struct {
 	// at Response Level.
 	// +optional
 	ResponseObject *runtime.Unknown `json:"responseObject,omitempty" protobuf:"bytes,14,opt,name=responseObject"`
+	// Time the request reached the apiserver.
+	// +optional
+	RequestReceivedTimestamp metav1.MicroTime `json:"requestReceivedTimestamp" protobuf:"bytes,15,opt,name=requestReceivedTimestamp"`
+	// Time the request reached current audit stage.
+	// +optional
+	StageTimestamp metav1.MicroTime `json:"stageTimestamp" protobuf:"bytes,16,opt,name=stageTimestamp"`
 }
 
 // +k8s:deepcopy-gen:interfaces=k8s.io/apimachinery/pkg/runtime.Object

staging/src/k8s.io/apiserver/pkg/audit/format.go

@@ -61,7 +61,7 @@ func EventString(ev *auditinternal.Event) string {
 	}
 
 	return fmt.Sprintf("%s AUDIT: id=%q stage=%q ip=%q method=%q user=%q groups=%q as=%q asgroups=%q namespace=%q uri=%q response=\"%s\"",
-		ev.Timestamp.Format(time.RFC3339Nano), ev.AuditID, ev.Stage, ip, ev.Verb, username, groups, asuser, asgroups, namespace, ev.RequestURI, response)
+		ev.RequestReceivedTimestamp.Format(time.RFC3339Nano), ev.AuditID, ev.Stage, ip, ev.Verb, username, groups, asuser, asgroups, namespace, ev.RequestURI, response)
 }
 
 func auditStringSlice(inList []string) string {

staging/src/k8s.io/apiserver/pkg/audit/request.go

@@ -40,7 +40,7 @@ import (
 
 func NewEventFromRequest(req *http.Request, level auditinternal.Level, attribs authorizer.Attributes) (*auditinternal.Event, error) {
 	ev := &auditinternal.Event{
-		Timestamp:  metav1.NewTime(time.Now()),
+		RequestReceivedTimestamp: metav1.NewMicroTime(time.Now()),
 		Verb:       attribs.GetVerb(),
 		RequestURI: req.URL.RequestURI(),
 	}

staging/src/k8s.io/apiserver/pkg/endpoints/filters/audit.go

@@ -148,7 +148,12 @@ func processAuditEvent(sink audit.Sink, ev *auditinternal.Event, omitStages []au
 			return
 		}
 	}
-	ev.CreationTimestamp = metav1.NewTime(time.Now())
+
+	if ev.Stage == auditinternal.StageRequestReceived {
+		ev.StageTimestamp = metav1.NewMicroTime(ev.RequestReceivedTimestamp.Time)
+	} else {
+		ev.StageTimestamp = metav1.NewMicroTime(time.Now())
+	}
 	audit.ObserveEvent()
 	sink.ProcessEvents(ev)
 }

staging/src/k8s.io/apiserver/plugin/pkg/audit/log/backend_test.go

@@ -73,7 +73,7 @@ func TestLogEventsLegacy(t *testing.T) {
 				SourceIPs: []string{
 					"127.0.0.1",
 				},
-				Timestamp: metav1.NewTime(time.Now()),
+				RequestReceivedTimestamp: metav1.NewMicroTime(time.Now()),
 				AuditID:                  types.UID(uuid.NewRandom().String()),
 				Stage:                    auditinternal.StageRequestReceived,
 				Verb:                     "get",
@@ -130,10 +130,8 @@ func TestLogEventsJson(t *testing.T) {
 			SourceIPs: []string{
 				"127.0.0.1",
 			},
-			// When encoding to json format, the nanosecond part of timestamp is
+			RequestReceivedTimestamp: metav1.NewMicroTime(time.Now().Truncate(time.Microsecond)),
-			// lost and it will become zero when we decode event back, so we rounding
+			StageTimestamp:           metav1.NewMicroTime(time.Now().Truncate(time.Microsecond)),
-			// timestamp down to a multiple of second.
-			Timestamp: metav1.NewTime(time.Now().Truncate(time.Second)),
 			AuditID:                  types.UID(uuid.NewRandom().String()),
 			Stage:                    auditinternal.StageRequestReceived,
 			Verb:                     "get",