Log early lock expiration

CHANGELOG.md

@@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 
 ### Added
 
+- `ManagedScheduler`
+	- warns in case lock was released before job finished (via optional logger)
 - `ExplainCommand`
 	- explains cron expression syntax
 - `ListCommand`

composer.json

@@ -34,6 +34,7 @@
 		"orisai/clock": "^1.2.0",
 		"orisai/cron-expression-explainer": "^1.0.0",
 		"orisai/exceptions": "^1.1.0",
+		"psr/log": "^1.0.0|^2.0.0|^3.0.0",
 		"symfony/console": "^5.3.0|^6.0.0",
 		"symfony/lock": "^5.3.0|^6.0.0",
 		"symfony/polyfill-php80": "^1.29.0",

docs/README.md

@@ -17,6 +17,7 @@ Cron job scheduler - with locks, parallelism and more
 	- [Before run event](#before-run-event)
 	- [After run event](#after-run-event)
 - [Handling errors](#handling-errors)
+- [Logging potential problems](#logging-potential-problems)
 - [Locks and job overlapping](#locks-and-job-overlapping)
 - [Parallelization and process isolation](#parallelization-and-process-isolation)
 - [Job types](#job-types)
@@ -358,6 +359,21 @@ $errorHandler = function(Throwable $throwable, JobInfo $info, JobResult $result)
 $scheduler = new SimpleScheduler($errorHandler);
 ```
 
+## Logging potential problems
+
+Using a [PSR-3](https://www.php-fig.org/psr/psr-3/)-compatible logger
+(like [Monolog](https://github.com/Seldaek/monolog)) you may log some situations which do not fail the job, but are most
+certainly unwanted:
+
+- [Lock](#locks-and-job-overlapping) was released before the job finished. Your job has access to the lock and should
+  extend the lock time so this does not happen.
+
+```php
+use Orisai\Scheduler\SimpleScheduler;
+
+$scheduler = new SimpleScheduler(null, null, null, null, $logger);
+```
+
 ## Locks and job overlapping
 
 Jobs are time-based and simply run at specified intervals. If they take too long, they may overlap and run

src/ManagedScheduler.php

@@ -25,6 +25,8 @@
 use Orisai\Scheduler\Status\RunParameters;
 use Orisai\Scheduler\Status\RunSummary;
 use Psr\Clock\ClockInterface;
+use Psr\Log\LoggerInterface;
+use Psr\Log\NullLogger;
 use Symfony\Component\Lock\LockFactory;
 use Symfony\Component\Lock\Store\InMemoryStore;
 use Throwable;
@@ -44,6 +46,8 @@ class ManagedScheduler implements Scheduler
 
 	private Clock $clock;
 
+	private LoggerInterface $logger;
+
 	/** @var list<Closure(JobInfo, JobResult): void> */
 	private array $lockedJobCallbacks = [];
 
@@ -67,13 +71,15 @@ public function __construct(
 		?Closure $errorHandler = null,
 		?LockFactory $lockFactory = null,
 		?JobExecutor $executor = null,
-		?ClockInterface $clock = null
+		?ClockInterface $clock = null,
+		?LoggerInterface $logger = null
 	)
 	{
 		$this->jobManager = $jobManager;
 		$this->errorHandler = $errorHandler;
 		$this->lockFactory = $lockFactory ?? new LockFactory(new InMemoryStore());
 		$this->clock = ClockAdapterFactory::create($clock ?? new SystemClock());
+		$this->logger = $logger ?? new NullLogger();
 
 		$this->executor = $executor ?? new BasicJobExecutor(
 			$this->clock,
@@ -276,6 +282,12 @@ private function runInternal($id, JobSchedule $jobSchedule, int $runSecond): arr
 				// Handled bellow
 			}
 
+			if ($lock->isExpired()) {
+				$this->logger->warning("Lock of job '$id' expired before the job finished.", [
+					'id' => $id,
+				]);
+			}
+
 			$result = new JobResult(
 				$expression,
 				$this->getCurrentTime($jobSchedule),

src/SimpleScheduler.php

@@ -9,6 +9,7 @@
 use Orisai\Scheduler\Job\Job;
 use Orisai\Scheduler\Manager\SimpleJobManager;
 use Psr\Clock\ClockInterface;
+use Psr\Log\LoggerInterface;
 use Symfony\Component\Lock\LockFactory;
 
 final class SimpleScheduler extends ManagedScheduler
@@ -20,7 +21,8 @@ public function __construct(
 		?Closure $errorHandler = null,
 		?LockFactory $lockFactory = null,
 		?JobExecutor $executor = null,
-		?ClockInterface $clock = null
+		?ClockInterface $clock = null,
+		?LoggerInterface $logger = null
 	)
 	{
 		$this->jobManager = new SimpleJobManager();
@@ -31,6 +33,7 @@ public function __construct(
 			$lockFactory,
 			$executor,
 			$clock,
+			$logger,
 		);
 	}
 

tests/Doubles/TestExpiredLockFactory.php

@@ -0,0 +1,33 @@
+<?php declare(strict_types = 1);
+
+namespace Tests\Orisai\Scheduler\Doubles;
+
+use Symfony\Component\Lock\Key;
+use Symfony\Component\Lock\LockFactory;
+use Symfony\Component\Lock\LockInterface;
+use Symfony\Component\Lock\Store\InMemoryStore;
+
+final class TestExpiredLockFactory extends LockFactory
+{
+
+	public function __construct()
+	{
+		// Just to satisfy the parent requirements
+		parent::__construct(new InMemoryStore());
+	}
+
+	public function createLock(string $resource, ?float $ttl = 300.0, ?bool $autoRelease = null): LockInterface
+	{
+		return $this->createLockFromKey(new Key($resource), $ttl, $autoRelease);
+	}
+
+	public function createLockFromKey(Key $key, ?float $ttl = 300.0, ?bool $autoRelease = null): LockInterface
+	{
+		$lock = new TestLock();
+		$lock->isExpired = true;
+		$lock->remainingLifetime = 0;
+
+		return $lock;
+	}
+
+}

tests/Doubles/TestLock.php

@@ -2,9 +2,9 @@
 
 namespace Tests\Orisai\Scheduler\Doubles;
 
-use Symfony\Component\Lock\LockInterface;
+use Symfony\Component\Lock\SharedLockInterface;
 
-final class TestLock implements LockInterface
+final class TestLock implements SharedLockInterface
 {
 
 	/** @var list<mixed> */
@@ -23,6 +23,13 @@ public function acquire(bool $blocking = false): bool
 		return true;
 	}
 
+	public function acquireRead(bool $blocking = false): bool
+	{
+		$this->calls[] = ['acquireRead', $blocking];
+
+		return true;
+	}
+
 	public function refresh(?float $ttl = null): void
 	{
 		$this->calls[] = ['refresh', $ttl];

tests/Doubles/TestLogger.php

@@ -0,0 +1,27 @@
+<?php declare(strict_types = 1);
+
+namespace Tests\Orisai\Scheduler\Doubles;
+
+use Psr\Log\AbstractLogger;
+use Stringable;
+
+final class TestLogger extends AbstractLogger
+{
+
+	/** @var list<mixed> */
+	public array $logs = [];
+
+	/**
+	 * @param string|Stringable $message
+	 * @param array<mixed> $context
+	 */
+	public function log($level, $message, array $context = []): void
+	{
+		$this->logs[] = [
+			$level,
+			$message,
+			$context,
+		];
+	}
+
+}

tests/Unit/SimpleSchedulerTest.php

@@ -31,7 +31,9 @@
 use Tests\Orisai\Scheduler\Doubles\CallbackList;
 use Tests\Orisai\Scheduler\Doubles\CustomNameJob;
 use Tests\Orisai\Scheduler\Doubles\JobInnerFailure;
+use Tests\Orisai\Scheduler\Doubles\TestExpiredLockFactory;
 use Tests\Orisai\Scheduler\Doubles\TestLockFactory;
+use Tests\Orisai\Scheduler\Doubles\TestLogger;
 use Throwable;
 use function count;
 use function rtrim;
@@ -975,6 +977,43 @@ public function testLockedJobEvent(): void
 		self::assertCount(2, $afterCollected);
 	}
 
+	public function testLockExpirationIsLogged(): void
+	{
+		$lockFactory = new TestExpiredLockFactory();
+		$clock = new FrozenClock(1);
+		$logger = new TestLogger();
+		$scheduler = new SimpleScheduler(null, $lockFactory, null, $clock, $logger);
+
+		$job = new CallbackJob(
+			static function (): void {
+				// Noop
+			},
+		);
+		$scheduler->addJob($job, new CronExpression('* * * * *'), 'first');
+		$scheduler->addJob($job, new CronExpression('* * * * *'), 'second');
+
+		$scheduler->run();
+		self::assertSame(
+			[
+				[
+					'warning',
+					"Lock of job 'first' expired before the job finished.",
+					[
+						'id' => 'first',
+					],
+				],
+				[
+					'warning',
+					"Lock of job 'second' expired before the job finished.",
+					[
+						'id' => 'second',
+					],
+				],
+			],
+			$logger->logs,
+		);
+	}
+
 	public function testRepeat(): void
 	{
 		$clock = new FrozenClock(1);