Code Coverage
 
Lines
Functions and Methods
Classes and Traits
Total
80.75% covered (warning)
80.75%
151 / 187
33.33% covered (danger)
33.33%
4 / 12
CRAP
0.00% covered (danger)
0.00%
0 / 1
RequestLogger
80.75% covered (warning)
80.75%
151 / 187
33.33% covered (danger)
33.33%
4 / 12
76.58
0.00% covered (danger)
0.00%
0 / 1
 hasQueryLogs
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 sample
0.00% covered (danger)
0.00%
0 / 6
0.00% covered (danger)
0.00%
0 / 1
12
 reportLogs
75.00% covered (warning)
75.00%
6 / 8
0.00% covered (danger)
0.00%
0 / 1
3.14
 addRequest
78.95% covered (warning)
78.95%
15 / 19
0.00% covered (danger)
0.00%
0 / 1
6.34
 appendLastLogPayload
0.00% covered (danger)
0.00%
0 / 3
0.00% covered (danger)
0.00%
0 / 1
6
 getQueryTypesUsed
0.00% covered (danger)
0.00%
0 / 4
0.00% covered (danger)
0.00%
0 / 1
6
 setResultPages
100.00% covered (success)
100.00%
5 / 5
100.00% covered (success)
100.00%
1 / 1
3
 buildCirrusSearchRequestEvent
88.24% covered (warning)
88.24%
90 / 102
0.00% covered (danger)
0.00%
0 / 1
19.59
 extractTitleStrings
100.00% covered (success)
100.00%
4 / 4
100.00% covered (success)
100.00%
1 / 1
2
 buildLogMessage
81.25% covered (warning)
81.25%
13 / 16
0.00% covered (danger)
0.00%
0 / 1
8.42
 encodeHits
100.00% covered (success)
100.00%
10 / 10
100.00% covered (success)
100.00%
1 / 1
2
 getPhpRequestTookMs
77.78% covered (warning)
77.78%
7 / 9
0.00% covered (danger)
0.00%
0 / 1
4.18
1<?php
2
3namespace CirrusSearch;
4
5use MediaWiki\Context\RequestContext;
6use MediaWiki\Deferred\DeferredUpdates;
7use MediaWiki\Json\FormatJson;
8use MediaWiki\Logger\LoggerFactory;
9use MediaWiki\MediaWikiServices;
10use MediaWiki\Search\ISearchResultSet;
11use MediaWiki\User\User;
12use MediaWiki\User\UserIdentity;
13use MediaWiki\WikiMap\WikiMap;
14use Wikimedia\Services\NoSuchServiceException;
15
16/**
17 * Handles logging information about requests made to various destinations,
18 * such as monolog, EventBus and statsd.
19 *
20 * @license GPL-2.0-or-later
21 */
22class RequestLogger {
23    /**
24     * @const int max number of results to store in cirrussearch-request logs (per request)
25     */
26    private const LOG_MAX_RESULTS = 50;
27
28    // If a title hit was given to the user, but the hit was not
29    // obtained via ElasticSearch, we won't really know where it came from.
30    // We still want to log the fact that the request set generated a hit
31    // for this title.  When this happens, the hit index field value will be this.
32    private const UNKNOWN_HIT_INDEX = '_UNKNOWN_';
33
34    /**
35     * @const string EventBus stream to log requests to.
36     */
37    private const STREAM = 'mediawiki.cirrussearch-request';
38
39    /**
40     * @var RequestLog[] Set of requests made
41     */
42    private $logs = [];
43
44    /**
45     * @var string[] Result page ids that were returned to user
46     */
47    private $resultTitleStrings = [];
48
49    /**
50     * @var string[][] Extra payload for the logs, indexed first by the log index
51     *  in self::$logs, and second by the payload item name.
52     */
53    private $extraPayload = [];
54
55    /**
56     * @return bool True when logs have been generated during the current
57     *  php execution.
58     */
59    public function hasQueryLogs() {
60        return (bool)$this->logs;
61    }
62
63    /**
64     * @param float $percentage A value between 0 and 1 indiciating the
65     *  percentage of calls that should return true.
66     * @return bool True on $percentage calls to this method
67     */
68    private function sample( $percentage ) {
69        if ( $percentage <= 0 ) {
70            return false;
71        }
72        if ( $percentage >= 1 ) {
73            return true;
74        }
75        $rand = random_int( 0, PHP_INT_MAX ) / PHP_INT_MAX;
76        return $rand <= $percentage;
77    }
78
79    /**
80     * Summarizes all the requests made in this process and reports
81     * them along with the test they belong to.
82     */
83    private function reportLogs() {
84        if ( $this->logs ) {
85            try {
86                $eventBusFactory = MediaWikiServices::getInstance()->getService( 'EventBus.EventBusFactory' );
87            } catch ( NoSuchServiceException ) {
88                return;
89            }
90            $stream = $eventBusFactory->getInstanceForStream( self::STREAM );
91            $event = $this->buildCirrusSearchRequestEvent();
92            $stream->send( [ $event ] );
93            // reset logs
94            $this->logs = [];
95        }
96    }
97
98    /**
99     * @param RequestLog $log The log about a network request to be added
100     * @param User|null $user The user performing the request, or null
101     *  for actions that don't have a user (such as index updates).
102     * @param int|null $slowMillis The threshold in ms after which the request
103     *  will be considered slow.
104     * @return array A map of information about the performed request, suitible
105     *  for use as a psr-3 log context.
106     */
107    public function addRequest( RequestLog $log, ?UserIdentity $user = null, $slowMillis = null ) {
108        global $wgCirrusSearchLogElasticRequests;
109
110        // @todo Is this necessary here? Check on what uses the response value
111        $finalContext = $log->getLogVariables() + [
112            'source' => Util::getExecutionContext(),
113            'executor' => Util::getExecutionId(),
114            'identity' => Util::generateIdentToken(),
115        ];
116        if ( $wgCirrusSearchLogElasticRequests ) {
117            $this->logs[] = $log;
118            if ( count( $this->logs ) === 1 ) {
119                DeferredUpdates::addCallableUpdate( function () {
120                    $this->reportLogs();
121                } );
122            }
123
124            $logMessage = $this->buildLogMessage( $log, $finalContext );
125            LoggerFactory::getInstance( 'CirrusSearchRequests' )->debug( $logMessage, $finalContext );
126            if ( $slowMillis && $log->getTookMs() >= $slowMillis ) {
127                if ( $user !== null ) {
128                    $finalContext['user'] = $user->getName();
129                    $logMessage .= ' for {user}';
130                }
131                LoggerFactory::getInstance( 'CirrusSearchSlowRequests' )->info( $logMessage, $finalContext );
132            }
133        }
134
135        return $finalContext;
136    }
137
138    /**
139     * @param string $key
140     * @param string $value
141     */
142    public function appendLastLogPayload( $key, $value ) {
143        $idx = count( $this->logs ) - 1;
144        if ( isset( $this->logs[$idx] ) ) {
145            $this->extraPayload[$idx][$key] = $value;
146        }
147    }
148
149    /**
150     * Report the types of queries that were issued
151     * within the current request.
152     *
153     * @return string[]
154     */
155    public function getQueryTypesUsed() {
156        $types = [];
157        foreach ( $this->logs as $log ) {
158            $types[] = $log->getQueryType();
159        }
160        return array_unique( $types );
161    }
162
163    /**
164     * This is set externally because we don't have complete control, from the
165     * SearchEngine interface, of what is actually sent to the user. Instead hooks
166     * receive the final results that will be sent to the user and set them here.
167     *
168     * Accepts two result sets because some places (Special:Search) perform multiple
169     * searches. This can be called multiple times, but only that last call wins. For
170     * API's that is correct, for Special:Search a hook catches the final results and
171     * sets them here.
172     *
173     * @param ISearchResultSet[] $matches
174     */
175    public function setResultPages( array $matches ) {
176        $titleStrings = [];
177        foreach ( $matches as $resultSet ) {
178            if ( $resultSet !== null ) {
179                $titleStrings = array_merge( $titleStrings, $this->extractTitleStrings( $resultSet ) );
180            }
181        }
182        $this->resultTitleStrings = $titleStrings;
183    }
184
185    /**
186     * Builds and ships a log context of an object that conforms to the
187     * JSONSchema  mediawiki/search/requestset event schema.
188     *
189     * @return array mediawiki/search/requestset event object
190     */
191    private function buildCirrusSearchRequestEvent() {
192        global $wgServerName;
193        $webRequest = RequestContext::getMain()->getRequest();
194
195        // for the moment RequestLog::getRequests() is still created in the
196        // old format to serve the old log formats, so here we transform the
197        // context into the new mediawiki/cirrussearch/request event format.
198        // At some point the context should just be created in the correct format.
199        $elasticSearchRequests = [];
200
201        // If false, then at least one of the Elasticsearch request responses
202        // returned was not from cache
203        $allRequestsCached = true;
204
205        // While building the elasticSearchRequests object, collect
206        // a list of all hits from all Elasticsearch requests.
207        $allHits = [];
208
209        // Iterate over each individual Elasticsearch request
210        foreach ( $this->logs as $idx => $elasticSearchRequestLog ) {
211            foreach ( $elasticSearchRequestLog->getRequests() as $requestContext ) {
212                // Build an entry in the elasticSearchRequests array from each logged
213                // Elasticsearch request.
214                $requestEntry = [];
215
216                Util::setIfDefined( $requestContext, 'query', $requestEntry, 'query', 'strval' );
217                Util::setIfDefined( $requestContext, 'queryType', $requestEntry, 'query_type', 'strval' );
218                Util::setIfDefined(
219                    $requestContext, 'index', $requestEntry, 'indices',
220                    // Use list for search indices, not csv string.
221                    static function ( $v ) {
222                        return explode( ',', $v );
223                    }
224                );
225                Util::setIfDefined(
226                    $requestContext, 'namespaces', $requestEntry, 'namespaces',
227                    // Make sure namespace values are all integers.
228                    static function ( $v ) {
229                        if ( !$v ) {
230                            return $v;
231                        } else {
232                            return array_values( array_map( 'intval', $v ) );
233                        }
234                    }
235                );
236                Util::setIfDefined( $requestContext, 'tookMs', $requestEntry, 'request_time_ms', 'intval' );
237                Util::setIfDefined( $requestContext, 'elasticTookMs', $requestEntry, 'search_time_ms', 'intval' );
238                Util::setIfDefined( $requestContext, 'limit', $requestEntry, 'limit', 'intval' );
239                Util::setIfDefined( $requestContext, 'hitsTotal', $requestEntry, 'hits_total', 'intval' );
240                Util::setIfDefined( $requestContext, 'hitsReturned', $requestEntry, 'hits_returned', 'intval' );
241                Util::setIfDefined( $requestContext, 'hitsOffset', $requestEntry, 'hits_offset', 'intval' );
242                Util::setIfDefined( $requestContext, 'suggestion', $requestEntry, 'suggestion', 'strval' );
243
244                // suggestion_requested is true if suggestionRequested or if any suggestion is present.
245                $requestEntry['suggestion_requested'] =
246                    (bool)( $requestContext['suggestionRequested'] ?? isset( $requestContext['suggestion'] ) );
247
248                Util::setIfDefined( $requestContext, 'maxScore', $requestEntry, 'max_score', 'floatval' );
249
250                if ( isset( $this->extraPayload[$idx] ) ) {
251                    // fields in extraPayload keys must be explicitly
252                    // set here if we want to include them in the event.
253                    Util::setIfDefined(
254                        $this->extraPayload[$idx], 'langdetect', $requestEntry, 'langdetect', 'strval'
255                    );
256                }
257
258                Util::setIfDefined( $requestContext, 'syntax', $requestEntry, 'syntax' );
259
260                // If response was servied from cache.
261                $requestEntry['cached'] = (bool)$elasticSearchRequestLog->isCachedResponse();
262                // $wereAllResponsesCached will be used later for
263                // deteriming if all responses for the request set were cached.
264                if ( !$requestEntry['cached'] ) {
265                    $allRequestsCached = false;
266                }
267
268                Util::setIfDefined(
269                    $requestContext, 'hits', $requestEntry, 'hits',
270                    $this->encodeHits( ... )
271                );
272                if ( isset( $requestEntry['hits'] ) ) {
273                    $allHits = array_merge( $allHits, $requestEntry['hits'] );
274                }
275
276                $elasticSearchRequests[] = $requestEntry;
277            }
278        }
279
280        // Reindex allHits by page titles. It's maybe not perfect, but it's
281        // hopefully a "close enough" representation of where our final result
282        // set came from. maybe :(
283        $allHitsByTitle = [];
284        foreach ( $allHits as $hit ) {
285            '@phan-var array $hit';
286            $allHitsByTitle[$hit['page_title']] = $hit;
287        }
288        $resultHits = [];
289        // $this->resultTitleStrings give us title hits that were actually provided to the user.
290        // Build a subset top level list of hits from each sub request's list of hits.
291        $resultTitleStrings = array_slice( $this->resultTitleStrings, 0, self::LOG_MAX_RESULTS );
292        foreach ( $resultTitleStrings as $titleString ) {
293            // $allHitsByTitle[$titleString] will have the hit. If there isn't a hit
294            // for this title, then this title 'hit' did not come from a ElasticSearch request,
295            // so log a 'fake' hit for it.  In this case, the index will be self::UNKNOWN_HIT_INDEX.
296            $hit = $allHitsByTitle[$titleString] ?? [
297                'page_title' => (string)$titleString,
298                'index' => self::UNKNOWN_HIT_INDEX,
299            ];
300            $resultHits[] = $hit;
301        }
302
303        $gen = MediaWikiServices::getInstance()->getGlobalIdGenerator();
304        $requestEvent = [
305            // This schema can be found in the mediawiki/event-schemas repository.
306            // The $schema URI here should be updated if we increment schema versions.
307            '$schema' => '/mediawiki/cirrussearch/request/0.0.1',
308            'meta' => [
309                'request_id' => $webRequest->getRequestId(),
310                'id' => $gen->newUUIDv4(),
311                'domain' => $wgServerName,
312                'stream' => 'mediawiki.cirrussearch-request',
313            ],
314            'http' => [
315                'method' => $webRequest->getMethod(),
316                'client_ip' => $webRequest->getIP(),
317                'has_cookies' => $webRequest->getHeader( 'Cookie' ) ? true : false,
318            ],
319            'database' => WikiMap::getCurrentWikiId(),
320            'mediawiki_host' => gethostname(),
321            'search_id' => Util::getRequestSetToken(),
322            'source' => Util::getExecutionContext(),
323            'identity' => Util::generateIdentToken(),
324            'request_time_ms' => $this->getPhpRequestTookMs(),
325            'all_elasticsearch_requests_cached' => $allRequestsCached,
326        ];
327
328        $webRequestValues = $webRequest->getValues();
329        if ( $webRequestValues ) {
330            $requestEvent['params'] = [];
331            // Make sure all params are string keys and values
332            foreach ( $webRequestValues as $k => $v ) {
333                if ( !is_scalar( $v ) ) {
334                    // This is potentially a multi-dimensional array. JSON is
335                    // perhaps not the best format, but this gives a good
336                    // guarantee about always returning a string, and
337                    // faithfully represents the variety of shapes request
338                    // parameters can be parsed into.
339                    $v = FormatJson::encode( $v );
340                }
341                $k = $webRequest->normalizeUnicode( $k );
342                $requestEvent['params'][(string)$k] = (string)$v;
343            }
344        }
345
346        // Don't set these fields if there is no data.
347        if ( $resultHits ) {
348            $requestEvent['hits'] = $resultHits;
349        }
350        if ( $elasticSearchRequests ) {
351            $requestEvent['elasticsearch_requests'] = $elasticSearchRequests;
352        }
353        // Should always be true, but don't accidently instantiate user testing if somehow
354        // it wasn't done previously.
355        if ( UserTestingStatus::hasInstance() ) {
356            $ut = UserTestingStatus::getInstance();
357            if ( $ut->isActive() ) {
358                // Wrap into an array. UserTesting does not support multiple
359                // concurrent tests in one request, but the schema was written
360                // when that was a possibility.
361                $requestEvent['backend_user_tests'] = [ $ut->getTrigger() ];
362            }
363        }
364
365        // If in webrequests, log these request headers in http.headers.
366        $httpRequestHeadersToLog = [ 'accept-language', 'referer', 'user-agent', 'x-forwarded-for' ];
367        foreach ( $httpRequestHeadersToLog as $header ) {
368            if ( $webRequest->getHeader( $header ) ) {
369                $requestEvent['http']['request_headers'][$header] =
370                    (string)$webRequest->normalizeUnicode( $webRequest->getHeader( $header ) );
371            }
372        }
373
374        return $requestEvent;
375    }
376
377    /**
378     * @param ISearchResultSet $matches
379     * @return string[]
380     */
381    private function extractTitleStrings( ISearchResultSet $matches ) {
382        $strings = [];
383        foreach ( $matches as $result ) {
384            $strings[] = (string)$result->getTitle();
385        }
386
387        return $strings;
388    }
389
390    /**
391     * @param RequestLog $log The request to build a log message about
392     * @param array $context Request specific log variables from RequestLog::getLogVariables()
393     * @return string a PSR-3 compliant message describing $context
394     */
395    private function buildLogMessage( RequestLog $log, array $context ) {
396        $message = $log->getDescription();
397        $message .= " against {index} took {tookMs} millis";
398        if ( isset( $context['elasticTookMs'] ) ) {
399            $message .= " and {elasticTookMs} Elasticsearch millis";
400            if ( isset( $context['elasticTook2PassMs'] ) && $context['elasticTook2PassMs'] >= 0 ) {
401                $message .= " (with 2nd pass: {elasticTook2PassMs} ms)";
402            }
403        }
404        if ( isset( $context['hitsTotal'] ) ) {
405            $message .= ". Found {hitsTotal} total results";
406            $message .= " and returned {hitsReturned} of them starting at {hitsOffset}";
407        }
408        if ( isset( $context['namespaces'] ) ) {
409            $namespaces = implode( ', ', $context['namespaces'] );
410            $message .= " within these namespaces: $namespaces";
411        }
412        if ( isset( $context['suggestion'] ) && strlen( $context['suggestion'] ) > 0 ) {
413            $message .= " and suggested '{suggestion}'";
414        }
415        $message .= ". Requested via {source} for {identity} by executor {executor}";
416
417        return $message;
418    }
419
420    /**
421     * Enforce all type constraints on the hits field and limit
422     * the number of results to the maximum specified.
423     *
424     * @param array[] $hits
425     * @return array[]
426     */
427    private function encodeHits( array $hits ) {
428        $formattedHits = [];
429        foreach ( array_slice( $hits, 0, self::LOG_MAX_RESULTS )  as $hit ) {
430            $formattedHit = [];
431            Util::setIfDefined( $hit, 'title', $formattedHit, 'page_title', 'strval' );
432            Util::setIfDefined( $hit, 'pageId', $formattedHit, 'page_id', 'intval' );
433            Util::setIfDefined( $hit, 'index', $formattedHit, 'index', 'strval' );
434            Util::setIfDefined( $hit, 'score', $formattedHit, 'score', 'floatval' );
435            Util::setIfDefined( $hit, 'profileName', $formattedHit, 'profile_name', 'strval' );
436            $formattedHits[] = $formattedHit;
437        }
438        return $formattedHits;
439    }
440
441    /**
442     * Note that this is only accurate for hhvm and php-fpm
443     * since they close the request to the user before running
444     * deferred updates.
445     *
446     * @return int The number of ms the php request took
447     */
448    private function getPhpRequestTookMs() {
449        $timing = RequestContext::getMain()->getTiming();
450        $startMark = $timing->getEntryByName( 'requestStart' );
451        $endMark  = $timing->getEntryByName( 'requestShutdown' );
452        if ( $startMark && $endMark ) {
453            // should always work, but Timing can return null so
454            // fallbacks are provided.
455            $tookS = $endMark['startTime'] - $startMark['startTime'];
456        } elseif ( isset( $_SERVER['REQUEST_TIME_FLOAT'] ) ) {
457            // php >= 5.4
458            $tookS = microtime( true ) - $_SERVER['REQUEST_TIME_FLOAT'];
459        } else {
460            // php 5.3
461            $tookS = microtime( true ) - $_SERVER['REQUEST_TIME'];
462        }
463
464        return intval( 1000 * $tookS );
465    }
466}