Obey db scoped console logging when evaluating whether to log (#6553)

base/dcp_dest.go

@@ -64,7 +64,7 @@ func NewDCPDest(ctx context.Context, callback sgbucket.FeedEventCallbackFunc, bu
 		InfofCtx(d.loggingCtx, KeyDCP, "Starting sharded feed for %s.  Total partitions:%v", d.feedID, d.partitionCountStat.String())
 	}
 
-	if LogDebugEnabled(KeyDCP) {
+	if LogDebugEnabled(d.loggingCtx, KeyDCP) {
 		InfofCtx(d.loggingCtx, KeyDCP, "Using DCP Logging Receiver")
 		logRec := &DCPLoggingDest{dest: d}
 		return logRec, d.loggingCtx, nil

base/logging.go

@@ -369,20 +369,20 @@ func ConsoleLogKey() *LogKeyMask {
 
 // LogInfoEnabled returns true if either the console should log at info level,
 // or if the infoLogger is enabled.
-func LogInfoEnabled(logKey LogKey) bool {
-	return consoleLogger.shouldLog(nil, LevelInfo, logKey) || infoLogger.shouldLog(LevelInfo)
+func LogInfoEnabled(ctx context.Context, logKey LogKey) bool {
+	return consoleLogger.shouldLog(ctx, LevelInfo, logKey) || infoLogger.shouldLog(LevelInfo)
 }
 
 // LogDebugEnabled returns true if either the console should log at debug level,
 // or if the debugLogger is enabled.
-func LogDebugEnabled(logKey LogKey) bool {
-	return consoleLogger.shouldLog(nil, LevelDebug, logKey) || debugLogger.shouldLog(LevelDebug)
+func LogDebugEnabled(ctx context.Context, logKey LogKey) bool {
+	return consoleLogger.shouldLog(ctx, LevelDebug, logKey) || debugLogger.shouldLog(LevelDebug)
 }
 
 // LogTraceEnabled returns true if either the console should log at trace level,
 // or if the traceLogger is enabled.
-func LogTraceEnabled(logKey LogKey) bool {
-	return consoleLogger.shouldLog(nil, LevelTrace, logKey) || traceLogger.shouldLog(LevelTrace)
+func LogTraceEnabled(ctx context.Context, logKey LogKey) bool {
+	return consoleLogger.shouldLog(ctx, LevelTrace, logKey) || traceLogger.shouldLog(LevelTrace)
 }
 
 // AssertLogContains asserts that the logs produced by function f contain string s.

base/util.go

@@ -620,13 +620,13 @@ func (s SortedUint64Slice) Sort() {
 	sort.Sort(s)
 }
 
-func WriteHistogram(expvarMap *expvar.Map, since time.Time, prefix string) {
-	WriteHistogramForDuration(expvarMap, time.Since(since), prefix)
+func WriteHistogram(ctx context.Context, expvarMap *expvar.Map, since time.Time, prefix string) {
+	WriteHistogramForDuration(ctx, expvarMap, time.Since(since), prefix)
 }
 
-func WriteHistogramForDuration(expvarMap *expvar.Map, duration time.Duration, prefix string) {
+func WriteHistogramForDuration(ctx context.Context, expvarMap *expvar.Map, duration time.Duration, prefix string) {
 
-	if LogDebugEnabled(KeyAll) {
+	if LogDebugEnabled(ctx, KeyAll) {
 		var durationMs int
 		if duration < 1*time.Second {
 			durationMs = int(duration/(100*time.Millisecond)) * 100

db/blip.go

@@ -57,8 +57,8 @@ func NewSGBlipContextWithProtocols(ctx context.Context, id string, protocol ...s
 		bc, err = blip.NewContextCustomID(id, protocol...)
 	}
 
-	bc.LogMessages = base.LogDebugEnabled(base.KeyWebSocket)
-	bc.LogFrames = base.LogDebugEnabled(base.KeyWebSocketFrame)
+	bc.LogMessages = base.LogDebugEnabled(ctx, base.KeyWebSocket)
+	bc.LogFrames = base.LogDebugEnabled(ctx, base.KeyWebSocketFrame)
 	bc.Logger = defaultBlipLogger(ctx)
 
 	return bc, err

db/blip_sync_context.go

@@ -172,7 +172,7 @@ func (bsc *BlipSyncContext) register(profile string, handlerFn func(*blipHandler
 		handler := newBlipHandler(bsc.loggingCtx, bsc, bsc.copyContextDatabase(), bsc.incrementSerialNumber())
 
 		// Trace log the full message body and properties
-		if base.LogTraceEnabled(base.KeySyncMsg) {
+		if base.LogTraceEnabled(bsc.loggingCtx, base.KeySyncMsg) {
 			rqBody, _ := rq.Body()
 			base.TracefCtx(bsc.loggingCtx, base.KeySyncMsg, "Recv Req %s: Body: '%s' Properties: %v", rq, base.UD(rqBody), base.UD(rq.Properties))
 		}
@@ -194,7 +194,7 @@ func (bsc *BlipSyncContext) register(profile string, handlerFn func(*blipHandler
 		}
 
 		// Trace log the full response body and properties
-		if base.LogTraceEnabled(base.KeySyncMsg) {
+		if base.LogTraceEnabled(bsc.loggingCtx, base.KeySyncMsg) {
 			resp := rq.Response()
 			if resp == nil {
 				return
@@ -553,7 +553,7 @@ func (bsc *BlipSyncContext) sendDelta(sender *blip.Sender, docID string, collect
 // sendBLIPMessage is a simple wrapper around all sent BLIP messages
 func (bsc *BlipSyncContext) sendBLIPMessage(sender *blip.Sender, msg *blip.Message) bool {
 	ok := sender.Send(msg)
-	if base.LogTraceEnabled(base.KeySyncMsg) {
+	if base.LogTraceEnabled(bsc.loggingCtx, base.KeySyncMsg) {
 		rqBody, _ := msg.Body()
 		base.TracefCtx(bsc.loggingCtx, base.KeySyncMsg, "Sent Req %s: Body: '%s' Properties: %v", msg, base.UD(rqBody), base.UD(msg.Properties))
 	}
@@ -641,7 +641,7 @@ func (bsc *BlipSyncContext) sendRevision(sender *blip.Sender, docID, revID strin
 
 	history := toHistory(rev.History, knownRevs, maxHistory)
 	properties := blipRevMessageProperties(history, rev.Deleted, seq)
-	if base.LogDebugEnabled(base.KeySync) {
+	if base.LogDebugEnabled(bsc.loggingCtx, base.KeySync) {
 		base.DebugfCtx(bsc.loggingCtx, base.KeySync, "Sending rev %q %s based on %d known, digests: %v", base.UD(docID), revID, len(knownRevs), digests(attachmentStorageMeta))
 	}
 	return bsc.sendRevisionWithProperties(sender, docID, revID, collectionIdx, bodyBytes, attachmentStorageMeta, properties, seq, nil)

db/change_cache.go

@@ -705,7 +705,7 @@ func (c *changeCache) processEntry(ctx context.Context, change *LogEntry) channe
 		heap.Push(&c.pendingLogs, change)
 		numPending := len(c.pendingLogs)
 		c.internalStats.pendingSeqLen = numPending
-		if base.LogDebugEnabled(base.KeyCache) {
+		if base.LogDebugEnabled(ctx, base.KeyCache) {
 			base.DebugfCtx(ctx, base.KeyCache, "  Deferring #%d (%d now waiting for #%d...#%d) doc %q / %q",
 				sequence, numPending, c.nextSequence, c.pendingLogs[0].Sequence-1, base.UD(change.DocID), change.RevID)
 		}
@@ -762,7 +762,7 @@ func (c *changeCache) _addToCache(ctx context.Context, change *LogEntry) []chann
 	// updatedChannels tracks the set of channels that should be notified of the change.  This includes
 	// the change's active channels, as well as any channel removals for the active revision.
 	updatedChannels := c.channelCache.AddToCache(ctx, change)
-	if base.LogDebugEnabled(base.KeyChanges) {
+	if base.LogDebugEnabled(ctx, base.KeyChanges) {
 		base.DebugfCtx(ctx, base.KeyChanges, " #%d ==> channels %v", change.Sequence, base.UD(updatedChannels))
 	}
 

db/event_handler.go

@@ -155,7 +155,7 @@ func (wh *Webhook) HandleEvent(ctx context.Context, event Event) bool {
 		}
 
 		// Check Log Level first, as SanitizedUrl is expensive to evaluate.
-		if base.LogDebugEnabled(base.KeyEvents) {
+		if base.LogDebugEnabled(ctx, base.KeyEvents) {
 			base.DebugfCtx(ctx, base.KeyEvents, "Webhook handler ran for event.  Payload %s posted to URL %s, got status %s",
 				base.UD(string(payload)), base.UD(wh.SanitizedUrl(ctx)), resp.Status)
 		}

rest/handler.go

@@ -600,7 +600,7 @@ func (h *handler) removeCorruptConfigIfExists(ctx context.Context, bucket, confi
 
 func (h *handler) logRequestLine() {
 	// Check Log Level first, as SanitizeRequestURL is expensive to evaluate.
-	if !base.LogInfoEnabled(base.KeyHTTP) {
+	if !base.LogInfoEnabled(h.ctx(), base.KeyHTTP) {
 		return
 	}