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