colrpc: enhance warnings from the outbox by yuzefovich · Pull Request #68567 · cockroachdb/cockroach

yuzefovich · 2021-08-06T22:34:10Z

This commit marks several string constants as "safe" from the
redactability perspective so that the warnings logged by the outboxes
are more helpful. Additionally, several minor nits around error
formatting are addressed.

Release note: None

cockroach-teamcity · 2021-08-06T22:34:17Z

This change is

knz

It seems to me that you don't yet fully understand how redactability works. If a type implements redactability already (especially if it contains mixes of safe and unsafe information, like errors) then it will expand itself as a mixed redactable string in formatting contexts. You should not use redact.Safe. in many cases in your PR your proposed change is outright invalid, as it promises (via redact.Safe) that you've guaranteed the data "under it" does not contain unsafe information , while errors definitely contain unsafe stuff. in fact, quite generally any use of redact.Safe should be considered code smell.

Use the RedactableString type more liberally, as well as the SafeFormatter interface.

knz · 2021-08-09T16:37:16Z

pkg/sql/colexec/colbuilder/execplan.go

 		return errors.New("processorConstructor is nil")
 	}
-	log.VEventf(ctx, 1, "planning a row-execution processor in the vectorized flow because %v", causeToWrap)
+	log.VEventf(ctx, 1, "planning a row-execution processor in the vectorized flow because %v", redact.Safe(causeToWrap))


Make causeToWrap a redact.RedactableString and prepare redactability at the source.

knz · 2021-08-09T16:37:28Z

pkg/sql/colexec/colbuilder/execplan.go

