Code Coverage
 
Lines
Functions and Methods
Classes and Traits
Total
71.72% covered (warning)
71.72%
71 / 99
35.29% covered (danger)
35.29%
6 / 17
CRAP
0.00% covered (danger)
0.00%
0 / 1
ElasticsearchIntermediary
71.72% covered (warning)
71.72%
71 / 99
35.29% covered (danger)
35.29%
6 / 17
76.20
0.00% covered (danger)
0.00%
0 / 1
 __construct
85.71% covered (warning)
85.71%
6 / 7
0.00% covered (danger)
0.00%
0 / 1
2.01
 setResultPages
66.67% covered (warning)
66.67%
2 / 3
0.00% covered (danger)
0.00%
0 / 1
2.15
 getQueryTypesUsed
0.00% covered (danger)
0.00%
0 / 3
0.00% covered (danger)
0.00%
0 / 1
6
 hasQueryLogs
0.00% covered (danger)
0.00%
0 / 3
0.00% covered (danger)
0.00%
0 / 1
6
 start
75.00% covered (warning)
75.00%
3 / 4
0.00% covered (danger)
0.00%
0 / 1
2.06
 success
100.00% covered (success)
100.00%
2 / 2
100.00% covered (success)
100.00%
1 / 1
1
 successViaCache
0.00% covered (danger)
0.00%
0 / 3
0.00% covered (danger)
0.00%
0 / 1
6
 failure
88.24% covered (warning)
88.24%
15 / 17
0.00% covered (danger)
0.00%
0 / 1
2.01
 getSearchMetrics
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 finishRequest
100.00% covered (success)
100.00%
17 / 17
100.00% covered (success)
100.00%
1 / 1
3
 appendLastLogPayload
0.00% covered (danger)
0.00%
0 / 3
0.00% covered (danger)
0.00%
0 / 1
6
 startNewLog
100.00% covered (success)
100.00%
3 / 3
100.00% covered (success)
100.00%
1 / 1
1
 newLog
n/a
0 / 0
n/a
0 / 0
0
 getTimeout
100.00% covered (success)
100.00%
7 / 7
100.00% covered (success)
100.00%
1 / 1
3
 getClientTimeout
85.71% covered (warning)
85.71%
6 / 7
0.00% covered (danger)
0.00%
0 / 1
3.03
 appendMetrics
100.00% covered (success)
100.00%
1 / 1
100.00% covered (success)
100.00%
1 / 1
1
 isMSearchResultSetOK
0.00% covered (danger)
0.00%
0 / 2
0.00% covered (danger)
0.00%
0 / 1
6
 runMSearch
