feat: downgrade log level callback succeeded (#2329)

packages/common/src/stopwatch.ts

@@ -1,9 +1,12 @@
 import dayjs from "dayjs";
+import duration from "dayjs/plugin/duration";
 import relativeTime from "dayjs/plugin/relativeTime";
 import updateLocale from "dayjs/plugin/updateLocale";
 
 dayjs.extend(relativeTime);
 dayjs.extend(updateLocale);
+dayjs.extend(duration);
+
 dayjs.updateLocale("en", {
   relativeTime: {
     future: "in %s",
@@ -38,6 +41,10 @@ export class Stopwatch {
     return dayjs().millisecond(this.startTime).fromNow(true);
   }
 
+  getElapsedInMilliseconds() {
+    return performance.now() - this.startTime;
+  }
+
   reset() {
     this.startTime = performance.now();
   }

packages/cron-jobs-core/src/creator.ts

@@ -16,6 +16,7 @@ export interface CreateCronJobCreatorOptions<TAllowedNames extends string> {
 
 interface CreateCronJobOptions {
   runOnStart?: boolean;
+  expectedMaximumDurationInMillis?: number;
   beforeStart?: () => MaybePromise<void>;
 }
 
@@ -25,6 +26,7 @@ const createCallback = <TAllowedNames extends string, TName extends TAllowedName
   options: CreateCronJobOptions,
   creatorOptions: CreateCronJobCreatorOptions<TAllowedNames>,
 ) => {
+  const expectedMaximumDurationInMillis = options.expectedMaximumDurationInMillis ?? 1000;
   return (callback: () => MaybePromise<void>) => {
     const catchingCallbackAsync = async () => {
       try {
@@ -34,9 +36,16 @@ const createCallback = <TAllowedNames extends string, TName extends TAllowedName
         const beforeCallbackTook = stopwatch.getElapsedInHumanWords();
         await callback();
         const callbackTook = stopwatch.getElapsedInHumanWords();
-        creatorOptions.logger.logInfo(
+        creatorOptions.logger.logDebug(
           `The callback of '${name}' cron job succeeded (before callback took ${beforeCallbackTook}, callback took ${callbackTook})`,
         );
+
+        const durationInMillis = stopwatch.getElapsedInMilliseconds();
+        if (durationInMillis > expectedMaximumDurationInMillis) {
+          creatorOptions.logger.logWarning(
+            `The callback of '${name}' succeeded but took ${(durationInMillis - expectedMaximumDurationInMillis).toFixed(2)}ms longer than expected (${expectedMaximumDurationInMillis}ms). This may indicate that your network performance, host performance or something else is too slow. If this happens too often, it should be looked into.`,
+          );
+        }
         await creatorOptions.onCallbackSuccess?.(name);
       } catch (error) {
         // eslint-disable-next-line @typescript-eslint/restrict-template-expressions

packages/cron-jobs-core/src/logger.ts

@@ -2,6 +2,7 @@ export interface Logger {
   logDebug(message: string): void;
   logInfo(message: string): void;
   logError(error: unknown): void;
+  logWarning(message: string): void;
 }
 
 export class ConsoleLogger implements Logger {
@@ -16,4 +17,8 @@ export class ConsoleLogger implements Logger {
   public logError(error: unknown) {
     console.error(error);
   }
+
+  public logWarning(message: string) {
+    console.warn(message);
+  }
 }

packages/cron-jobs/src/jobs/icons-updater.ts

@@ -11,6 +11,7 @@ import { createCronJob } from "../lib";
 
 export const iconsUpdaterJob = createCronJob("iconsUpdater", EVERY_WEEK, {
   runOnStart: true,
+  expectedMaximumDurationInMillis: 10 * 1000,
 }).withCallback(async () => {
   logger.info("Updating icon repository cache...");
   const stopWatch = new Stopwatch();

packages/cron-jobs/src/lib/index.ts

@@ -16,6 +16,10 @@ class WinstonCronJobLogger implements Logger {
   logError(error: unknown) {
     logger.error(error);
   }
+
+  logWarning(message: string) {
+    logger.warn(message);
+  }
 }
 
 export const { createCronJob, createCronJobGroup } = createCronJobFunctions<