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.

Sign up for GitHub

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

pkg/util/log: don't falsify tenant ID tag in logs if none in ctx #95789

Merged
merged 1 commit into from
Mar 14, 2023
+85 −59
Merged

pkg/util/log: don't falsify tenant ID tag in logs if none in ctx #95789

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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: 0 additions & 5 deletions pkg/base/serverident/server_ident.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -104,12 +104,7 @@ func GetIdentificationPayload(ctx context.Context) IDPayload {
}

// TenantID returns the tenant ID associated with this idPayload.
// if the idPayload has no tenant ID set, we default to the system
// tenant ID. NB: This function should never return an empty string.
func (ip IDPayload) TenantID() string {
if ip.TenantIDInternal == "" {
return SystemTenantID
}
return ip.TenantIDInternal
}

Expand Down
2 changes: 1 addition & 1 deletion pkg/util/log/fluent_client_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -94,7 +94,7 @@ func TestFluentClient(t *testing.T) {
msg, err := json.Marshal(info)
require.NoError(t, err)

const expected = `{"T":1,"c":1,"f":"util/log/fluent_client_test.go","g":222,"l":77,"message":"hello world","n":1,"r":1,"s":1,"sev":"I","t":"XXX","tag":"logtest.ops","v":"v999.0.0"}`
const expected = `{"c":1,"f":"util/log/fluent_client_test.go","g":222,"l":77,"message":"hello world","n":1,"r":1,"s":1,"sev":"I","t":"XXX","tag":"logtest.ops","v":"v999.0.0"}`
require.Equal(t, expected, string(msg))
}

