mirror of
https://github.com/coder/coder.git
synced 2026-06-02 20:48:20 +00:00
chore(coderd/notifications): avoid generating warning logs for trivial enqueue failures (#19840)
I noticed during a scaletest that many warning logs were being generated when enqueuing notifications. The error was: ``` failed to notify of workspace creation: notification is not enabled ``` I don't think we should be warning if automated notifications fail to send to users because they have them disabled. To fix, we'll stop returning these errors.
This commit is contained in:
@@ -73,12 +73,14 @@ func NewStoreEnqueuer(cfg codersdk.NotificationsConfig, store Store, helpers tem
|
||||
}
|
||||
|
||||
// Enqueue queues a notification message for later delivery, assumes no structured input data.
|
||||
// Returns the IDs of successfully enqueued messages, if any.
|
||||
func (s *StoreEnqueuer) Enqueue(ctx context.Context, userID, templateID uuid.UUID, labels map[string]string, createdBy string, targets ...uuid.UUID) ([]uuid.UUID, error) {
|
||||
return s.EnqueueWithData(ctx, userID, templateID, labels, nil, createdBy, targets...)
|
||||
}
|
||||
|
||||
// Enqueue queues a notification message for later delivery.
|
||||
// Messages will be dequeued by a notifier later and dispatched.
|
||||
// Returns the IDs of successfully enqueued messages, if any.
|
||||
func (s *StoreEnqueuer) EnqueueWithData(ctx context.Context, userID, templateID uuid.UUID, labels map[string]string, data map[string]any, createdBy string, targets ...uuid.UUID) ([]uuid.UUID, error) {
|
||||
metadata, err := s.store.FetchNewMessageMetadata(ctx, database.FetchNewMessageMetadataParams{
|
||||
UserID: userID,
|
||||
@@ -141,14 +143,26 @@ func (s *StoreEnqueuer) EnqueueWithData(ctx context.Context, userID, templateID
|
||||
//
|
||||
// This is more efficient than fetching the user's preferences for each enqueue, and centralizes the business logic.
|
||||
if strings.Contains(err.Error(), ErrCannotEnqueueDisabledNotification.Error()) {
|
||||
return nil, ErrCannotEnqueueDisabledNotification
|
||||
s.log.Debug(ctx, "notification not enqueued",
|
||||
slog.F("template_id", templateID),
|
||||
slog.F("user_id", userID),
|
||||
slog.F("method", method),
|
||||
slog.Error(ErrCannotEnqueueDisabledNotification),
|
||||
)
|
||||
continue
|
||||
}
|
||||
|
||||
// If the enqueue fails due to a dedupe hash conflict, this means that a notification has already been enqueued
|
||||
// today with identical properties. It's far simpler to prevent duplicate sends in this central manner, rather than
|
||||
// having each notification enqueue handle its own logic.
|
||||
if database.IsUniqueViolation(err, database.UniqueNotificationMessagesDedupeHashIndex) {
|
||||
return nil, ErrDuplicate
|
||||
s.log.Debug(ctx, "notification not enqueued",
|
||||
slog.F("template_id", templateID),
|
||||
slog.F("user_id", userID),
|
||||
slog.F("method", method),
|
||||
slog.Error(ErrDuplicate),
|
||||
)
|
||||
continue
|
||||
}
|
||||
|
||||
s.log.Warn(ctx, "failed to enqueue notification", slog.F("template_id", templateID), slog.F("input", input), slog.Error(err))
|
||||
|
||||
@@ -35,6 +35,7 @@ import (
|
||||
"golang.org/x/xerrors"
|
||||
|
||||
"cdr.dev/slog"
|
||||
"cdr.dev/slog/sloggers/sloghuman"
|
||||
"github.com/coder/quartz"
|
||||
"github.com/coder/serpent"
|
||||
|
||||
@@ -1654,7 +1655,8 @@ func TestDisabledByDefaultBeforeEnqueue(t *testing.T) {
|
||||
|
||||
ctx := dbauthz.AsNotifier(testutil.Context(t, testutil.WaitSuperLong))
|
||||
store, _ := dbtestutil.NewDB(t)
|
||||
logger := testutil.Logger(t)
|
||||
logbuf := strings.Builder{}
|
||||
logger := testutil.Logger(t).AppendSinks(sloghuman.Sink(&logbuf)).Leveled(slog.LevelDebug)
|
||||
|
||||
cfg := defaultNotificationsConfig(database.NotificationMethodSmtp)
|
||||
enq, err := notifications.NewStoreEnqueuer(cfg, store, defaultHelpers(), logger.Named("enqueuer"), quartz.NewReal())
|
||||
@@ -1662,10 +1664,12 @@ func TestDisabledByDefaultBeforeEnqueue(t *testing.T) {
|
||||
user := createSampleUser(t, store)
|
||||
|
||||
// We want to try enqueuing a notification on a template that is disabled
|
||||
// by default. We expect this to fail.
|
||||
// by default. We expect this to be a no-op that produces a debug log.
|
||||
templateID := notifications.TemplateWorkspaceManuallyUpdated
|
||||
_, err = enq.Enqueue(ctx, user.ID, templateID, map[string]string{}, "test")
|
||||
require.ErrorIs(t, err, notifications.ErrCannotEnqueueDisabledNotification, "enqueuing did not fail with expected error")
|
||||
notifIDs, err := enq.Enqueue(ctx, user.ID, templateID, map[string]string{}, "test")
|
||||
require.NoError(t, err)
|
||||
require.Contains(t, logbuf.String(), notifications.ErrCannotEnqueueDisabledNotification.Error())
|
||||
require.Empty(t, notifIDs)
|
||||
}
|
||||
|
||||
// TestDisabledBeforeEnqueue ensures that notifications cannot be enqueued once a user has disabled that notification template
|
||||
@@ -1679,7 +1683,8 @@ func TestDisabledBeforeEnqueue(t *testing.T) {
|
||||
|
||||
ctx := dbauthz.AsNotifier(testutil.Context(t, testutil.WaitSuperLong))
|
||||
store, _ := dbtestutil.NewDB(t)
|
||||
logger := testutil.Logger(t)
|
||||
logbuf := strings.Builder{}
|
||||
logger := testutil.Logger(t).AppendSinks(sloghuman.Sink(&logbuf)).Leveled(slog.LevelDebug)
|
||||
|
||||
// GIVEN: an enqueuer & a sample user
|
||||
cfg := defaultNotificationsConfig(database.NotificationMethodSmtp)
|
||||
@@ -1697,9 +1702,12 @@ func TestDisabledBeforeEnqueue(t *testing.T) {
|
||||
require.NoError(t, err, "failed to set preferences")
|
||||
require.EqualValues(t, 1, n, "unexpected number of affected rows")
|
||||
|
||||
// THEN: enqueuing the "workspace deleted" notification should fail with an error
|
||||
_, err = enq.Enqueue(ctx, user.ID, templateID, map[string]string{}, "test")
|
||||
require.ErrorIs(t, err, notifications.ErrCannotEnqueueDisabledNotification, "enqueueing did not fail with expected error")
|
||||
// THEN: enqueuing the "workspace deleted" notification should fail be
|
||||
// a no-op that produces a debug log
|
||||
notifIDs, err := enq.Enqueue(ctx, user.ID, templateID, map[string]string{}, "test")
|
||||
require.NoError(t, err)
|
||||
require.Contains(t, logbuf.String(), notifications.ErrCannotEnqueueDisabledNotification.Error())
|
||||
require.Empty(t, notifIDs)
|
||||
}
|
||||
|
||||
// TestDisabledAfterEnqueue ensures that notifications enqueued before a notification template was disabled will not be
|
||||
@@ -1909,7 +1917,8 @@ func TestNotificationDuplicates(t *testing.T) {
|
||||
|
||||
ctx := dbauthz.AsNotifier(testutil.Context(t, testutil.WaitSuperLong))
|
||||
store, pubsub := dbtestutil.NewDB(t)
|
||||
logger := testutil.Logger(t)
|
||||
logbuf := strings.Builder{}
|
||||
logger := testutil.Logger(t).AppendSinks(sloghuman.Sink(&logbuf)).Leveled(slog.LevelDebug)
|
||||
|
||||
method := database.NotificationMethodSmtp
|
||||
cfg := defaultNotificationsConfig(method)
|
||||
@@ -1933,10 +1942,12 @@ func TestNotificationDuplicates(t *testing.T) {
|
||||
map[string]string{"initiator": "danny"}, "test", user.ID)
|
||||
require.NoError(t, err)
|
||||
|
||||
// WHEN: the second is enqueued, the enqueuer will reject the request.
|
||||
_, err = enq.Enqueue(ctx, user.ID, notifications.TemplateWorkspaceDeleted,
|
||||
// WHEN: the second is enqueued, the enqueuer will reject it as a duplicate.
|
||||
ids, err := enq.Enqueue(ctx, user.ID, notifications.TemplateWorkspaceDeleted,
|
||||
map[string]string{"initiator": "danny"}, "test", user.ID)
|
||||
require.ErrorIs(t, err, notifications.ErrDuplicate)
|
||||
require.NoError(t, err)
|
||||
require.Contains(t, logbuf.String(), notifications.ErrDuplicate.Error())
|
||||
require.Empty(t, ids)
|
||||
|
||||
// THEN: when the clock is advanced 24h, the notification will be accepted.
|
||||
// NOTE: the time is used in the dedupe hash, so by advancing 24h we're creating a distinct notification from the one
|
||||
|
||||
Reference in New Issue
Block a user