Hashar has uploaded a new change for review.

  https://gerrit.wikimedia.org/r/313625

Change subject: (WIP) jobqueue: runJobs log now have context passed to them 
(WIP)
......................................................................

(WIP) jobqueue: runJobs log now have context passed to them (WIP)

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 RELEASE-NOTES-1.28
M includes/jobqueue/JobRunner.php
2 files changed, 34 insertions(+), 5 deletions(-)


  git pull ssh://gerrit.wikimedia.org:29418/mediawiki/core 
refs/changes/25/313625/1

diff --git a/RELEASE-NOTES-1.28 b/RELEASE-NOTES-1.28
index 4f687a1..610ab94 100644
--- a/RELEASE-NOTES-1.28
+++ b/RELEASE-NOTES-1.28
@@ -206,6 +206,7 @@
 * IP::isConfiguredProxy() and IP::isTrustedProxy() were removed. Callers should
   migrate to using the same functions on a ProxyLookup instance, obtainable 
from
   MediaWikiServices.
+* (T146469) 'runJobs' logs now have context attached to them.
 
 == Compatibility ==
 
diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php
index ed3aa9a..6ed98e3 100644
--- a/includes/jobqueue/JobRunner.php
+++ b/includes/jobqueue/JobRunner.php
@@ -262,7 +262,10 @@
        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 is part of toString() but we need it here to 
ease processing
+                       'job_type' => $job->getType()
+               ] );
                $this->debugCallback( $msg );
 
                // Run the job...
@@ -318,12 +321,25 @@
                }
 
                if ( $status === false ) {
+                       $msg = $job->toString() . " t={job_duration} 
error={job_error}";
+                       $this->logger->error( $msg, [
+                               # Job type is part of toString() but we need it 
here to ease processing
+                               '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 is part of toString() but we need it 
here to ease processing
+                               'job_type' => $job->getType(),
+                               'job_duration' => $timeMs,
+                       ] );
+
                        $msg = $job->toString() . " t=$timeMs good";
-                       $this->logger->info( $msg );
                        $this->debugCallback( $msg );
                }
 
@@ -471,7 +487,12 @@
                if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) {
                        $msg = "Detected excessive memory usage 
($usedBytes/$maxBytes).";
                        $this->debugCallback( $msg );
-                       $this->logger->error( $msg );
+
+                       $msg = "Detected excessive memory usage 
({used_bytes}/{max_bytes}).";
+                       $this->logger->error( $msg, [
+                               'used_bytes' => $usedBytes,
+                               'max_bytes' => $maxBytes,
+                       ] );
 
                        return false;
                }
@@ -528,8 +549,15 @@
                }
 
                $ms = intval( 1000 * $time );
+
+               $msg = $job->toString() . " COMMIT ENQUEUED 
[{job_commit_write_ms}ms of writes]";
+               $this->logger->info( $msg, [
+                       # Job type is part of toString() but we need it here to 
ease processing
+                       '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: newchange
Gerrit-Change-Id: Ib6a771c7d3f83bd75b2994bfab9bbebfd1f5aa6c
Gerrit-PatchSet: 1
Gerrit-Project: mediawiki/core
Gerrit-Branch: master
Gerrit-Owner: Hashar <[email protected]>

_______________________________________________
MediaWiki-commits mailing list
[email protected]
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits

Reply via email to