From b8c57efaad12461efdb0f3778594b71952793577 Mon Sep 17 00:00:00 2001 From: Joas Schilling Date: Wed, 20 Dec 2023 15:35:40 +0100 Subject: [PATCH] fix(log): Improve logging of background job details for better reproduction/debugging Signed-off-by: Joas Schilling --- cron.php | 7 ++++--- lib/public/BackgroundJob/Job.php | 7 ++++--- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/cron.php b/cron.php index 41c5157befa..a6716a68714 100644 --- a/cron.php +++ b/cron.php @@ -148,7 +148,8 @@ try { break; } - $logger->debug('CLI cron call has selected job with ID ' . strval($job->getId()), ['app' => 'cron']); + $jobDetails = get_class($this) . ' (id: ' . $this->getId() . ', arguments: ' . json_encode($this->getArgument()) . ')'; + $logger->debug('CLI cron call has selected job ' . $jobDetails, ['app' => 'cron']); $memoryBefore = memory_get_usage(); $memoryPeakBefore = memory_get_peak_usage(); @@ -159,10 +160,10 @@ try { $memoryPeakAfter = memory_get_peak_usage(); if ($memoryAfter - $memoryBefore > 10_000_000) { - $logger->warning('Used memory grew by more than 10 MB when executing job ' . get_class($job) . ' : ' . \OCP\Util::humanFileSize($memoryAfter). ' (before: ' . \OCP\Util::humanFileSize($memoryBefore) . ')', ['app' => 'cron']); + $logger->warning('Used memory grew by more than 10 MB when executing job ' . $jobDetails . ': ' . \OCP\Util::humanFileSize($memoryAfter). ' (before: ' . \OCP\Util::humanFileSize($memoryBefore) . ')', ['app' => 'cron']); } if ($memoryPeakAfter > 300_000_000) { - $logger->warning('Cron job used more than 300 MB of ram after executing job ' . get_class($job) . ': ' . \OCP\Util::humanFileSize($memoryPeakAfter) . ' (before: ' . \OCP\Util::humanFileSize($memoryPeakBefore) . ')', ['app' => 'cron']); + $logger->warning('Cron job used more than 300 MB of ram after executing job ' . $jobDetails . ': ' . \OCP\Util::humanFileSize($memoryPeakAfter) . ' (before: ' . \OCP\Util::humanFileSize($memoryPeakBefore) . ')', ['app' => 'cron']); } // clean up after unclean jobs diff --git a/lib/public/BackgroundJob/Job.php b/lib/public/BackgroundJob/Job.php index a574e90e1a0..2842486b74d 100644 --- a/lib/public/BackgroundJob/Job.php +++ b/lib/public/BackgroundJob/Job.php @@ -76,16 +76,17 @@ abstract class Job implements IJob, IParallelAwareJob { $logger = $this->logger ?? \OCP\Server::get(LoggerInterface::class); try { + $jobDetails = get_class($this) . ' (id: ' . $this->getId() . ', arguments: ' . json_encode($this->getArgument()) . ')'; $jobStartTime = $this->time->getTime(); - $logger->debug('Run ' . get_class($this) . ' job with ID ' . $this->getId(), ['app' => 'cron']); + $logger->debug('Starting job ' . $jobDetails, ['app' => 'cron']); $this->run($this->argument); $timeTaken = $this->time->getTime() - $jobStartTime; - $logger->debug('Finished ' . get_class($this) . ' job with ID ' . $this->getId() . ' in ' . $timeTaken . ' seconds', ['app' => 'cron']); + $logger->debug('Finished job ' . $jobDetails . ' in ' . $timeTaken . ' seconds', ['app' => 'cron']); $jobList->setExecutionTime($this, $timeTaken); } catch (\Throwable $e) { if ($logger) { - $logger->error('Error while running background job (class: ' . get_class($this) . ', arguments: ' . print_r($this->argument, true) . ')', [ + $logger->error('Error while running background job ' . $jobDetails, [ 'app' => 'core', 'exception' => $e, ]); -- 2.39.5