From 40a9ad6ea1cd300075eecf43e70cc8ade8828919 Mon Sep 17 00:00:00 2001
From: Antoine Musso <hashar@free.fr>
Date: Fri, 30 Sep 2016 23:34:33 +0200
Subject: [PATCH] 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
---
 includes/jobqueue/JobRunner.php | 34 ++++++++++++++++++++++++++++-----
 1 file changed, 29 insertions(+), 5 deletions(-)

diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php
index 49b7a459a6..db881d5eb9 100644
--- 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";
-		$this->logger->debug( $msg );
+		$this->logger->debug( $msg, [
+			'job_type' => $job->getType(),
+		] );
 		$this->debugCallback( $msg );
 
 		// Run the job...
@@ -339,12 +341,23 @@ class JobRunner implements LoggerAwareInterface {
 		}
 
 		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 @@ class JobRunner implements LoggerAwareInterface {
 		}
 		$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 @@ class JobRunner implements LoggerAwareInterface {
 		}
 
 		$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
-- 
2.20.1