Logging transactions can expose sensitive information

[grepory]

When transactions take too long, the entire transaction is logged. This can include potentially sensitive data included in transactions that are stored in etcd (e.g. password hashes in our case). E.g.

time="2018-11-15T17:46:31Z" level=warning msg="request \"header:<ID:10788204787227406862 > txn:<compare:<key:\\\"/sensu.io/users/agent\\\" version:0 > success:<request_put:<key:\\\"/sensu.io/users/agent\\\" value:\\\"{\\\\\\\"username\\\\\\\":\\\\\\\"agent\\\\\\\",\\\\\\\"password\\\\\\\":\\\\\\\"[~~~HASH REDACTED~~~]\\\\\\\",\\\\\\\"roles\\\\\\\":[\\\\\\\"agent\\\\\\\"],\\\\\\\"disabled\\\\\\\":false}\\\" > > > \" took too long (7.010072416s) to execute" component=etcd pkg=etcdserver

We discovered this when some instances in CircleCI were having IO issues today. I definitely recognize the value in logging these, but if there's a way to reduce this to debug-level logging information, that might be preferable. We already log timeout errors (which this caused) in our client application:

time="2018-11-15T17:46:31Z" level=error msg="unable to setup agent user" component=backend.seeds error="etcdserver: request timed out"

And there's another warning-level message in etcd that that's really quite useful:

time="2018-11-15T17:46:20Z" level=warning msg="sync duration of 4.122922318s, expected less than 1s" component=etcd pkg=wal

If the gRPC server returned a more useful error message without the specific details about the cause of the timeout (I'm not exactly sure how feasible this is as I didn't spelunk too terribly far), that would be more helpful from the client side--especially if we can correlate transaction IDs.

The log messages happen here in current master:

etcd/etcdserver/util.go

Lines 140 to 164 in e8b940f

	func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) {
	d := time.Since(now)
	if d > warnApplyDuration {
	if lg != nil {
	lg.Warn(
	"apply request took too long",
	zap.Duration("took", d),
	zap.Duration("expected-duration", warnApplyDuration),
	zap.String("prefix", prefix),
	zap.String("request", reqStringer.String()),
	zap.String("response", resp),
	zap.Error(err),
	)
	} else {
	var result string
	if err != nil {
	result = fmt.Sprintf("error:%v", err)
	} else {
	result = resp
	}
	plog.Warningf("%srequest %q with result %q took too long (%v) to execute", prefix, reqStringer.String(), result, d)
	}
	slowApplies.Inc()
	}
	}

And we're using 3.3.2:

etcd/etcdserver/util.go

Lines 108 to 114 in c9d46ab

	func warnOfExpensiveGenericRequest(now time.Time, stringer fmt.Stringer, prefix string) {
	// TODO: add metrics
	d := time.Since(now)
	if d > warnApplyDuration {
	plog.Warningf("%srequest %q took too long (%v) to execute", prefix, stringer.String(), d)
	}
	}

We want to keep the warning-level log messages as they include a considerable amount of valuable debugging information at a level that is not as verbose as debug. Suggestions or thoughts?

[hexfusion]

@grepory I believe this was resolved by #9821

https://github.com/etcd-io/etcd/blob/master/CHANGELOG-3.3.md#v338-2018-06-15

So give 3.3.8+ a try.

[grepory]

Crap. Thank you! We'll work on updating our etcd dependency. I appreciate it. I'll re-open if that's not the case.