Code Coverage |
||||||||||
Lines |
Functions and Methods |
Classes and Traits |
||||||||
| Total | |
73.91% |
85 / 115 |
|
35.29% |
6 / 17 |
CRAP | |
0.00% |
0 / 1 |
| ElasticsearchIntermediary | |
73.91% |
85 / 115 |
|
35.29% |
6 / 17 |
68.40 | |
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 | |
91.30% |
21 / 23 |
|
0.00% |
0 / 1 |
2.00 | |||
| getSearchMetrics | |
100.00% |
1 / 1 |
|
100.00% |
1 / 1 |
1 | |||
| finishRequest | |
100.00% |
25 / 25 |
|
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\Config\ConfigException; |
| 13 | use MediaWiki\Context\RequestContext; |
| 14 | use MediaWiki\Logger\LoggerFactory; |
| 15 | use MediaWiki\Status\Status; |
| 16 | use MediaWiki\User\UserIdentity; |
| 17 | use 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 | */ |
| 37 | abstract 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::getStatsFactory(); |
| 228 | $type = ElasticaErrorHandler::classifyError( $exception ); |
| 229 | $clusterName = $connection->getClusterName(); |
| 230 | $context['cirrussearch_error_type'] = $type; |
| 231 | |
| 232 | $stats->getCounter( "backend_failures_total" ) |
| 233 | ->setLabel( "search_cluster", $clusterName ) |
| 234 | ->setLabel( "type", $type ) |
| 235 | ->copyToStatsdAt( "CirrusSearch.$clusterName.backend_failure.$type" ) |
| 236 | ->increment(); |
| 237 | |
| 238 | LoggerFactory::getInstance( 'CirrusSearch' )->warning( |
| 239 | "Search backend error during {$logType} after {tookMs}: {error_message}", |
| 240 | $context |
| 241 | ); |
| 242 | return $status; |
| 243 | } |
| 244 | |
| 245 | /** |
| 246 | * Get the search metrics we have |
| 247 | * @return array |
| 248 | */ |
| 249 | public function getSearchMetrics() { |
| 250 | return $this->searchMetrics; |
| 251 | } |
| 252 | |
| 253 | /** |
| 254 | * Log the completion of a request to Elasticsearch. |
| 255 | * |
| 256 | * @param Connection $connection |
| 257 | * @return RequestLog|null The log for the finished request, or null if no |
| 258 | * request was started. |
| 259 | */ |
| 260 | private function finishRequest( Connection $connection ) { |
| 261 | if ( !$this->currentRequestLog ) { |
| 262 | LoggerFactory::getInstance( 'CirrusSearch' )->warning( |
| 263 | 'finishRequest called without staring a request' |
| 264 | ); |
| 265 | return null; |
| 266 | } |
| 267 | $log = $this->currentRequestLog; |
| 268 | $this->currentRequestLog = null; |
| 269 | |
| 270 | $log->finish(); |
| 271 | $tookMs = $log->getTookMs(); |
| 272 | $clusterName = $connection->getClusterName(); |
| 273 | $this->searchMetrics['wgCirrusTookMs'] = $tookMs; |
| 274 | self::$requestLogger->addRequest( $log, $this->user, $this->slowMillis ); |
| 275 | $type = $log->getQueryType(); |
| 276 | $stats = Util::getStatsFactory(); |
| 277 | $stats->getTiming( "request_time_seconds" ) |
| 278 | ->setLabel( "search_cluster", $clusterName ) |
| 279 | ->setLabel( "type", $type ) |
| 280 | ->copyToStatsdAt( [ |
| 281 | "CirrusSearch.$clusterName.requestTimeMs.$type", |
| 282 | "CirrusSearch.$clusterName.requestTime" |
| 283 | ] ) |
| 284 | ->observe( $tookMs ); |
| 285 | if ( $log->getElasticTookMs() ) { |
| 286 | $this->searchMetrics['wgCirrusElasticTime'] = $log->getElasticTookMs(); |
| 287 | } |
| 288 | |
| 289 | return $log; |
| 290 | } |
| 291 | |
| 292 | /** |
| 293 | * @param string $key |
| 294 | * @param string $value |
| 295 | */ |
| 296 | public static function appendLastLogPayload( $key, $value ) { |
| 297 | if ( self::$requestLogger !== null ) { |
| 298 | // Guard only for unit tests that heavily mock classes |
| 299 | self::$requestLogger->appendLastLogPayload( $key, $value ); |
| 300 | } else { |
| 301 | Assert::invariant( defined( 'MW_PHPUNIT_TEST' ), |
| 302 | 'appendLastLogPayload must only be called after self::$requestLogger has been set ' . |
| 303 | 'or during unit tests' ); |
| 304 | } |
| 305 | } |
| 306 | |
| 307 | /** |
| 308 | * @param string $description A psr-3 compliant string describing the request |
| 309 | * @param string $queryType The type of search being performed such as |
| 310 | * fulltext, get, etc. |
| 311 | * @param array $extra A map of additional request-specific data |
| 312 | * @return RequestLog |
| 313 | */ |
| 314 | protected function startNewLog( $description, $queryType, array $extra = [] ) { |
| 315 | $log = $this->newLog( $description, $queryType, $extra ); |
| 316 | $this->start( $log ); |
| 317 | |
| 318 | return $log; |
| 319 | } |
| 320 | |
| 321 | /** |
| 322 | * @param string $description A psr-3 compliant string describing the request |
| 323 | * @param string $queryType The type of search being performed such as |
| 324 | * fulltext, get, etc. |
| 325 | * @param array $extra A map of additional request-specific data |
| 326 | * @return RequestLog |
| 327 | */ |
| 328 | abstract protected function newLog( $description, $queryType, array $extra = [] ); |
| 329 | |
| 330 | /** |
| 331 | * @param string $searchType |
| 332 | * @return string search retrieval timeout |
| 333 | */ |
| 334 | protected function getTimeout( $searchType = 'default' ) { |
| 335 | $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchSearchShardTimeout', $searchType ); |
| 336 | if ( $timeout !== null ) { |
| 337 | return $timeout; |
| 338 | } |
| 339 | $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchSearchShardTimeout', 'default' ); |
| 340 | if ( $timeout !== null ) { |
| 341 | return $timeout; |
| 342 | } |
| 343 | throw new ConfigException( "wgCirrusSearchSearchShardTimeout should have at least a 'default' entry configured" ); |
| 344 | } |
| 345 | |
| 346 | /** |
| 347 | * @param string $searchType |
| 348 | * @return int the client side timeout |
| 349 | */ |
| 350 | protected function getClientTimeout( $searchType = 'default' ) { |
| 351 | $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchClientSideSearchTimeout', $searchType ); |
| 352 | if ( $timeout !== null ) { |
| 353 | return $timeout; |
| 354 | } |
| 355 | $timeout = $this->connection->getConfig()->getElement( 'CirrusSearchClientSideSearchTimeout', 'default' ); |
| 356 | if ( $timeout !== null ) { |
| 357 | return $timeout; |
| 358 | } |
| 359 | throw new ConfigException( "wgCirrusSearchClientSideSearchTimeout should have at least a 'default' entry configured" ); |
| 360 | } |
| 361 | |
| 362 | /** |
| 363 | * @param SearchMetricsProvider $provider |
| 364 | */ |
| 365 | protected function appendMetrics( SearchMetricsProvider $provider ) { |
| 366 | $this->searchMetrics += $provider->getMetrics(); |
| 367 | } |
| 368 | |
| 369 | /** |
| 370 | * check validity of the multisearch response |
| 371 | * |
| 372 | * @param MultiResultSet $multiResultSet |
| 373 | * @return bool |
| 374 | */ |
| 375 | public static function isMSearchResultSetOK( MultiResultSet $multiResultSet ): bool { |
| 376 | return !$multiResultSet->hasError() && |
| 377 | // Catches HTTP errors (ex: 5xx) not reported |
| 378 | // by hasError() |
| 379 | $multiResultSet->getResponse()->isOk(); |
| 380 | } |
| 381 | |
| 382 | /** |
| 383 | * @param Search $search |
| 384 | * @param RequestLog $log |
| 385 | * @param Connection|null $connection |
| 386 | * @param callable|null $resultsTransformer that accepts a Multi/ResultSets |
| 387 | * @return Status |
| 388 | */ |
| 389 | protected function runMSearch( |
| 390 | Search $search, |
| 391 | RequestLog $log, |
| 392 | ?Connection $connection = null, |
| 393 | ?callable $resultsTransformer = null |
| 394 | ): Status { |
| 395 | $connection = $connection ?: $this->connection; |
| 396 | $this->start( $log ); |
| 397 | try { |
| 398 | $multiResultSet = $search->search(); |
| 399 | $lastRequest = $connection->getClient()->getLastRequest(); |
| 400 | if ( !$multiResultSet->getResponse()->isOk() ) { |
| 401 | // bad response from server. Should elastica be throwing an exception for this? |
| 402 | if ( $lastRequest !== null ) { |
| 403 | return $this->failure( new ResponseException( $lastRequest, $multiResultSet->getResponse() ), $connection ); |
| 404 | } else { |
| 405 | return $this->failure( new RuntimeException( "Client::getLastRequest() should not be null" ), $connection ); |
| 406 | } |
| 407 | } |
| 408 | foreach ( $multiResultSet->getResultSets() as $resultSet ) { |
| 409 | if ( $resultSet->getResponse()->hasError() ) { |
| 410 | if ( $lastRequest !== null ) { |
| 411 | return $this->failure( new ResponseException( $lastRequest, $resultSet->getResponse() ), $connection ); |
| 412 | } else { |
| 413 | return $this->failure( new RuntimeException( "Client::getLastRequest() should not be null" ), $connection ); |
| 414 | } |
| 415 | } |
| 416 | } |
| 417 | |
| 418 | return $this->success( $resultsTransformer !== null ? $resultsTransformer( $multiResultSet ) : $multiResultSet, $connection ); |
| 419 | } catch ( ExceptionInterface $e ) { |
| 420 | return $this->failure( $e, $connection ); |
| 421 | } |
| 422 | } |
| 423 | } |