jenkins-bot has submitted this change and it was merged. ( https://gerrit.wikimedia.org/r/313625 )
Change subject: jobqueue: Add job_type to PSR logging context ...................................................................... jobqueue: Add job_type to PSR logging context The mediawiki.runJobs errors are collected in Logstash but the whole job description and errors are a single field message. That is challenging to split logs per job type, get the longest running jobs ... That can be worked around on the log receiving side by parsing MediaWiki messages eg https://gerrit.wikimedia.org/r/#/c/312504/ Bryan Davis suggested a better long term solution is to use the PSR3 logger with structured log messages. Culprit: 'type' is a reverved word. Hence prefix all context variables with 'job_'. Bug: T146469 Change-Id: Ib6a771c7d3f83bd75b2994bfab9bbebfd1f5aa6c --- M includes/jobqueue/JobRunner.php 1 file changed, 29 insertions(+), 5 deletions(-) Approvals: Aaron Schulz: Looks good to me, approved Krinkle: Looks good to me, but someone else must approve jenkins-bot: Verified diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php index 49b7a45..db881d5e 100644 --- a/includes/jobqueue/JobRunner.php +++ b/includes/jobqueue/JobRunner.php @@ -281,7 +281,9 @@ private function executeJob( Job $job, LBFactory $lbFactory, $stats, $popTime ) { $jType = $job->getType(); $msg = $job->toString() . " STARTING"; - $this->logger->debug( $msg ); + $this->logger->debug( $msg, [ + 'job_type' => $job->getType(), + ] ); $this->debugCallback( $msg ); // Run the job... @@ -339,12 +341,23 @@ } if ( $status === false ) { + $msg = $job->toString() . " t={job_duration} error={job_error}"; + $this->logger->error( $msg, [ + 'job_type' => $job->getType(), + 'job_duration' => $timeMs, + 'job_error' => $error, + ] ); + $msg = $job->toString() . " t=$timeMs error={$error}"; - $this->logger->error( $msg ); $this->debugCallback( $msg ); } else { + $msg = $job->toString() . " t={job_duration} good"; + $this->logger->info( $msg, [ + 'job_type' => $job->getType(), + 'job_duration' => $timeMs, + ] ); + $msg = $job->toString() . " t=$timeMs good"; - $this->logger->info( $msg ); $this->debugCallback( $msg ); } @@ -488,9 +501,14 @@ } $usedBytes = memory_get_usage(); if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) { + $msg = "Detected excessive memory usage ({used_bytes}/{max_bytes})."; + $this->logger->error( $msg, [ + 'used_bytes' => $usedBytes, + 'max_bytes' => $maxBytes, + ] ); + $msg = "Detected excessive memory usage ($usedBytes/$maxBytes)."; $this->debugCallback( $msg ); - $this->logger->error( $msg ); return false; } @@ -552,8 +570,14 @@ } $ms = intval( 1000 * $time ); + + $msg = $job->toString() . " COMMIT ENQUEUED [{job_commit_write_ms}ms of writes]"; + $this->logger->info( $msg, [ + 'job_type' => $job->getType(), + 'job_commit_write_ms' => $ms, + ] ); + $msg = $job->toString() . " COMMIT ENQUEUED [{$ms}ms of writes]"; - $this->logger->info( $msg ); $this->debugCallback( $msg ); // Wait for an exclusive lock to commit -- To view, visit https://gerrit.wikimedia.org/r/313625 To unsubscribe, visit https://gerrit.wikimedia.org/r/settings Gerrit-MessageType: merged Gerrit-Change-Id: Ib6a771c7d3f83bd75b2994bfab9bbebfd1f5aa6c Gerrit-PatchSet: 5 Gerrit-Project: mediawiki/core Gerrit-Branch: master Gerrit-Owner: Hashar <has...@free.fr> Gerrit-Reviewer: Aaron Schulz <asch...@wikimedia.org> Gerrit-Reviewer: BryanDavis <bda...@wikimedia.org> Gerrit-Reviewer: Hashar <has...@free.fr> Gerrit-Reviewer: Krinkle <krinklem...@gmail.com> Gerrit-Reviewer: jenkins-bot <> _______________________________________________ MediaWiki-commits mailing list MediaWiki-commits@lists.wikimedia.org https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
