Truncate long queries in error logs by demmer · Pull Request #2794 · vitessio/vitess

demmer · 2017-04-21T19:32:20Z

This change is

sougou · 2017-04-21T19:38:37Z

go/vt/vttablet/tabletserver/query_engine.go

 	response.Write([]byte(fmt.Sprintf("Length: %d\n", len(keys))))
 	for _, v := range keys {
-		response.Write([]byte(fmt.Sprintf("%#v\n", utils.TruncateQuery(v))))
+		response.Write([]byte(fmt.Sprintf("%#v\n", utils.TruncateQuery(v, 512))))


I'll be fine with using sqldb.SQLErrorTruncateLen everywhere uniformly.

My only thought on that is that they are somewhat orthogonal -- truncating in the UI isn't actually affecting errors so I'd want to name it something different.

sougou · 2017-04-21T19:39:50Z

@michael-berlin Do you have any thoughts? Change looks good to me, except for that one comment.

mberlin-bot · 2017-04-21T21:12:30Z

Overall change looks good to me. See my comments on the flags discussion below.

Reviewed 5 of 5 files at r2, 3 of 3 files at r3.
Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 10 at r3 (raw file):

	"bytes"
	"fmt"
	"github.com/youtube/vitess/go/vt/utils"

Go readability: This must go in a separate group.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

var (
	// Maximum length for a query in a sqlerror string. 0 means unlimited.
	SQLErrorTruncateLen int = 0

I don't think you need this variable. It adds an extra indirection.

Instead, you can just export sqlErrorTruncateLen and use it directly.

go/vt/vttablet/endtoend/misc_test.go, line 536 at r3 (raw file):

		map[string]interface{}{"data": buf.String()},
	)
	if (err == nil){

Go readability: Surrounding parentheses are not needed.

It looks like you're skipping the Git precommit hook. I thought it would complain about this? Can you please double check?

go/vt/vttablet/tabletserver/query_engine.go, line 473 at r3 (raw file):

Previously, demmer (Michael Demmer) wrote…

My only thought on that is that they are somewhat orthogonal -- truncating in the UI isn't actually affecting errors so I'd want to name it something different.

The 512 should be a constant because you're using it in several places and somebody may change it in one place and forget about the others.

In the name of the constant you could reflect that the limit is meant as default for UI purposes.

In general, I think it makes sense to have two different values for UI truncating and log truncating.

How about just adding a second flag (instead of a constant)? The default value for the second flag could be 512 then.

Comments from Reviewable

sougou-bot · 2017-04-21T22:04:49Z

Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

I don't think you need this variable. It adds an extra indirection.

Instead, you can just export sqlErrorTruncateLen and use it directly.

I think what you mean here is define the flag locally here and use it internally? I don't think it needs to be exported out of here since nobody else reads the value.

Comments from Reviewable

mberlin-bot · 2017-04-21T22:41:00Z

Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

Previously, sougou-bot (Sugu Sougoumarane) wrote…

I think what you mean here is define the flag locally here and use it internally? I don't think it needs to be exported out of here since nobody else reads the value.

Yes, SGTM.

What do you think about my other comment i.e. moving the 512 default value to a flag as well? Where should we define that flag?

Comments from Reviewable

sougou-bot · 2017-04-21T23:14:39Z

Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

Yes, SGTM.

What do you think about my other comment i.e. moving the 512 default value to a flag as well? Where should we define that flag?

I see that the value is used once in sqlparser and twice in tabletserver. If at all, maybe a constant in tabletserver and leave the one in sqlparser alone.

Comments from Reviewable

mberlin-bot · 2017-04-22T04:25:10Z

Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

Previously, sougou-bot (Sugu Sougoumarane) wrote…

I see that the value is used once in sqlparser and twice in tabletserver. If at all, maybe a constant in tabletserver and leave the one in sqlparser alone.

It's also used in vtgate. Let's definitely make this a constant (ideally in go/vt/utils/utils.go) and not duplicate this magic value of 512.

Instead of a constant, we could also add a function for that.

// TruncateQueryForUI is used when displaying queries on various Vitess status pages.
// By truncating the query to 512 characters, we avoid that loading the page takes too long.
func TruncateQueryForUI(query string) string {
  return TruncateQuery(query, 512)
}

Comments from Reviewable

demmer · 2017-04-22T05:00:24Z

Review status: all files reviewed at latest revision, 4 unresolved discussions, some commit checks failed.

go/sqldb/sql_error.go, line 22 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

It's also used in vtgate. Let's definitely make this a constant (ideally in go/vt/utils/utils.go) and not duplicate this magic value of 512.

Instead of a constant, we could also add a function for that.
// TruncateQueryForUI is used when displaying queries on various Vitess status pages.
// By truncating the query to 512 characters, we avoid that loading the page takes too long.
func TruncateQueryForUI(query string) string {
  return TruncateQuery(query, 512)
}

I had the same thought actually and did basically the same thing.

Will polish up the tests and make sure it covers the cases that have been biting us in production.

Comments from Reviewable

demmer · 2017-04-22T16:22:17Z

Done

Review status: 0 of 12 files reviewed at latest revision, 4 unresolved discussions.

go/sqldb/sql_error.go, line 10 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

Go readability: This must go in a separate group.

No longer relevant.

go/vt/vttablet/endtoend/misc_test.go, line 536 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

Go readability: Surrounding parentheses are not needed.

It looks like you're skipping the Git precommit hook. I thought it would complain about this? Can you please double check?

I ended up moving around repositories to work with my VM and the symlinks were pointed at dead-ends.

However even after fixing them I don't see to be able to get one of these to fail.

go/vt/vttablet/tabletserver/query_engine.go, line 473 at r3 (raw file):

Previously, mberlin-bot (Michael Berlin) wrote…

The 512 should be a constant because you're using it in several places and somebody may change it in one place and forget about the others.

In the name of the constant you could reflect that the limit is meant as default for UI purposes.

In general, I think it makes sense to have two different values for UI truncating and log truncating.

How about just adding a second flag (instead of a constant)? The default value for the second flag could be 512 then.

I ended up adding two functions and separate command line args for each.

Comments from Reviewable

demmer · 2017-04-25T14:34:38Z

@sougou @michael-berlin When manually forcing various errors I realized my previous attempts didn't actually truncate as expected.

Reworked the implementation and verified this properly truncates errors from vttablet and vtgate.

sougou · 2017-04-25T14:34:54Z

I was thinking you could also use sqlparser.SplitTrailingComment (https://github.com/youtube/vitess/blob/master/go/vt/sqlparser/comments.go#L14), and then truncate the query part only.

demmer · 2017-04-25T15:52:50Z

@sougou That's a good idea... though perhaps for cleanliness I should move all the truncate functions into the sqlparser package as opposed to sqldb?

sougou · 2017-04-26T00:23:17Z

Yeah. That sounds like a good idea.

demmer · 2017-04-26T12:51:12Z

@sougou Updated as per your suggestion to preserve the comments.

sougou

Change looks good. Couple of minor comments.

sougou · 2017-04-30T18:30:03Z

go/vt/vttablet/endtoend/misc_test.go

In all these tests, it may be simpler and more robust to do equality comparison with the exact output we want.

sougou · 2017-04-30T18:30:31Z

go/vt/sqlparser/truncate_query.go

Rename to TruncateForLog?

sougou · 2017-04-30T18:32:16Z

go/vt/vtgate/vtgate_test.go

Like in the other comment, you can build a wantVars variable and perform an equality comparison using reflect.DeepEqual.

As per PR feedback, added command line flags to separately control the maximum length of queries in the UI and in error logs. Also added additional cases for errors from vtgate.

After testing more cases in the actual deployment I realized that in several cases we actually have a protobuf object and therefore need to call fmt.Sprintf to generate the value before truncating the string.

demmer · 2017-05-01T19:06:53Z

@sougou Updated with your suggestions.

googlebot added the cla: yes label Apr 21, 2017

sougou reviewed Apr 21, 2017

View reviewed changes

demmer force-pushed the truncate-long-queries-in-error-logs branch from 0014ee7 to a4543ce Compare April 22, 2017 05:31

demmer mentioned this pull request Apr 26, 2017

truncate long queries in logs tinyspeck/vitess#5

Merged

sougou reviewed Apr 30, 2017

View reviewed changes

demmer added 12 commits May 1, 2017 12:05

add query truncation in vtgate /debug/query_plans

7c5ee8d

rework TruncateQuery to take the max length as an argument

3b04800

add a common option to truncate long queries in errors

a41d70c

rework error log and debug ui truncation

a499ebf

As per PR feedback, added command line flags to separately control the maximum length of queries in the UI and in error logs. Also added additional cases for errors from vtgate.

go fmt the new additions

54af94d

add truncation to tabletserver QueryAsString

f3bb556

rework the error string truncation again

95a57e1

After testing more cases in the actual deployment I realized that in several cases we actually have a protobuf object and therefore need to call fmt.Sprintf to generate the value before truncating the string.

move the TruncateFor helpers into the sqlparser package

ca4e27e

preserve trailing comments when truncating long queries

8554ad5

rename TruncateForError to TruncateForLog as suggested in PR

a41c061

remove unnecessary extra space before comments

6f0289d

rework truncation tests to use exact equality

223b887

demmer force-pushed the truncate-long-queries-in-error-logs branch from 1d09b58 to 223b887 Compare May 1, 2017 19:06

sougou approved these changes May 1, 2017

View reviewed changes

sougou merged commit 33ee8b1 into vitessio:master May 1, 2017

Conversation

demmer commented Apr 21, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sougou Apr 21, 2017

Choose a reason for hiding this comment

Uh oh!

demmer Apr 21, 2017

Choose a reason for hiding this comment

Uh oh!

sougou commented Apr 21, 2017

Uh oh!

mberlin-bot commented Apr 21, 2017

Uh oh!

sougou-bot commented Apr 21, 2017

Uh oh!

mberlin-bot commented Apr 21, 2017

Uh oh!

sougou-bot commented Apr 21, 2017

Uh oh!

mberlin-bot commented Apr 22, 2017

Uh oh!

demmer commented Apr 22, 2017

Uh oh!

demmer commented Apr 22, 2017

Uh oh!

demmer commented Apr 25, 2017

Uh oh!

sougou commented Apr 25, 2017

Uh oh!

demmer commented Apr 25, 2017

Uh oh!

sougou commented Apr 26, 2017

Uh oh!

demmer commented Apr 26, 2017

Uh oh!

sougou left a comment

Choose a reason for hiding this comment

Uh oh!

sougou Apr 30, 2017

Choose a reason for hiding this comment

Uh oh!

sougou Apr 30, 2017

Choose a reason for hiding this comment

Uh oh!

sougou Apr 30, 2017

Choose a reason for hiding this comment

Uh oh!

demmer commented May 1, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

demmer commented Apr 21, 2017 •

edited

Loading