Log to logstash when VIP Search ratelimiting starts.

search/includes/classes/class-queue.php

@@ -19,6 +19,7 @@ class Queue {
 	public $schema;
 	public $statsd;
 	public $indexables;
+	public $logger;
 
 	public const INDEX_COUNT_CACHE_GROUP = 'vip_search';
 	public const INDEX_COUNT_CACHE_KEY = 'index_op_count';
@@ -71,6 +72,11 @@ public function init() {
 
 		$this->indexables = \ElasticPress\Indexables::factory();
 
+		// Logger - can be set explicitly for mocking purposes
+		if ( ! $this->logger ) {
+			$this->logger = new \Automattic\VIP\Logstash\Logger();
+		}
+
 		$this->setup_hooks();
 	}
 
@@ -868,6 +874,7 @@ public function ratelimit_indexing( $bail, $sync_manager, $indexable_slug ) {
 
 			if ( ! self::is_indexing_ratelimited() ) {
 				self::turn_on_index_ratelimiting();
+				$this->log_index_ratelimiting_start();
 			}
 		} else {
 			$this->clear_index_limiting_start_timestamp();
@@ -1073,4 +1080,22 @@ public function maybe_update_stat( $stat, $value ) {
 
 		$this->statsd->update_stats( $stat, $value, 1, 'c' );
 	}
+
+	/**
+	 * When indexing rate limting first begins, log this information and surface as a PHP warning
+	 */
+	public function log_index_ratelimiting_start() {
+		$message = sprintf(
+			'Application %d - %s has triggered Elasticsearch indexing rate limiting, which will last for %d seconds. Large batch indexing operations are being queued for indexing in batches over time.',
+			FILES_CLIENT_SITE_ID,
+			\home_url(),
+			self::$index_queueing_ttl
+		);
+
+		$this->logger->log(
+			'warning',
+			'vip_search_indexing_rate_limiting',
+			$message
+		);
+	}
 }

search/includes/classes/class-search.php

@@ -780,7 +780,11 @@ public function rate_limit_ep_query_integration( $skip ) {
 		// If the query count has exceeded the maximum
 		// only allow half of the queries to use VIP Search
 		if ( self::query_count_incr() > self::$max_query_count ) {
+			// Go first so that cache entries aren't set yet for first occurrence.
+			$this->maybe_log_query_ratelimiting_start();
+
 			$this->handle_query_limiting_start_timestamp();
+
 			$this->maybe_alert_for_prolonged_query_limiting();
 
 			// Should be roughly half over time
@@ -1511,4 +1515,20 @@ public function maybe_send_timing_stat( $stat, $duration ) {
 
 		$this->statsd->timing( $stat, $duration );
 	}
+
+	/**
+	 * When query rate limting first begins, log this information and surface as a PHP warning
+	 */
+	public function maybe_log_query_ratelimiting_start() {
+		if ( false === wp_cache_get( self::QUERY_RATE_LIMITED_START_CACHE_KEY, self::QUERY_COUNT_CACHE_GROUP ) ) {
+			$message = sprintf(
+				'Application %d - %s has triggered Elasticsearch query rate limiting, which will last up to %d seconds. Subsequent or repeat occurrences are possible. Half of traffic is diverted to the database when queries are rate limited.',
+				FILES_CLIENT_SITE_ID,
+				\home_url(),
+				self::$query_count_ttl
+			);
+
+			$this->logger->log( 'warning', 'vip_search_query_rate_limiting', $message );
+		}
+	}
 }

tests/search/includes/classes/test-class-queue.php

@@ -735,6 +735,21 @@ public function test__ratelimit_indexing__handles_start_correctly() {
 			] )
 			->getMock();
 
+		$partially_mocked_queue->logger = $this->getMockBuilder( \Automattic\VIP\Logstash\Logger::class )
+				->setMethods( [ 'log' ] )
+				->getMock();
+
+		$partially_mocked_queue->logger->expects( $this->once() )
+				->method( 'log' )
+				->with(
+					$this->equalTo( 'warning' ),
+					$this->equalTo( 'vip_search_indexing_rate_limiting' ),
+					$this->equalTo(
+						'Application 123 - http://example.org has triggered Elasticsearch indexing rate limiting, which will last for 300 seconds. Large batch indexing operations are being queued for indexing in batches over time.'
+					),
+					$this->anything()
+				);
+
 		$sync_manager = new \stdClass();
 		$sync_manager->sync_queue = range( 3, 9 );
 
@@ -1255,6 +1270,25 @@ public function test__maybe_update_stat_sampling_invalid_value_param( $value ) {
 		$this->queue->maybe_update_stat( 'test', $value );
 	}
 
+	public function test__log_index_ratelimiting_start() {
+		$this->queue->logger = $this->getMockBuilder( \Automattic\VIP\Logstash\Logger::class )
+				->setMethods( [ 'log' ] )
+				->getMock();
+
+		$this->queue->logger->expects( $this->once() )
+				->method( 'log' )
+				->with(
+					$this->equalTo( 'warning' ),
+					$this->equalTo( 'vip_search_indexing_rate_limiting' ),
+					$this->equalTo(
+						'Application 123 - http://example.org has triggered Elasticsearch indexing rate limiting, which will last for 300 seconds. Large batch indexing operations are being queued for indexing in batches over time.'
+					),
+					$this->anything()
+				);
+
+		$this->queue->log_index_ratelimiting_start();
+	}
+
 	/**
 	 * Helper function for accessing protected methods.
 	 */

tests/search/test-class-search.php

@@ -2349,6 +2349,43 @@ public function test__ep_handle_failed_request__log_message( $response, $expecte
 		$es->ep_handle_failed_request( $response, '' );
 	}
 
+	public function test__maybe_log_query_ratelimiting_start_should_do_nothing_if_ratelimiting_already_started() {
+		$es = new \Automattic\VIP\Search\Search();
+		$es->init();
+
+		wp_cache_set( $es::QUERY_RATE_LIMITED_START_CACHE_KEY, time(), $es::QUERY_COUNT_CACHE_GROUP );
+
+		$es->logger = $this->getMockBuilder( \Automattic\VIP\Logstash\Logger::class )
+				->setMethods( [ 'log' ] )
+				->getMock();
+
+		$es->logger->expects( $this->never() )->method( 'log' );
+
+		$es->maybe_log_query_ratelimiting_start();
+	}
+
+	public function test__maybe_log_query_ratelimiting_start_should_log_if_ratelimiting_not_already_started() {
+		$es = new \Automattic\VIP\Search\Search();
+		$es->init();
+
+		$es->logger = $this->getMockBuilder( \Automattic\VIP\Logstash\Logger::class )
+				->setMethods( [ 'log' ] )
+				->getMock();
+
+		$es->logger->expects( $this->once() )
+				->method( 'log' )
+				->with(
+					$this->equalTo( 'warning' ),
+					$this->equalTo( 'vip_search_query_rate_limiting' ),
+					$this->equalTo(
+						'Application 123 - http://example.org has triggered Elasticsearch query rate limiting, which will last up to 300 seconds. Subsequent or repeat occurrences are possible. Half of traffic is diverted to the database when queries are rate limited.'
+					),
+					$this->anything()
+				);
+
+		$es->maybe_log_query_ratelimiting_start();
+	}
+
 	/**
 	 * Helper function for accessing protected methods.
 	 */