CBG-4928: Update log messages on changes feed being cancelled #7880

RIT3shSapata · 2025-11-14T09:12:46Z

CBG-4928

Describe your PR here...

Currently SGW logs the changes feed cancellation messages at warn level with "error" in the message
These are not necessarily errors, therefore the message level and messages have been updated appropriately
The other part of this ticket is implemented in CBG-4928 do not log warning for closed blip sender #7878

Pre-review checklist

Removed debug logging (fmt.Print, log.Print, ...)
Logging sensitive data? Make sure it's tagged (e.g. base.UD(docID), base.MD(dbName))
Updated relevant information in the API specifications (such as endpoint descriptions, schemas, ...) in docs/api

Dependencies (if applicable)

Link upstream PRs
Update Go module dependencies when merged

Integration Tests

GSI=true,xattrs=true https://jenkins.sgwdev.com/job/SyncGatewayIntegration/0000/

Copilot

Pull Request Overview

This PR updates the logging approach for changes feed cancellation scenarios. Currently, these cancellations are logged as warnings with "error" in the messages, but they are not necessarily errors. The changes downgrade the log level from WarnfCtx to InfofCtx, add the base.KeyChanges log key for better filtering, and update the error messages to be more descriptive and accurate.

Key Changes

Downgraded log level from warning to info for changes feed cancellation messages
Added base.KeyChanges log key to enable targeted log filtering
Updated error messages to be more descriptive (e.g., "Error retrieving changes" → "Could not retrieve changes")

Reviewed Changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.

File	Description
db/channel_cache_single.go	Simplified error message when changes feed is cancelled while waiting for view lock
db/changes.go	Downgraded two log statements from warning to info level and updated messages to be more descriptive
base/error.go	Updated `ErrChannelFeed` message from "Error while building channel feed" to "Failed to build channel feed"

Copilot · 2025-11-14T09:13:42Z

db/changes.go

 			changes, err := singleChannelCache.GetChanges(ctx, paginationOptions)
 			if err != nil {
-				base.WarnfCtx(ctx, "Error retrieving changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)
+				base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)


The error message 'Could not retrieve changes' is vague and doesn't clearly indicate that the changes feed was cancelled. Consider using a more specific message like 'Changes feed cancelled for channel %q: %v' to better reflect the actual cause.

Suggested change

base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)

if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {

base.InfofCtx(ctx, base.KeyChanges, "Changes feed cancelled for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)

} else {

base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)

}

Copilot · 2025-11-14T09:13:42Z

