Track which web request created a job

We currently push a request id into structured logging (monolog/
logstash) to allow seeing all logs that were triggered by the same
request. This extends that to pass the id through jobs so jobs triggered
by a web request also share the same id and can be tracked together.
This web request id will follow jobs both directly created by a request,
and jobs created by those jobs.

This should give us some more visibility when debugging into what
started a particular job, and if a large number of jobs blowing up the
job queue are somehow related.

Change-Id: Iedbd031e6e9bb18fd6f7b923c8c305102255ab4b

diff --git a/includes/WebRequest.php b/includes/WebRequest.php
index b18d59c..b159f79 100644 (file)
--- a/includes/WebRequest.php
+++ b/includes/WebRequest.php
@@ -43,6 +43,12 @@ class WebRequest {
         */
        const GETHEADER_LIST = 1;
 
+       /**
+        * The unique request ID.
+        * @var string
+        */
+       private static $reqId;
+
        /**
         * Lazy-init response object
         * @var WebResponse
@@ -257,14 +263,23 @@ class WebRequest {
         * @since 1.27
         */
        public static function getRequestId() {
-               static $reqId;
-
-               if ( !$reqId ) {
-                       $reqId = isset( $_SERVER['UNIQUE_ID'] )
+               if ( !self::$reqId ) {
+                       self::$reqId = isset( $_SERVER['UNIQUE_ID'] )
                                ? $_SERVER['UNIQUE_ID'] : wfRandomString( 24 );
                }
 
-               return $reqId;
+               return self::$reqId;
+       }
+
+       /**
+        * Override the unique request ID. This is for sub-requests, such as jobs,
+        * that wish to use the same id but are not part of the same execution context.
+        *
+        * @param string $id
+        * @since 1.27
+        */
+       public static function overrideRequestId( $id ) {
+               self::$reqId = $id;
        }
 
        /**

diff --git a/includes/jobqueue/Job.php b/includes/jobqueue/Job.php
index 9ccf6f8..bbd0ddb 100644 (file)
--- a/includes/jobqueue/Job.php
+++ b/includes/jobqueue/Job.php
@@ -92,6 +92,10 @@ abstract class Job implements IJobSpecification {
 
                // expensive jobs may set this to true
                $this->removeDuplicates = false;
+
+               if ( !isset( $this->params['requestId'] ) ) {
+                       $this->params['requestId'] = WebRequest::getRequestId();
+               }
        }
 
        /**
@@ -152,6 +156,18 @@ abstract class Job implements IJobSpecification {
                        : null;
        }
 
+       /**
+        * @return string|null Id of the request that created this job. Follows
+        *  jobs recursively, allowing to track the id of the request that started a
+        *  job when jobs insert jobs which insert other jobs.
+        * @since 1.27
+        */
+       public function getRequestId() {
+               return isset( $this->params['requestId'] )
+                       ? $this->params['requestId']
+                       : null;
+       }
+
        /**
         * @return int|null UNIX timestamp of when the job was runnable, or null
         * @since 1.26
@@ -214,6 +230,8 @@ abstract class Job implements IJobSpecification {
                        unset( $info['params']['rootJobTimestamp'] );
                        // Likewise for jobs with different delay times
                        unset( $info['params']['jobReleaseTimestamp'] );
+                       // Identical jobs from different requests should count as duplicates
+                       unset( $info['params']['requestId'] );
                        // Queues pack and hash this array, so normalize the order
                        ksort( $info['params'] );
                }

diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php
index 0a0a7a2..a2f55b9 100644 (file)
--- a/includes/jobqueue/JobRunner.php
+++ b/includes/jobqueue/JobRunner.php
@@ -163,6 +163,8 @@ class JobRunner implements LoggerAwareInterface {
                                $popTime = time();
                                $jType = $job->getType();
 
+                               WebRequest::overrideRequestId( $job->getRequestId() );
+
                                // Back off of certain jobs for a while (for throttling and for errors)
                                $ttw = $this->getBackoffTimeToWait( $job );
                                if ( $ttw > 0 ) {

diff --git a/tests/phpunit/includes/jobqueue/JobTest.php b/tests/phpunit/includes/jobqueue/JobTest.php
index 3c648f9..600a36f 100644 (file)
--- a/tests/phpunit/includes/jobqueue/JobTest.php
+++ b/tests/phpunit/includes/jobqueue/JobTest.php
@@ -23,34 +23,36 @@ class JobTest extends MediaWikiTestCase {
                        ->method( '__toString' )
                        ->will( $this->returnValue( '{STRING_OBJ_VAL}' ) );
 
+               $requestId = 'requestId=' . WebRequest::getRequestId();
+
                return [
                        [
                                $this->getMockJob( false ),
-                               'someCommand '
+                               'someCommand  ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ 'key' => 'val' ] ),
-                               'someCommand  key=val'
+                               'someCommand  key=val ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ 'key' => [ 'inkey' => 'inval' ] ] ),
-                               'someCommand  key={"inkey":"inval"}'
+                               'someCommand  key={"inkey":"inval"} ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ 'val1' ] ),
-                               'someCommand  0=val1'
+                               'someCommand  0=val1 ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ 'val1', 'val2' ] ),
-                               'someCommand  0=val1 1=val2'
+                               'someCommand  0=val1 1=val2 ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ new stdClass() ] ),
-                               'someCommand  0=object(stdClass)'
+                               'someCommand  0=object(stdClass) ' . $requestId
                        ],
                        [
                                $this->getMockJob( [ $mockToStringObj ] ),
-                               'someCommand  0={STRING_OBJ_VAL}'
+                               'someCommand  0={STRING_OBJ_VAL} ' . $requestId
                        ],
                        [
                                $this->getMockJob( [
@@ -73,7 +75,8 @@ class JobTest extends MediaWikiTestCase {
                                'rootJobSignature=45868e99bba89064e4483743ebb9b682ef95c1a7 ' .
                                'rootJobTimestamp=20160309110158 masterPos=' .
                                '{"file":"db1023-bin.001288","pos":"308257743","asOfTime":1457521464.3814} ' .
-                               'triggeredRecursive=1'
+                               'triggeredRecursive=1 ' .
+                               $requestId
                        ],
                ];
        }