Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Capture log params from context metadata #1049

Merged
merged 10 commits into from
Aug 19, 2024
Merged
Show file tree
Hide file tree
Changes from 8 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions backend/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,11 @@ func withContextualLogAttributes(ctx context.Context, pCtx PluginContext) contex
args = append(args, "uname", pCtx.User.Name)
}
}

if ctxLogAttributes := log.contextualAttributesFromIncomingContext(ctx); len(ctxLogAttributes) > 0 {
args = append(args, ctxLogAttributes...)
}

ctx = log.WithContextualAttributes(ctx, args)
return ctx
}
55 changes: 55 additions & 0 deletions backend/log/context_grpc.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,55 @@
package log

import (
"context"
"fmt"
"strings"

"google.golang.org/grpc/metadata"
)

const (
logParamsCtxMetadataKey = "loggerParamsCtxMetadata"
logParamSeparator = ":"
)

// WithContextualAttributesForOutgoingContext will append the given key/value log parameters to the outgoing context.
func WithContextualAttributesForOutgoingContext(ctx context.Context, logParams []any) context.Context {
if len(logParams) == 0 || len(logParams)%2 != 0 {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it could be confusing to do nothing if by mistake someone calls this with an uneven set of logParams. What if len(logParams)%2 != 0 you add an empty param at the end? (That's how the logger works, right?)

Copy link
Member Author

@wbrowne wbrowne Aug 16, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I can see that it's quite unforgiving, but I'm aiming for simplicity here.

you add an empty param at the end? (That's how the logger works, right?)

Usually what I see is the EXTRA_VALUE_AT_END - which can be a bit strange/unexpected. Plus we can't know if we're missing specifically a key or a value, so fudging things to work can also end up in a weird state.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah, the problem is that if someone hits this, it would be difficult to know what's going on since no error or anything is returned but up to you if you want to leave that for later.

return ctx
}

for i := 0; i < len(logParams); i += 2 {
k := logParams[i].(string)
wbrowne marked this conversation as resolved.
Show resolved Hide resolved
v := logParams[i+1].(string)
if k == "" || v == "" {
continue
}

ctx = metadata.AppendToOutgoingContext(ctx, logParamsCtxMetadataKey, logParam(k, v))
}

return ctx
}

// ContextualAttributesFromIncomingContext returns the contextual key/value log parameters from the given incoming context.
func ContextualAttributesFromIncomingContext(ctx context.Context) []any {
wbrowne marked this conversation as resolved.
Show resolved Hide resolved
logParams := metadata.ValueFromIncomingContext(ctx, logParamsCtxMetadataKey)
if len(logParams) == 0 {
return nil
}

var attrs []any
for _, param := range logParams {
kv := strings.Split(param, logParamSeparator)
wbrowne marked this conversation as resolved.
Show resolved Hide resolved
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it may be needed to scape the logParamSeparator in case a param includes : on it?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great catch. I just updated it to be 3 characters instead 👀 rather than making things more complex. WDYT?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess that's fine unless the parameter is a ipv6 😅 I was more thinking about replacing : with \: but it can be left for later.

if len(kv) != 2 || kv[0] == "" || kv[1] == "" {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

an empty value is not a valid value?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I wanted to keep things simple for now. I don't foresee this being used heavily as it's quite a special use case. Can always revisit if it becomes important

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be useful to see if a value is set but it's empty but maybe I am missing something so up to you.

continue
}
attrs = append(attrs, kv[0], kv[1])
}
return attrs
}

func logParam(k, v string) string {
return fmt.Sprintf("%s%s%s", k, logParamSeparator, v)
}
117 changes: 117 additions & 0 deletions backend/log/context_grpc_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,117 @@
package log

import (
"context"
"testing"

"github.com/stretchr/testify/require"
"google.golang.org/grpc/metadata"
)

func TestWithContextualAttributesForOutgoingContext(t *testing.T) {
tcs := []struct {
name string
logParams []any
expected []string
}{
{
name: "empty log params",
logParams: []any{},
expected: []string{},
},
{
name: "log params with odd number of elements",
logParams: []any{"key1", "value1", "key2"},
expected: []string{},
},
{
name: "log params with empty key",
logParams: []any{"", "value1"},
expected: []string{},
},
{
name: "log params with empty value",
logParams: []any{"key1", ""},
expected: []string{},
},
{
name: "log params with valid key and value",
logParams: []any{"key1", "value1"},
expected: []string{logParam("key1", "value1")},
},
{
name: "log params with multiple key value pairs",
logParams: []any{"key1", "value1", "key2", "value2"},
expected: []string{logParam("key1", "value1"), logParam("key2", "value2")},
},
}

for _, tc := range tcs {
t.Run(tc.name, func(t *testing.T) {
ctx := WithContextualAttributesForOutgoingContext(context.Background(), tc.logParams)
md, ok := metadata.FromOutgoingContext(ctx)
if len(tc.expected) == 0 {
require.False(t, ok)
return
}

require.True(t, ok)
got := md.Get(logParamsCtxMetadataKey)
if len(got) != len(tc.expected) {
t.Fatalf("expected %v, got %v", tc.expected, got)
}
for i := range got {
if got[i] != tc.expected[i] {
t.Fatalf("expected %v, got %v", tc.expected, got)
}
}
})
}
}

func TestContextualAttributesFromIncomingContext(t *testing.T) {
tcs := []struct {
name string
md metadata.MD
expected []any
}{
{
name: "empty metadata",
md: metadata.MD{},
expected: nil,
},
{
name: "metadata without log params",
md: metadata.MD{"key1": []string{"value1"}},
expected: nil,
},
{
name: "metadata with valid log params",
md: metadata.MD{logParamsCtxMetadataKey: []string{logParam("key1", "value1"), logParam("key2", "value2")}},
expected: []any{"key1", "value1", "key2", "value2"},
},
{
name: "metadata with missing key",
md: metadata.MD{logParamsCtxMetadataKey: []string{logParam("", "value1"), logParam("key2", "value2")}},
expected: []any{"key2", "value2"},
},
{
name: "metadata with missing value",
md: metadata.MD{logParamsCtxMetadataKey: []string{logParam("key1", ""), logParam("key2", "value2")}},
expected: []any{"key2", "value2"},
},
{
name: "metadata with invalid key + value",
md: metadata.MD{logParamsCtxMetadataKey: []string{logParam("", ""), logParam("key2", "value2")}},
expected: []any{"key2", "value2"},
},
}

for _, tc := range tcs {
t.Run(tc.name, func(t *testing.T) {
ctx := metadata.NewIncomingContext(context.Background(), tc.md)
got := ContextualAttributesFromIncomingContext(ctx)
require.Equal(t, tc.expected, got)
})
}
}
Loading