improvement(logs): log each admission refusal once per window and demote per-request success chatter to debug (#9722)

Admission gate warnings now share the blocked-run throttle with their error row, so a sender redelivering into a refusal logs once per window instead of on every attempt. The webhook processor no longer repeats the refusal preprocessing already logged.

Per-request success-path lines (preprocessing steps, valid-token checks, billing intermediate steps, Slack trigger-filter skips, table upserts, trigger and execution-state selection, storage uploads) move to debug. The billing top-up line keeps the payer and model. PostHog upstream connection failures log at warn, and the idempotency failure warning uses a static message with fields.

Author: waleedlatif1

apps/sim/app/api/billing/update-cost/route.ts

@@ -196,7 +196,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
   const startTime = Date.now()
 
   try {
-    logger.info(`[${requestId}] Update cost request started`)
+    logger.debug(`[${requestId}] Update cost request started`)
 
     // Check authentication (internal API key)
     const authResult = checkInternalApiKey(req)
@@ -324,7 +324,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
       ...(idempotencyKey ? { [TraceAttr.BillingIdempotencyKey]: idempotencyKey } : {}),
     })
 
-    logger.info(`[${requestId}] Processing cost update`, {
+    logger.debug(`[${requestId}] Processing cost update`, {
       userId,
       cost,
       model,
@@ -408,7 +408,7 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
           }
         : undefined
 
-    logger.info(`[${requestId}] Billing payer resolved`, {
+    logger.debug(`[${requestId}] Billing payer resolved`, {
       userId,
       billingProtocol: protocol,
       billingResolution: getBillingResolution(isMarkerlessLegacy, billingAttribution),
@@ -443,7 +443,10 @@ async function updateCostInner(req: NextRequest, span: Span): Promise<NextRespon
     const billed = result.billed
     logger.info(`[${requestId}] Cumulative cost top-up`, {
       userId,
+      billingPayer: billingContext?.billingEntity ?? { type: 'user', id: userId },
+      workspaceId: resolvedWorkspaceId,
       source,
+      model,
       cumulativeCost: cost,
       billedDelta: result.delta,
       newTotal: result.total,

apps/sim/app/ingest/[[...path]]/route.test.ts

@@ -31,7 +31,7 @@ describe('PostHog ingest proxy', () => {
     const response = await POST(createIngestRequest(controller.signal))
 
     expect(response.status).toBe(499)
-    expect(logger.error).not.toHaveBeenCalled()
+    expect(logger.warn).not.toHaveBeenCalled()
   })
 
   it('reports an upstream failure while the client is still connected', async () => {
@@ -40,7 +40,7 @@ describe('PostHog ingest proxy', () => {
     const response = await POST(createIngestRequest())
 
     expect(response.status).toBe(502)
-    expect(logger.error).toHaveBeenCalledWith(
+    expect(logger.warn).toHaveBeenCalledWith(
       'PostHog proxy error',
       expect.objectContaining({ error: 'The operation timed out.' })
     )

apps/sim/app/ingest/[[...path]]/route.ts

@@ -61,7 +61,7 @@ async function handler(request: NextRequest) {
       logger.info('Client closed PostHog proxy request', { method: request.method })
       return new NextResponse(null, { status: 499 })
     }
-    logger.error('PostHog proxy error', {
+    logger.warn('PostHog proxy error', {
       url,
       method: request.method,
       error: toError(error).message,

apps/sim/background/webhook-execution.ts

@@ -1100,7 +1100,7 @@ async function executeWebhookJobInternal(
         }
       }
 
-      logger.info(`[${requestId}] Executing workflow for ${payload.provider} webhook`)
+      logger.debug(`[${requestId}] Executing workflow for ${payload.provider} webhook`)
 
       const metadata: ExecutionMetadata = {
         requestId,

apps/sim/executor/handlers/trigger/handler.ts

@@ -15,7 +15,7 @@ export class TriggerBlockHandler implements BlockHandler {
     block: SerializedBlock,
     inputs: Record<string, any>
   ): Promise<any> {
-    logger.info(`Executing trigger block: ${block.id} (Type: ${block.metadata?.id})`)
+    logger.debug(`Executing trigger block: ${block.id} (Type: ${block.metadata?.id})`)
 
     if (block.metadata?.id === BlockType.STARTER) {
       return this.executeStarterBlock(ctx, block, inputs)

apps/sim/lib/core/idempotency/service.ts

@@ -714,7 +714,10 @@ export class IdempotencyService {
         )
       }
 
-      logger.warn(`Operation failed: ${claimResult.normalizedKey} - ${errorMessage}`)
+      logger.warn('Idempotent operation failed', {
+        key: claimResult.normalizedKey,
+        error: errorMessage,
+      })
       throw error
     }
   }

apps/sim/lib/execution/preprocessing.test.ts

@@ -15,6 +15,7 @@ import {
   billingUsageReservationMockFns,
 } from '@sim/testing/mocks/billing-usage-reservation.mock'
 import { executionLimitsMock } from '@sim/testing/mocks/execution-limits.mock'
+import { getMockLogger } from '@sim/testing/mocks/logger.mock'
 import { loggingSessionMockFns } from '@sim/testing/mocks/logging-session.mock'
 import { createMockRedis } from '@sim/testing/mocks/redis.mock'
 import { redisConfigMockFns, resetRedisConfigMock } from '@sim/testing/mocks/redis-config.mock'
@@ -1123,6 +1124,22 @@ describe('preprocessExecution admission rejection codes and blocked-run log thro
     expect(loggingSessionMockFns.mockSafeCompleteWithError).toHaveBeenCalledTimes(1)
   })
 
+  it('logs one warning for repeated refusals of a workflow by the same gate', async () => {
+    const workflowId = 'workflow-1'
+    const logger = getMockLogger('ExecutionPreprocessing')
+    logger.warn.mockClear()
+
+    for (let attempt = 0; attempt < 3; attempt++) {
+      await refuse(workflowId, { throttleErrorLogs: true })
+    }
+
+    expect(logger.warn).toHaveBeenCalledOnce()
+    expect(logger.warn).toHaveBeenCalledWith(
+      'Attributed usage gate blocked actor',
+      expect.objectContaining({ workflowId })
+    )
+  })
+
   it('writes a row for a different gate refusing the same workflow inside the window', async () => {
     const workflowId = 'workflow-1'
     await refuse(workflowId, { throttleErrorLogs: true })

apps/sim/lib/execution/preprocessing.ts

@@ -362,6 +362,12 @@ function startAdmissionReads(params: {
   }
 }
 
+/** A gate refusal's warning, emitted alongside its error row so both share the throttle window. */
+interface GateWarning {
+  message: string
+  fields: Record<string, unknown>
+}
+
 export async function preprocessExecution(
   options: PreprocessExecutionOptions
 ): Promise<PreprocessExecutionResult> {
@@ -401,11 +407,15 @@ export async function preprocessExecution(
   const isFailureLogSuppressed = (failure: PreprocessExecutionError): boolean =>
     suppressRetryableFailureLogs && failure.statusCode >= 500 && failure.retryable === true
 
-  /** Records an admission gate's error row, at most once per gate and outcome per window when throttled. */
+  /**
+   * Records an admission gate's warning and error row, at most once per gate and outcome per window
+   * when throttled, so a sender redelivering into a refusal does not log every attempt.
+   */
   const recordGateFailure = async (
     gate: 'ban' | 'usage' | 'rate-limit' | 'reservation',
     failure: PreprocessExecutionError,
-    record: Parameters<typeof logPreprocessingError>[0]
+    record: Parameters<typeof logPreprocessingError>[0],
+    warning?: GateWarning
   ): Promise<void> => {
     if (isFailureLogSuppressed(failure)) return
     if (
@@ -416,10 +426,12 @@ export async function preprocessExecution(
     ) {
       return
     }
+    if (warning)
+      logger.warn(warning.message, { requestId, workflowId, triggerType, ...warning.fields })
     await recordPreprocessingError(record)
   }
 
-  logger.info(`[${requestId}] Starting execution preprocessing`, {
+  logger.debug(`[${requestId}] Starting execution preprocessing`, {
     workflowId,
     userId,
     triggerType,
@@ -577,21 +589,21 @@ export async function preprocessExecution(
       }
       actorUserId = validatedAttribution.actorUserId
       billingAttribution = validatedAttribution
-      logger.info(`[${requestId}] Reusing serialized billing attribution`, {
+      logger.debug(`[${requestId}] Reusing serialized billing attribution`, {
         actorUserId,
         billingEntity: billingAttribution.billingEntity,
       })
     }
 
     if (!actorUserId && useAuthenticatedUserAsActor && userId) {
       actorUserId = userId
-      logger.info(`[${requestId}] Using authenticated user as actor: ${actorUserId}`)
+      logger.debug(`[${requestId}] Using authenticated user as actor: ${actorUserId}`)
     }
 
     if (!actorUserId) {
       billingAttribution = await admission.attributionFor(workspaceId)
       actorUserId = billingAttribution.actorUserId
-      logger.info(`[${requestId}] Using atomically resolved system actor and payer`, {
+      logger.debug(`[${requestId}] Using atomically resolved system actor and payer`, {
         actorUserId,
         billingEntity: billingAttribution.billingEntity,
       })
@@ -672,6 +684,7 @@ export async function preprocessExecution(
   interface GateFailure {
     response: PreprocessExecutionFailure
     recordError?: Parameters<typeof recordPreprocessingError>[0]
+    warning?: GateWarning
   }
 
   /** Usage figures captured by the read gate and reused by the atomic reservation. */
@@ -690,13 +703,8 @@ export async function preprocessExecution(
     try {
       const bannedUserIds = await gateReads.bannedUserIds
       if (bannedUserIds.length > 0) {
-        logger.warn(`[${requestId}] Execution blocked: banned account`, {
-          workflowId,
-          bannedUserIds,
-          triggerType,
-        })
-
         return {
+          warning: { message: 'Execution blocked: banned account', fields: { bannedUserIds } },
           response: {
             success: false,
             error: {
@@ -774,16 +782,17 @@ export async function preprocessExecution(
           }
         : null
       if (usageCheck.isExceeded) {
-        logger.warn(`[${requestId}] Attributed usage gate blocked actor ${actorUserId}.`, {
-          currentUsage: snapshot?.currentUsage,
-          limit: snapshot?.limit,
-          scope: usageCheck.scope,
-          workflowId,
-          triggerType,
-        })
-
         return {
           failure: {
+            warning: {
+              message: 'Attributed usage gate blocked actor',
+              fields: {
+                actorUserId,
+                currentUsage: snapshot?.currentUsage,
+                limit: snapshot?.limit,
+                scope: usageCheck.scope,
+              },
+            },
             response: {
               success: false,
               error: {
@@ -876,13 +885,11 @@ export async function preprocessExecution(
       )
 
       if (!info.allowed) {
-        logger.warn(`[${requestId}] Rate limit exceeded for user ${actorUserId}`, {
-          triggerType,
-          remaining: info.remaining,
-          resetAt: info.resetAt,
-        })
-
         return {
+          warning: {
+            message: 'Rate limit exceeded',
+            fields: { actorUserId, remaining: info.remaining, resetAt: info.resetAt },
+          },
           response: {
             success: false,
             error: {
@@ -947,7 +954,8 @@ export async function preprocessExecution(
       await recordGateFailure(
         banFailure ? 'ban' : 'usage',
         readGateFailure.response.error,
-        readGateFailure.recordError
+        readGateFailure.recordError,
+        readGateFailure.warning
       )
     }
     return readGateFailure.response
@@ -959,7 +967,8 @@ export async function preprocessExecution(
       await recordGateFailure(
         'rate-limit',
         rateLimitFailure.response.error,
-        rateLimitFailure.recordError
+        rateLimitFailure.recordError,
+        rateLimitFailure.warning
       )
     }
     return rateLimitFailure.response
@@ -1009,12 +1018,6 @@ export async function preprocessExecution(
           reservation.reason
         )
         const message = RESERVATION_DENIAL_MESSAGE[reservation.reason]
-        logger.warn(`[${requestId}] Admission reservation full for user ${actorUserId}`, {
-          workflowId,
-          triggerType,
-          constraint: reservation.reason,
-        })
-
         const failure: PreprocessExecutionError = {
           message,
           statusCode: descriptor.statusCode,
@@ -1026,17 +1029,25 @@ export async function preprocessExecution(
             constraint: reservation.reason,
           },
         }
-        await recordGateFailure('reservation', failure, {
-          workflowId,
-          executionId,
-          triggerType,
-          requestId,
-          userId: actorUserId,
-          workspaceId,
-          errorMessage: message,
-          loggingSession: providedLoggingSession,
-          triggerData,
-        })
+        await recordGateFailure(
+          'reservation',
+          failure,
+          {
+            workflowId,
+            executionId,
+            triggerType,
+            requestId,
+            userId: actorUserId,
+            workspaceId,
+            errorMessage: message,
+            loggingSession: providedLoggingSession,
+            triggerData,
+          },
+          {
+            message: 'Admission reservation full',
+            fields: { actorUserId, constraint: reservation.reason },
+          }
+        )
 
         return { success: false, error: failure }
       }
@@ -1068,7 +1079,7 @@ export async function preprocessExecution(
     }
   }
 
-  logger.info(`[${requestId}] All preprocessing checks passed`, {
+  logger.debug(`[${requestId}] All preprocessing checks passed`, {
     workflowId,
     actorUserId,
     triggerType,

apps/sim/lib/oauth/credential-service.ts

@@ -1764,7 +1764,7 @@ export async function resolveCredentialTokenBundle(
     logger.error(`[${requestId}] Missing access token for credential`)
     return null
   }
-  if (!result.refreshed) logger.info(`[${requestId}] Access token is valid for credential`)
+  if (!result.refreshed) logger.debug(`[${requestId}] Access token is valid for credential`)
   return { accessToken: result.accessToken }
 }
 
@@ -1817,7 +1817,7 @@ export async function refreshTokenIfNeeded(
     throw new Error('OAuth access token expired and cannot be refreshed; reconnect the account')
   }
   if (result.kind === 'token') {
-    if (!result.refreshed) logger.info(`[${requestId}] Access token is valid`)
+    if (!result.refreshed) logger.debug(`[${requestId}] Access token is valid`)
     /** A row storing neither token returns its empty token as before; callers decide how to fail. */
     return {
       accessToken: result.accessToken ?? credential.accessToken,

apps/sim/lib/table/rows/service.ts

@@ -959,7 +959,7 @@ export async function upsertRow(
     }
   })
 
-  logger.info(
+  logger.debug(
     `[${requestId}] Upserted (${result.operation}) row ${result.row.id} in table ${data.tableId}`
   )