feat(filtermanager): add way to inject log args (#683)

Signed-off-by: spacewander <spacewanderlzx@gmail.com>

api/pkg/filtermanager/api/api.go

@@ -225,6 +225,21 @@ type FilterCallbackHandler interface {
 
 	// PluginState returns the PluginState associated to this request.
 	PluginState() PluginState
+
+	// WithLogArg injectes `key: value` as the suffix of application log created by this
+	// callback's Log* methods. The injected log arguments are only valid in the current request.
+	// This method can be used to inject IDs or other context information into the logs.
+	WithLogArg(key string, value any) FilterCallbackHandler
+	LogTracef(format string, v ...any)
+	LogTrace(message string)
+	LogDebugf(format string, v ...any)
+	LogDebug(message string)
+	LogInfof(format string, v ...any)
+	LogInfo(message string)
+	LogWarnf(format string, v ...any)
+	LogWarn(message string)
+	LogErrorf(format string, v ...any)
+	LogError(message string)
 }
 
 // FilterFactory returns a per-request Filter which has configuration bound to it.

api/pkg/filtermanager/api_impl.go

@@ -148,6 +148,9 @@ type filterManagerCallbackHandler struct {
 	pluginState api.PluginState
 
 	streamInfo *filterManagerStreamInfo
+
+	logArgNames string
+	logArgs     []any
 }
 
 func (cb *filterManagerCallbackHandler) Reset() {
@@ -200,3 +203,52 @@ func (cb *filterManagerCallbackHandler) PluginState() api.PluginState {
 	cb.cacheLock.Unlock()
 	return cb.pluginState
 }
+
+func (cb *filterManagerCallbackHandler) WithLogArg(key string, value any) api.FilterCallbackHandler {
+	// As the log is embedded into the Envoy's log, it's not so necessary to use structural logging
+	// here. So far the value is just an ID string, introduce complex processions like quoting is
+	// overkill.
+	cb.logArgNames = cb.logArgNames + fmt.Sprintf(", %s: %%v", key)
+	cb.logArgs = append(cb.logArgs, value)
+	return cb
+}
+
+func (cb *filterManagerCallbackHandler) LogTracef(format string, v ...any) {
+	api.LogTracef(format+cb.logArgNames, append(v, cb.logArgs...)...)
+}
+
+func (cb *filterManagerCallbackHandler) LogDebugf(format string, v ...any) {
+	api.LogDebugf(format+cb.logArgNames, append(v, cb.logArgs...)...)
+}
+
+func (cb *filterManagerCallbackHandler) LogInfof(format string, v ...any) {
+	api.LogInfof(format+cb.logArgNames, append(v, cb.logArgs...)...)
+}
+
+func (cb *filterManagerCallbackHandler) LogWarnf(format string, v ...any) {
+	api.LogWarnf(format+cb.logArgNames, append(v, cb.logArgs...)...)
+}
+
+func (cb *filterManagerCallbackHandler) LogErrorf(format string, v ...any) {
+	api.LogErrorf(format+cb.logArgNames, append(v, cb.logArgs...)...)
+}
+
+func (cb *filterManagerCallbackHandler) LogTrace(message string) {
+	api.LogTrace(message + fmt.Sprintf(cb.logArgNames, cb.logArgs...))
+}
+
+func (cb *filterManagerCallbackHandler) LogDebug(message string) {
+	api.LogDebug(message + fmt.Sprintf(cb.logArgNames, cb.logArgs...))
+}
+
+func (cb *filterManagerCallbackHandler) LogInfo(message string) {
+	api.LogInfo(message + fmt.Sprintf(cb.logArgNames, cb.logArgs...))
+}
+
+func (cb *filterManagerCallbackHandler) LogWarn(message string) {
+	api.LogWarn(message + fmt.Sprintf(cb.logArgNames, cb.logArgs...))
+}
+
+func (cb *filterManagerCallbackHandler) LogError(message string) {
+	api.LogError(message + fmt.Sprintf(cb.logArgNames, cb.logArgs...))
+}

api/pkg/filtermanager/api_impl_test.go

@@ -17,9 +17,11 @@ package filtermanager
 import (
 	"fmt"
 	"net/http"
+	"strings"
 	"sync"
 	"testing"
 
+	"github.com/agiledragon/gomonkey/v2"
 	"github.com/stretchr/testify/assert"
 
 	"mosn.io/htnn/api/pkg/filtermanager/api"
@@ -150,3 +152,84 @@ func TestAccessCacheFieldsConcurrently(t *testing.T) {
 	}
 	wg.Wait()
 }
+
+func testLogFilterFactory(c interface{}, callbacks api.FilterCallbackHandler) api.Filter {
+	return &testLogFilter{
+		callbacks: callbacks,
+	}
+}
+
+type testLogFilter struct {
+	api.PassThroughFilter
+	callbacks api.FilterCallbackHandler
+}
+
+func (f *testLogFilter) DecodeHeaders(headers api.RequestHeaderMap, endStream bool) api.ResultAction {
+	cb := f.callbacks.WithLogArg("k1", 1)
+	for _, fu := range []func(string){
+		f.callbacks.LogTrace, f.callbacks.LogDebug, f.callbacks.LogInfo, f.callbacks.LogWarn, f.callbacks.LogError,
+	} {
+		fu("testLog: msg")
+	}
+	cb.WithLogArg("k2", 2)
+	for _, fu := range []func(string, ...any){
+		f.callbacks.LogTracef, f.callbacks.LogDebugf, f.callbacks.LogInfof, f.callbacks.LogWarnf, f.callbacks.LogErrorf,
+	} {
+		fu("testLog: out: %s", 0)
+	}
+	return api.Continue
+}
+
+func TestLogWithArgs(t *testing.T) {
+	fmtStr := map[string]string{}
+	fmtArgs := map[string][]any{}
+
+	patch := gomonkey.NewPatches()
+	for _, s := range []struct {
+		level string
+		logf  func(string, ...any)
+		log   func(string)
+	}{
+		{"Trace", api.LogTracef, api.LogTrace},
+		{"Debug", api.LogDebugf, api.LogDebug},
+		{"Info", api.LogInfof, api.LogInfo},
+		{"Warn", api.LogWarnf, api.LogWarn},
+		{"Error", api.LogErrorf, api.LogError},
+	} {
+		level := s.level
+
+		patch.ApplyFunc(s.logf, func(format string, args ...any) {
+			if !strings.HasPrefix(format, "testLog: ") {
+				return
+			}
+			fmtStr[level+"f"] = strings.Clone(format)
+			fmtArgs[level+"f"] = args
+		})
+		patch.ApplyFunc(s.log, func(msg string) {
+			if !strings.HasPrefix(msg, "testLog: ") {
+				return
+			}
+			fmtStr[level] = strings.Clone(msg)
+		})
+	}
+	defer patch.Reset()
+
+	cb := envoy.NewCAPIFilterCallbackHandler()
+	config := initFilterManagerConfig("ns")
+	config.parsed = []*model.ParsedFilterConfig{
+		{
+			Name:    "log",
+			Factory: testLogFilterFactory,
+		},
+	}
+	m := FilterManagerFactory(config)(cb).(*filterManager)
+	h := http.Header{}
+	hdr := envoy.NewRequestHeaderMap(h)
+	m.DecodeHeaders(hdr, true)
+	cb.WaitContinued()
+	for _, level := range []string{"Trace", "Debug", "Info", "Warn", "Error"} {
+		assert.Equal(t, "testLog: msg, k1: 1", fmtStr[level])
+		assert.Equal(t, "testLog: out: %s, k1: %v, k2: %v", fmtStr[level+"f"])
+		assert.Equal(t, []any{0, 1, 2}, fmtArgs[level+"f"])
+	}
+}

api/plugins/tests/pkg/envoy/capi.go

@@ -518,6 +518,40 @@ func (i *filterCallbackHandler) PluginState() api.PluginState {
 	return i.pluginState
 }
 
+func (i *filterCallbackHandler) WithLogArg(key string, value any) api.FilterCallbackHandler {
+	return i
+}
+
+func (i *filterCallbackHandler) LogTracef(format string, v ...any) {
+}
+
+func (i *filterCallbackHandler) LogTrace(message string) {
+}
+
+func (i *filterCallbackHandler) LogDebugf(format string, v ...any) {
+}
+
+func (i *filterCallbackHandler) LogDebug(message string) {
+}
+
+func (i *filterCallbackHandler) LogInfof(format string, v ...any) {
+}
+
+func (i *filterCallbackHandler) LogInfo(message string) {
+}
+
+func (i *filterCallbackHandler) LogWarnf(format string, v ...any) {
+}
+
+func (i *filterCallbackHandler) LogWarn(message string) {
+}
+
+func (i *filterCallbackHandler) LogErrorf(format string, v ...any) {
+}
+
+func (i *filterCallbackHandler) LogError(message string) {
+}
+
 var _ api.FilterCallbackHandler = (*filterCallbackHandler)(nil)
 
 type capiFilterCallbackHandler struct {