Skip to content

log: create crdb-v2 log entry parser and integrate it into debug merge-logs#65633

Merged
craig[bot] merged 1 commit intocockroachdb:masterfrom
cameronnunez:v2-parser
Jul 14, 2021
Merged

log: create crdb-v2 log entry parser and integrate it into debug merge-logs#65633
craig[bot] merged 1 commit intocockroachdb:masterfrom
cameronnunez:v2-parser

Conversation

@cameronnunez
Copy link
Copy Markdown
Contributor

@cameronnunez cameronnunez commented May 24, 2021

Fixes #65504.

The crdb-v2 log file format is not recognized by some tools like debug merge-logs.
This is makes it difficult/impossible to merge log files properly.
This patch creates a new parser and integrates it into debug merge-logs.

Release note (cli change): the tool debug merge-logs is now able to recognize
crdb-v2 formatted log files.

@cameronnunez cameronnunez added C-enhancement Solution expected to add code/behavior + preserve backward-compat (pg compat issues are exception) A-logging In and around the logging infrastructure. labels May 24, 2021
@cameronnunez cameronnunez requested a review from knz May 24, 2021 19:56
@cockroach-teamcity
Copy link
Copy Markdown
Member

This change is Reviewable

@cameronnunez cameronnunez marked this pull request as draft May 24, 2021 19:57
Copy link
Copy Markdown
Contributor

@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.

All right before anything else we need to talk a little bit about how to organize this work.

For any kind of project that looks like "we need to get data from point A to point B in different forms"
There is necessarily a conversion step, meaning we have at least two algorithms of interest: parsing the input into an intermediate representation, then printing out the representation in the output format.

Whenever there are two separate algorithms, we can split the work into two sub-projects.
The one you're looking at here is thus specifically the parser.

Now you have a simpler project "we need to parse data from place X (e.g. a file) into place Y (a data structure)"

If that is the project you're working on, the commit message should reflect that, and explain what are X and Y.

Next thing to talk about is how to go about a programming task to implement an algorithm. Most of the time, it's extremely useful for productivity to set up a test program (or better yet - a unit test) ahead of starting to implement the algorithm. This way, at every step of the implementation you can exercise your implementation so far by running your test and see what the test says.

What does a test look like for a parser? That's a programming exercise in its own right. A parsing test is a collection of candidate inputs, with logic that applies the parser (yet to be programmed) to the input, then compares the actual output (from the parser) to some expected output (defined in the test).

For this kind of test structure nowadays we use the datadriven package. An example such test can be found in pkg/sql/pgwire/hba/hba_test.go.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained

@knz
Copy link
Copy Markdown
Contributor

knz commented May 25, 2021

In this case you'd thus start by populating some test code in format_crdb_v2_test.go and see how that goes.

@cameronnunez cameronnunez force-pushed the v2-parser branch 4 times, most recently from 6ae171f to af56499 Compare May 26, 2021 18:17
@cameronnunez
Copy link
Copy Markdown
Contributor Author

cameronnunez commented May 27, 2021

@knz

Wrote up some test cases for parsing single line entries, which the current form of the parser has passed.

Now looking at combining multi-line entries into single entries in memory. I am trying to figure out if I am going in the right direction by working on a v2 version of the peek function (which is called by the pop function) in debug_merge_logs.go. Am I headed in the right direction here or should I be looking elsewhere?

@cameronnunez cameronnunez requested a review from knz May 27, 2021 00:12
Copy link
Copy Markdown
Contributor

@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.

Reviewed 3 of 4 files at r1.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @cameronnunez)