db/changes.go

 							// On feed error, send the error and exit changes processing
 							if current[i].Err == base.ErrChannelFeed {
-								base.WarnfCtx(ctx, "MultiChangesFeed got error reading changes feed: %v", current[i].Err)
+								base.InfofCtx(ctx, base.KeyChanges, "Could not read changes feed: %v", current[i].Err)


The error message 'Could not read changes feed' is ambiguous and doesn't clearly indicate a cancellation scenario. Consider using 'Changes feed cancelled: %v' or 'Changes feed operation cancelled: %v' for clarity.

Suggested change

base.InfofCtx(ctx, base.KeyChanges, "Could not read changes feed: %v", current[i].Err)

base.InfofCtx(ctx, base.KeyChanges, "Changes feed cancelled: %v", current[i].Err)

Copilot · 2025-11-14T09:13:43Z

base/error.go

 	ErrUpdateCancel          = &sgError{"Cancel update"}
 	ErrImportCancelledPurged = HTTPErrorf(http.StatusNotFound, "Import Cancelled Due to Purge")
-	ErrChannelFeed           = &sgError{"Error while building channel feed"}
+	ErrChannelFeed           = &sgError{"Failed to build channel feed"}


The error message 'Failed to build channel feed' still implies a failure rather than a cancellation, which contradicts the PR's goal of treating these as non-error scenarios. Consider renaming to 'Channel feed cancelled' or similar to better reflect the intended semantics.

Suggested change

ErrChannelFeed = &sgError{"Failed to build channel feed"}

ErrChannelFeed = &sgError{"Channel feed cancelled"}

I think we can drop this, because I think this error wouldn't show up if we avoid logging it at all.

torcolvin · 2025-11-14T13:35:19Z

db/channel_cache_single.go

 	// overhead in that case (and prevent feedback loop on query backlog)
 	if options.ChangesCtx.Err() != nil {
-		return nil, fmt.Errorf("Changes feed cancelled while waiting for view lock")
+		return nil, fmt.Errorf("Changes feed cancelled")


Suggested change

return nil, fmt.Errorf("Changes feed cancelled")

return nil, fmt.Errorf("Changes feed cancelled %w", options.ChangesCtx.Err())

This would tell us in downstream while it was canceled, particularly if we are able to determine a cause, this will make the above easier to reason about I think.

torcolvin · 2025-11-14T13:37:28Z

db/changes.go

 			changes, err := singleChannelCache.GetChanges(ctx, paginationOptions)
 			if err != nil {
-				base.WarnfCtx(ctx, "Error retrieving changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)
+				base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)


Assuming the context cancellation is passed back in the error message:

if !errors.Is(err, context.Canceled) && errors.Is(err, context.DeadlineExceeded) { base.WarnfCtx(ctx, "Error retrieving changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err) }

However, I think to match the behavior of below if we don't always wrap the context error message:

Suggested change

base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)

if options.ChangesCtx.Err() != nil {

base.WarnfCtx(ctx, "Error retrieving changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)

}

torcolvin · 2025-11-14T13:39:52Z

db/changes.go

 							if current[i].Err == base.ErrChannelFeed {
-								base.WarnfCtx(ctx, "MultiChangesFeed got error reading changes feed: %v", current[i].Err)


Suggested change

if current[i].Err == base.ErrChannelFeed {

base.WarnfCtx(ctx, "MultiChangesFeed got error reading changes feed: %v", current[i].Err)

if !options.ChangesCtx.Err() {

base.WarnfCtx(ctx, "MultiChangesFeed got error reading changes feed: %v", current[i].Err)

}

In this case, it's not clear whether that err from current[i].Err is better than the error returned.

torcolvin · 2025-11-14T13:47:41Z

base/error.go

 	ErrUpdateCancel          = &sgError{"Cancel update"}
 	ErrImportCancelledPurged = HTTPErrorf(http.StatusNotFound, "Import Cancelled Due to Purge")
-	ErrChannelFeed           = &sgError{"Error while building channel feed"}
+	ErrChannelFeed           = &sgError{"Failed to build channel feed"}


I think we can drop this, because I think this error wouldn't show up if we avoid logging it at all.

torcolvin · 2025-11-14T13:49:18Z

db/channel_cache_single.go

 	// Check whether the changes process has been terminated while we waited for the view lock, to avoid the view
 	// overhead in that case (and prevent feedback loop on query backlog)


Suggested change

// Check whether the changes process has been terminated while we waited for the view lock, to avoid the view

// overhead in that case (and prevent feedback loop on query backlog)

// Check whether the changes process has been terminated before running a query

update log messages

dd83197

RIT3shSapata requested a review from torcolvin November 14, 2025 09:12

RIT3shSapata assigned torcolvin Nov 14, 2025

Copilot AI review requested due to automatic review settings November 14, 2025 09:12

Copilot AI reviewed Nov 14, 2025

View reviewed changes

torcolvin reviewed Nov 14, 2025

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

CBG-4928: Update log messages on changes feed being cancelled #7880

CBG-4928: Update log messages on changes feed being cancelled #7880

RIT3shSapata commented Nov 14, 2025

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI Nov 14, 2025

Uh oh!

Copilot AI Nov 14, 2025

Uh oh!

Copilot AI Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

torcolvin Nov 14, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

-				base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)
+				if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {
+					base.InfofCtx(ctx, base.KeyChanges, "Changes feed cancelled for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)
+				} else {
+					base.InfofCtx(ctx, base.KeyChanges, "Could not retrieve changes for channel %q: %v", base.UD(singleChannelCache.ChannelID().Name), err)
+				}

	base.InfofCtx(ctx, base.KeyChanges, "Could not read changes feed: %v", current[i].Err)
	base.InfofCtx(ctx, base.KeyChanges, "Changes feed cancelled: %v", current[i].Err)

	ErrChannelFeed = &sgError{"Failed to build channel feed"}
	ErrChannelFeed = &sgError{"Channel feed cancelled"}

	return nil, fmt.Errorf("Changes feed cancelled")
	return nil, fmt.Errorf("Changes feed cancelled %w", options.ChangesCtx.Err())

		if current[i].Err == base.ErrChannelFeed {
		base.WarnfCtx(ctx, "MultiChangesFeed got error reading changes feed: %v", current[i].Err)

		// Check whether the changes process has been terminated while we waited for the view lock, to avoid the view
		// overhead in that case (and prevent feedback loop on query backlog)

CBG-4928: Update log messages on changes feed being cancelled #7880

Are you sure you want to change the base?

CBG-4928: Update log messages on changes feed being cancelled #7880

Conversation

RIT3shSapata commented Nov 14, 2025

Pre-review checklist

Dependencies (if applicable)

Integration Tests

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Key Changes

Reviewed Changes

Uh oh!

Copilot AI Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

Copilot AI Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

Copilot AI Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

torcolvin Nov 14, 2025

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants