From bab7d79c3c622f11d6a58963e27ab6625ecc38fb Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 4 Jun 2021 20:43:30 +0200 Subject: [PATCH] util/log: make `logpb.Entry` slightly more able to represent crdb-v2 entries Prior to this change, we did not have a public data structure able to represent the various fields available in a `crdb-v2` log entry: the existing `logpb.Entry` was not able to distinguish structured and non-structured entries, and did not have the ability to delimit the message and the stack trace. This patch extends `logpb.Entry` to make it more able to represent `crdb-v2` entries, at least for the purpose of extending `debug merge-log` towards conversion between logging formats. Additionally, the patch adds a *best effort* attempt at populating the new fields in the `crdb-v1` entry parser. This is best effort because the crdb-v1 parser is lossy so we cannot faithfully parse its entries reliably. Release note: None --- docs/generated/logformats.md | 2 +- pkg/util/log/format_crdb_v1.go | 21 +++ pkg/util/log/format_crdb_v1_test.go | 7 + pkg/util/log/format_crdb_v2.go | 2 +- pkg/util/log/log_entry.go | 7 +- pkg/util/log/logpb/log.pb.go | 193 +++++++++++++++++++++------- pkg/util/log/logpb/log.proto | 22 ++++ pkg/util/log/testdata/crdb_v1 | 43 ++++--- 8 files changed, 234 insertions(+), 63 deletions(-) diff --git a/docs/generated/logformats.md b/docs/generated/logformats.md index 1ebca1bd927b..1f07098d5a4a 100644 --- a/docs/generated/logformats.md +++ b/docs/generated/logformats.md @@ -291,7 +291,7 @@ to indicate whether the remainder of the line is a structured entry, or a continuation of a previous entry. Finally, in the previous format, structured entries -were prefixed with the string `Structured entry:`. In +were prefixed with the string `Structured entry: `. In the new format, they are prefixed by the `=` continuation indicator. diff --git a/pkg/util/log/format_crdb_v1.go b/pkg/util/log/format_crdb_v1.go index 3a368868a887..4f0d0a5771d0 100644 --- a/pkg/util/log/format_crdb_v1.go +++ b/pkg/util/log/format_crdb_v1.go @@ -471,6 +471,27 @@ func (d *EntryDecoder) Decode(entry *logpb.Entry) error { r = d.sensitiveEditor(r) entry.Message = string(r.msg) entry.Redactable = r.redactable + + if strings.HasPrefix(entry.Message, structuredEntryPrefix+"{") || /* crdb-v1 prefix */ + strings.HasPrefix(entry.Message, " ={") /* crdb-v2 prefix, happens when using the v1 parser against a v2 file */ { + if entry.Message[0] == ' ' { + entry.StructuredStart = 2 + } else { + entry.StructuredStart = uint32(len(structuredEntryPrefix)) + } + if nl := strings.IndexByte(entry.Message, '\n'); nl != -1 { + entry.StructuredEnd = uint32(nl) + entry.StackTraceStart = uint32(nl + 1) + } else { + entry.StructuredEnd = uint32(len(entry.Message)) + } + } + // Note: we only know how to populate entry.StackTraceStart upon + // parse if the entry was structured (see above). If it is not + // structured, we cannot distinguish where the message ends and + // where the stack trace starts. This is another reason why the + // crdb-v1 format is lossy. + return nil } } diff --git a/pkg/util/log/format_crdb_v1_test.go b/pkg/util/log/format_crdb_v1_test.go index 3fe3bd8bacc6..6d80dfc59599 100644 --- a/pkg/util/log/format_crdb_v1_test.go +++ b/pkg/util/log/format_crdb_v1_test.go @@ -76,6 +76,13 @@ func TestCrdbV1EncodeDecode(t *testing.T) { buf.WriteString("# after parse:\n") for _, entry := range outputEntries { fmt.Fprintf(&buf, "%# v\n", pretty.Formatter(entry)) + if entry.StructuredEnd != 0 { + var payload interface{} + if err := json.Unmarshal([]byte(entry.Message[entry.StructuredStart:entry.StructuredEnd]), &payload); err != nil { + td.Fatalf(t, "JSON entry not parsable: %v", err) + } + fmt.Fprintf(&buf, "JSON payload in previous entry: %+v\n", payload) + } } return buf.String() diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index af4833c4dba0..38266391f261 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -143,7 +143,7 @@ to indicate whether the remainder of the line is a structured entry, or a continuation of a previous entry. Finally, in the previous format, structured entries -were prefixed with the string ` + "`Structured entry:`" + `. In +were prefixed with the string ` + "`" + structuredEntryPrefix + "`" + `. In the new format, they are prefixed by the ` + "`=`" + ` continuation indicator. `) diff --git a/pkg/util/log/log_entry.go b/pkg/util/log/log_entry.go index 2f83e9b393f0..7ccb555aaef3 100644 --- a/pkg/util/log/log_entry.go +++ b/pkg/util/log/log_entry.go @@ -248,16 +248,21 @@ func (e logEntry) convertToLegacy() (res logpb.Entry) { // At this point, the message only contains the JSON fields of the // payload. Add the decoration suitable for our legacy file // format. - res.Message = "Structured entry: {" + res.Message + "}" + res.Message = structuredEntryPrefix + "{" + res.Message + "}" + res.StructuredStart = uint32(len(structuredEntryPrefix)) + res.StructuredEnd = uint32(len(res.Message)) } if e.stacks != nil { + res.StackTraceStart = uint32(len(res.Message)) + 1 res.Message += "\n" + string(e.stacks) } return res } +const structuredEntryPrefix = "Structured entry: " + func renderTagsAsString(tags *logtags.Buffer, redactable bool) string { if redactable { return string(renderTagsAsRedactable(tags)) diff --git a/pkg/util/log/logpb/log.pb.go b/pkg/util/log/logpb/log.pb.go index 6bcded72d9a0..6517e133b68c 100644 --- a/pkg/util/log/logpb/log.pb.go +++ b/pkg/util/log/logpb/log.pb.go @@ -290,6 +290,25 @@ type Entry struct { Redactable bool `protobuf:"varint,9,opt,name=redactable,proto3" json:"redactable,omitempty"` // Channel is the channel on which the message was sent. Channel Channel `protobuf:"varint,10,opt,name=channel,proto3,enum=cockroach.util.log.Channel" json:"channel,omitempty"` + // StructuredEnd, if non-zero, indicates that the entry + // is structured; it is also the index + // inside the Message field where the JSON payload ends (exclusive). + StructuredEnd uint32 `protobuf:"varint,11,opt,name=structured_end,json=structuredEnd,proto3" json:"structured_end,omitempty"` + // StructuredStart, when StructuredEnd is non-zero, is the index + // inside the Message field where the JSON payload starts (inclusive). + StructuredStart uint32 `protobuf:"varint,12,opt,name=structured_start,json=structuredStart,proto3" json:"structured_start,omitempty"` + // StackTraceStart is the index inside Message where a detailed + // stack trace starts. If zero, no stack trace is present. Stack + // traces are always separated from the message using a newline + // character. If a stack trace is included, StackTracePosition is + // the index of the character immediately after the newline + // character. + // + // We use an index-in-string field in the protobuf, instead of two + // separate string fields, because previous-version consumers of + // Entry are still expecting the message and the stack trace in the + // same field. + StackTraceStart uint32 `protobuf:"varint,13,opt,name=stack_trace_start,json=stackTraceStart,proto3" json:"stack_trace_start,omitempty"` } func (m *Entry) Reset() { *m = Entry{} } @@ -407,50 +426,55 @@ func init() { func init() { proto.RegisterFile("util/log/logpb/log.proto", fileDescriptor_84e824ab4ae60f77) } var fileDescriptor_84e824ab4ae60f77 = []byte{ - // 683 bytes of a gzipped FileDescriptorProto - 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x6c, 0x53, 0xc1, 0x6a, 0xeb, 0x46, - 0x14, 0xb5, 0x2c, 0xc9, 0x92, 0xae, 0x1f, 0x61, 0x3a, 0xbc, 0x82, 0xda, 0x97, 0x2a, 0x26, 0x14, - 0x6a, 0xb2, 0x70, 0x20, 0xa5, 0xd0, 0x5d, 0x91, 0xed, 0x71, 0xa2, 0xd6, 0x91, 0x9d, 0x91, 0x93, - 0x94, 0x76, 0x21, 0x64, 0x7b, 0xa2, 0x88, 0x4a, 0x1a, 0x23, 0xc9, 0x85, 0xf4, 0x1f, 0x0a, 0xfd, - 0x88, 0x7e, 0x45, 0xfb, 0x03, 0x59, 0x66, 0x99, 0x55, 0x68, 0x9d, 0x1f, 0x29, 0x33, 0xb6, 0xd2, - 0xc0, 0xcb, 0xc2, 0xe6, 0x9c, 0x33, 0x67, 0xee, 0xdc, 0x39, 0x57, 0x03, 0xf6, 0xba, 0x4a, 0xd2, - 0xe3, 0x94, 0xc7, 0xe2, 0xb7, 0x9a, 0x8b, 0xff, 0xde, 0xaa, 0xe0, 0x15, 0xc7, 0x78, 0xc1, 0x17, - 0xbf, 0x14, 0x3c, 0x5a, 0xdc, 0xf6, 0x84, 0xa7, 0x97, 0xf2, 0xf8, 0xf3, 0xf7, 0x31, 0x8f, 0xb9, - 0x5c, 0x3e, 0x16, 0x68, 0xeb, 0x3c, 0xfc, 0xab, 0x09, 0x3a, 0xc9, 0xab, 0xe2, 0x0e, 0x7f, 0x0b, - 0x66, 0xc9, 0x7e, 0x65, 0x45, 0x52, 0xdd, 0xd9, 0x4a, 0x47, 0xe9, 0xee, 0x9d, 0xec, 0xf7, 0x3e, - 0x2e, 0xd3, 0x0b, 0x76, 0x1e, 0xfa, 0xe2, 0xc6, 0x18, 0xb4, 0x2a, 0xc9, 0x98, 0xdd, 0xec, 0x28, - 0x5d, 0x95, 0x4a, 0x8c, 0xf7, 0xc1, 0x8a, 0x79, 0xc1, 0xd7, 0x55, 0x92, 0x33, 0xbb, 0x25, 0x17, - 0xfe, 0x17, 0xc4, 0x8e, 0x9b, 0x24, 0x65, 0xb6, 0xda, 0x51, 0xba, 0x16, 0x95, 0x58, 0x68, 0xa9, - 0x30, 0x6b, 0xdb, 0x2a, 0x02, 0x63, 0x1b, 0x8c, 0x8c, 0x95, 0x65, 0x14, 0x33, 0x5b, 0x97, 0xd6, - 0x9a, 0xca, 0x33, 0xa3, 0xb8, 0xb4, 0x8d, 0x6d, 0x05, 0x81, 0x85, 0x7b, 0xc1, 0xd7, 0x79, 0xc5, - 0x0a, 0xdb, 0xec, 0x28, 0x5d, 0x8d, 0xd6, 0x14, 0x3b, 0x00, 0x05, 0x5b, 0x46, 0x8b, 0x2a, 0x9a, - 0xa7, 0xcc, 0xb6, 0x3a, 0x4a, 0xd7, 0xa4, 0xaf, 0x14, 0xfc, 0x0d, 0x18, 0x8b, 0xdb, 0x28, 0xcf, - 0x59, 0x6a, 0x83, 0xbc, 0xfa, 0x87, 0xb7, 0xae, 0x3e, 0xd8, 0x5a, 0x68, 0xed, 0x3d, 0xfc, 0x5d, - 0x81, 0xf6, 0x28, 0x49, 0xd9, 0x90, 0x55, 0x51, 0x92, 0xca, 0x06, 0x56, 0x05, 0x8f, 0x8b, 0x28, - 0x93, 0x09, 0x5a, 0xb4, 0xa6, 0xa2, 0xdd, 0x5b, 0x5e, 0x56, 0x32, 0x22, 0x8b, 0x4a, 0x8c, 0x3f, - 0x80, 0xb5, 0x2e, 0x59, 0x11, 0xe6, 0x51, 0x56, 0x27, 0x61, 0x0a, 0xc1, 0x8f, 0x32, 0xf6, 0x92, - 0xa9, 0xfe, 0x2a, 0xd3, 0xcf, 0x40, 0x5d, 0x25, 0xcb, 0x6d, 0x9a, 0x7d, 0x63, 0xf3, 0x74, 0xa0, - 0x4e, 0xbd, 0x21, 0x15, 0xda, 0xf7, 0x9a, 0xa9, 0x21, 0xfd, 0xf0, 0x4f, 0x05, 0x4c, 0xd1, 0x8f, - 0x97, 0xdf, 0x70, 0x51, 0x41, 0x56, 0xde, 0x76, 0x22, 0x31, 0xfe, 0x02, 0xa0, 0x4c, 0x7e, 0x63, - 0xe1, 0xfc, 0xae, 0x62, 0xe5, 0x6e, 0x5e, 0x96, 0x50, 0xfa, 0x42, 0xc0, 0x5f, 0xc2, 0x5e, 0xc6, - 0x97, 0xa1, 0x38, 0x2c, 0xcc, 0xa3, 0x9c, 0x97, 0xb2, 0x2d, 0x95, 0xbe, 0xcb, 0xf8, 0x72, 0x96, - 0x64, 0xcc, 0x17, 0x1a, 0xfe, 0x0e, 0x8c, 0xe5, 0xf6, 0xc2, 0x72, 0x56, 0xed, 0x93, 0x83, 0xb7, - 0xc2, 0x7a, 0x95, 0x4b, 0x5f, 0xbb, 0x7f, 0x3a, 0x68, 0xd0, 0x7a, 0xd7, 0xd1, 0xcf, 0x60, 0xd6, - 0x5f, 0x11, 0x6e, 0x83, 0x71, 0xe9, 0xff, 0xe0, 0x4f, 0xae, 0x7d, 0xd4, 0xc0, 0x26, 0x68, 0x9e, - 0x3f, 0x9a, 0x20, 0x45, 0xc8, 0xd7, 0x2e, 0xf5, 0x3d, 0xff, 0x14, 0x35, 0xb1, 0x05, 0x3a, 0xa1, - 0x74, 0x42, 0x91, 0x2a, 0xe0, 0xc8, 0x9d, 0xb9, 0x63, 0xa4, 0x09, 0xb3, 0x3f, 0xf1, 0x09, 0xd2, - 0x85, 0x79, 0x48, 0x46, 0xee, 0xe5, 0x78, 0x86, 0x5a, 0x47, 0x7f, 0x2b, 0x60, 0xec, 0x06, 0x85, - 0x0d, 0x50, 0x87, 0xe4, 0x0a, 0x35, 0x04, 0x98, 0x4c, 0x03, 0xa4, 0x60, 0x80, 0xd6, 0x19, 0x71, - 0xc7, 0xb3, 0x33, 0xd4, 0x14, 0xdb, 0x82, 0xd9, 0x84, 0xba, 0xa7, 0x04, 0xa9, 0xf8, 0x1d, 0x98, - 0x01, 0x09, 0x02, 0x6f, 0xe2, 0x07, 0x48, 0xc3, 0x7b, 0x00, 0xc1, 0xc5, 0x38, 0x0c, 0x06, 0x67, - 0xe4, 0xdc, 0x45, 0xba, 0xe0, 0x97, 0x01, 0xa1, 0xa1, 0x3b, 0x3c, 0xf7, 0x7c, 0xd4, 0x12, 0x7c, - 0x4a, 0xbd, 0x2b, 0x6f, 0x4c, 0x4e, 0x49, 0x80, 0x0c, 0xfc, 0x1e, 0x50, 0x40, 0xfc, 0xc0, 0x9b, - 0x79, 0x57, 0x24, 0x74, 0x07, 0x03, 0x12, 0x04, 0xc8, 0x94, 0x35, 0x2f, 0xc6, 0x21, 0xf9, 0x91, - 0x0c, 0x90, 0x55, 0xb3, 0x29, 0xa1, 0x23, 0x04, 0xf8, 0x53, 0xf8, 0x44, 0x30, 0xcf, 0x9f, 0x11, - 0xea, 0xbb, 0x3b, 0xb9, 0xdd, 0xff, 0xea, 0xfe, 0x5f, 0xa7, 0x71, 0xbf, 0x71, 0x94, 0x87, 0x8d, - 0xa3, 0x3c, 0x6e, 0x1c, 0xe5, 0x9f, 0x8d, 0xa3, 0xfc, 0xf1, 0xec, 0x34, 0x1e, 0x9e, 0x9d, 0xc6, - 0xe3, 0xb3, 0xd3, 0xf8, 0x49, 0x97, 0x6f, 0x7d, 0xde, 0x92, 0xcf, 0xf7, 0xeb, 0xff, 0x02, 0x00, - 0x00, 0xff, 0xff, 0x14, 0x81, 0x8f, 0xee, 0x04, 0x04, 0x00, 0x00, + // 753 bytes of a gzipped FileDescriptorProto + 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x6c, 0x94, 0xd1, 0x6e, 0xdb, 0x36, + 0x14, 0x86, 0xad, 0x48, 0xb6, 0xa4, 0xe3, 0x24, 0x63, 0x89, 0x0e, 0xd0, 0xd6, 0x4e, 0x31, 0x82, + 0x0d, 0xf3, 0x72, 0xe1, 0x02, 0x1d, 0x06, 0xec, 0x6e, 0x50, 0x6c, 0x3a, 0xd1, 0xe6, 0xca, 0x29, + 0xe9, 0xa4, 0xc3, 0x76, 0x21, 0x28, 0x32, 0xeb, 0x08, 0x91, 0xc4, 0x40, 0xa2, 0x07, 0x64, 0xef, + 0x30, 0x60, 0x0f, 0xb1, 0x87, 0x18, 0xb0, 0x17, 0xc8, 0x65, 0x2f, 0x7b, 0x55, 0x6c, 0xce, 0x8b, + 0x0c, 0xa4, 0xad, 0xc6, 0x40, 0x7b, 0x61, 0xe3, 0x3f, 0xbf, 0x3e, 0x1e, 0xf2, 0xf0, 0x1c, 0x10, + 0xbc, 0xa5, 0xcc, 0xf2, 0x67, 0xb9, 0x58, 0xa8, 0xdf, 0xcd, 0xa5, 0xfa, 0x1f, 0xdc, 0x54, 0x42, + 0x0a, 0x8c, 0x53, 0x91, 0x5e, 0x57, 0x22, 0x49, 0xaf, 0x06, 0x8a, 0x19, 0xe4, 0x62, 0xf1, 0xf9, + 0xe3, 0x85, 0x58, 0x08, 0xfd, 0xf9, 0x99, 0x52, 0x6b, 0xf2, 0xf0, 0x6f, 0x13, 0xda, 0xa4, 0x94, + 0xd5, 0x2d, 0xfe, 0x1e, 0x9c, 0x9a, 0xff, 0xc6, 0xab, 0x4c, 0xde, 0x7a, 0x46, 0xcf, 0xe8, 0xef, + 0x3f, 0x7f, 0x3a, 0xf8, 0x30, 0xcd, 0x80, 0x6d, 0x18, 0xfa, 0x9e, 0xc6, 0x18, 0x2c, 0x99, 0x15, + 0xdc, 0xdb, 0xe9, 0x19, 0x7d, 0x93, 0x6a, 0x8d, 0x9f, 0x82, 0xbb, 0x10, 0x95, 0x58, 0xca, 0xac, + 0xe4, 0x5e, 0x47, 0x7f, 0x78, 0x30, 0xd4, 0x8a, 0xd7, 0x59, 0xce, 0x3d, 0xb3, 0x67, 0xf4, 0x5d, + 0xaa, 0xb5, 0xf2, 0x72, 0x05, 0x5b, 0xeb, 0x2c, 0x4a, 0x63, 0x0f, 0xec, 0x82, 0xd7, 0x75, 0xb2, + 0xe0, 0x5e, 0x5b, 0xa3, 0x4d, 0xa8, 0xf7, 0x4c, 0x16, 0xb5, 0x67, 0xaf, 0x33, 0x28, 0xad, 0xe8, + 0x54, 0x2c, 0x4b, 0xc9, 0x2b, 0xcf, 0xe9, 0x19, 0x7d, 0x8b, 0x36, 0x21, 0xf6, 0x01, 0x2a, 0x3e, + 0x4f, 0x52, 0x99, 0x5c, 0xe6, 0xdc, 0x73, 0x7b, 0x46, 0xdf, 0xa1, 0x5b, 0x0e, 0xfe, 0x0e, 0xec, + 0xf4, 0x2a, 0x29, 0x4b, 0x9e, 0x7b, 0xa0, 0x4b, 0x7f, 0xf2, 0xb1, 0xd2, 0x87, 0x6b, 0x84, 0x36, + 0x2c, 0xfe, 0x0a, 0xf6, 0x6b, 0x59, 0x2d, 0x53, 0xb9, 0xac, 0xf8, 0x3c, 0xe6, 0xe5, 0xdc, 0xeb, + 0xf6, 0x8c, 0xfe, 0x1e, 0xdd, 0x7b, 0x70, 0x49, 0x39, 0xc7, 0xdf, 0x00, 0xda, 0xc2, 0x6a, 0x99, + 0x54, 0xd2, 0xdb, 0xd5, 0xe0, 0x27, 0x0f, 0x3e, 0x53, 0x36, 0x3e, 0x82, 0x47, 0xb5, 0x4c, 0xd2, + 0xeb, 0x58, 0x56, 0x49, 0xca, 0x37, 0xec, 0x5e, 0xc3, 0x26, 0xe9, 0xf5, 0x4c, 0xf9, 0x9a, 0x3d, + 0xfc, 0xc3, 0x80, 0xee, 0x38, 0xcb, 0xf9, 0x88, 0xcb, 0x24, 0xcb, 0x75, 0xf9, 0x37, 0x95, 0x58, + 0x54, 0x49, 0xa1, 0xfb, 0xe7, 0xd2, 0x26, 0x54, 0x97, 0x75, 0x25, 0x6a, 0xa9, 0x1b, 0xe4, 0x52, + 0xad, 0xf1, 0x13, 0x70, 0x97, 0x35, 0xaf, 0xe2, 0x32, 0x29, 0x9a, 0x3e, 0x38, 0xca, 0x88, 0x92, + 0x82, 0xbf, 0xef, 0x68, 0x7b, 0xab, 0xa3, 0x9f, 0x81, 0x79, 0x93, 0xcd, 0xd7, 0xbd, 0x3c, 0xb6, + 0x57, 0xef, 0x0e, 0xcc, 0xb3, 0x70, 0x44, 0x95, 0xf7, 0xa3, 0xe5, 0x58, 0xa8, 0x7d, 0xf8, 0x97, + 0x01, 0x8e, 0x3a, 0x4f, 0x58, 0xbe, 0x16, 0x2a, 0x83, 0xce, 0xbc, 0x3e, 0x89, 0xd6, 0xf8, 0x0b, + 0x80, 0x3a, 0xfb, 0x9d, 0xc7, 0x97, 0xb7, 0x92, 0xd7, 0x9b, 0x69, 0x71, 0x95, 0x73, 0xac, 0x0c, + 0xfc, 0x25, 0xec, 0x17, 0x62, 0x1e, 0xab, 0xcd, 0xe2, 0x32, 0x29, 0x45, 0xad, 0x8f, 0x65, 0xd2, + 0xdd, 0x42, 0xcc, 0x67, 0x59, 0xc1, 0x23, 0xe5, 0xe1, 0x1f, 0xc0, 0x9e, 0xaf, 0x0b, 0xd6, 0x93, + 0xd2, 0x7d, 0x7e, 0xf0, 0xb1, 0x56, 0x6d, 0xdd, 0xcb, 0xb1, 0x75, 0xf7, 0xee, 0xa0, 0x45, 0x9b, + 0x55, 0x47, 0xbf, 0x82, 0xd3, 0xcc, 0x30, 0xee, 0x82, 0x7d, 0x1e, 0xfd, 0x14, 0x4d, 0x5f, 0x45, + 0xa8, 0x85, 0x1d, 0xb0, 0xc2, 0x68, 0x3c, 0x45, 0x86, 0xb2, 0x5f, 0x05, 0x34, 0x0a, 0xa3, 0x13, + 0xb4, 0x83, 0x5d, 0x68, 0x13, 0x4a, 0xa7, 0x14, 0x99, 0x4a, 0x8e, 0x83, 0x59, 0x30, 0x41, 0x96, + 0x82, 0xa3, 0x69, 0x44, 0x50, 0x5b, 0xc1, 0x23, 0x32, 0x0e, 0xce, 0x27, 0x33, 0xd4, 0x39, 0xfa, + 0xc7, 0x00, 0x7b, 0x33, 0x26, 0xd8, 0x06, 0x73, 0x44, 0x2e, 0x50, 0x4b, 0x89, 0xe9, 0x19, 0x43, + 0x06, 0x06, 0xe8, 0x9c, 0x92, 0x60, 0x32, 0x3b, 0x45, 0x3b, 0x6a, 0x19, 0x9b, 0x4d, 0x69, 0x70, + 0x42, 0x90, 0x89, 0x77, 0xc1, 0x61, 0x84, 0xb1, 0x70, 0x1a, 0x31, 0x64, 0xe1, 0x7d, 0x00, 0xf6, + 0x72, 0x12, 0xb3, 0xe1, 0x29, 0x79, 0x11, 0xa0, 0xb6, 0x8a, 0xcf, 0x19, 0xa1, 0x71, 0x30, 0x7a, + 0x11, 0x46, 0xa8, 0xa3, 0xe2, 0x33, 0x1a, 0x5e, 0x84, 0x13, 0x72, 0x42, 0x18, 0xb2, 0xf1, 0x63, + 0x40, 0x8c, 0x44, 0x2c, 0x9c, 0x85, 0x17, 0x24, 0x0e, 0x86, 0x43, 0xc2, 0x18, 0x72, 0x74, 0xce, + 0x97, 0x93, 0x98, 0xfc, 0x4c, 0x86, 0xc8, 0x6d, 0xa2, 0x33, 0x42, 0xc7, 0x08, 0xf0, 0xa7, 0xf0, + 0x48, 0x45, 0x61, 0x34, 0x23, 0x34, 0x0a, 0x36, 0x76, 0xf7, 0xf8, 0xeb, 0xbb, 0xff, 0xfc, 0xd6, + 0xdd, 0xca, 0x37, 0xde, 0xac, 0x7c, 0xe3, 0xed, 0xca, 0x37, 0xfe, 0x5d, 0xf9, 0xc6, 0x9f, 0xf7, + 0x7e, 0xeb, 0xcd, 0xbd, 0xdf, 0x7a, 0x7b, 0xef, 0xb7, 0x7e, 0x69, 0xeb, 0x97, 0xe6, 0xb2, 0xa3, + 0x1f, 0x8f, 0x6f, 0xff, 0x0f, 0x00, 0x00, 0xff, 0xff, 0xc5, 0x77, 0x0c, 0x15, 0x82, 0x04, 0x00, + 0x00, } func (m *Entry) Marshal() (dAtA []byte, err error) { @@ -473,6 +497,21 @@ func (m *Entry) MarshalToSizedBuffer(dAtA []byte) (int, error) { _ = i var l int _ = l + if m.StackTraceStart != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StackTraceStart)) + i-- + dAtA[i] = 0x68 + } + if m.StructuredStart != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StructuredStart)) + i-- + dAtA[i] = 0x60 + } + if m.StructuredEnd != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StructuredEnd)) + i-- + dAtA[i] = 0x58 + } if m.Channel != 0 { i = encodeVarintLog(dAtA, i, uint64(m.Channel)) i-- @@ -691,6 +730,15 @@ func (m *Entry) Size() (n int) { if m.Channel != 0 { n += 1 + sovLog(uint64(m.Channel)) } + if m.StructuredEnd != 0 { + n += 1 + sovLog(uint64(m.StructuredEnd)) + } + if m.StructuredStart != 0 { + n += 1 + sovLog(uint64(m.StructuredStart)) + } + if m.StackTraceStart != 0 { + n += 1 + sovLog(uint64(m.StackTraceStart)) + } return n } @@ -1007,6 +1055,63 @@ func (m *Entry) Unmarshal(dAtA []byte) error { break } } + case 11: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StructuredEnd", wireType) + } + m.StructuredEnd = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StructuredEnd |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 12: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StructuredStart", wireType) + } + m.StructuredStart = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StructuredStart |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 13: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StackTraceStart", wireType) + } + m.StackTraceStart = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StackTraceStart |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } default: iNdEx = preIndex skippy, err := skipLog(dAtA[iNdEx:]) diff --git a/pkg/util/log/logpb/log.proto b/pkg/util/log/logpb/log.proto index bf3f99ff3d9e..0099e3f21515 100644 --- a/pkg/util/log/logpb/log.proto +++ b/pkg/util/log/logpb/log.proto @@ -226,6 +226,28 @@ message Entry { // Channel is the channel on which the message was sent. Channel channel = 10; + + // StructuredEnd, if non-zero, indicates that the entry + // is structured; it is also the index + // inside the Message field where the JSON payload ends (exclusive). + uint32 structured_end = 11; + + // StructuredStart, when StructuredEnd is non-zero, is the index + // inside the Message field where the JSON payload starts (inclusive). + uint32 structured_start = 12; + + // StackTraceStart is the index inside Message where a detailed + // stack trace starts. If zero, no stack trace is present. Stack + // traces are always separated from the message using a newline + // character. If a stack trace is included, StackTracePosition is + // the index of the character immediately after the newline + // character. + // + // We use an index-in-string field in the protobuf, instead of two + // separate string fields, because previous-version consumers of + // Entry are still expecting the message and the stack trace in the + // same field. + uint32 stack_trace_start = 13; } // A FileDetails holds all of the particulars that can be parsed by the name of diff --git a/pkg/util/log/testdata/crdb_v1 b/pkg/util/log/testdata/crdb_v1 index 5a98967466c1..9969b2d43b38 100644 --- a/pkg/util/log/testdata/crdb_v1 +++ b/pkg/util/log/testdata/crdb_v1 @@ -9,8 +9,8 @@ entries 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} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹info›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +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} +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} entries {"counter": 2, "message": "hello ‹world›"} @@ -19,8 +19,8 @@ entries I000101 00:00:12.300000 456 somefile.go:136 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:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"hello ‹world›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹hello ?world?›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +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} entries @@ -32,8 +32,8 @@ line 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} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"multi-\nline", Tags:"", Counter:0x3, Redactable:true, Channel:0} +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} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"multi-\nline", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} entries @@ -45,9 +45,9 @@ W000101 00:00:12.300000 456 somefile.go:136 2 warning E000101 00:00:12.300000 456 somefile.go:136 3 error F000101 00:00:12.300000 456 somefile.go:136 4 fatal # after parse: -logpb.Entry{Severity:2, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹warning›", Tags:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:3, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹error›", Tags:"", Counter:0x3, Redactable:true, Channel:0} -logpb.Entry{Severity:4, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹fatal›", Tags:"", Counter:0x4, Redactable:true, Channel:0} +logpb.Entry{Severity:2, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹warning›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:3, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹error›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:4, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹fatal›", Tags:"", Counter:0x4, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest regression_56873 @@ -58,8 +58,8 @@ entries I000101 00:00:12.300000 456 somefile.go:136 [sometags] 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›", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹sometags›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +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} subtest end @@ -70,7 +70,7 @@ entries ---- I000101 00:00:12.300000 456 2@somefile.go: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} +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} subtest end @@ -81,17 +81,28 @@ entries ---- 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} +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} subtest end subtest structured_entry entries -{"counter": 2, "message": "Structured entry: {'hello':123}", "redactable": true} +{"counter": 2, "message": "Structured entry: {\"hello\":123}", "redactable": true} +{"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 ⋮ 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 ={"hello":123} +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 ={"hello":123} +stack trace: +foo # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {'hello':123}", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {\"hello\":123}", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x1f, StructuredStart:0x12, StackTraceStart:0x0} +JSON payload in previous entry: map[hello:123] +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:" ={\"hello\":123}", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0xf, StructuredStart:0x2, StackTraceStart:0x0} +JSON payload in previous entry: map[hello:123] +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:" ={\"hello\":123}\nstack trace:\nfoo", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0xf, StructuredStart:0x2, StackTraceStart:0x10} +JSON payload in previous entry: map[hello:123] subtest end