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

diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php
index 49b7a45..db881d5 100644 (file)
--- a/includes/jobqueue/JobRunner.php
+++ b/includes/jobqueue/JobRunner.php
@@ -281,7 +281,9 @@ class JobRunner implements LoggerAwareInterface {
        private function executeJob( Job $job, LBFactory $lbFactory, $stats, $popTime ) {
                $jType = $job->getType();
                $msg = $job->toString() . " STARTING";
        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...
                $this->debugCallback( $msg );
 
                // Run the job...


@@ -339,12 +341,23 @@ class JobRunner implements LoggerAwareInterface {
                }
 
                if ( $status === false ) {
                }
 
                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}";
                        $msg = $job->toString() . " t=$timeMs error={$error}";

-                       $this->logger->error( $msg );

                        $this->debugCallback( $msg );
                } else {
                        $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";
                        $msg = $job->toString() . " t=$timeMs good";

-                       $this->logger->info( $msg );

                        $this->debugCallback( $msg );
                }
 
                        $this->debugCallback( $msg );
                }
 


@@ -488,9 +501,14 @@ class JobRunner implements LoggerAwareInterface {
                }
                $usedBytes = memory_get_usage();
                if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) {
                }
                $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 );
                        $msg = "Detected excessive memory usage ($usedBytes/$maxBytes).";
                        $this->debugCallback( $msg );

-                       $this->logger->error( $msg );

 
                        return false;
                }
 
                        return false;
                }


@@ -552,8 +570,14 @@ class JobRunner implements LoggerAwareInterface {
                }
 
                $ms = intval( 1000 * $time );
                }
 
                $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]";
                $msg = $job->toString() . " COMMIT ENQUEUED [{$ms}ms of writes]";

-               $this->logger->info( $msg );

                $this->debugCallback( $msg );
 
                // Wait for an exclusive lock to commit
                $this->debugCallback( $msg );
 
                // Wait for an exclusive lock to commit