From 12891ec388798c5f2ec21e7f7906ad766d079f11 Mon Sep 17 00:00:00 2001 From: Roberto Sebestyen Date: Sun, 15 Jan 2023 23:35:23 -0500 Subject: [PATCH] better logging --- src/cron-job.ts | 7 ++++++- test/cron-scheduler.test.ts | 13 +++++++++++++ 2 files changed, 19 insertions(+), 1 deletion(-) diff --git a/src/cron-job.ts b/src/cron-job.ts index cfa17c0..24f97cd 100644 --- a/src/cron-job.ts +++ b/src/cron-job.ts @@ -27,8 +27,12 @@ export class CronJob { this.throwError(`End date cannot be before start date, start: ${this._jobOptions.startDate.toISOString()} end: ${this._jobOptions.endDate.toISOString()}`); } + let execIterations = ''; + if (this._jobOptions.numberOfScheduledIterationsToExecute) { + execIterations = ` for ${this._jobOptions.numberOfScheduledIterationsToExecute} iterations.`; + } this._scheduleGenerator = new CronScheduleGenerator(cronSchedule, this._jobOptions.startDate!); - this.log('info', `Scheduled to execute: ${this._scheduleGenerator.englishDescriptionOfSchedule}`); + this.log('info', `Scheduled to execute: ${this._scheduleGenerator.englishDescriptionOfSchedule}${execIterations}`); this._jobRunnerPromise = new Promise((resolve, reject) => { this._resolveJobRunner = resolve; @@ -135,6 +139,7 @@ export class CronJob { const now = this.getNow(); try { this.numberOfExecutedIterations += 1; + this.log('info', `Executing iteration #${this.numberOfExecutedIterations}`); // bind the "this" context because it gets lost const logger = this.log.bind(this); const actionResult = this.jobWorkerFunction(now, logger); diff --git a/test/cron-scheduler.test.ts b/test/cron-scheduler.test.ts index b33e34f..20e6cd6 100644 --- a/test/cron-scheduler.test.ts +++ b/test/cron-scheduler.test.ts @@ -163,12 +163,15 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Hello this is a test 2010-01-01T00:01:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:02:00.000Z the time is now 2010-01-01T00:01:00.000Z.', + 'Job [testjob123]: Executing iteration #2', 'Job [testjob123]: Hello this is a test 2010-01-01T00:02:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:03:00.000Z the time is now 2010-01-01T00:02:00.000Z.', + 'Job [testjob123]: Executing iteration #3', 'Job [testjob123]: Hello this is a test 2010-01-01T00:03:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: End date reached, resolving job promise...', @@ -225,12 +228,15 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Hello this is a test 2010-01-01T00:01:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:02:00.000Z the time is now 2010-01-01T00:01:00.000Z.', + 'Job [testjob123]: Executing iteration #2', 'Job [testjob123]: Hello this is a test 2010-01-01T00:02:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:03:00.000Z the time is now 2010-01-01T00:02:00.000Z.', + 'Job [testjob123]: Executing iteration #3', 'Job [testjob123]: Hello this is a test 2010-01-01T00:03:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: End date reached, resolving job promise...', @@ -342,6 +348,7 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Hello this is a test 2010-01-01T00:01:00.000Z', 'Job [testjob123]: Scheduled did not finish!', ]); @@ -401,6 +408,7 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Scheduled did not finish!', ]); @@ -461,6 +469,7 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Scheduled did not finish!', ]); @@ -521,6 +530,7 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Scheduled did not finish!', ]); @@ -591,12 +601,15 @@ describe('chron scheduler', function () { expect(consoleMessages).eql([ 'Job [testjob123]: Scheduled to execute: At every minute', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:01:00.000Z the time is now 2010-01-01T00:00:00.000Z.', + 'Job [testjob123]: Executing iteration #1', 'Job [testjob123]: Hello this is a test 2010-01-01T00:01:00.000Z', 'Job [testjob123]: Scheduled did not finish!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:02:00.000Z the time is now 2010-01-01T00:01:00.000Z.', + 'Job [testjob123]: Executing iteration #2', 'Job [testjob123]: Hello this is a test 2010-01-01T00:02:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: Scheduling to trigger in the next 60000 ms, at 2010-01-01T00:03:00.000Z the time is now 2010-01-01T00:02:00.000Z.', + 'Job [testjob123]: Executing iteration #3', 'Job [testjob123]: Hello this is a test 2010-01-01T00:03:00.000Z', 'Job [testjob123]: Scheduled trigger finished!', 'Job [testjob123]: End date reached, resolving job promise...',