pkg/cli/debug_merge_logs.go, line 531 at r1 (raw file):

}
func (s *fileLogStream) peekV2() (logpb.Entry, bool) {
	for !s.read && s.err == nil {
  1. This logic belongs to the entry parser in the log package, not the merge-logs command.

  2. you can capture all the continuation lines using a single regular expression. No need for a "moreLines" loop.

Let's make some time together and I will teach you about the magic of regular expressions.


pkg/util/log/format_crdb_v2.go, line 465 at r1 (raw file):

		}
		b := d.scanner.Bytes()
		m := d.re.FindSubmatch(b)
  1. You're using the v1 regular expression. It's unsuitable for v2. You need to define a new regular expression.

  2. Separately from a new regexp, another question is whether you want to reuse the existing EntryDecoder type or define a new one. It can go either way.

  • Different types:
    • Pros: can use the same method name Decode on both types with a different implementation
    • Cons: code duplication
  • Same type, different fields
    • Pros: can reuse (part of) the constructor
    • Cons: either different Decode method name, or need to plug a method via a function attribute

Do you have an opinion on the matter?


pkg/util/log/format_crdb_v2_test.go, line 193 at r1 (raw file):

				fmt.Println("Here")
				fmt.Println(e.File == "")
				err := NewEntryDecoder(strings.NewReader(td.Input), 1).DecodeV2(&e)

Don't use literal constants in constructors. The constant for redactability has a name, use the name.

Also, we want the test to see that the redactability information is preserved. Your choice of using WithFlattenedSensitiveData here removes it. You need WithMarkedSensitiveData.


pkg/util/log/format_crdb_v2_test.go, line 197 at r1 (raw file):

					return fmt.Sprintf("error: %v\n", err)
				}
				var sb strings.Builder

Using strings.Builder here and the all the tablewriter code below is very cute but it's overkill :)

You can simplify all this to:

return fmt.Sprintf("%# v", pretty.Formatter(e))

@cameronnunez cameronnunez force-pushed the v2-parser branch 6 times, most recently from aef44d3 to 35bd33b Compare June 4, 2021 00:53
@cameronnunez cameronnunez requested a review from knz June 4, 2021 00:54
Copy link
Copy Markdown
Contributor

@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.

I love how you have simplified the code. It looks much better this way.
Let's move on to polishing this a bit further.

Reviewed 3 of 4 files at r2.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @cameronnunez and @knz)


pkg/util/log/format_crdb_v2.go, line 472 at r2 (raw file):

		/* Context tags     				*/ `(?:\[((?:[^]]|\][^ ])+)\] )` +
		/* Counter          				*/ `((?:\d+)?) ` +
	  /* Continuation marker			*/ `([ =!+|])` +

please ensure the comments align with the previous lines properly.


pkg/util/log/format_crdb_v2.go, line 532 at r2 (raw file):

	}

	// Process the file.

Can you handle the (gostd) case in the same way as the crdb-v1 code thanks
(also add a test for it)


pkg/util/log/format_crdb_v2.go, line 559 at r2 (raw file):

	// Process the log message.
	// While the entry has additional lines, collect the full message.
	entry.Message = string(trimFinalNewLines(m[12]))

Can I suggest you replace the direct assignment of entry.Message by a strings.Builder,
with entry.Message = buf.String() at the end. This will save allocations.


pkg/util/log/format_crdb_v2.go, line 582 at r2 (raw file):

			entry.Message += msg
		case "!":
			entry.Message += "\n(stack trace: " + msg

please don't enclose the stack trace between parentheses - they are commonly many lines long, and the reader will become confused by the time the closing parenthesis is encountered.
(Also not using parentheses will allow you to simplify the case below)


pkg/util/log/format_crdb_v2.go, line 585 at r2 (raw file):

			hasStackTrace = true
		default:
			hasMoreLines = false

I don't think you need hasMoreLines - a simple break would suffice here.


pkg/util/log/format_crdb_v2.go, line 595 at r2 (raw file):

}

