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

util/log: new config field format-options, custom timezones in log output #104265

Merged
merged 11 commits into from
Jun 14, 2023

Conversation

knz
Copy link
Contributor

@knz knz commented Jun 2, 2023

Fixes #39097.
Fixes #88741.

This PR introduces a framework to define per-format customization options.
See the individual commits for details.

JSON output changes

The following options for the json format are available:

  • datetime-format: introduce a new datetime field
  • datetime-timezone: configure the tz for the new datetime field
  • fluent-tag: see format doc
  • tag-style: see format doc

Example:

file-defaults:
  format: json
  format-options: { datetime-format: rfc3339, datetime-timezone: America/New_York }

Results in entries like this:

{...,"timestamp":"1685719746.454267736","datetime":"2023-06-02T11:29:06.454267736-04:00",...}

i.e. the timestamp field is unchanged for backward-compatibility; a new datetime field is introduced alongside it.

Text output format changes

Format options are now also supported for crdb-v1 and crdb-v2. In particular, the timezone option changes the time zone used to print out the timestamp columns.

For example:

file-defaults:
   format: crdb-v2
   format-options: {timezone: america/new_york}

Example logging output:

I230606 12:43:01.553407-040000 1 1@cli/start.go:575 ⋮ [n?] 4  soft memory limit of Go runtime is set to 35 GiB
                       ^^^^^^^ indicates GMT-4 was used.

See the individual commits and the generated documentation for details.

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@knz knz force-pushed the 20230602-log-options branch from 768bd68 to 3000a98 Compare June 6, 2023 15:56
@knz knz requested a review from abarganier June 6, 2023 18:12
@knz knz changed the title util/log: new config field format-options util/log: new config field format-options, custom timezones in log output Jun 6, 2023
@knz knz marked this pull request as ready for review June 6, 2023 18:23
@knz knz requested a review from a team June 6, 2023 18:23
Copy link
Contributor

@Santamaura Santamaura left a comment

Choose a reason for hiding this comment

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

Reviewed 3 of 9 files at r1, 1 of 3 files at r2, 3 of 5 files at r6, 1 of 7 files at r7, 3 of 3 files at r8, 5 of 10 files at r9, all commit messages.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @abarganier and @knz)


pkg/util/log/flags.go line 262 at r9 (raw file):

		case *formatCrdbV2:
			t.colorProfile = nil
		}

When we are in this if condition, why do we need to do the switch statement if the result would be the same?


pkg/util/log/format_crdb_v2.go line 749 at r9 (raw file):

func (f entryDecoderV2Fragment) getTimestamp() (unixNano int64) {
	ts := string(f[v2DateTimeIdx])
	timeFormat := MessageTimeFormat

the way timeFormat is set is also done identically in format_crdb_v1.go should it be in some util function to avoid code duplication?

knz added 11 commits June 13, 2023 11:06
This commit introduces a framework to define per-format customization options.

Release note: None
Also apply format config options if any.

Release note: None
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.
Release note (cli change): The `json` log output format now recognizes
the extra format option `datetime-timezone` which selects which timezone
to use when formatting the `datetime` field.
`datetime-timezone` must be combined with `datetime-format` because
the default value for the latter option is `none`, i.e. `datetime`
is not produced by default.

For example:

```yaml
sinks:
  fluent-groups:
     custom-json:
        format: json
        format-options: {datetime-format: rfc3339, datetime-timezone: America/New_York}
```
I found this buglet during testing. It's not possible to trigger it in
prod code.

Release note: None
Release note (cli change): The `json` log format now recognizes
the format options `tag-style` and `fluent-tag`. The
existing formats `json-compact`, `json-fluent`, `json-fluent-compact`
have been redefined to become aliases for `json` with different
defaults for the two new options.
Release note (cli change): The `crdb-v1` log format now recognizes the
format options `show-counter` and `colors`. The existing formats
`crdb-v1-tty`, `crdb-v1-count`, `crdb-v1-tty-count` have been
redefined to become aliases for `crdb-v1` with different defaults for
the two new options.

Release note (cli change): The `crdb-v2` log format now recognizes the
format option `colors`. The existing formats `crdb-v2-tty` has been
redefined to become aliases for `crdb-v2` with a different default for
the new option.
Release note (cli change): The log output formats `crdb-v1` and
`crdb-v2` now support the format option `timezone`. When specified,
the corresponding time zone is used to produce the timestamp column.

For example:
```yaml
file-defaults:
   format: crdb-v2
   format-options: {timezone: america/new_york}
```

Example logging output:
```
I230606 12:43:01.553407-040000 1 1@cli/start.go:575 ⋮ [n?] 4  soft memory limit of Go runtime is set to 35 GiB
                       ^^^^^^^ indicates GMT-4 was used.
```

The timezone offset is also always included in the format if it is not
zero (e.g. for non-UTC time zones). This is necessary to ensure that
the times can be read back precisely.

Release note (cli change): The command `cockroach debug merge-log` was
adapted to understand time zones in input files read with format
`crdb-v1` or `crdb-v2`.

Release note (backward-incompatible change): When a deployment is
configured to use a time zone (new feature) for log file output using
formats `crdb-v1` or `crdb-v2`, it becomes impossible to process the
new output log files using the `cockroach debug merge-log` command
from a previous version. The newest `cockroach debug merge-log` code
must be used instead.
@knz knz force-pushed the 20230602-log-options branch from 38d3c33 to 5cfcccb Compare June 13, 2023 10:27
Copy link
Contributor Author

@knz knz left a comment

Choose a reason for hiding this comment

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

Thanks for the initial review - RFAL.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @abarganier and @Santamaura)


pkg/util/log/flags.go line 262 at r9 (raw file):

Previously, Santamaura (Alex Santamaura) wrote…

When we are in this if condition, why do we need to do the switch statement if the result would be the same?

Because there are other formats than crdb-v1 and crdb-v2. For these other formats, we can't reset colorProfile to nil (the attribute doesn't even exist).

(Note: this is a type switch, not a value switch.)


pkg/util/log/format_crdb_v2.go line 749 at r9 (raw file):

Previously, Santamaura (Alex Santamaura) wrote…

the way timeFormat is set is also done identically in format_crdb_v1.go should it be in some util function to avoid code duplication?

Sure, why not. Done.

@knz knz requested a review from Santamaura June 13, 2023 10:28
Copy link
Contributor

@Santamaura Santamaura left a comment

Choose a reason for hiding this comment

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

:lgtm:

Reviewed 1 of 7 files at r7, 5 of 10 files at r9, 2 of 2 files at r11, all commit messages.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @abarganier)

Copy link
Contributor

@abarganier abarganier left a comment

Choose a reason for hiding this comment

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

:lgtm_strong:

This is really excellent work. I feel like it gets rid of a solid amount of tech debt on top of delivering an important feature!

Reducing the number of log format aliases in favor of format options, and nuking all that code (e.g. formatJsonCompact) was an especially nice surprise.

The config for the formatting options is great, it feels simple & extensible. I'm sure that will come in handy in the future.

Again, nice work on this!

Reviewable status: :shipit: complete! 2 of 0 LGTMs obtained (waiting on @knz)


-- commits line 24 at r3:
Good call on the escape hatch. This is a nice feature!

@knz
Copy link
Contributor Author

knz commented Jun 14, 2023

TFYRs!

bors r=Santamaura,abargainier

@craig
Copy link
Contributor

craig bot commented Jun 14, 2023

Build succeeded:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
4 participants