log: add support for decoding JSON logs #79356

dhartunian · 2022-04-04T18:02:26Z

Previously, our logging code did not have the ability to recognize and
decode JSON formatted log files. This led to problems when retrieving
logs via API endpoints and when running commands such as merge-logs to
process logs from debug.zip files.

This commit adds support for the json, json-compact, json-fluent, and
json-fluent-compact formats via one generalized JSON decoder.

Resolves #66684

Release note (ops change, cli change): debug zip and merge-logs commands
will now work with JSON formatted logs.

Jira issue: CRDB-14742

cockroach-teamcity · 2022-04-04T18:02:36Z

This change is

abarganier

Thanks for handling this, David! I have a few comments, but admittedly I learned about a lot of what's going on here "on the fly", so I'd feel better getting another review from someone more familiar with logging than I am.

For anyone else in my situation reviewing, the docs were helpful here.

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @cameronnunez and @dhartunian)

pkg/util/log/format_json.go, line 423 at r1 (raw file):

}

func getFirstMatchString(obj map[string]interface{}, fields [2]string) (string, bool) {

nit: can we add a comment to this and getFirstMatchInt64 explaining a bit about what these functions do?

pkg/util/log/format_json.go, line 498 at r1 (raw file):

		if event, ok := ev.(map[string]interface{}); ok {
			if len(event) > 0 {
				// TODO(davidh): HANDLE ERROR!!!!

Is there a case where an empty event is acceptable? If not, should this function be "best effort" and continue along? Or should we stop and return an error?

Code quote:

// TODO(davidh): HANDLE ERROR!!!!

pkg/util/log/format_json.go, line 524 at r1 (raw file):

			}
			// TODO(davidh): does redaction need to be handled here???
			// TODO(davidh): in the test cases, tag values are not getting redacted...

The way that tags are handled in the Decoder for format_crdb_v2 make it seem like we should be handling redaction here, no?

Code quote:

			// TODO(davidh): does redaction need to be handled here???
			// TODO(davidh): in the test cases, tag values are not getting redacted...

pkg/util/log/format_json.go, line 553 at r1 (raw file):

}

func fromFluent(timestamp string) (int64, error) {

nit: can we comment this with an example of the expected format, and note the output format (nanoseconds)?

Code quote:

func fromFluent(timestamp string) (int64, error) {

knz · 2022-04-07T20:08:24Z

I suggest you queue this work behind #78177 and/or work with @THardy98 to specify clearly how a long json entry would be split across multiple lines. The parser must be able to aggregate a split entry and re-construct the full thing.

knz · 2022-04-07T20:13:16Z

btw the crdb-v2 parser that @cameronnunez wrote ahs multi-line aggregation already, so perhaps it's possible to reuse the same model.

cameronnunez

Thanks for tackling this!

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @abarganier, @cameronnunez, and @dhartunian)

pkg/util/log/format_json.go, line 499 at r1 (raw file):

			if len(event) > 0 {
				// TODO(davidh): HANDLE ERROR!!!!
				by, _ := json.Marshal(event)

Noticing that the event gets sorted here, which isn't really a problem but will be later on when wanting to convert between log formats in a predictable way. See other comment related to sorting.

pkg/util/log/format_json.go, line 523 at r1 (raw file):

				}
			}
			// TODO(davidh): does redaction need to be handled here???

The tags need to be marked as sensitive when no redaction marker is present. Think the following should do the trick:

  r := redactablePackage{
    msg:        []byte(s.String()),
    redactable: entry.Redactable,
  }
  r = d.sensitiveEditor(r)
  entry.Tags = string(r.msg)

pkg/util/log/format_json.go, line 528 at r1 (raw file):

			t.FormatToString(s)
			tagStrings := strings.Split(s.String(), ",")
			sort.Strings(tagStrings)

What's the motivation behind sorting the tags? Seems like unsorted gives a more expected output. Also think unsorted is better future-proofing since we'll want to enable the ability to convert between log formats eventually, which would mean consistent "round-tripping" would be necessary (i.e. converting to a crdb log format, then back to json and seeing the same initial entry).

pkg/util/log/testdata/parse_json, line 70 at r1 (raw file):

{"channel_numeric":1,"channel":"OPS","timestamp":"1136214245.654321000","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"}
----
logpb.Entry{Severity:2, Time:1136214245654321000, Goroutine:11, File:"util/log/format_json_test.go", Line:123, Message:"‹hello world›", Tags:"long=2,noval,s1", Counter:0x0, Redactable:true, Channel:1, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0}

Example where the tags should be enclosed with redaction markers, just like the message. If the entry is not redactable, the sensitivity of the entry is unknown, so the message and the tags are assumed to be entirely sensitive.

pkg/util/log/format_json_test.go, line 99 at r1 (raw file):

}

