From 46935c71eae7912dc2b70db3e0426e074fdff4a4 Mon Sep 17 00:00:00 2001 From: spacewander Date: Tue, 13 Aug 2024 11:50:56 +0800 Subject: [PATCH] feat(filtermanager): add way to inject log args Signed-off-by: spacewander --- api/pkg/filtermanager/api/api.go | 15 +++++ api/pkg/filtermanager/api_impl.go | 52 ++++++++++++++++ api/pkg/filtermanager/api_impl_test.go | 83 ++++++++++++++++++++++++++ api/plugins/tests/pkg/envoy/capi.go | 34 +++++++++++ 4 files changed, 184 insertions(+) diff --git a/api/pkg/filtermanager/api/api.go b/api/pkg/filtermanager/api/api.go index 3a5c065c..2d5b6348 100644 --- a/api/pkg/filtermanager/api/api.go +++ b/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. diff --git a/api/pkg/filtermanager/api_impl.go b/api/pkg/filtermanager/api_impl.go index 67d79995..71148560 100644 --- a/api/pkg/filtermanager/api_impl.go +++ b/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...)) +} diff --git a/api/pkg/filtermanager/api_impl_test.go b/api/pkg/filtermanager/api_impl_test.go index 80c094d4..66dfedb3 100644 --- a/api/pkg/filtermanager/api_impl_test.go +++ b/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"]) + } +} diff --git a/api/plugins/tests/pkg/envoy/capi.go b/api/plugins/tests/pkg/envoy/capi.go index c51664fd..8b0a2af7 100644 --- a/api/plugins/tests/pkg/envoy/capi.go +++ b/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 {