Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
Total | |
71.43% |
75 / 105 |
|
35.29% |
6 / 17 |
CRAP | |
0.00% |
0 / 1 |
ElasticsearchIntermediary | |
71.43% |
75 / 105 |
|
35.29% |
6 / 17 |
77.32 | |
0.00% |
0 / 1 |
__construct | |
85.71% |
6 / 7 |
|
0.00% |
0 / 1 |
2.01 | |||
setResultPages | |
66.67% |
2 / 3 |
|
0.00% |
0 / 1 |
2.15 | |||
getQueryTypesUsed | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
6 | |||
hasQueryLogs | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
6 | |||
start | |
75.00% |
3 / 4 |
|
0.00% |
0 / 1 |
2.06 | |||
success | |
100.00% |
2 / 2 |
|
100.00% |
1 / 1 |
1 | |||
successViaCache | |
0.00% |
0 / 3 |
|
0.00% |
0 / 1 |
6 | |||
failure | |
89.47% |
17 / 19 |
|
0.00% |
0 / 1 |
2.00 | |||
getSearchMetrics | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
1 | |||
finishRequest | |
100.00% |
19 / 19 |
|
100.00% |
1 / 1 |
3 | |||
appendLastLogPayload | |
0.00% |
0 / 5 |
|
0.00% |
0 / 1 |
6 | |||
startNewLog | |
100.00% |
3 / 3 |
|
100.00% |
1 / 1 |
1 | |||
newLog | n/a |
0 / 0 |
n/a |
0 / 0 |
0 | |||||
getTimeout | |
100.00% |
7 / 7 |
|
100.00% |
1 / 1 |
3 | |||
getClientTimeout | |
85.71% |
6 / 7 |
|
0.00% |
0 / 1 |
3.03 | |||
appendMetrics | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
1 | |||
isMSearchResultSetOK | |
0.00% |
0 / 2 |
|
0.00% |
0 / 1 |
6 | |||
runMSearch | |
50.00% |
8 / 16 |
|
0.00% |
0 / 1 |
19.12 |
1 | <?php |
2 | |
3 | namespace CirrusSearch; |
4 | |
5 | use CirrusSearch\Search\SearchMetricsProvider; |
6 | use Elastica\Exception\ExceptionInterface; |
7 | use Elastica\Exception\ResponseException; |
8 | use Elastica\Exception\RuntimeException; |
9 | use Elastica\Multi\ResultSet as MultiResultSet; |
10 | use Elastica\Multi\Search; |
11 | use ISearchResultSet; |
12 | use MediaWiki\Logger\LoggerFactory; |
13 | use MediaWiki\User\UserIdentity; |
14 | use RequestContext; |
15 | use Status; |
16 | use 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 | */ |
36 | abstract 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 | } |