50.00% covered (danger)
50.00%
8 / 16
0.00% covered (danger)
0.00%
0 / 1
19.12
1<?php
2
3namespace CirrusSearch;
4
5use CirrusSearch\Search\SearchMetricsProvider;
6use Elastica\Exception\ExceptionInterface;
7use Elastica\Exception\ResponseException;
8use Elastica\Exception\RuntimeException;
9use Elastica\Multi\ResultSet as MultiResultSet;
10use Elastica\Multi\Search;
11use ISearchResultSet;
12use MediaWiki\Logger\LoggerFactory;
13use MediaWiki\User\UserIdentity;
14use RequestContext;
15use Status;
16use Wikimedia\Assert\Assert;
17
18/**
19 * Base class with useful functions for communicating with Elasticsearch.
20 *
21 * This program is free software; you can redistribute it and/or modify
22 * it under the terms of the GNU General Public License as published by
23 * the Free Software Foundation; either version 2 of the License, or
24 * (at your option) any later version.
25 *
26 * This program is distributed in the hope that it will be useful,
27 * but WITHOUT ANY WARRANTY; without even the implied warranty of
28 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
29 * GNU General Public License for more details.
30 *
31 * You should have received a copy of the GNU General Public License along
32 * with this program; if not, write to the Free Software Foundation, Inc.,
33 * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
34 * http://www.gnu.org/copyleft/gpl.html
35 */
36abstract class ElasticsearchIntermediary {
37    /**
38     * @var Connection
39     */
40    protected $connection;
41
42    /**
43     * @var UserIdentity|null user for which we're performing this search or null in
44     * the case of requests kicked off by jobs
45     */
46    protected $user;
47
48    /**
49     * @var RequestLog|null Log for in-progress search request
50     */
51    protected $currentRequestLog = null;
52
53    /**
54     * @var int how many millis a request through this intermediary needs to
55     * take before it counts as slow. 0 means none count as slow.
56     */
57    private $slowMillis;
58
59    /**
60     * @var array Metrics about a completed search
61     */
62    private $searchMetrics = [];
63
64    /**
65     * @var int artificial extra backend latency in micro seconds
66     */
67    private $extraBackendLatency;
68
69    /**
70     * @var RequestLogger
71     */
72    protected static $requestLogger;
73
74    /**
75     * @param Connection $connection
76     * @param UserIdentity|null $user user for which this search is being performed.
77     *  Attached to slow request logs.  Note that null isn't for anonymous users
78     *  - those are still User objects and should be provided if possible.  Null
79     *  is for when the action is being performed in some context where the user
80     *  that caused it isn't available.  Like when an action is being performed
81     *  during a job.
82     * @param float|null $slowSeconds how many seconds a request through this
83     *  intermediary needs to take before it counts as slow.  0 means none count
84     *  as slow. Defaults to CirrusSearchSlowSearch config option.
85     * @param int $extraBackendLatency artificial backend latency.
86     */
87    protected function __construct( Connection $connection, UserIdentity $user = null, $slowSeconds = null, $extraBackendLatency = 0 ) {
88        $this->connection = $connection;
89        $this->user = $user ?? RequestContext::getMain()->getUser();
90        $this->slowMillis = (int)( 1000 * ( $slowSeconds ?? $connection->getConfig()->get( 'CirrusSearchSlowSearch' ) ) );
91        $this->extraBackendLatency = $extraBackendLatency;
92        if ( self::$requestLogger === null ) {
93            self::$requestLogger = new RequestLogger;
94        }
95        // This isn't explicitly used, but we need to make sure it is
96        // instantiated so it has the opportunity to override global
97        // configuration for test buckets.
98        UserTestingStatus::getInstance();
99    }
100
101    /**
102     * This is set externally because we don't have complete control, from the
103     * SearchEngine interface, of what is actually sent to the user. Instead hooks
104     * receive the final results that will be sent to the user and set them here.
105     *
106     * Accepts two result sets because some places (Special:Search) perform multiple
107     * searches. This can be called multiple times, but only that last call wins. For
108     * API's that is correct, for Special:Search a hook catches the final results and
109     * sets them here.
110     *
111     * @param ISearchResultSet[] $matches
112     */
113    public static function setResultPages( array $matches ) {
114        if ( self::$requestLogger === null ) {
115            // This could happen if Cirrus is not the active engine,
116            // but the hook is still loaded. In this case, do nothing.
117            return;
118        } else {
119            self::$requestLogger->setResultPages( $matches );
120        }
121    }
122
123    /**
124     * Report the types of queries that were issued
125     * within the current request.
126     *
127     * @return string[]
128     */
129    public static function getQueryTypesUsed() {
130        if ( self::$requestLogger === null ) {
131            // This can happen when, for example, completion search is
132            // triggered against NS_SPECIAL, where searching is done strictly
133            // in PHP and never actually creates a  SearchEngine.
134            return [];
135        } else {
136            return self::$requestLogger->getQueryTypesUsed();
137        }
138    }
139
140    /**
141     * @return bool True when query logs have been generated by the
142     *  current php execution.
143     */
144    public static function hasQueryLogs() {
145        if ( self::$requestLogger === null ) {
146            return false;
147        }
148        return self::$requestLogger->hasQueryLogs();
149    }
150
151    /**
152     * Mark the start of a request to Elasticsearch.  Public so it can be
153     * called from pool counter methods.
154     *
155     * @param RequestLog $log
156     */
157    public function start( RequestLog $log ) {
158        $this->currentRequestLog = $log;
159        $log->start();
160        if ( $this->extraBackendLatency ) {
161            usleep( $this->extraBackendLatency );
162        }
163    }
164
165    /**
166     * Log a successful request and return the provided result in a good
167     * Status.  If you don't need the status just ignore the return.  Public so
168     * it can be called from pool counter methods.
169     *
170     * @param mixed|null $result result of the request.  defaults to null in case
171     *  the request doesn't have a result
172     * @param Connection|null $connection The connection the succesful
173     *  request was performed against. Will use $this->connection when not
174     *  provided.
175     * @return Status wrapping $result
176     */
177    public function success( $result = null, Connection $connection = null ) {
178        $this->finishRequest( $connection ?? $this->connection );
179        return Status::newGood( $result );
180    }
181
182    /**
183     * Log a successful request when the response comes from a cache outside
184     * elasticsearch. This is a combination of self::start() and self::success().
185     *
186     * @param RequestLog $log
187     */
188    public function successViaCache( RequestLog $log ) {
189        if ( $this->extraBackendLatency ) {
190            usleep( $this->extraBackendLatency );
191        }
192        self::$requestLogger->addRequest( $log );
193    }
194
195    /**
196     * Log a failure and return an appropriate status.  Public so it can be
197     * called from pool counter methods.
198     *
199     * @param ExceptionInterface|null $exception if the request failed
200     * @param Connection|null $connection The connection that the failed
201     *  request was performed against. Will use $this->connection when not
202     *  provided.
203     * @return Status representing a backend failure
204     */
205    public function failure( ExceptionInterface $exception = null, Connection $connection = null ) {
206        $connection ??= $this->connection;
207        $log = $this->finishRequest( $connection );
208        if ( $log === null ) {
209            // Request was never started, likely trying to close a request
210            // a second time. If so that was already logged by finishRequest.
211            $context = [];
212            $logType = 'not_started';
213        } else {
214            $context = $log->getLogVariables();
215            $logType = $log->getDescription();
216        }
217        list( $status, $message ) = ElasticaErrorHandler::extractMessageAndStatus( $exception );
218        // This could be multiple MB if the failure is coming from an update
219        // script, as the whole update script is returned in the error
220        // including the parameters. Truncate to a reasonable level so
221        // downstream log processing doesn't truncate them (and then fail to
222        // parse the truncated json). Take the first 4k to leave plenty of room for
223        // whatever else.
224        $context['error_message'] = mb_substr( $message, 0, 4096 );
225
226        $stats = Util::getStatsDataFactory();
227        $type = ElasticaErrorHandler::classifyError( $exception );
228        $clusterName = $connection->getClusterName();
229        $context['cirrussearch_error_type'] = $type;
230
231        $stats->increment( "CirrusSearch.$clusterName.backend_failure.$type" );
232
233        LoggerFactory::getInstance( 'CirrusSearch' )->warning(
234            "Search backend error during {$logType} after {tookMs}: {error_message}",
235            $context
236        );
237        return $status;
238    }
239
240    /**
241     * Get the search metrics we have
242     * @return array
243     */
244    public function getSearchMetrics() {
245        return $this->searchMetrics;
246    }
247
248    /**
249     * Log the completion of a request to Elasticsearch.
250     *
251     * @param Connection $connection
252     * @return RequestLog|null The log for the finished request, or null if no
253     * request was started.
254     */
255    private function finishRequest( Connection $connection ) {
256        if ( !$this->currentRequestLog ) {
257            LoggerFactory::getInstance( 'CirrusSearch' )->warning(
258                'finishRequest called without staring a request'
259            );
260            return null;
261        }
262        $log = $this->currentRequestLog;
263        $this->currentRequestLog = null;
264
265        $log->finish();
266        $tookMs = $log->getTookMs();
267        $clusterName = $connection->getClusterName();
268        $stats = Util::getStatsDataFactory();
269        $stats->timing( "CirrusSearch.$clusterName.requestTime", $tookMs );
270        $this->searchMetrics['wgCirrusTookMs'] = $tookMs;
271        self::$requestLogger->addRequest( $log, $this->user, $this->slowMillis );
272        $type = $log->getQueryType();
273        $stats->timing( "CirrusSearch.$clusterName.requestTimeMs.$type", $tookMs );
274        if ( $log->getElasticTookMs() ) {
275            $this->searchMetrics['wgCirrusElasticTime'] = $log->getElasticTookMs();
276        }
277
278        return $log;
279    }
280
281    /**
282     * @param string $key
283     * @param string $value
284     */
285    public static function appendLastLogPayload( $key, $value ) {
286        if ( self::$requestLogger !== null ) {
287            // Guard only for unit tests that heavily mock classes
288            self::$requestLogger->appendLastLogPayload( $key, $value );
289        } else {
290            Assert::invariant( defined( 'MW_PHPUNIT_TEST' ),
291                'appendLastLogPayload must only be called after self::$requestLogger has been set ' .
292                'or during unit tests' );
293        }
294    }
295
296    /**
297     * @param string $description A psr-3 compliant string describing the request
298     * @param string $queryType The type of search being performed such as
299     * fulltext, get, etc.
300     * @param array $extra A map of additional request-specific data
301     * @return RequestLog
302     */
303    protected function startNewLog( $description, $queryType, array $extra = [] ) {
304        $log = $this->newLog( $description, $queryType, $extra );
305        $this->start( $log );
306
307        return $log;
308    }
309
310    /**
311     * @param string $description A psr-3 compliant string describing the request
312     * @param string $queryType The type of search being performed such as
313     * fulltext, get, etc.
314     * @param array $extra A map of additional request-specific data
315     * @return RequestLog
316     */
317    abstract protected function newLog( $description, $queryType, array $extra = [] );
318
319    /**
320     * @param string $searchType
321     * @return string search retrieval timeout
322     */
323    protected function getTimeout( $searchType = 'default' ) {
324        $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchSearchShardTimeout', $searchType );
325        if ( $timeout !== null ) {
326            return $timeout;
327        }
328        $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchSearchShardTimeout', 'default' );
329        if ( $timeout !== null ) {
330            return $timeout;
331        }
332        throw new \ConfigException( "wgCirrusSearchSearchShardTimeout should have at least a 'default' entry configured" );
333    }
334
335    /**
336     * @param string $searchType
337     * @return int the client side timeout
338     */
339    protected function getClientTimeout( $searchType = 'default' ) {
340        $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchClientSideSearchTimeout', $searchType );
341        if ( $timeout !== null ) {
342            return $timeout;
343        }
344        $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchClientSideSearchTimeout', 'default' );
345        if ( $timeout !== null ) {
346            return $timeout;
347        }
348        throw new \ConfigException( "wgCirrusSearchClientSideSearchTimeout should have at least a 'default' entry configured" );
349    }
350
351    /**
352     * @param SearchMetricsProvider $provider
353     */
354    protected function appendMetrics( SearchMetricsProvider $provider ) {
355        $this->searchMetrics += $provider->getMetrics();
356    }
357
358    /**
359     * check validity of the multisearch response
360     *
361     * @param MultiResultSet $multiResultSet
362     * @return bool
363     */
364    public static function isMSearchResultSetOK( MultiResultSet $multiResultSet ): bool {
365        return !$multiResultSet->hasError() &&
366               // Catches HTTP errors (ex: 5xx) not reported
367               // by hasError()
368               $multiResultSet->getResponse()->isOk();
369    }
370
371    /**
372     * @param Search $search
373     * @param RequestLog $log
374     * @param Connection|null $connection
375     * @param callable|null $resultsTransformer that accepts a Multi/ResultSets
376     * @return Status
377     */
378    protected function runMSearch(
379        Search $search,
380        RequestLog $log,
381        Connection $connection = null,
382        callable $resultsTransformer = null
383    ): Status {
384        $connection = $connection ?: $this->connection;
385        $this->start( $log );
386        try {
387            $multiResultSet = $search->search();
388            $lastRequest = $connection->getClient()->getLastRequest();
389            if ( !$multiResultSet->getResponse()->isOk() ) {
390                // bad response from server. Should elastica be throwing an exception for this?
391                if ( $lastRequest !== null ) {
392                    return $this->failure( new ResponseException( $lastRequest, $multiResultSet->getResponse() ), $connection );
393                } else {
394                    return $this->failure( new RuntimeException( "Client::getLastRequest() should not be null" ), $connection );
395                }
396            }
397            foreach ( $multiResultSet->getResultSets() as $resultSet ) {
398                if ( $resultSet->getResponse()->hasError() ) {
399                    if ( $lastRequest !== null ) {
400                        return $this->failure( new ResponseException( $lastRequest, $resultSet->getResponse() ), $connection );
401                    } else {
402                        return $this->failure( new RuntimeException( "Client::getLastRequest() should not be null" ), $connection );
403                    }
404                }
405            }
406
407            return $this->success( $resultsTransformer !== null ? $resultsTransformer( $multiResultSet ) : $multiResultSet, $connection );
408        } catch ( ExceptionInterface $e ) {
409            return $this->failure( $e, $connection );
410        }
411    }
412}