Reduce false error logging (round 1) (#2415)

* Don't log an error when the snapshot shouldn't be created, it's normal for this to happen

* Slack alerts, skip `account_inactive` errors

* v3 finalize run with no locked isn't an error

* Another false error

* Finalize run CRASHED runs were logging errors

* All slack alert errors are warnings except invalid blocks

Author: matt-aitken

apps/webapp/app/v3/services/alerts/deliverAlert.server.ts

@@ -158,7 +158,7 @@ export class DeliverAlertService extends BaseService {
       }
     } catch (error) {
       if (error instanceof SkipRetryError) {
-        logger.error("[DeliverAlert] Skipping retry", {
+        logger.warn("[DeliverAlert] Skipping retry", {
           reason: error.message,
         });
 
@@ -951,7 +951,7 @@ export class DeliverAlertService extends BaseService {
       return await client.chat.postMessage(message);
     } catch (error) {
       if (isWebAPIRateLimitedError(error)) {
-        logger.error("[DeliverAlert] Slack rate limited", {
+        logger.warn("[DeliverAlert] Slack rate limited", {
           error,
           message,
         });
@@ -960,7 +960,7 @@ export class DeliverAlertService extends BaseService {
       }
 
       if (isWebAPIHTTPError(error)) {
-        logger.error("[DeliverAlert] Slack HTTP error", {
+        logger.warn("[DeliverAlert] Slack HTTP error", {
           error,
           message,
         });
@@ -969,7 +969,7 @@ export class DeliverAlertService extends BaseService {
       }
 
       if (isWebAPIRequestError(error)) {
-        logger.error("[DeliverAlert] Slack request error", {
+        logger.warn("[DeliverAlert] Slack request error", {
           error,
           message,
         });
@@ -978,7 +978,7 @@ export class DeliverAlertService extends BaseService {
       }
 
       if (isWebAPIPlatformError(error)) {
-        logger.error("[DeliverAlert] Slack platform error", {
+        logger.warn("[DeliverAlert] Slack platform error", {
           error,
           message,
         });
@@ -991,10 +991,19 @@ export class DeliverAlertService extends BaseService {
           throw new SkipRetryError("Slack invalid blocks");
         }
 
+        if (error.data.error === "account_inactive") {
+          logger.info("[DeliverAlert] Slack account inactive, skipping retry", {
+            error,
+            message,
+          });
+
+          throw new SkipRetryError("Slack account inactive");
+        }
+
         throw new Error("Slack platform error");
       }
 
-      logger.error("[DeliverAlert] Failed to send slack message", {
+      logger.warn("[DeliverAlert] Failed to send slack message", {
         error,
         message,
       });

apps/webapp/app/v3/services/finalizeTaskRun.server.ts

@@ -150,7 +150,7 @@ export class FinalizeTaskRunService extends BaseService {
     }
 
     if (isFatalRunStatus(run.status)) {
-      logger.error("FinalizeTaskRunService: Fatal status", { runId: run.id, status: run.status });
+      logger.warn("FinalizeTaskRunService: Fatal status", { runId: run.id, status: run.status });
 
       const extendedRun = await this._prisma.taskRun.findFirst({
         where: { id: run.id },
@@ -170,7 +170,7 @@ export class FinalizeTaskRunService extends BaseService {
       });
 
       if (extendedRun && extendedRun.runtimeEnvironment.type !== "DEVELOPMENT") {
-        logger.error("FinalizeTaskRunService: Fatal status, requesting worker exit", {
+        logger.warn("FinalizeTaskRunService: Fatal status, requesting worker exit", {
           runId: run.id,
           status: run.status,
         });
@@ -305,9 +305,10 @@ export class FinalizeTaskRunService extends BaseService {
     });
 
     if (!run.lockedById) {
-      logger.error(
+      // This happens when a run is expired or was cancelled before an attempt, it's not a problem
+      logger.info(
         "FinalizeTaskRunService: No lockedById, so can't get the BackgroundWorkerTask. Not creating an attempt.",
-        { runId: run.id }
+        { runId: run.id, status: run.status }
       );
       return;
     }

internal-packages/run-engine/src/engine/systems/checkpointSystem.ts

@@ -62,7 +62,7 @@ export class CheckpointSystem {
           snapshot.executionStatus === "QUEUED_EXECUTING");
 
       if (!isValidSnapshot) {
-        this.$.logger.error("Tried to createCheckpoint on an invalid snapshot", {
+        this.$.logger.info("Tried to createCheckpoint on an invalid snapshot", {
           snapshot,
           snapshotId,
         });

internal-packages/run-engine/src/engine/systems/dequeueSystem.ts

@@ -8,7 +8,7 @@ import { PrismaClientOrTransaction } from "@trigger.dev/database";
 import { getRunWithBackgroundWorkerTasks } from "../db/worker.js";
 import { sendNotificationToWorker } from "../eventBus.js";
 import { getMachinePreset } from "../machinePresets.js";
-import { isDequeueableExecutionStatus } from "../statuses.js";
+import { isDequeueableExecutionStatus, isExecuting } from "../statuses.js";
 import { RunEngineOptions } from "../types.js";
 import { ExecutionSnapshotSystem, getLatestExecutionSnapshot } from "./executionSnapshotSystem.js";
 import { RunAttemptSystem } from "./runAttemptSystem.js";
@@ -132,9 +132,16 @@ export class DequeueSystem {
                   },
                   tx: prisma,
                 });
-                this.$.logger.error(
-                  `RunEngine.dequeueFromWorkerQueue(): Run is not in a valid state to be dequeued: ${runId}\n ${snapshot.id}:${snapshot.executionStatus}`
-                );
+
+                if (isExecuting(snapshot.executionStatus)) {
+                  this.$.logger.error(
+                    `RunEngine.dequeueFromWorkerQueue(): Run is not in a valid state to be dequeued: ${runId}\n ${snapshot.id}:${snapshot.executionStatus}`
+                  );
+                } else {
+                  this.$.logger.warn(
+                    `RunEngine.dequeueFromWorkerQueue(): Run is in an expected not valid state to be dequeued: ${runId}\n ${snapshot.id}:${snapshot.executionStatus}`
+                  );
+                }
 
                 return;
               }