Skip to content

Commit

Permalink
util/log: MVP of customizable 'datetime' field for JSON output
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@knz
knz committed Jun 13, 2023
1 parent d628ec9 commit 56da2cb
Show file tree
Hide file tree
Showing 5 changed files with 81 additions and 11 deletions.
24 changes: 24 additions & 0 deletions docs/generated/logformats.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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. |
Expand Down Expand Up @@ -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`. |



Expand All @@ -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. |
Expand Down Expand Up @@ -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`. |



Expand All @@ -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. |
Expand Down Expand Up @@ -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`. |



Expand All @@ -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. |
Expand Down Expand Up @@ -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`. |



56 changes: 47 additions & 9 deletions pkg/util/log/format_json.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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" }
Expand All @@ -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) }
Expand All @@ -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) }
Expand Down Expand Up @@ -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`" + `. |
`)

Expand All @@ -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"},
Expand Down Expand Up @@ -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('{')
Expand Down Expand Up @@ -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(`,"`)
Expand Down
3 changes: 2 additions & 1 deletion pkg/util/log/format_json_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
2 changes: 1 addition & 1 deletion pkg/util/log/formats.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}()

Expand Down
7 changes: 7 additions & 0 deletions pkg/util/log/testdata/json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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›"}

0 comments on commit 56da2cb

Please sign in to comment.