api: local log audit (#4536)

ref #4537, close #4602

Signed-off-by: Cabinfever_B <cabinfeveroier@gmail.com>

Co-authored-by: ShuNing <nolouch@gmail.com>
Co-authored-by: Ti Chi Robot <ti-community-prow-bot@tidb.io>

pkg/audit/audit.go

@@ -16,6 +16,15 @@ package audit
 
 import (
 	"net/http"
+
+	"github.com/pingcap/log"
+	"github.com/tikv/pd/pkg/requestutil"
+	"go.uber.org/zap"
+)
+
+const (
+	// LocalLogLabel is label name of LocalLogBackend
+	LocalLogLabel = "local-log"
 )
 
 // BackendLabels is used to store some audit backend labels.
@@ -43,7 +52,7 @@ type Sequence struct {
 	before bool
 }
 
-// ProcessBeforeHandler is used to help backend implement audit.Backend
+// ProcessBeforeHandler is used to identify whether this backend should execute before handler
 func (s *Sequence) ProcessBeforeHandler() bool {
 	return s.before
 }
@@ -54,6 +63,30 @@ type Backend interface {
 	ProcessHTTPRequest(req *http.Request) bool
 	// Match is used to determine if the backend matches
 	Match(*BackendLabels) bool
-	// ProcessBeforeHandler is used to identify whether this backend should execute before handler
 	ProcessBeforeHandler() bool
 }
+
+// LocalLogBackend is an implementation of audit.Backend
+// and it uses `github.com/pingcap/log` to implement audit
+type LocalLogBackend struct {
+	*LabelMatcher
+	*Sequence
+}
+
+// NewLocalLogBackend returns a LocalLogBackend
+func NewLocalLogBackend(before bool) Backend {
+	return &LocalLogBackend{
+		LabelMatcher: &LabelMatcher{backendLabel: LocalLogLabel},
+		Sequence:     &Sequence{before: before},
+	}
+}
+
+// ProcessHTTPRequest is used to implement audit.Backend
+func (l *LocalLogBackend) ProcessHTTPRequest(r *http.Request) bool {
+	requestInfo, ok := requestutil.RequestInfoFrom(r.Context())
+	if !ok {
+		return false
+	}
+	log.Info("Audit Log", zap.String("service-info", requestInfo.String()))
+	return true
+}

pkg/audit/audit_test.go

@@ -15,9 +15,16 @@
 package audit
 
 import (
+	"fmt"
+	"net/http"
+	"os"
+	"strings"
 	"testing"
+	"time"
 
 	. "github.com/pingcap/check"
+	"github.com/pingcap/log"
+	"github.com/tikv/pd/pkg/requestutil"
 )
 
 func Test(t *testing.T) {
@@ -37,3 +44,56 @@ func (s *testAuditSuite) TestLabelMatcher(c *C) {
 	labels2 := &BackendLabels{Labels: []string{"testFail"}}
 	c.Assert(matcher.Match(labels2), Equals, false)
 }
+
+func (s *testAuditSuite) TestLocalLogBackendUsingFile(c *C) {
+	backend := NewLocalLogBackend(true)
+	fname := initLog()
+	defer os.Remove(fname)
+	req, _ := http.NewRequest("GET", "http://127.0.0.1:2379/test?test=test", strings.NewReader("testBody"))
+	info := requestutil.GetRequestInfo(req)
+	req = req.WithContext(requestutil.WithRequestInfo(req.Context(), info))
+	c.Assert(backend.ProcessHTTPRequest(req), Equals, true)
+	b, _ := os.ReadFile(fname)
+	output := strings.SplitN(string(b), "]", 4)
+	c.Assert(output[3], Equals, fmt.Sprintf(" [\"Audit Log\"] [service-info=\"{ServiceLabel:, Method:HTTP/1.1/GET:/test, Component:anonymous, IP:, "+
+		"StartTime:%s, URLParam:{\\\"test\\\":[\\\"test\\\"]}, BodyParam:testBody}\"]\n",
+		time.Unix(info.StartTimeStamp, 0).String()))
+}
+
+func BenchmarkLocalLogAuditUsingTerminal(b *testing.B) {
+	b.StopTimer()
+	backend := NewLocalLogBackend(true)
+	req, _ := http.NewRequest("GET", "http://127.0.0.1:2379/test?test=test", strings.NewReader("testBody"))
+	b.StartTimer()
+	for i := 0; i < b.N; i++ {
+		info := requestutil.GetRequestInfo(req)
+		req = req.WithContext(requestutil.WithRequestInfo(req.Context(), info))
+		backend.ProcessHTTPRequest(req)
+	}
+}
+
+func BenchmarkLocalLogAuditUsingFile(b *testing.B) {
+	b.StopTimer()
+	backend := NewLocalLogBackend(true)
+	fname := initLog()
+	defer os.Remove(fname)
+	req, _ := http.NewRequest("GET", "http://127.0.0.1:2379/test?test=test", strings.NewReader("testBody"))
+	b.StartTimer()
+	for i := 0; i < b.N; i++ {
+		info := requestutil.GetRequestInfo(req)
+		req = req.WithContext(requestutil.WithRequestInfo(req.Context(), info))
+		backend.ProcessHTTPRequest(req)
+	}
+}
+
+func initLog() string {
+	cfg := &log.Config{}
+	f, _ := os.CreateTemp("/tmp", "pd_tests")
+	fname := f.Name()
+	f.Close()
+	cfg.File.Filename = fname
+	cfg.Level = "info"
+	lg, p, _ := log.InitLogger(cfg)
+	log.ReplaceGlobals(lg, p)
+	return fname
+}

pkg/requestutil/request_info.go

@@ -36,6 +36,12 @@ type RequestInfo struct {
 	StartTimeStamp int64
 }
 
+func (info *RequestInfo) String() string {
+	s := fmt.Sprintf("{ServiceLabel:%s, Method:%s, Component:%s, IP:%s, StartTime:%s, URLParam:%s, BodyParam:%s}",
+		info.ServiceLabel, info.Method, info.Component, info.IP, time.Unix(info.StartTimeStamp, 0), info.URLParam, info.BodyParam)
+	return s
+}
+
 // GetRequestInfo returns request info needed from http.Request
 func GetRequestInfo(r *http.Request) RequestInfo {
 	return RequestInfo{

pkg/testutil/leak.go

@@ -35,4 +35,6 @@ var LeakOptions = []goleak.Option{
 	goleak.IgnoreTopFunction("net/http.(*persistConn).writeLoop"),
 	goleak.IgnoreTopFunction("net/http.(*persistConn).readLoop"),
 	goleak.IgnoreTopFunction("runtime.goparkunlock"),
+	// natefinch/lumberjack#56, It's a goroutine leak bug. Another ignore option PR https://github.com/pingcap/tidb/pull/27405/
+	goleak.IgnoreTopFunction("gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun"),
 }