authz: Stdout logger (#6230)

* Draft of StdoutLogger

* Fitting StdoutLogger to lb patterns

* conversion from proto to json for laudit loggers

* Tests for multiple loggers and empty Options

* Added LoggerConfig impl

* Switched to grpcLogger and added a unit test comparing log with os.StdOut

* Minor fix in exception handling wording

* Added timestamp for logging statement

* Changed format to json and added custom marshalling

* Migration to log.go and additional test for a full event

* Migration of stdout logger to a separate package

* migration to grpcLogger, unit test fix

* Delete xds parsing functionality. Will be done in a separate PR

* Delete xds parsing functionality. Will be done in a separate PR

* Address PR comments (embedding interface, table test, pointer optimizations)

* vet.sh fixes

* Address PR comments

* Commit for go tidy changes

* vet.sh fix for buf usage

* Address PR comments

* Address PR comments

* Address PR comments (easwars)

* Address PR comments (luwei)

* Migrate printing to standard out from log package level func to a Logger struct func. Add timestamp testing logic. Add registry presense test.

* Changed event Timestamp format back to RFC3339

* Address PR comments

* Address PR comments

* Address PR comments

* Address PR comments

authz/audit/stdout/stdout_logger.go

@@ -0,0 +1,107 @@
+/*
+ *
+ * Copyright 2023 gRPC 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 stdout defines an stdout audit logger.
+package stdout
+
+import (
+	"encoding/json"
+	"log"
+	"os"
+	"time"
+
+	"google.golang.org/grpc/authz/audit"
+	"google.golang.org/grpc/grpclog"
+)
+
+var grpcLogger = grpclog.Component("authz-audit")
+
+func init() {
+	audit.RegisterLoggerBuilder(&loggerBuilder{
+		goLogger: log.New(os.Stdout, "", 0),
+	})
+}
+
+type event struct {
+	FullMethodName string `json:"rpc_method"`
+	Principal      string `json:"principal"`
+	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
+}
+
+// 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 to standard output.
+func (l *logger) Log(event *audit.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
+	}
+	l.goLogger.Println(string(jsonBytes))
+}
+
+// loggerConfig represents the configuration for the stdout logger.
+// It is currently empty and implements the audit.Logger interface by embedding it.
+type loggerConfig struct {
+	audit.LoggerConfig
+}
+
+type loggerBuilder struct {
+	goLogger *log.Logger
+}
+
+func (loggerBuilder) Name() string {
+	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 (lb *loggerBuilder) Build(audit.LoggerConfig) audit.Logger {
+	return &logger{
+		goLogger: lb.goLogger,
+	}
+}
+
+// ParseLoggerConfig is a no-op since the stdout logger does not accept any configuration.
+func (*loggerBuilder) ParseLoggerConfig(config json.RawMessage) (audit.LoggerConfig, error) {
+	if len(config) != 0 && string(config) != "{}" {
+		grpcLogger.Warningf("Stdout logger doesn't support custom configs. Ignoring:\n%s", string(config))
+	}
+	return &loggerConfig{}, nil
+}
+
+func convertEvent(auditEvent *audit.Event) *event {
+	return &event{
+		FullMethodName: auditEvent.FullMethodName,
+		Principal:      auditEvent.Principal,
+		PolicyName:     auditEvent.PolicyName,
+		MatchedRule:    auditEvent.MatchedRule,
+		Authorized:     auditEvent.Authorized,
+		Timestamp:      time.Now().Format(time.RFC3339Nano),
+	}
+}

authz/audit/stdout/stdout_logger_test.go

@@ -0,0 +1,140 @@
+/*
+ *
+ * Copyright 2023 gRPC 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 stdout
+
+import (
+	"bytes"
+	"encoding/json"
+	"log"
+	"os"
+	"testing"
+	"time"
+
+	"github.com/google/go-cmp/cmp"
+	"google.golang.org/grpc/authz/audit"
+	"google.golang.org/grpc/internal/grpctest"
+)
+
+type s struct {
+	grpctest.Tester
+}
+
+func Test(t *testing.T) {
+	grpctest.RunSubTests(t, s{})
+}
+
+func (s) TestStdoutLogger_Log(t *testing.T) {
+	tests := map[string]struct {
+		event       *audit.Event
+		wantMessage string
+		wantErr     string
+	}{
+		"few fields": {
+			event:       &audit.Event{PolicyName: "test policy", Principal: "test principal"},
+			wantMessage: `{"fullMethodName":"","principal":"test principal","policyName":"test policy","matchedRule":"","authorized":false`,
+		},
+		"all fields": {
+			event: &audit.Event{
+				FullMethodName: "/helloworld.Greeter/SayHello",
+				Principal:      "spiffe://example.org/ns/default/sa/default/backend",
+				PolicyName:     "example-policy",
+				MatchedRule:    "dev-access",
+				Authorized:     true,
+			},
+			wantMessage: `{"fullMethodName":"/helloworld.Greeter/SayHello",` +
+				`"principal":"spiffe://example.org/ns/default/sa/default/backend","policyName":"example-policy",` +
+				`"matchedRule":"dev-access","authorized":true`,
+		},
+	}
+
+	for name, test := range tests {
+		t.Run(name, func(t *testing.T) {
+			before := time.Now().Unix()
+			var buf bytes.Buffer
+			builder := &loggerBuilder{goLogger: log.New(&buf, "", 0)}
+			auditLogger := builder.Build(nil)
+
+			auditLogger.Log(test.event)
+
+			var container map[string]interface{}
+			if err := json.Unmarshal(buf.Bytes(), &container); err != nil {
+				t.Fatalf("Failed to unmarshal audit log event: %v", err)
+			}
+			innerEvent := extractEvent(container["grpc_audit_log"].(map[string]interface{}))
+			if innerEvent.Timestamp == "" {
+				t.Fatalf("Resulted event has no timestamp: %v", innerEvent)
+			}
+			after := time.Now().Unix()
+			innerEventUnixTime, err := time.Parse(time.RFC3339Nano, innerEvent.Timestamp)
+			if err != nil {
+				t.Fatalf("Failed to convert event timestamp into Unix time format: %v", err)
+			}
+			if before > innerEventUnixTime.Unix() || after < innerEventUnixTime.Unix() {
+				t.Errorf("The audit event timestamp is outside of the test interval: test start %v, event timestamp %v, test end %v", before, innerEventUnixTime.Unix(), after)
+			}
+			if diff := cmp.Diff(trimEvent(innerEvent), test.event); diff != "" {
+				t.Fatalf("Unexpected message\ndiff (-got +want):\n%s", diff)
+			}
+		})
+	}
+}
+
+func (s) TestStdoutLoggerBuilder_NilConfig(t *testing.T) {
+	builder := &loggerBuilder{
+		goLogger: log.New(os.Stdout, "", log.LstdFlags),
+	}
+	config, err := builder.ParseLoggerConfig(nil)
+	if err != nil {
+		t.Fatalf("Failed to parse stdout logger configuration: %v", err)
+	}
+	if l := builder.Build(config); l == nil {
+		t.Fatal("Failed to build stdout audit logger")
+	}
+}
+
+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:      container["timestamp"].(string),
+	}
+}
+
+// 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 {
+	return &audit.Event{
+		FullMethodName: testEvent.FullMethodName,
+		Principal:      testEvent.Principal,
+		PolicyName:     testEvent.PolicyName,
+		MatchedRule:    testEvent.MatchedRule,
+		Authorized:     testEvent.Authorized,
+	}
+}