authz: Stdout logger

authz/audit/stdout/stdout_logger.go

@@ -22,6 +22,7 @@ package stdout
 import (
 	"encoding/json"
 	"log"
+	"os"
 	"time"
 
 	"google.golang.org/grpc/authz/audit"
@@ -35,32 +36,32 @@ func init() {
 }
 
 type event struct {
-	FullMethodName string `json:"fullMethodName"`
+	FullMethodName string `json:"rpc_method"`
 	Principal      string `json:"principal"`
-	PolicyName     string `json:"policyName"`
-	MatchedRule    string `json:"matchedRule"`
+	PolicyName     string `json:"policy_name"`
+	MatchedRule    string `json:"matched_rule"`
 	Authorized     bool   `json:"authorized"`
-	Timestamp      string `json:"timestamp"` // Time when the audit event is logged via Log method
+	Timestamp      int64  `json:"timestamp"` // Time when the audit event is logged via Log method
 }
 
 // logger implements the audit.Logger interface by logging to standard output.
 type logger struct {
+	goLogger *log.Logger
 }
 
-// Log marshals the audit.Event to json and prints it using log.go
+// Log marshals the audit.Event to json and prints it to standard output.
 func (logger *logger) Log(event *audit.Event) {
-	jsonBytes, err := json.Marshal(convertEvent(event))
+	jsonContainer := map[string]interface{}{
+		"grpc_audit_log": convertEvent(event),
+	}
+	jsonBytes, err := json.Marshal(jsonContainer)
 	if err != nil {
 		grpcLogger.Errorf("failed to marshal AuditEvent data to JSON: %v", err)
 		return
 	}
-	log.Println(string(jsonBytes))
+	logger.goLogger.Println(string(jsonBytes))
 }
 
-const (
-	stdName = "stdout"
-)
-
 // loggerConfig represents the configuration for the stdout logger.
 // It is currently empty and implements the audit.Logger interface by embedding it.
 type loggerConfig struct {
@@ -70,14 +71,17 @@ type loggerConfig struct {
 type loggerBuilder struct{}
 
 func (loggerBuilder) Name() string {
-	return stdName
+	return "stdout_logger"
 }
 
 // Build returns a new instance of the stdout logger.
 // Passed in configuration is ignored as the stdout logger does not
 // expect any configuration to be provided.
 func (*loggerBuilder) Build(audit.LoggerConfig) audit.Logger {
-	return &logger{}
+	l := log.New(os.Stdout, "", log.LstdFlags)
+	return &logger{
+		goLogger: l,
+	}
 }
 
 // ParseLoggerConfig is a no-op since the stdout logger does not accept any configuration.
@@ -95,6 +99,6 @@ func convertEvent(auditEvent *audit.Event) *event {
 		PolicyName:     auditEvent.PolicyName,
 		MatchedRule:    auditEvent.MatchedRule,
 		Authorized:     auditEvent.Authorized,
-		Timestamp:      time.Now().Format(time.RFC3339),
+		Timestamp:      time.Now().Unix(),
 	}
 }

authz/audit/stdout/stdout_logger_test.go

@@ -22,8 +22,8 @@ import (
 	"bytes"
 	"encoding/json"
 	"log"
-	"strings"
 	"testing"
+	"time"
 
 	"github.com/google/go-cmp/cmp"
 	"google.golang.org/grpc/authz/audit"
@@ -62,26 +62,29 @@ func (s) TestStdoutLogger_Log(t *testing.T) {
 		},
 	}
 
-	content := json.RawMessage(`{"name": "conf", "val": "to be ignored"}`)
-	builder := &loggerBuilder{}
-	config, _ := builder.ParseLoggerConfig(content)
-	auditLogger := builder.Build(config)
-	log.SetFlags(0)
-
 	for name, test := range tests {
 		t.Run(name, func(t *testing.T) {
+			before := time.Now().Unix()
 			var buf bytes.Buffer
-			log.SetOutput(&buf)
+			l := log.New(&buf, "", 0)
+			auditLogger := &logger{
+				goLogger: l,
+			}
 			auditLogger.Log(test.event)
-			var e event
-			if err := json.Unmarshal(buf.Bytes(), &e); err != nil {
+			var container map[string]interface{}
+			if err := json.Unmarshal(buf.Bytes(), &container); err != nil {
 				t.Fatalf("Failed to unmarshal audit log event: %v", err)
 			}
-			if strings.TrimSpace(e.Timestamp) == "" {
-				t.Fatalf("Resulted event has no timestamp: %v", e)
+			innerEvent := extractEvent(container["grpc_audit_log"].(map[string]interface{}))
+			if innerEvent.Timestamp == 0 {
+				t.Fatalf("Resulted event has no timestamp: %v", innerEvent)
 			}
-
-			if diff := cmp.Diff(trimEvent(e), test.event); diff != "" {
+			after := time.Now().Unix()
+			if before > innerEvent.Timestamp || after < innerEvent.Timestamp {
+				t.Fatalf("The audit event timestamp is outside of the test interval: test start %v, event timestamp %v, test end %v",
+					before, innerEvent.Timestamp, after)
+			}
+			if diff := cmp.Diff(trimEvent(innerEvent), test.event); diff != "" {
 				t.Fatalf("Unexpected message\ndiff (-got +want):\n%s", diff)
 			}
 		})
@@ -99,6 +102,25 @@ func (s) TestStdoutLoggerBuilder_NilConfig(t *testing.T) {
 	}
 }
 
+func (s) TestStdoutLoggerBuilder_Registration(t *testing.T) {
+	if audit.GetLoggerBuilder("stdout_logger") == nil {
+		t.Fatal("stdout logger is not registered")
+	}
+}
+
+// extractEvent extracts an stdout.event from a map
+// unmarshalled from a logged json message.
+func extractEvent(container map[string]interface{}) event {
+	return event{
+		FullMethodName: container["rpc_method"].(string),
+		Principal:      container["principal"].(string),
+		PolicyName:     container["policy_name"].(string),
+		MatchedRule:    container["matched_rule"].(string),
+		Authorized:     container["authorized"].(bool),
+		Timestamp:      int64(container["timestamp"].(float64)),
+	}
+}
+
 // trimEvent converts a logged stdout.event into an audit.Event
 // by removing Timestamp field. It is used for comparing events during testing.
 func trimEvent(testEvent event) *audit.Event {