func TestCrdbJsonDecode(t *testing.T) {

nit: Maybe rename to TestJSONDecode? The other tests have Crdb in the name because they are concerning the crdb formats.

dhartunian

I suggest you queue this work behind #78177 and/or work with @THardy98 to specify clearly how a long json entry would be split across multiple lines. The parser must be able to aggregate a split entry and re-construct the full thing.

@knz I don't think I will wait for that PR. Re-constructing multiline logs can be a separate feature that we implement for merge-logs.

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

pkg/util/log/format_json.go, line 423 at r1 (raw file):

Previously, abarganier (Alex Barganier) wrote…

nit: can we add a comment to this and getFirstMatchInt64 explaining a bit about what these functions do?

Eliminated this function.

pkg/util/log/format_json.go, line 498 at r1 (raw file):

Previously, abarganier (Alex Barganier) wrote…

Is there a case where an empty event is acceptable? If not, should this function be "best effort" and continue along? Or should we stop and return an error?

Refactored with empty error handled more naturally.

pkg/util/log/format_json.go, line 499 at r1 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

Noticing that the event gets sorted here, which isn't really a problem but will be later on when wanting to convert between log formats in a predictable way. See other comment related to sorting.

Added a note below that this seems to be for facilitating tests...in which case the round-trip conversion test may need to enforce sorting anyway.

pkg/util/log/format_json.go, line 523 at r1 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

The tags need to be marked as sensitive when no redaction marker is present. Think the following should do the trick:
  r := redactablePackage{
    msg:        []byte(s.String()),
    redactable: entry.Redactable,
  }
  r = d.sensitiveEditor(r)
  entry.Tags = string(r.msg)

👍 thanks! Done.

pkg/util/log/format_json.go, line 524 at r1 (raw file):

Previously, abarganier (Alex Barganier) wrote…

The way that tags are handled in the Decoder for format_crdb_v2 make it seem like we should be handling redaction here, no?

Yep, done.

pkg/util/log/format_json.go, line 528 at r1 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

What's the motivation behind sorting the tags? Seems like unsorted gives a more expected output. Also think unsorted is better future-proofing since we'll want to enable the ability to convert between log formats eventually, which would mean consistent "round-tripping" would be necessary (i.e. converting to a crdb log format, then back to json and seeing the same initial entry).

Great question, I think I copied this from elsewhere and my guess is that this makes testing straightforward because the fields appear in a predictable order and you can just string match on the expected stringified object without doing field-by-field comparison.

pkg/util/log/format_json.go, line 553 at r1 (raw file):

Previously, abarganier (Alex Barganier) wrote…

nit: can we comment this with an example of the expected format, and note the output format (nanoseconds)?

Done.

pkg/util/log/testdata/parse_json, line 70 at r1 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

Example where the tags should be enclosed with redaction markers, just like the message. If the entry is not redactable, the sensitivity of the entry is unknown, so the message and the tags are assumed to be entirely sensitive.

Done. Thanks for pointing out where this is necessary.

pkg/util/log/format_json_test.go, line 99 at r1 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

nit: Maybe rename to TestJSONDecode? The other tests have Crdb in the name because they are concerning the crdb formats.

Done.

knz · 2022-04-23T09:42:48Z

Re-constructing multiline logs can be a separate feature that we implement for merge-logs.

How so? The GetLogs HTTP API has a contract that it delivers fully formed log entries. By not merging the entries we're changing the definition of the API.

I'm OK with this PR going first, but then @THardy98's PR will also need to contain the merging code.

dhartunian · 2022-04-25T14:46:29Z

Re-constructing multiline logs can be a separate feature that we implement for merge-logs.

How so? The GetLogs HTTP API has a contract that it delivers fully formed log entries. By not merging the entries we're changing the definition of the API.

I'm OK with this PR going first, but then @THardy98's PR will also need to contain the merging code.

@knz I'm confused about the multi-line approach: are the split lines fully-formed log entries or not? If we go through so much trouble to maintain that split lines are indepenent, fully-formed entries, then why must we also insist that tooling merge them back together? I'd rather the split lines feature be "simple" in that case and not maintain all metadata for every split line.

knz · 2022-04-25T14:57:27Z

hm i got my wires crossed. I thought the HTTP API was merging the entries alredy, but that was wrong. apparently only merge-logs does the merging (or any tool downstream). It makes sense - it ensures that no single entry hogs up a http response payload.

So you can ignore my previous comment.

dhartunian · 2022-05-03T15:58:44Z

friendly ping @abarganier @cameronnunez

abarganier

Ah apologies for the delay - . The splitting of Decode into Decode and Populate made this much easier to follow, nice work!

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @abarganier, @cameronnunez, and @dhartunian)