Expand Down
29 changes: 15 additions & 14 deletions pkg/util/log/format_crdb_v1.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -316,22 +316,23 @@ func formatLogEntryInternalV1(
// the static size of tmp. But we do have an upper bound.
buf.Grow(len(entry.Tags) + 14 + len(entry.Message))

// We must always tag with tenant ID.
// We must always tag with tenant ID if present.
buf.Write(cp[ttycolor.Blue])
buf.WriteByte('[')
buf.WriteByte(TenantIDLogTagKey)
if entry.TenantID != "" {
buf.WriteString(entry.TenantID)
} else {
// If no tenant ID was set, default to the system tenant ID
buf.WriteString(serverident.SystemTenantID)
}
// Display the tags if set.
if len(entry.Tags) != 0 {
buf.WriteByte(',')
buf.WriteString(entry.Tags)
if entry.TenantID != "" || len(entry.Tags) != 0 {
buf.WriteByte('[')
if entry.TenantID != "" {
buf.WriteByte(TenantIDLogTagKey)
buf.WriteString(entry.TenantID)
if len(entry.Tags) != 0 {
buf.WriteByte(',')
}
}
// Display the tags if set.
if len(entry.Tags) != 0 {
buf.WriteString(entry.Tags)
}
buf.WriteString("] ")
}
buf.WriteString("] ")
buf.Write(cp[ttycolor.Reset])

// Display the counter if set and enabled.
Expand Down
25 changes: 17 additions & 8 deletions pkg/util/log/format_crdb_v2.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -291,14 +291,23 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer {

// Display the tags if set.
buf.Write(cp[ttycolor.Blue])
// We must always tag with tenant ID.
buf.WriteByte('[')
writeTagToBuffer(buf, tenantIDLogTagBytePrefix, []byte(entry.TenantID()))
if entry.payload.tags != nil {
buf.WriteByte(',')
entry.payload.tags.formatToBuffer(buf)
}
buf.WriteByte(']')
// We must always tag with tenant ID if present.
tID := entry.TenantID()
if tID != "" || entry.payload.tags != nil {
buf.WriteByte('[')
if tID != "" {
writeTagToBuffer(buf, tenantIDLogTagBytePrefix, []byte(entry.TenantID()))
if entry.payload.tags != nil {
buf.WriteByte(',')
}
}
if entry.payload.tags != nil {
entry.payload.tags.formatToBuffer(buf)
}
buf.WriteByte(']')
} else {
buf.WriteString("[-]")
}
buf.Write(cp[ttycolor.Reset])
buf.WriteByte(' ')

Expand Down
10 changes: 10 additions & 0 deletions pkg/util/log/format_crdb_v2_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,11 @@ func TestFormatCrdbV2(t *testing.T) {
t.Fatal(err)
}

emptyCtx := context.Background()

sysCtx := context.Background()
sysIDPayload := testIDPayload{tenantID: "1"}
sysCtx = context.WithValue(sysCtx, serverident.ServerIdentificationContextKey{}, sysIDPayload)
sysCtx = logtags.AddTag(sysCtx, "noval", nil)
sysCtx = logtags.AddTag(sysCtx, "s", "1")
sysCtx = logtags.AddTag(sysCtx, "long", "2")
Expand Down Expand Up @@ -141,6 +145,9 @@ func TestFormatCrdbV2(t *testing.T) {
// Secondary tenant entries
makeStructuredEntry(tenantCtx, severity.INFO, channel.DEV, 0, ev),
makeUnstructuredEntry(tenantCtx, severity.WARNING, channel.OPS, 0, false, "hello %s", "world"),
// Entries with empty ctx
makeStructuredEntry(emptyCtx, severity.INFO, channel.DEV, 0, ev),
makeUnstructuredEntry(emptyCtx, severity.WARNING, channel.OPS, 0, false, "hello %s", "world"),
}

// We only use the datadriven framework for the ability to rewrite the output.
Expand Down Expand Up @@ -178,6 +185,9 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) {
crdbV2LongLineLen.set(maxLen)

entry := logEntry{
IDPayload: serverident.IDPayload{
TenantIDInternal: "1",
},
payload: entryPayload{
redactable: redactable,
message: td.Input,
Expand Down
12 changes: 6 additions & 6 deletions pkg/util/log/format_json.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -294,12 +294,12 @@ func formatJSON(entry logEntry, forFluent bool, tags tagChoice) *buffer {
buf.WriteString(`":`)
buf.WriteString(entry.NodeID)
}
// The entry's idPayload always returns a tenant ID,
// so write the tenant ID tag in any case.
buf.WriteString(`,"`)
buf.WriteString(jtags['T'].tags[tags])
buf.WriteString(`":`)
buf.WriteString(entry.TenantID())
if entry.TenantID() != "" {
buf.WriteString(`,"`)
buf.WriteString(jtags['T'].tags[tags])
buf.WriteString(`":`)
buf.WriteString(entry.TenantID())
}
if entry.SQLInstanceID != "" {
buf.WriteString(`,"`)
buf.WriteString(jtags['q'].tags[tags])
Expand Down
4 changes: 3 additions & 1 deletion pkg/util/log/format_json_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,8 @@ func TestJSONFormats(t *testing.T) {
}

ctx := context.Background()
sysIDPayload := testIDPayload{tenantID: "1"}
ctx = context.WithValue(ctx, serverident.ServerIdentificationContextKey{}, sysIDPayload)
ctx = logtags.AddTag(ctx, "noval", nil)
ctx = logtags.AddTag(ctx, "s", "1")
ctx = logtags.AddTag(ctx, "long", "2")
Expand All @@ -53,7 +55,7 @@ func TestJSONFormats(t *testing.T) {
}(),
// Normal (non-header) entries.
{},
{IDPayload: serverident.IDPayload{ClusterID: "abc", NodeID: "123"}},
{IDPayload: serverident.IDPayload{TenantIDInternal: "1", ClusterID: "abc", NodeID: "123"}},
{IDPayload: serverident.IDPayload{TenantIDInternal: "456", SQLInstanceID: "123"}},
makeStructuredEntry(ctx, severity.INFO, channel.DEV, 0, &logpb.TestingStructuredLogEvent{
CommonEventDetails: logpb.CommonEventDetails{
Expand Down
15 changes: 10 additions & 5 deletions pkg/util/log/redact_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import (
"strings"
"testing"

"github.com/cockroachdb/cockroach/pkg/base/serverident"
"github.com/cockroachdb/cockroach/pkg/util/envutil"
"github.com/cockroachdb/cockroach/pkg/util/leaktest"
"github.com/cockroachdb/cockroach/pkg/util/log/logconfig"
Expand All @@ -43,7 +44,11 @@ func TestRedactedLogOutput(t *testing.T) {

defer TestingSetRedactable(false)()

Errorf(context.Background(), "test1 %v end", "hello")
ctx := context.Background()
sysIDPayload := testIDPayload{tenantID: "1"}
ctx = context.WithValue(ctx, serverident.ServerIdentificationContextKey{}, sysIDPayload)

Errorf(ctx, "test1 %v end", "hello")
if contains(redactableIndicator, t) {
t.Errorf("expected no marker indicator, got %q", contents())
}
Expand All @@ -54,14 +59,14 @@ func TestRedactedLogOutput(t *testing.T) {
// markers are disabled.
resetCaptured()

Errorf(context.Background(), "test2 %v end", startRedactable+"hello"+endRedactable)
Errorf(ctx, "test2 %v end", startRedactable+"hello"+endRedactable)
if !contains("test2 ?hello? end", t) {
t.Errorf("expected escaped markers, got %q", contents())
}

resetCaptured()
_ = TestingSetRedactable(true)
Errorf(context.Background(), "test3 %v end", "hello")
Errorf(ctx, "test3 %v end", "hello")
if !contains(redactableIndicator+" [T1] 3 test3", t) {
t.Errorf("expected marker indicator, got %q", contents())
}
Expand All @@ -71,7 +76,7 @@ func TestRedactedLogOutput(t *testing.T) {

// Verify that safe parts of errors don't get enclosed in redaction markers
resetCaptured()
Errorf(context.Background(), "test3e %v end",
Errorf(ctx, "test3e %v end",
errors.AssertionFailedf("hello %v",
errors.Newf("error-in-error %s", "world"))) // nolint:errwrap
if !contains(redactableIndicator+" [T1] 4 test3e", t) {
Expand All @@ -85,7 +90,7 @@ func TestRedactedLogOutput(t *testing.T) {
resetCaptured()

const specialString = "x" + startRedactable + "hello" + endRedactable + "y"
Errorf(context.Background(), "test4 %v end", specialString)
Errorf(ctx, "test4 %v end", specialString)
if contains(specialString, t) {
t.Errorf("expected markers to be removed, got %q", contents())
}
Expand Down
28 changes: 14 additions & 14 deletions pkg/util/log/testdata/crdb_v1
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,8 @@ entries
{"counter": 2, "message": ""}
{"counter": 3, "message": "info"}
----
I000101 00:00:12.300000 456 somefile.go:136 [T1] 2
I000101 00:00:12.300000 456 somefile.go:136 [T1] 3 info
I000101 00:00:12.300000 456 somefile.go:136 2
I000101 00:00:12.300000 456 somefile.go:136 3 info
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹info›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
Expand All @@ -16,8 +16,8 @@ entries
{"counter": 2, "message": "hello ‹world›", "tags": "sometags"}
{"counter": 3, "message": "hello ‹world›", "redactable": true}
----
I000101 00:00:12.300000 456 somefile.go:136 [T1,sometags] 2 hello ‹world›
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 3 hello ‹world›
I000101 00:00:12.300000 456 somefile.go:136 [sometags] 2 hello ‹world›
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 hello ‹world›
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹hello ?world?›", Tags:"‹sometags›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"hello ‹world›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
Expand All @@ -27,9 +27,9 @@ entries
{"counter": 2, "message": "multi-\nline"}
{"counter": 3, "message": "multi-\nline", "redactable": true}
----
I000101 00:00:12.300000 456 somefile.go:136 [T1] 2 multi-
I000101 00:00:12.300000 456 somefile.go:136 2 multi-
line
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 3 multi-
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 multi-
line
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹multi-›\n‹line›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
Expand All @@ -55,8 +55,8 @@ entries
{"counter": 2, "tags": "sometags,someothertags,nsql?", "message": "foo"}
{"counter": 3, "tags": "", "message": "foo"}
----
I000101 00:00:12.300000 456 somefile.go:136 [T1,sometags,someothertags,nsql?] 2 foo
I000101 00:00:12.300000 456 somefile.go:136 [T1] 3 foo
I000101 00:00:12.300000 456 somefile.go:136 [sometags,someothertags,nsql?] 2 foo
I000101 00:00:12.300000 456 somefile.go:136 3 foo
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹sometags,someothertags,nsql?›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}
Expand All @@ -68,7 +68,7 @@ subtest different_channel
entries
{"counter": 2, "channel": 2, "message": "foo"}
----
I000101 00:00:12.300000 456 [email protected]:136 [T1] 2 foo
I000101 00:00:12.300000 456 [email protected]:136 2 foo
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x2, Redactable:true, Channel:2, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}

Expand All @@ -79,7 +79,7 @@ subtest ipv6_in_tags
entries
{"counter": 2, "tags": "client=[1::]:2", "message": "foo"}
----
I000101 00:00:12.300000 456 somefile.go:136 [T1,client=[1::]:2] 2 foo
I000101 00:00:12.300000 456 somefile.go:136 [client=[1::]:2] 2 foo
# after parse:
logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹client=[1::]:2›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0, TenantID:"1"}

Expand All @@ -91,8 +91,8 @@ entries
{"counter": 2, "message": "Structured entry: {\"hello\":123}", "redactable": true}
{"counter": 2, "message": "Structured entry: {\"hello\":123}\nstack trace:\nfoo", "redactable": true}
----
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 2 Structured entry: {"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 2 Structured entry: {"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {"hello":123}
stack trace:
foo
# after parse:
Expand All @@ -106,8 +106,8 @@ entries
{"counter": 2, "message": " ={\"hello\":123}", "redactable": true}
{"counter": 2, "message": " ={\"hello\":123}\nstack trace:\nfoo", "redactable": true}
----
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 2 ={"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ [T1] 2 ={"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 ={"hello":123}
I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 ={"hello":123}
stack trace:
foo
# after parse:
Expand Down
6 changes: 5 additions & 1 deletion pkg/util/log/testdata/crdb_v2
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@ run
#
I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [T1,noval,s‹1›,long=‹2›] hello ‹world›
#
I060102 15:04:05.654321 11 :123 [T1]
I060102 15:04:05.654321 11 :123 [-]
#
I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [T1,noval,s‹1›,long=‹2›] ={"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}
#
Expand Down Expand Up @@ -42,3 +42,7 @@ E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [T1,noval,s
I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [T2,noval,p‹3›,longKey=‹456›] ={"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}
#
W060102 15:04:05.654321 11 1@util/log/format_crdb_v2_test.go:123 [T2,noval,p3,longKey=456] hello world
#
I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [-] ={"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}
#
W060102 15:04:05.654321 11 1@util/log/format_crdb_v2_test.go:123 [-] hello world
8 changes: 4 additions & 4 deletions pkg/util/log/testdata/json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,10 +6,10 @@ json-fluent-compact: {"tag":"logtest.unknown","header":1,"t":"1136214245.6543210
json-compact: {"header":1,"t":"1136214245.654321000","T":1,"v":"v999.0.0","g":11,"f":"util/log/format_json_test.go","l":123,"r":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"}
json: {"header":1,"timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","goroutine":11,"file":"util/log/format_json_test.go","line":123,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"}
#
json-fluent-compact: {"tag":"logtest.dev","c":0,"t":"1136214245.654321000","T":1,"s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""}
json-fluent: {"tag":"logtest.dev","channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","tenant_id":1,"severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""}
json-compact: {"c":0,"t":"1136214245.654321000","T":1,"s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""}
json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","tenant_id":1,"severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""}
json-fluent-compact: {"tag":"logtest.dev","c":0,"t":"1136214245.654321000","s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""}
json-fluent: {"tag":"logtest.dev","channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""}
json-compact: {"c":0,"t":"1136214245.654321000","s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""}
json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""}
#
json-fluent-compact: {"tag":"logtest.dev","c":0,"t":"1136214245.654321000","x":"abc","N":123,"T":1,"s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""}
json-fluent: {"tag":"logtest.dev","channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","cluster_id":"abc","node_id":123,"tenant_id":1,"severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""}
Expand Down