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