pkg/util/log/format_json.go line 423 at r1 (raw file):

Previously, dhartunian (David Hartunian) wrote…

Eliminated this function.

Ack.

pkg/util/log/format_json.go line 498 at r1 (raw file):

Previously, dhartunian (David Hartunian) wrote…

Refactored with empty error handled more naturally.

I like the new structure of this - much easier to follow. Well done!

pkg/util/log/format_json.go line 436 at r3 (raw file):

	jsonCommon

	//Channel         Channel  `json:"channel,omitempty"`

nit: do we want to keep these commented-out lines here and in JsonCompactEntry?

Code quote:

//Channel         Channel  `json:"channel,omitempty"`

cameronnunez

Reviewable status: complete! 2 of 0 LGTMs obtained (waiting on @abarganier, @cameronnunez, and @dhartunian)

a discussion (no related file):
good work!

Previously, our logging code did not have the ability to recognize and decode JSON formatted log files. This led to problems when retrieving logs via API endpoints and when running commands such as `merge-logs` to process logs from debug.zip files. This commit adds support for the json, json-compact, json-fluent, and json-fluent-compact formats via one generalized JSON decoder. Resolves cockroachdb#66684 Release note (ops change, cli change): debug zip and merge-logs commands will now work with JSON formatted logs.

dhartunian · 2022-05-17T14:07:16Z

...merge_logs_crdb-v1/missing_format/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log

@@ -2,4 +2,4 @@
 {"header":1,"timestamp":"1631568932.530923000","goroutine":1,"file":"util/log/file_sync_buffer.go","line":238,"redactable":1,"tags":{"config":""},"message":"running on machine: "}
 {"header":1,"timestamp":"1631568932.530929000","goroutine":1,"file":"util/log/file_sync_buffer.go","line":238,"redactable":1,"tags":{"config":""},"message":"binary: CockroachDB CCL v21.2.0-alpha.00000000-4019-g6d1becda18-dirty (x86_64-apple-darwin20.6.0, built , go1.16.6)"}
 {"header":1,"timestamp":"1631568932.530934000","goroutine":1,"file":"util/log/file_sync_buffer.go","line":238,"redactable":1,"tags":{"config":""},"message":"arguments: []"}
-{"header":1,"timestamp":"1631568932.530945000","goroutine":1,"file":"util/log/file_sync_buffer.go","line":238,"redactable":1,"tags":{"config":""},"message":"log format (utf8=✓): json"}
+{"header":1,"timestamp":"1631568932.530945000","goroutine":1,"file":"util/log/file_sync_buffer.go","line":238,"redactable":1,"tags":{"config":""},"message":"log format (utf8=✓): json-unsupported"}


@cameronnunez just want to check that I'm editing this test correctly. seems we support all our formats now so need to set something unknown to trigger the error.

Yes! This works.

dhartunian · 2022-05-18T16:23:31Z

TFTRs!

bors r=cameronnunez,abarganier

craig · 2022-05-18T17:54:14Z

Build failed (retrying...):

GitHub CI (Cockroach)

craig · 2022-05-18T19:45:28Z

Build succeeded:

GitHub CI (Cockroach)

blathers-crl · 2022-05-18T19:45:46Z

Encountered an error creating backports. Some common things that can go wrong:

The backport branch might have already existed.
There was a merge conflict.
The backport branch contained merge commits.

You might need to create your backport manually using the backport tool.