func (d *EntryDecoderV2) split(data []byte, atEOF bool) (advance int, token []byte, err error) {

Where is this code used?

@cameronnunez
Copy link
Copy Markdown
Contributor Author

cameronnunez commented Jun 4, 2021

Can you handle the (gostd) case in the same way as the crdb-v1 code thanks
(also add a test for it)

Yes! The second test includes handling the (gostd) case.

// Process the log message.
// While the entry has additional lines, collect the full message.
entry.Message = string(trimFinalNewLines(m[12]))

Can I suggest you replace the direct assignment of entry.Message by a strings.Builder,
with entry.Message = buf.String() at the end. This will save allocations.

Yes agreed, that's more efficient.

			hasStackTrace = true
		default:
			hasMoreLines = false

I don't think you need hasMoreLines - a simple break would suffice here.

I decided to use hasMoreLines because it seems that break breaks out of the switch instead of the for loop.

func (d *EntryDecoderV2) split(data []byte, atEOF bool) (advance int, token []byte, err error) {

Where is this code used?

This was used when the decoder had a scanner field, but it no longer does so this function is now not needed - thanks!

craig bot pushed a commit that referenced this pull request Jun 7, 2021
65342:  multi-region syntax diagrams r=ericharmeling a=ericharmeling

- Updated ALTER/CREATE DATABASE diagrams for multi-region
- Updated CREATE TABLE diagram for multi-region
- Added opt_locality diagram

Release note: None

66096: util/log: extend `logpb.Entry` with more fine grained fields r=cameronnunez a=knz

Needed for #65633 and #61378.

cc @cockroachdb/server 

66142: cli: skip under testrace as this test might be timing out r=jlinder a=adityamaru

Release note: None

Co-authored-by: Eric Harmeling <eric.harmeling@cockroachlabs.com>
Co-authored-by: Raphael 'kena' Poss <knz@thaumogen.net>
Co-authored-by: Aditya Maru <adityamaru@gmail.com>
@cameronnunez cameronnunez force-pushed the v2-parser branch 2 times, most recently from f0013ab to b05a534 Compare June 7, 2021 17:56
Copy link
Copy Markdown
Contributor

@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.

Can you remove the last commit r4 "Merge branch 'cockroachdb:master' into v2-parser"

And instead do a rebase operation.
(We generally never merge the master branch into PR branches)

After you do a rebase, please refresh your parser test to include the new fields in logpb.Entry
Also please populate the new fields (StructuredStart/End, StackTraceStart) since you have enough information for them. You'll need them in the debug command code.

Reviewed 1 of 4 files at r2, 5 of 5 files at r3, 2 of 2 files at r4.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @cameronnunez)


pkg/util/log/format_crdb_v2.go, line 472 at r2 (raw file):

Previously, knz (kena) wrote…

please ensure the comments align with the previous lines properly.

there's still a misalignment. Probably due to using tabs instead of spaces?


pkg/util/log/format_crdb_v2.go, line 555 at r3 (raw file):

	var entryMsg strings.Builder

	fmt.Fprintf(&entryMsg, string(trimFinalNewLines(m[12])))

Fprint, not Fprintf


pkg/util/log/format_crdb_v2.go, line 572 at r3 (raw file):

		switch cont {
		case "+":
			fmt.Fprintf(&entryMsg, "\n"+msg)

Fprintf(..., "%s\n", msg)


pkg/util/log/format_crdb_v2.go, line 574 at r3 (raw file):

			fmt.Fprintf(&entryMsg, "\n"+msg)
		case "|":
			fmt.Fprintf(&entryMsg, msg)

Fprint


pkg/util/log/format_crdb_v2.go, line 576 at r3 (raw file):

			fmt.Fprintf(&entryMsg, msg)
		case "!":
			fmt.Fprintf(&entryMsg, "\nstack trace:\n"+msg)

Fprintf with suitable %s

@cameronnunez cameronnunez force-pushed the v2-parser branch 3 times, most recently from 2ce3e20 to 5583230 Compare June 28, 2021 19:57
Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez left a comment

Choose a reason for hiding this comment

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

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


pkg/cli/debug_merge_logs.go, line 558 at r21 (raw file):

Previously, ajwerner wrote…

Now that we're buffering a whole file in RAM (something I was actively trying to avoid when I wrote this), we can have this just return ([]byte, error).

Done.


pkg/cli/debug_merge_logs.go, line 575 at r21 (raw file):

Previously, ajwerner wrote…

This part is sort of bogus now -- and also N^2. If you're going to read all of the data from the file, do it earlier and then do all the searching in memory.

In that world, you should set i as the offset in the search. At the end this would look like:

// Delete the `fi` and `size` stuff above
data, err := ioutil.ReadAll(f)
if err != nil {
    return err
}
offset := sort.Search(len(data), func(i int) bool {
    decoder, err := log.NewEntryDecoderf(data[i:], editMode, format)
    if err != nil {
			panic(err)
		}
		if err = decoder.Decode(&e); err != nil {
			if err == io.EOF {
				return true
			}
			panic(err)
		}
		return e.Time >= from.UnixNano()
})
return data[offset:], nil
</blockquote></details>

Done.
___
*[pkg/util/log/format_crdb_v2.go, line 479 at r24](https://reviewable.io/reviews/cockroachdb/cockroach/65633#-MaUwsbULP0fmfvW7fY--r24-479:-MdJnjo69rn_-I0kj-rP:b-tbnhw0) ([raw file](https://github.com/cockroachdb/cockroach/blob/43db208df562a47be32a5f5f402b0924a6dbd39b/pkg/util/log/format_crdb_v2.go#L479)):*
<details><summary><i>Previously, ajwerner wrote…</i></summary><blockquote>

If this line is non-empty this indicates corruption of the log file rather than the end, right? 
</blockquote></details>

Agreed - fixed.


<!-- Sent from Reviewable.io -->

@cameronnunez
Copy link
Copy Markdown
Contributor Author

These implementations don't need to know anything about each other. I'd also love to see individual files just for the different version encoders.

Fixed. Regarding encoding, I will file that as a separate issue as this PR is focused primarily on decoding.

  1. It's a bummer that we don't have a streaming implementation of the v2 decoder. Fortunately, I think the streaming decoding should be much easier for v1 than for v2 because of its line-oriented protocol.

Done.

  1. It feels like the old format should "round-trip" through the new format. Ideally we could log anything in v1, decode it with the v1 decoder, write it in v2, decode it with the v2 decoder, write it back out in v1 and assert that the original bytes and final bytes are perfectly equivalent.

I will mention this when filing the separate issue for encoding.

Copy link
Copy Markdown
Contributor

@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.

Reviewed 8 of 12 files at r18, 3 of 39 files at r25, 2 of 29 files at r26, 2 of 2 files at r27, 4 of 4 files at r28, 36 of 36 files at r29.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (waiting on @ajwerner, @cameronnunez, and @knz)


pkg/server/status.go, line 1006 at r29 (raw file):

	reader, err := log.GetLogReader(req.File, true /* restricted */)
	if reader == nil || err != nil {
		return nil, fmt.Errorf("log file %s could not be opened: %s", req.File, err)

errors.Newf

use %q for the file name not %s


pkg/util/log/file_api.go, line 375 at r29 (raw file):

) ([]logpb.Entry, bool, error) {
	reader, err := GetLogReader(file.Name, true /* restricted */)
	if reader == nil || err != nil {

can you explain (to me) when it's possible for reader to be nil?


pkg/util/log/log_decoder.go, line 31 at r29 (raw file):

// The format of the log file determines how the decoder is constructed.
func NewEntryDecoder(in io.Reader, editMode EditSensitiveData) (EntryDecoder, error) {
	return NewEntryDecoderf(in, editMode, ""/*format*/)

I think this is missing a run of gofmt?

@ajwerner
Copy link
Copy Markdown
Contributor

FYI I've been taking a stab at helping to get this over the finish line. Will post an update soon.

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez left a comment

Choose a reason for hiding this comment

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

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


pkg/server/status.go, line 1006 at r29 (raw file):

Previously, knz (kena) wrote…

errors.Newf

use %q for the file name not %s

Done.


pkg/util/log/file_api.go, line 375 at r29 (raw file):

Previously, knz (kena) wrote…

can you explain (to me) when it's possible for reader to be nil?

From what I understand, reader is nil only when err is not nil, correct? So reader == nil can be removed, right?


pkg/util/log/log_decoder.go, line 31 at r29 (raw file):

Previously, knz (kena) wrote…

I think this is missing a run of gofmt?

Yes, on it.

@cameronnunez
Copy link
Copy Markdown
Contributor Author

cameronnunez commented Jun 30, 2021

FYI I've been taking a stab at helping to get this over the finish line. Will post an update soon.

:lgtm:

Previously, cameronnunez (Cameron Nunez) wrote…

Would StructuredStart not always be 0 for crdb-v2 formatted entries?

It might be, but still this needs to be explained in the code (at least with a comment; you can even add entry.StructuredStart = 0 to clarify).

Based on @knz's comments from earlier, I made an update to include entry.StructuredStart = 0.

if m.isStructured() {
		entry.StructuredStart = 0
		entry.StructuredEnd = uint32(len(m.getMsg()))
	}

@@ -0,0 +1,20 @@
I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27)
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I'm going to be honest, I don't really understand what's going on here. Isn't this just the vanilla v1 format?

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez Jun 30, 2021

Choose a reason for hiding this comment

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

The test decodes crdb-v2 formatted log entries and encodes them as crdb-v1. More work needs to be done for encoding crdb-v2 log entries. At the time being, testdata/merge_logs_v2/results and testdata/merge_logs_v1/results are identical except for results/5.* because the corresponding test cases have log entries with no logging tags - the two parsers digest this situation differently. For the crdb-v2 parser, - is stored when there are no logging tags whereas the crdb-v1 parser is fine with the empty string.

Comment on lines +470 to +471
/* Context tags */ `(?:\[(?P<tags>(?:[^]]|\][^ ])+)\])` +
/* Counter */ `(?: (?P<counter>\d+))? ? ?` +
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

This isn't quite right. Especially the ? ? after counter. What about:

			/* Context tags             */ `(?:\[(?P<tags>(?:[^]]|\][^ ])+)\])` +
			/* Counter                  */ `(?: (?P<counter>\d+)|  )?` +

The reason I did it like this is that there are some entries that are "non standard" which have just one total space between the tag and the message. Do we need deal with those too? See:

I181130 22:14:34.828612 740 storage/store_rebalancer.go:277  [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27)

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez Jun 30, 2021

Choose a reason for hiding this comment

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

I do not recall adding the ? ? after the counter. Should be removed.

The reference docs state that:

For entries that do not have a counter value associated (e.g., header entries in file sinks), the counter position in the common prefix is empty: tags is then followed by two ASCII space characters, instead of one space; the counter, and another space.

The presence of the two ASCII spaces indicates reliably that no counter was present.

So I think we should keep it such that the absence of a counter is represented by two ASCII spaces between tags and cont? This would mean we would not have to worry about the case you have pointed out. I think this makes sense given that the continuation marker is the central update with crdb-v2, so consistency there is important.

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez Jun 30, 2021

Choose a reason for hiding this comment

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

Just noticed there was a malformed entry in the testdata: a log entry that was crdb-v1 formatted (single space between tags and the message instead of three spaces). Fixed and I changed the above to:

			/* Context tags             */ `(?:\[(?P<tags>(?:[^]]|\][^ ])+)\] )` +
			/* Counter                  */ `(?P<counter>(?:\d+)?) ` +

Passes all the tests.

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @ajwerner and @knz)


pkg/server/status.go, line 1006 at r36 (raw file):

Previously, ajwerner wrote…

This is still not quite right. This should be errors.Wrapf(err, "log file %q could not be opened", req.File)

Done.


pkg/util/log/file_api.go, line 293 at r36 (raw file):

Previously, ajwerner wrote…

Needs a comment.

Done.


pkg/util/log/log_decoder.go, line 115 at r36 (raw file):

Previously, ajwerner wrote…

This belongs in pkg/util/log/format_crdb_v1.go

Done.


pkg/util/log/log_decoder.go, line 160 at r36 (raw file):

Previously, ajwerner wrote…

can we get rid of this and replace it with bytes.TrimRight(s, "\n")

Done.

Copy link
Copy Markdown
Contributor

@ajwerner ajwerner left a comment

Choose a reason for hiding this comment

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

LGTM but I'd like @knz to sign off.

const MessageTimeFormat = "060102 15:04:05.999999"

// FormatLegacyEntry writes the contents of the legacy log entry struct to the specified writer.
func FormatLegacyEntry(e logpb.Entry, w io.Writer) error {
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Doesn't need to be in this PR but how would you feel about making Format into a type. It can have methods like FormatEntry and NewDecoder.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Sounds like a good idea to me!

v2SeverityIdx = entryREV2.SubexpIndex("severity")
v2DateTimeIdx = entryREV2.SubexpIndex("datetime")
v2GoroutineIdx = entryREV2.SubexpIndex("goroutine")
v2GoStdIdx = entryREV2.SubexpIndex("gostd")
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Seems like we're not using this. Does it mean we lose this information? Should we store it somewhere?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I created a group for the go standard library flag so that the parser would ignore it when present. I do not think we need to store it? Maybe @knz has some thoughts on this. For now I can remove that line.

Copy link
Copy Markdown
Contributor

@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.

All right I can see you got the overall structure right now. 💯
Also very big thanks to @ajwerner for helping, I also learned a few tricks (e.g. the parsing fragments).

Here are a few remaining points to wrap up this PR:

  1. before you process the comments below, please squash your PR. I do not want to expand the view in Reviewable further in width. From now on, every subsequent iteration on your PR should be on just 1 commit that is amended every time.

  2. there are a few remaining comments below inline in the code.

  3. As CI is telling you, you will need to modify TestAuthenticationAndHBARules in pgwire/auth_test.go to properly recognize structured entries, since logpb.Entry has now changed.

  4. As CI is telling you now, there's a unit test in the server package that's now failing because your parser is good :)
    image.png

    The idea is that this test was written back when the v1 parser was used to parse v2 files, and that was introducing a stray space at the start of the log messages. So the test was written to expect that space. Of course, with a v2 parser that stray space is not there any more (it never should have been). So you can update the test accordingly.

Reviewed 26 of 30 files at r31, 5 of 45 files at r40, 75 of 82 files at r41, 1 of 4 files at r42, 3 of 3 files at r44.
Dismissed @ajwerner from 3 discussions.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @ajwerner and @cameronnunez)


pkg/server/status.go, line 1006 at r36 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

Done.

There's still a stray : %s at the end now. That's invalid.


pkg/util/log/file_api.go, line 375 at r29 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

From what I understand, "reader" is nil only when "err" is not nil, correct? So "reader == nil" can be removed, right?

yes I think so.


pkg/util/log/file_api.go, line 293 at r45 (raw file):

}

// FetchEntriesFromFilesWithFormat is like FetchEntriesFromFiles but has the log entry format with 'format'.

"... is like FetchEntriesFromFiles but the caller can specified the format of the log file."


pkg/util/log/format_crdb_v1.go, line 440 at r45 (raw file):

		// Process the remainder of the log message.
		r := redactablePackage{
			msg:        bytes.TrimRight(msg, "\n"),

This simplification is not an improvement. bytes.TrimRight() incurs two heap allocations and is going to iterate 3 times over the final newlines.
The original code is objectively better.


pkg/util/log/format_crdb_v2.go, line 471 at r36 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

Just noticed there was a malformed entry in the testdata: a log entry that was crdb-v1 formatted (single space between tags and the message instead of three spaces). Fixed and I changed the above to:

			/* Context tags             */ `(?:\[(?P<tags>(?:[^]]|\][^ ])+)\] )` +
			/* Counter                  */ `(?P<counter>(?:\d+)?) ` +

Passes all the tests.

that looks better thanks 👍


pkg/util/log/format_crdb_v2.go, line 478 at r42 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

I created a group for the go standard library flag so that the parser would ignore it when present. I do not think we need to store it? Maybe @knz has some thoughts on this. For now I can remove that line.

I see v2MsgIdx being defined below. I think this is used now?


pkg/util/log/format_crdb_v2.go, line 470 at r45 (raw file):

			/* Line                     */ `(?:(?P<line>\d+) )` +
			/* Redactable flag          */ `(?P<redactable>(?:` + redactableIndicator + `)?) ` +
			/* Context tags             */ `(?:\[(?P<tags>(?:[^]]|\][^ ])+)\] )` +

I believe this one can be simplified to just

   ...  `\[(?P<tags>(?:[^]]|\][^ ])+)\] ` +

(the outer non-grouping parentheses can be omitted)


pkg/util/log/format_crdb_v2.go, line 503 at r45 (raw file):

			err = errors.Wrapf(r, "decoding on line %d", d.lines)
		default:
			err = errors.AssertionFailedf("panic decoding on line %d: %v", d.lines, r)

if the panic object is not an error, then do not change it into an error. Instead, propagate it:

default:
  panic(r)

pkg/util/log/format_crdb_v2.go, line 597 at r45 (raw file):

func (d *entryDecoderV2) popFragment() {
	if d.nextFragment == nil {
		panic("cannot pop unpopulated fragment")

this should be an panic(errors.AssertionFailedf("..."))


pkg/util/log/log_decoder.go, line 42 at r45 (raw file):

	var format string

	formats := map[string]string{

This is not the right location to define this mapping.

Generally, complex objects that do not depend on a function's parameters nor the time of invocation should be defined in the global scope.
In this particular case, in formats.go.


pkg/util/log/log_decoder.go, line 53 at r45 (raw file):

		"json-fluent":         "json",
		"json-fluent-compact": "json",
		"v1":                  "v1",

I do not understand this entry nor the next one. Are you trying to invent new format names? I don't see why we should support more names for parsing than are available in the logging output configuration.


pkg/util/log/log_decoder.go, line 57 at r45 (raw file):

	}

	// If the log format has been specified, use the corresponding parser.

This comment is not reflecting the conditional immediately below it.


pkg/util/log/log_decoder.go, line 79 at r45 (raw file):

	f, ok := formats[logFormat]
	if !ok {
		return nil, errors.New("unknown log file format")

include the value specified by the user inside the error message


pkg/util/log/log_decoder.go, line 97 at r45 (raw file):

		d = decoder
	default:
		return nil, unimplemented.NewWithIssue(66684, "unable to decode this log file format")

for next time: when you link to an issue from the code, ensure the issue has the label X-anchored-telemetry.


pkg/util/log/log_decoder.go, line 106 at r45 (raw file):

	var re = regexp.MustCompile(
		`(?m)^` +
			/* Prefix */ `(?:.*\[config\]   log format \(utf8=.+\): )` +

FYI: with a little extension to this regexp, you can also auto-detect json log files.


pkg/util/log/testdata/parse, line 112 at r36 (raw file):

Previously, cameronnunez (Cameron Nunez) wrote…

For crdb-v2 formatted log entries, if the counter position is empty, it is represented by two ASCII space characters, instead of one space. The third space is a continuation indicator. Most of the test data was copied from testdata/crdb_v2 from the same directory.

I agree this looks good

Copy link
Copy Markdown
Contributor Author

@cameronnunez cameronnunez left a comment

Choose a reason for hiding this comment

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

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @ajwerner, @cameronnunez, and @knz)


pkg/server/status.go, line 1006 at r36 (raw file):

Previously, knz (kena) wrote…

There's still a stray : %s at the end now. That's invalid.

Fixed.


pkg/util/log/file_api.go, line 375 at r29 (raw file):

Previously, knz (kena) wrote…

yes I think so.

Got it. Removed.


pkg/util/log/file_api.go, line 293 at r45 (raw file):

Previously, knz (kena) wrote…

"... is like FetchEntriesFromFiles but the caller can specified the format of the log file."

Done.


pkg/util/log/format_crdb_v1.go, line 440 at r45 (raw file):

Previously, knz (kena) wrote…

This simplification is not an improvement. bytes.TrimRight() incurs two heap allocations and is going to iterate 3 times over the final newlines.
The original code is objectively better.

Understood, reverted back to the original code.


pkg/util/log/format_crdb_v2.go, line 470 at r45 (raw file):

Previously, knz (kena) wrote…

I believe this one can be simplified to just

   ...  `\[(?P<tags>(?:[^]]|\][^ ])+)\] ` +

(the outer non-grouping parentheses can be omitted)

Updated.


pkg/util/log/format_crdb_v2.go, line 503 at r45 (raw file):

Previously, knz (kena) wrote…

if the panic object is not an error, then do not change it into an error. Instead, propagate it:

default:
  panic(r)

Done.


pkg/util/log/format_crdb_v2.go, line 597 at r45 (raw file):

Previously, knz (kena) wrote…

this should be an panic(errors.AssertionFailedf("..."))

Fixed.


pkg/util/log/log_decoder.go, line 42 at r45 (raw file):

Previously, knz (kena) wrote…

This is not the right location to define this mapping.

Generally, complex objects that do not depend on a function's parameters nor the time of invocation should be defined in the global scope.
In this particular case, in formats.go.

Fixed.


pkg/util/log/log_decoder.go, line 53 at r45 (raw file):

Previously, knz (kena) wrote…

I do not understand this entry nor the next one. Are you trying to invent new format names? I don't see why we should support more names for parsing than are available in the logging output configuration.

I included them in case the user simplifies the format name (for example, a user passes "v2" instead of "crdb-v2") but this is unnecessary and seems undesirable, so this is now removed.


pkg/util/log/log_decoder.go, line 57 at r45 (raw file):

Previously, knz (kena) wrote…

This comment is not reflecting the conditional immediately below it.

Updated.


pkg/util/log/log_decoder.go, line 79 at r45 (raw file):

Previously, knz (kena) wrote…

include the value specified by the user inside the error message

Done.


pkg/util/log/log_decoder.go, line 97 at r45 (raw file):

Previously, knz (kena) wrote…

for next time: when you link to an issue from the code, ensure the issue has the label X-anchored-telemetry.

Will do 👍

Copy link
Copy Markdown
Contributor

@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.

:lgtm: but CI is telling you something remains to be fixed

Reviewed 5 of 8 files at r46, 5 of 5 files at r47.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @ajwerner and @cameronnunez)


pkg/sql/pgwire/auth_test.go, line 319 at r47 (raw file):

								if entry.StructuredEnd == 0 {
									// TODO(knz): Enhance this when the log file
									// contains proper markers for structured entries.

You can remove this comment now


pkg/util/log/formats.go, line 22 at r47 (raw file):

}

var formats = map[string]string{

I believe a better name for this variable is formatParsers (it's a mapping so the name should describe both the keys and the values in the map)

@cameronnunez
Copy link
Copy Markdown
Contributor Author

thanks you guys! @ajwerner @knz

@cameronnunez
Copy link
Copy Markdown
Contributor Author

bors r=knz,ajwerner

@cameronnunez
Copy link
Copy Markdown
Contributor Author

bors r-

@craig
Copy link
Copy Markdown
Contributor

craig bot commented Jul 13, 2021

Canceled.

@knz
Copy link
Copy Markdown
Contributor

knz commented Jul 14, 2021

as discussed offline: you can re-add the Co-authored-by: line in the commit message and merge this.

The remaining CI failure(s) if any are flakes in tests unrelated to your PR. We need to file issues when those occurs, to fix by other teams, but they should not block you from merging this.

The crdb-v2 log file format does not currently have an entry parser.
This patch creates the new parser alongside the v1 parser.

Release note (cli change): Previously, the crdb-v2 log file format
lacked a parser. This has now changed.

Co-authored-by: Andrew Werner <ajwerner@cockroachlabs.com>
@cameronnunez
Copy link
Copy Markdown
Contributor Author

bors r=knz,ajwerner

@craig
Copy link
Copy Markdown
Contributor

craig bot commented Jul 14, 2021

Build failed (retrying...):

@cameronnunez
Copy link
Copy Markdown
Contributor Author

bors r=knz,ajwerner

@craig
Copy link
Copy Markdown
Contributor

craig bot commented Jul 14, 2021

Already running a review

@craig
Copy link
Copy Markdown
Contributor

craig bot commented Jul 14, 2021

Build succeeded:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

A-logging In and around the logging infrastructure. C-enhancement Solution expected to add code/behavior + preserve backward-compat (pg compat issues are exception)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

log: implement a crdb-v2 log entry parser and use it in debug merge-logs

4 participants