From 56da2cb517f210685056294904a34c9ae5756e79 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 2 Jun 2023 11:49:51 +0200 Subject: [PATCH] util/log: MVP of customizable 'datetime' field for JSON output As of this commit, only the "full JSON" format (with format name `json`) recognizes the new option. In addition to the formats documented below, an operator can use `fmt:XXXX` to customize the output exactly using the Go time formatting string `XXXX`. This is introduced as an "escape hatch" if the pre-defined formats are found insufficient. Release note (cli change): The configuration for log output sinks now accepts a new `format-options` field. This can be used to customize the output of a given format. Each format accepts different options. One available option for the `json` output format is `datetime-format`. For example: ```yaml sinks: fluent-groups: custom-json: format: json format-options: {datetime-format: rfc3339} ``` This introduces a (new) field `datetime` in each output JSON event, with the format specified by the option. As of this writing, the following values are documented: - `none`: disable the creation of the `datetime` field. This is the default value. - `iso8601` / `rfc3339`: format the time stamp like "2006-01-02T15:04:05.999999999Z". - `rfc1123`: format the time stamp like "Mon, 02 Jan 2006 15:04:05 +0000". **Note that enabling the `datetime` field introduces CPU overhead and is nearly always unnecessary.** When using output to a log collector (e.g. via Fluent, Datadog etc) the log collector can be configured to transform the timestamp provided by CockroachDB, without requiring participation from CockroachDB itself. When inspecting a log file containing JSON output produced by CockroachDB, the command `cockroach debug merge-log` can be used to consume the JSON data and reformat it using the `crdb-v2` format which also includes the date/time using the RFC3339 format. --- docs/generated/logformats.md | 24 ++++++++++++++ pkg/util/log/format_json.go | 56 +++++++++++++++++++++++++++----- pkg/util/log/format_json_test.go | 3 +- pkg/util/log/formats.go | 2 +- pkg/util/log/testdata/json | 7 ++++ 5 files changed, 81 insertions(+), 11 deletions(-) diff --git a/docs/generated/logformats.md b/docs/generated/logformats.md index 8d94fd08e1c8..3984707aaf94 100644 --- a/docs/generated/logformats.md +++ b/docs/generated/logformats.md @@ -327,6 +327,7 @@ Each entry contains at least the following fields: | Field | Description | |-------|-------------| +| `datetime` | The pretty-printed date/time of the event timestamp, if enabled via options. | | `file` | The name of the source file where the event was emitted. | | `goroutine` | The identifier of the goroutine where the event was emitted. | | `line` | The line number where the event was emitted in the source. | @@ -369,6 +370,11 @@ contain delimiters (‹...›) around fields that are considered sensitive. These markers are automatically recognized by [`cockroach debug zip`](cockroach-debug-zip.html) and [`cockroach debug merge-logs`](cockroach-debug-merge-logs.html) when log redaction is requested. +Additional options recognized via `format-options`: + +| Option | Description | +|--------|-------------| +| `datetime-format` | The format to use for the `datetime` field. The value can be one of `none`, `iso8601`/`rfc3339` (synonyms), or `rfc1123`. Default is `none`. | @@ -385,6 +391,7 @@ Each entry contains at least the following fields: | Field | Description | |-------|-------------| +| `d` | The pretty-printed date/time of the event timestamp, if enabled via options. | | `f` | The name of the source file where the event was emitted. | | `g` | The identifier of the goroutine where the event was emitted. | | `l` | The line number where the event was emitted in the source. | @@ -427,6 +434,11 @@ contain delimiters (‹...›) around fields that are considered sensitive. These markers are automatically recognized by [`cockroach debug zip`](cockroach-debug-zip.html) and [`cockroach debug merge-logs`](cockroach-debug-merge-logs.html) when log redaction is requested. +Additional options recognized via `format-options`: + +| Option | Description | +|--------|-------------| +| `datetime-format` | The format to use for the `datetime` field. The value can be one of `none`, `iso8601`/`rfc3339` (synonyms), or `rfc1123`. Default is `none`. | @@ -444,6 +456,7 @@ Each entry contains at least the following fields: | Field | Description | |-------|-------------| | `tag` | A Fluent tag for the event, formed by the process name and the logging channel. | +| `datetime` | The pretty-printed date/time of the event timestamp, if enabled via options. | | `file` | The name of the source file where the event was emitted. | | `goroutine` | The identifier of the goroutine where the event was emitted. | | `line` | The line number where the event was emitted in the source. | @@ -486,6 +499,11 @@ contain delimiters (‹...›) around fields that are considered sensitive. These markers are automatically recognized by [`cockroach debug zip`](cockroach-debug-zip.html) and [`cockroach debug merge-logs`](cockroach-debug-merge-logs.html) when log redaction is requested. +Additional options recognized via `format-options`: + +| Option | Description | +|--------|-------------| +| `datetime-format` | The format to use for the `datetime` field. The value can be one of `none`, `iso8601`/`rfc3339` (synonyms), or `rfc1123`. Default is `none`. | @@ -503,6 +521,7 @@ Each entry contains at least the following fields: | Field | Description | |-------|-------------| | `tag` | A Fluent tag for the event, formed by the process name and the logging channel. | +| `d` | The pretty-printed date/time of the event timestamp, if enabled via options. | | `f` | The name of the source file where the event was emitted. | | `g` | The identifier of the goroutine where the event was emitted. | | `l` | The line number where the event was emitted in the source. | @@ -545,6 +564,11 @@ contain delimiters (‹...›) around fields that are considered sensitive. These markers are automatically recognized by [`cockroach debug zip`](cockroach-debug-zip.html) and [`cockroach debug merge-logs`](cockroach-debug-merge-logs.html) when log redaction is requested. +Additional options recognized via `format-options`: + +| Option | Description | +|--------|-------------| +| `datetime-format` | The format to use for the `datetime` field. The value can be one of `none`, `iso8601`/`rfc3339` (synonyms), or `rfc1123`. Default is `none`. | diff --git a/pkg/util/log/format_json.go b/pkg/util/log/format_json.go index b32c593f1ddc..4f30829261ca 100644 --- a/pkg/util/log/format_json.go +++ b/pkg/util/log/format_json.go @@ -17,10 +17,12 @@ import ( "sort" "strconv" "strings" + "time" "github.com/cockroachdb/cockroach/pkg/base/serverident" "github.com/cockroachdb/cockroach/pkg/util/jsonbytes" "github.com/cockroachdb/cockroach/pkg/util/log/logpb" + "github.com/cockroachdb/cockroach/pkg/util/timeutil" "github.com/cockroachdb/errors" "github.com/cockroachdb/logtags" "github.com/cockroachdb/redact" @@ -37,7 +39,7 @@ func (formatFluentJSONCompact) formatterName() string { return "json-fluent-comp func (formatFluentJSONCompact) doc() string { return formatJSONDoc(true /* fluent */, tagCompact) } func (f formatFluentJSONCompact) formatEntry(entry logEntry) *buffer { - return formatJSON(entry, true /* fluent */, tagCompact) + return formatJSON(entry, true /* fluent */, tagCompact, "") } func (formatFluentJSONCompact) contentType() string { return "application/json" } @@ -51,7 +53,7 @@ func (formatFluentJSONFull) setOption(k string, _ string) error { func (formatFluentJSONFull) formatterName() string { return "json-fluent" } func (f formatFluentJSONFull) formatEntry(entry logEntry) *buffer { - return formatJSON(entry, true /* fluent */, tagVerbose) + return formatJSON(entry, true /* fluent */, tagVerbose, "") } func (formatFluentJSONFull) doc() string { return formatJSONDoc(true /* fluent */, tagVerbose) } @@ -67,23 +69,44 @@ func (formatJSONCompact) setOption(k string, _ string) error { func (formatJSONCompact) formatterName() string { return "json-compact" } func (f formatJSONCompact) formatEntry(entry logEntry) *buffer { - return formatJSON(entry, false /* fluent */, tagCompact) + return formatJSON(entry, false /* fluent */, tagCompact, "") } func (formatJSONCompact) doc() string { return formatJSONDoc(false /* fluent */, tagCompact) } func (formatJSONCompact) contentType() string { return "application/json" } -type formatJSONFull struct{} +type formatJSONFull struct { + datetimeFormat string +} -func (formatJSONFull) setOption(k string, _ string) error { - return errors.Newf("unknown option: %q", redact.Safe(k)) +func (f *formatJSONFull) setOption(k string, v string) error { + switch k { + case "datetime-format": + switch v { + case "none": + f.datetimeFormat = "" + case "iso8601", "rfc3339": + f.datetimeFormat = time.RFC3339Nano + case "rfc1123": + f.datetimeFormat = time.RFC1123Z + default: + if strings.HasPrefix(v, "fmt:") { + f.datetimeFormat = v[4:] + } else { + return errors.Newf("unknown datetime-format value format: %q", v) + } + } + return nil + default: + return errors.Newf("unknown option: %q", redact.Safe(k)) + } } func (formatJSONFull) formatterName() string { return "json" } func (f formatJSONFull) formatEntry(entry logEntry) *buffer { - return formatJSON(entry, false /* fluent */, tagVerbose) + return formatJSON(entry, false /* fluent */, tagVerbose, f.datetimeFormat) } func (formatJSONFull) doc() string { return formatJSONDoc(false /* fluent */, tagVerbose) } @@ -167,6 +190,11 @@ fields that are considered sensitive. These markers are automatically recognized by ` + "[`cockroach debug zip`](cockroach-debug-zip.html)" + ` and ` + "[`cockroach debug merge-logs`](cockroach-debug-merge-logs.html)" + ` when log redaction is requested. +Additional options recognized via ` + "`format-options`" + `: + +| Option | Description | +|--------|-------------| +| ` + "`datetime-format`" + ` | The format to use for the ` + "`datetime`" + ` field. The value can be one of ` + "`none`" + `, ` + "`iso8601`/`rfc3339` (synonyms)" + `, or ` + "`rfc1123`" + `. Default is ` + "`none`" + `. | `) @@ -184,6 +212,8 @@ var jsonTags = map[byte]struct { "The name of the logging channel where the event was sent.", false}, 't': {[2]string{"t", "timestamp"}, "The timestamp at which the event was emitted on the logging channel.", true}, + 'd': {[2]string{"d", "datetime"}, + "The pretty-printed date/time of the event timestamp, if enabled via options.", true}, 's': {[2]string{"s", "severity_numeric"}, "The numeric value of the severity of the event.", false}, 'S': {[2]string{"sev", "severity"}, @@ -229,7 +259,7 @@ var channelNamesLowercase = func() map[Channel]string { return lnames }() -func formatJSON(entry logEntry, forFluent bool, tags tagChoice) *buffer { +func formatJSON(entry logEntry, forFluent bool, tags tagChoice, datetimeFormat string) *buffer { jtags := jsonTags buf := getBuffer() buf.WriteByte('{') @@ -295,7 +325,15 @@ func formatJSON(entry logEntry, forFluent bool, tags tagChoice) *buffer { n += buf.nDigits(9, n, int(entry.ts%1000000000), '0') buf.Write(buf.tmp[:n]) buf.WriteByte('"') - + // Extra "datetime" field if requested. + if len(datetimeFormat) > 0 { + t := timeutil.FromUnixNanos(entry.ts) + buf.WriteString(`,"`) + buf.WriteString(jtags['d'].tags[tags]) + buf.WriteString(`":"`) + buf.WriteString(t.Format(datetimeFormat)) + buf.WriteByte('"') + } // Server identifiers. if entry.ClusterID != "" { buf.WriteString(`,"`) diff --git a/pkg/util/log/format_json_test.go b/pkg/util/log/format_json_test.go index 6d1c70bdc870..9f13e2246032 100644 --- a/pkg/util/log/format_json_test.go +++ b/pkg/util/log/format_json_test.go @@ -73,7 +73,8 @@ func TestJSONFormats(t *testing.T) { formatFluentJSONCompact{}, formatFluentJSONFull{}, formatJSONCompact{}, - formatJSONFull{}, + &formatJSONFull{}, + &formatJSONFull{datetimeFormat: "2006-01-02 xx 15:04:05"}, } // We only use the datadriven framework for the ability to rewrite the output. diff --git a/pkg/util/log/formats.go b/pkg/util/log/formats.go index a8125cf5313c..af436c8087ad 100644 --- a/pkg/util/log/formats.go +++ b/pkg/util/log/formats.go @@ -53,7 +53,7 @@ var formatters = func() map[string]func() logFormatter { r(func() logFormatter { return formatFluentJSONCompact{} }) r(func() logFormatter { return formatFluentJSONFull{} }) r(func() logFormatter { return formatJSONCompact{} }) - r(func() logFormatter { return formatJSONFull{} }) + r(func() logFormatter { return &formatJSONFull{} }) return m }() diff --git a/pkg/util/log/testdata/json b/pkg/util/log/testdata/json index d70971ceb711..6167b5056912 100644 --- a/pkg/util/log/testdata/json +++ b/pkg/util/log/testdata/json @@ -5,33 +5,40 @@ json-fluent-compact: {"tag":"logtest.unknown","header":1,"t":"1136214245.6543210 json-fluent: {"tag":"logtest.unknown","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-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: {"header":1,"timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","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","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: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","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":""} json-compact: {"c":0,"t":"1136214245.654321000","x":"abc","N":123,"T":1,"s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""} json: {"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":""} + json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","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":""} # json-fluent-compact: {"tag":"logtest.dev","c":0,"t":"1136214245.654321000","T":456,"q":123,"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":456,"instance_id":123,"severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""} json-compact: {"c":0,"t":"1136214245.654321000","T":456,"q":123,"s":0,"g":11,"f":"","l":123,"n":0,"r":0,"message":""} json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","tenant_id":456,"instance_id":123,"severity_numeric":0,"severity":"UNKNOWN","goroutine":11,"file":"","line":123,"entry_counter":0,"redactable":0,"message":""} + json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","tenant_id":456,"instance_id":123,"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","T":1,"v":"v999.0.0","s":1,"sev":"I","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"event":{"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}} json-fluent: {"tag":"logtest.dev","channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":1,"severity":"INFO","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"event":{"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}} json-compact: {"c":0,"t":"1136214245.654321000","T":1,"v":"v999.0.0","s":1,"sev":"I","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"event":{"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}} json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":1,"severity":"INFO","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"event":{"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}} + json: {"channel_numeric":0,"channel":"DEV","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","tenant_id":1,"version":"v999.0.0","severity_numeric":1,"severity":"INFO","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"event":{"Timestamp":123,"EventType":"rename_database","Event":"‹rename from `hello` to `world`›"}} # json-fluent-compact: {"tag":"logtest.ops","c":1,"t":"1136214245.654321000","T":1,"v":"v999.0.0","s":2,"sev":"W","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":0,"tags":{"noval":"","s":"1","long":"2"},"message":"hello world"} json-fluent: {"tag":"logtest.ops","channel_numeric":1,"channel":"OPS","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":2,"severity":"WARNING","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":0,"tags":{"noval":"","s":"1","long":"2"},"message":"hello world"} json-compact: {"c":1,"t":"1136214245.654321000","T":1,"v":"v999.0.0","s":2,"sev":"W","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":0,"tags":{"noval":"","s":"1","long":"2"},"message":"hello world"} json: {"channel_numeric":1,"channel":"OPS","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":2,"severity":"WARNING","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":0,"tags":{"noval":"","s":"1","long":"2"},"message":"hello world"} + json: {"channel_numeric":1,"channel":"OPS","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","tenant_id":1,"version":"v999.0.0","severity_numeric":2,"severity":"WARNING","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":0,"tags":{"noval":"","s":"1","long":"2"},"message":"hello world"} # json-fluent-compact: {"tag":"logtest.health","c":2,"t":"1136214245.654321000","T":1,"v":"v999.0.0","s":3,"sev":"E","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"} json-fluent: {"tag":"logtest.health","channel_numeric":2,"channel":"HEALTH","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":3,"severity":"ERROR","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"} json-compact: {"c":2,"t":"1136214245.654321000","T":1,"v":"v999.0.0","s":3,"sev":"E","g":11,"f":"util/log/format_json_test.go","l":123,"n":0,"r":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"} json: {"channel_numeric":2,"channel":"HEALTH","timestamp":"1136214245.654321000","tenant_id":1,"version":"v999.0.0","severity_numeric":3,"severity":"ERROR","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"} + json: {"channel_numeric":2,"channel":"HEALTH","timestamp":"1136214245.654321000","datetime":"2006-01-02 xx 15:04:05","tenant_id":1,"version":"v999.0.0","severity_numeric":3,"severity":"ERROR","goroutine":11,"file":"util/log/format_json_test.go","line":123,"entry_counter":0,"redactable":1,"tags":{"noval":"","s":"‹1›","long":"‹2›"},"message":"hello ‹world›"}