error creating merge commit from fa7facf to blathers/backport-release-21.2-79356: POST https://api.github.com/repos/cockroachdb/cockroach/merges: 409 Merge conflict []

you may need to manually resolve merge conflicts with the backport tool.

Backport to branch 21.2.x failed. See errors above.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

dhartunian requested review from cameronnunez and a team April 4, 2022 18:02

dhartunian requested a review from a team as a code owner April 4, 2022 18:02

abarganier reviewed Apr 7, 2022

View reviewed changes

cameronnunez reviewed Apr 12, 2022

View reviewed changes

dhartunian force-pushed the add-json-support-to-log-decoder branch from 5c43681 to 99887a5 Compare April 22, 2022 22:03

dhartunian requested review from abarganier and cameronnunez April 22, 2022 22:04

dhartunian commented Apr 22, 2022

View reviewed changes

dhartunian force-pushed the add-json-support-to-log-decoder branch from 99887a5 to 952e390 Compare April 23, 2022 13:39

abarganier approved these changes May 3, 2022

View reviewed changes

cameronnunez approved these changes May 5, 2022

View reviewed changes

dhartunian added backport-21.2.x labels May 6, 2022

dhartunian force-pushed the add-json-support-to-log-decoder branch 2 times, most recently from e68f527 to 04e3bcf Compare May 16, 2022 19:26

dhartunian force-pushed the add-json-support-to-log-decoder branch from 04e3bcf to fa7facf Compare May 17, 2022 03:19

dhartunian requested a review from a team as a code owner May 17, 2022 03:19

dhartunian commented May 17, 2022

View reviewed changes

craig bot merged commit 4b65252 into cockroachdb:master May 18, 2022

blathers-crl bot mentioned this pull request May 18, 2022

release-22.1: log: add support for decoding JSON logs #81469

Merged

cockroach-teamcity mentioned this pull request May 18, 2022

log: add support for decoding JSON logs cockroachdb/docs#13884

Open

dhartunian removed the backport-22.1.x label May 19, 2022

dhartunian deleted the add-json-support-to-log-decoder branch May 19, 2022 17:25

dhartunian mentioned this pull request Jun 21, 2022

release-21.2: log: add support for decoding JSON logs #83147

Merged

dhartunian mentioned this pull request Jul 2, 2022

release-21.2: cli,log: allow use of debug merge-logs on older logs #83748

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log: add support for decoding JSON logs #79356

log: add support for decoding JSON logs #79356

dhartunian commented Apr 4, 2022 •

edited by cockroach-jira-scripts

Loading

cockroach-teamcity commented Apr 4, 2022

abarganier left a comment

knz commented Apr 7, 2022

knz commented Apr 7, 2022

cameronnunez left a comment

dhartunian left a comment

knz commented Apr 23, 2022

dhartunian commented Apr 25, 2022

knz commented Apr 25, 2022

dhartunian commented May 3, 2022

abarganier left a comment

cameronnunez left a comment

dhartunian May 17, 2022

cameronnunez May 17, 2022

dhartunian commented May 18, 2022

craig bot commented May 18, 2022

craig bot commented May 18, 2022

blathers-crl bot commented May 18, 2022

log: add support for decoding JSON logs #79356

log: add support for decoding JSON logs #79356

Conversation

dhartunian commented Apr 4, 2022 • edited by cockroach-jira-scripts Loading

cockroach-teamcity commented Apr 4, 2022

abarganier left a comment

Choose a reason for hiding this comment

knz commented Apr 7, 2022

knz commented Apr 7, 2022

cameronnunez left a comment

Choose a reason for hiding this comment

dhartunian left a comment

Choose a reason for hiding this comment

knz commented Apr 23, 2022

dhartunian commented Apr 25, 2022

knz commented Apr 25, 2022

dhartunian commented May 3, 2022

abarganier left a comment

Choose a reason for hiding this comment

cameronnunez left a comment

Choose a reason for hiding this comment

dhartunian May 17, 2022

Choose a reason for hiding this comment

cameronnunez May 17, 2022

Choose a reason for hiding this comment

dhartunian commented May 18, 2022

craig bot commented May 18, 2022

craig bot commented May 18, 2022

blathers-crl bot commented May 18, 2022

dhartunian commented Apr 4, 2022 •

edited by cockroach-jira-scripts

Loading