+	log.VEventf(ctx, 1, "planning a row-execution processor in the vectorized flow because %v", redact.Safe(causeToWrap))
 	if err := canWrap(flowCtx.EvalCtx.SessionData.VectorizeMode, spec); err != nil {
-		log.VEventf(ctx, 1, "planning a wrapped processor failed because %v", err)
+		log.VEventf(ctx, 1, "planning a wrapped processor failed because %v", redact.Safe(err))


No. Errors are never safe.

knz · 2021-08-09T16:37:53Z

pkg/sql/colexec/colbuilder/execplan.go

+	log.VEventf(ctx, 1, "planning a row-execution processor in the vectorized flow because %v", redact.Safe(causeToWrap))
 	if err := canWrap(flowCtx.EvalCtx.SessionData.VectorizeMode, spec); err != nil {
-		log.VEventf(ctx, 1, "planning a wrapped processor failed because %v", err)
+		log.VEventf(ctx, 1, "planning a wrapped processor failed because %v", redact.Safe(err))


Also by convention don't use the word "because" and simply use a colon instead.

knz · 2021-08-09T16:38:08Z

pkg/sql/colexec/colbuilder/execplan.go

 			result.OpMonitors = result.OpMonitors[:0]
 			if returnedErr != nil {
-				log.VEventf(ctx, 1, "vectorized planning failed with %v", returnedErr)
+				log.VEventf(ctx, 1, "vectorized planning failed with %v", redact.Safe(returnedErr))


See above. Also use a colon

knz · 2021-08-09T16:38:40Z

pkg/sql/colflow/colrpc/inbox.go

 		// occur. The Inbox must still be closed.
 		i.close()
-		log.VEventf(ctx, 1, "Inbox encountered an error in Init: %v", err)
+		log.VEventf(ctx, 1, "Inbox encountered an error in Init: %v", redact.Safe(err))


knz · 2021-08-09T16:45:04Z

pkg/sql/distsql/server.go

-	log.VEventf(ctx, 1, "connected inbound stream %s/%d", flowID.Short(), streamID)
+	log.VEventf(
+		ctx, 1, "connected inbound stream %s/%d",
+		redact.SafeString(flowID.Short()), redact.SafeInt(streamID),


Ditto above

knz · 2021-08-09T16:45:10Z

pkg/sql/distsql_running.go

 		for _, spec := range flows {
 			if err := colflow.IsSupported(vectorizeMode, spec); err != nil {
-				log.VEventf(ctx, 2, "failed to vectorize: %s", err)
+				log.VEventf(ctx, 2, "failed to vectorize: %s", redact.Safe(err))


knz · 2021-08-09T16:45:18Z

pkg/sql/distsql_running.go

 	// canceled.
 	if r.ctx.Err() != nil {
-		log.VEventf(r.ctx, 1, "encountered error (transitioning to shutting down): %v", r.ctx.Err())
+		log.VEventf(r.ctx, 1, "encountered error (transitioning to shutting down): %v", redact.Safe(r.ctx.Err()))


knz · 2021-08-09T16:45:23Z

pkg/sql/distsql_running.go

 		r.status = execinfra.ConsumerClosed
 	} else {
-		log.VEventf(r.ctx, 1, "encountered error (transitioning to draining): %v", err)
+		log.VEventf(r.ctx, 1, "encountered error (transitioning to draining): %v", redact.Safe(err))


knz · 2021-08-09T16:45:30Z

pkg/sql/exec_util.go

 	if err != nil {
 		// Don't use distSQL for this request.
-		log.VEventf(ctx, 1, "query not supported for distSQL: %s", err)
+		log.VEventf(ctx, 1, "query not supported for distSQL: %s", redact.Safe(err))


yuzefovich

Thanks for taking a look!

Yeah, you're right - I don't truly understand how it all works. One thing I'm confused about is how do I propagate an error as "safe" if I know that it is actually safe? Like I know the full code path an error goes through, and I'm creating the error via errors.New without any PII in the first place.

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @yuzefovich)

yuzefovich

I reverted most of the changes since I really wanted to fix the outbox logging. PTAL.

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

pkg/sql/colexec/colbuilder/execplan.go, line 543 at r1 (raw file):

Previously, knz (kena) wrote…

Make causeToWrap a redact.RedactableString and prepare redactability at the source.

Reverted.

pkg/sql/colexec/colbuilder/execplan.go, line 545 at r1 (raw file):

Previously, knz (kena) wrote…

Also by convention don't use the word "because" and simply use a colon instead.

Done.

pkg/sql/colexec/colbuilder/execplan.go, line 686 at r1 (raw file):

Previously, knz (kena) wrote…

See above. Also use a colon

Done.

pkg/sql/colflow/vectorized_flow.go, line 225 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/vectorized_flow.go, line 279 at r1 (raw file):

Previously, knz (kena) wrote…

Don't call String on ID. It's already handled.

I think we already have a redactable variant of the small trace somewhere. If not, you can create it. It's not the responsibility of callers to assert it's safe.

Reverted.

pkg/sql/colflow/vectorized_flow.go, line 282 at r1 (raw file):

Previously, knz (kena) wrote…

This needs Wrapf

Done.

pkg/sql/colflow/vectorized_flow.go, line 331 at r1 (raw file):

Previously, knz (kena) wrote…

Make Short return a redactable string.

Reverted.

pkg/sql/colflow/vectorized_flow.go, line 332 at r1 (raw file):

Previously, knz (kena) wrote…

Paths are definitely not safe!!!

Done.

pkg/sql/colflow/vectorized_flow.go, line 333 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/vectorized_flow.go, line 897 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/outbox.go, line 172 at r1 (raw file):

Previously, knz (kena) wrote…

Not needed. Node IDs are already handled.

Done.

pkg/sql/colflow/colrpc/outbox.go, line 181 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/outbox.go, line 192 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/outbox.go, line 205 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/outbox.go, line 230 at r1 (raw file):

Previously, knz (kena) wrote…

Make opName a safe string or redactable string at the source.

Done.

pkg/sql/colflow/colrpc/outbox.go, line 234 at r1 (raw file):

Previously, knz (kena) wrote…

Ditto opName. Also errors are definitely not safe.

Done.

pkg/sql/colflow/colrpc/outbox.go, line 241 at r1 (raw file):

Previously, knz (kena) wrote…

Make reason a safe or redactable string at the source.

Done.

pkg/sql/colflow/colrpc/outbox.go, line 330 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/outbox.go, line 399 at r1 (raw file):

Previously, knz (kena) wrote…

Make handshake handle the Safe formatter interface instead. It's not generally safe.

Reverted.

pkg/sql/distsql/server.go, line 162 at r1 (raw file):

Previously, knz (kena) wrote…

No

Also use %v not %s

Done.

pkg/sql/distsql/server.go, line 230 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/distsql/server.go, line 533 at r1 (raw file):

Previously, knz (kena) wrote…

These types should be handled already. Don't call String on integer-like values.

Done.

pkg/sql/distsql/server.go, line 592 at r1 (raw file):

Previously, knz (kena) wrote…

Ditto above

Done.

pkg/sql/distsql_running.go, line 303 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/distsql_running.go, line 799 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/distsql_running.go, line 802 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/exec_util.go, line 1264 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/inbox.go, line 283 at r1 (raw file):

Previously, knz (kena) wrote…

No.

Done.

pkg/sql/colflow/colrpc/inbox.go, line 304 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/inbox.go, line 417 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

pkg/sql/colflow/colrpc/inbox.go, line 447 at r1 (raw file):

Previously, knz (kena) wrote…

No

Done.

knz

I'm creating the error via errors.New without any PII in the first place.

Then if you try this experimentally you'll discover that there won't be any redaction markers in the end. It already works! You don't have to do anything extra for this.

(Conversely, if you find a case that doesn't seem to work, we can talk about it together)

One thing that was broken, is that use of Errorf("... %v", err) that you've now fixed. This would have broken the recursion. It's possible that you got confused by an error that was flattened by Errorf in that way.

Here are a couple other candidate problems in the colexec sources:

pkg/sql/colexec/colbuilder/execplan.go:                                 return r, errors.AssertionFailedf("unexpectedly couldn't plan a cast although IsCastSupported returned true: %v", err)
pkg/sql/colflow/vectorized_flow.go:             colexecerror.InternalError(errors.Errorf("unable to create temporary storage directory: %v", err))

One needs errors.NewAssertionErrorWithWrappedErrf
the other needs Wrap

Reviewed 3 of 12 files at r1, 9 of 9 files at r2, all commit messages.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @yuzefovich)

pkg/sql/colexec/hash_based_partitioner.go, line 266 at r2 (raw file):

	op := &hashBasedPartitioner{
		unlimitedAllocator: unlimitedAllocator,
		name:               redact.SafeString(name),

Why cast this here? Why not make the function's argument also a redact.SafeString?

(We want to assert throughout that the name variable is not assembled programmatically for example by including a table name)

pkg/sql/colflow/colrpc/outbox.go, line 330 at r1 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

Done.

still need to revert this

pkg/sql/colflow/colrpc/outbox.go, line 414 at r2 (raw file):

		reason := redact.SafeString("terminated gracefully")
		if errToSend != nil {
			reason = "encountered an error when sending batches"

you've forgotten to include the error.

Try this:

var reason redact.RedactableString
if errToSend != nil {
   reason = redact.Sprintf("encountered error when sending batches: %v", errToSend)
} else {
   reason = redact.Sprint(redact.SafeString("terminated gracefully"))
}

pkg/sql/colflow/colrpc/outbox.go, line 416 at r2 (raw file):

			reason = "encountered an error when sending batches"
		}
		o.moveToDraining(ctx, reason)

then you'll need to use redact.RedactableString in the call interface

knz · 2021-08-11T12:34:09Z

see also #68707 FYI

This commit marks several string constants as "safe" from the redactability perspective so that the warnings logged by the outboxes are more helpful. Additionally, several minor nits around error formatting are addressed. Release note: None

yuzefovich

Thanks for the information!

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

pkg/sql/colexec/hash_based_partitioner.go, line 266 at r2 (raw file):

Previously, knz (kena) wrote…

Why cast this here? Why not make the function's argument also a redact.SafeString?

(We want to assert throughout that the name variable is not assembled programmatically for example by including a table name)

Good point, fixed.

pkg/sql/colflow/colrpc/outbox.go, line 330 at r1 (raw file):

Previously, knz (kena) wrote…

still need to revert this

Oops.

pkg/sql/colflow/colrpc/outbox.go, line 414 at r2 (raw file):

Previously, knz (kena) wrote…

you've forgotten to include the error.

Try this:

var reason redact.RedactableString
if errToSend != nil {
   reason = redact.Sprintf("encountered error when sending batches: %v", errToSend)
} else {
   reason = redact.Sprint(redact.SafeString("terminated gracefully"))
}

Done.

pkg/sql/colflow/colrpc/outbox.go, line 416 at r2 (raw file):

Previously, knz (kena) wrote…

then you'll need to use redact.RedactableString in the call interface

Done.

knz

💯

Reviewed 8 of 8 files at r3, all commit messages.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @yuzefovich)

yuzefovich · 2021-08-16T14:30:28Z

TFTR!

bors r+

craig · 2021-08-16T16:10:15Z

Build succeeded:

GitHub CI (Cockroach)

blathers-crl · 2021-08-16T16:10:21Z

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 9ac3f70 to blathers/backport-release-21.1-68567: 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.1.x failed. See errors above.

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

yuzefovich added the backport-21.1.x label Aug 6, 2021

yuzefovich requested review from a team and knz August 6, 2021 22:34

yuzefovich force-pushed the outbox-safe-logging branch 2 times, most recently from a3506c8 to f900db8 Compare August 6, 2021 22:35

yuzefovich changed the title ~~sql: mark multiple constants or error as safe for not redacting~~ sql: mark multiple strings and errors as safe for not redacting Aug 6, 2021

knz reviewed Aug 9, 2021

View reviewed changes

yuzefovich commented Aug 9, 2021

View reviewed changes

yuzefovich force-pushed the outbox-safe-logging branch from f900db8 to a103de2 Compare August 9, 2021 17:45

yuzefovich changed the title ~~sql: mark multiple strings and errors as safe for not redacting~~ colrpc: enhance warnings from the outbox Aug 9, 2021

yuzefovich commented Aug 9, 2021

View reviewed changes

knz reviewed Aug 11, 2021

View reviewed changes

colrpc: enhance warnings from the outbox

9ac3f70

This commit marks several string constants as "safe" from the redactability perspective so that the warnings logged by the outboxes are more helpful. Additionally, several minor nits around error formatting are addressed. Release note: None

yuzefovich force-pushed the outbox-safe-logging branch from a103de2 to 9ac3f70 Compare August 13, 2021 17:08

yuzefovich commented Aug 13, 2021

View reviewed changes

knz approved these changes Aug 16, 2021

View reviewed changes

craig bot merged commit f2aded5 into cockroachdb:master Aug 16, 2021

yuzefovich deleted the outbox-safe-logging branch August 16, 2021 17:50

yuzefovich mentioned this pull request Aug 16, 2021

release-21.1: colrpc: enhance warnings from the outbox #69000

Merged

herkolategan mentioned this pull request Jul 18, 2024

sql: clean up TestLargeDynamicRows #127423

Merged

Conversation

yuzefovich commented Aug 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cockroach-teamcity commented Aug 6, 2021

Uh oh!

knz left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

yuzefovich left a comment

Choose a reason for hiding this comment

Uh oh!

yuzefovich left a comment

Choose a reason for hiding this comment

Uh oh!

knz left a comment

Choose a reason for hiding this comment

Uh oh!

knz commented Aug 11, 2021

Uh oh!

yuzefovich left a comment

Choose a reason for hiding this comment

Uh oh!

knz left a comment

Choose a reason for hiding this comment

Uh oh!

yuzefovich commented Aug 16, 2021

Uh oh!

craig bot commented Aug 16, 2021

Uh oh!

blathers-crl bot commented Aug 16, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

yuzefovich commented Aug 6, 2021 •

edited

Loading