| 1 |
<?php |
| 2 |
/** |
| 3 |
* Query Logger class |
| 4 |
* |
| 5 |
* phpcs:disable WordPress.DateTime.CurrentTimeTimestamp.Requested |
| 6 |
* |
| 7 |
* @since 4.4.0 |
| 8 |
* @package elasticpress |
| 9 |
*/ |
| 10 |
|
| 11 |
namespace ElasticPress; |
| 12 |
|
| 13 |
defined( 'ABSPATH' ) || exit; |
| 14 |
|
| 15 |
/** |
| 16 |
* Query Logger class |
| 17 |
* |
| 18 |
* @package ElasticPress |
| 19 |
*/ |
| 20 |
class QueryLogger { |
| 21 |
/** |
| 22 |
* String used to get and update the transient. |
| 23 |
*/ |
| 24 |
const CACHE_KEY = 'ep_query_log'; |
| 25 |
|
| 26 |
/** |
| 27 |
* Setup the logging functionality |
| 28 |
*/ |
| 29 |
public function setup() { |
| 30 |
add_action( 'ep_remote_request', [ $this, 'log_query' ], 10, 2 ); |
| 31 |
add_filter( 'ep_admin_notices', [ $this, 'maybe_add_notice' ] ); |
| 32 |
|
| 33 |
add_action( 'ep_sync_start_index', [ $this, 'clear_logs' ] ); |
| 34 |
} |
| 35 |
|
| 36 |
/** |
| 37 |
* Conditionally save a query to the log which is stored in options. This is a big performance hit so be careful. |
| 38 |
* |
| 39 |
* @param array $query Remote request arguments |
| 40 |
* @param string $type Request type |
| 41 |
*/ |
| 42 |
public function log_query( $query, $type ) { |
| 43 |
$last_sync = Utils\get_option( 'ep_last_sync', false ); |
| 44 |
if ( empty( $last_sync ) ) { |
| 45 |
return; |
| 46 |
} |
| 47 |
|
| 48 |
$logs = $this->get_logs(); |
| 49 |
|
| 50 |
/** |
| 51 |
* Filter the number of queries to keep in the log |
| 52 |
* |
| 53 |
* @since 4.4.0 |
| 54 |
* @hook ep_query_logger_queries_to_keep |
| 55 |
* @param {int} $keep Number of queries to keep in the log |
| 56 |
* @param {array} $query Remote request arguments |
| 57 |
* @param {string} $type Request type |
| 58 |
* @return {int} New number |
| 59 |
*/ |
| 60 |
$keep = apply_filters( 'ep_query_logger_queries_to_keep', 5, $query, $type ); |
| 61 |
|
| 62 |
if ( $keep > 0 && count( $logs ) >= $keep ) { |
| 63 |
return; |
| 64 |
} |
| 65 |
|
| 66 |
if ( ! $this->should_log_query_type( $query, (string) $type ) ) { |
| 67 |
return; |
| 68 |
} |
| 69 |
|
| 70 |
array_unshift( $logs, $this->format_log_entry( $query, $type ) ); |
| 71 |
|
| 72 |
$logs_json_str = $this->update_logs( $logs ); |
| 73 |
|
| 74 |
/** |
| 75 |
* Perform actions after a new query is logged |
| 76 |
* |
| 77 |
* @hook ep_query_logger_logged_query |
| 78 |
* @since 4.4.0 |
| 79 |
* @param {string} $logs_json_str The JSON string as stored in the transient |
| 80 |
* @param {array} $query Remote request arguments |
| 81 |
* @param {string} $type Request type |
| 82 |
*/ |
| 83 |
do_action( 'ep_query_logger_logged_query', $logs_json_str, $query, $type ); |
| 84 |
} |
| 85 |
|
| 86 |
/** |
| 87 |
* Return logged failed queries. |
| 88 |
* |
| 89 |
* @param bool $should_filter_old Whether it should filter out old entries or not. Default to true, only return entries newer than the limit |
| 90 |
* @return array |
| 91 |
*/ |
| 92 |
public function get_logs( bool $should_filter_old = true ) : array { |
| 93 |
$logs = ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) ? |
| 94 |
get_site_transient( self::CACHE_KEY, [] ) : |
| 95 |
get_transient( self::CACHE_KEY, [] ); |
| 96 |
|
| 97 |
$logs = (array) json_decode( (string) $logs, true ); |
| 98 |
|
| 99 |
if ( $should_filter_old ) { |
| 100 |
$current_time = current_time( 'timestamp' ); |
| 101 |
|
| 102 |
/** |
| 103 |
* Filter the period to keep queried logs. Defaults to DAY_IN_SECONDS |
| 104 |
* |
| 105 |
* @since 4.4.0 |
| 106 |
* @hook ep_query_logger_time_to_keep |
| 107 |
* @param {int} $period_to_keep The period to keep queried logs, in seconds |
| 108 |
* @return {int} New period |
| 109 |
*/ |
| 110 |
$period_to_keep = apply_filters( 'ep_query_logger_time_to_keep', DAY_IN_SECONDS ); |
| 111 |
|
| 112 |
$time_limit = $current_time - $period_to_keep; |
| 113 |
|
| 114 |
$logs = array_filter( |
| 115 |
(array) $logs, |
| 116 |
function ( $log ) use ( $time_limit ) { |
| 117 |
return ! empty( $log['timestamp'] ) && $log['timestamp'] > $time_limit; |
| 118 |
} |
| 119 |
); |
| 120 |
} |
| 121 |
|
| 122 |
/** |
| 123 |
* Filter the logs |
| 124 |
* |
| 125 |
* @since 4.4.0 |
| 126 |
* @hook ep_query_logger_logs |
| 127 |
* @param {int} $logs The logs array |
| 128 |
* @return {int} New array |
| 129 |
*/ |
| 130 |
$logs = apply_filters( 'ep_query_logger_logs', $logs ); |
| 131 |
|
| 132 |
return $logs; |
| 133 |
} |
| 134 |
|
| 135 |
/** |
| 136 |
* Update the logs array in the transient |
| 137 |
* |
| 138 |
* @param array $logs New logs array |
| 139 |
*/ |
| 140 |
public function update_logs( array $logs ) { |
| 141 |
/** |
| 142 |
* Filter the max cache size. Defaults to MB_IN_BYTES |
| 143 |
* |
| 144 |
* @since 4.4.0 |
| 145 |
* @hook ep_query_logger_max_cache_size |
| 146 |
* @param {int} $max_cache_size The max cache size in bytes |
| 147 |
* @return {int} New size |
| 148 |
*/ |
| 149 |
$max_cache_size = apply_filters( 'ep_query_logger_max_cache_size', MB_IN_BYTES ); |
| 150 |
|
| 151 |
$logs_json_str = wp_json_encode( $logs ); |
| 152 |
$logs_json_str_size = strlen( $logs_json_str ); |
| 153 |
|
| 154 |
// If the logs size is too big, remove older entries (except the newest one) |
| 155 |
if ( $logs_json_str_size >= $max_cache_size ) { |
| 156 |
$logs_count = count( $logs ); |
| 157 |
for ( $i = 0; $i < ( $logs_count - 1 ); $i++ ) { |
| 158 |
array_pop( $logs ); |
| 159 |
|
| 160 |
$logs_json_str = wp_json_encode( $logs ); |
| 161 |
$logs_json_str_size = strlen( $logs_json_str ); |
| 162 |
|
| 163 |
if ( $logs_json_str_size < $max_cache_size ) { |
| 164 |
break; |
| 165 |
} |
| 166 |
} |
| 167 |
} |
| 168 |
|
| 169 |
// If even removing older entries, it is still too big, try to limit some of its info |
| 170 |
if ( $logs_json_str_size >= $max_cache_size ) { |
| 171 |
$logs[0]['body'] = '(removed due to its size)'; |
| 172 |
|
| 173 |
$logs_json_str = wp_json_encode( $logs ); |
| 174 |
$logs_json_str_size = strlen( $logs_json_str ); |
| 175 |
|
| 176 |
if ( $logs_json_str_size >= $max_cache_size ) { |
| 177 |
$logs[0]['result'] = '(removed due to its size)'; |
| 178 |
} |
| 179 |
} |
| 180 |
|
| 181 |
\ElasticPress\Utils\delete_option( 'ep_hide_has_failed_queries_notice' ); |
| 182 |
|
| 183 |
if ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) { |
| 184 |
set_site_transient( self::CACHE_KEY, $logs_json_str, DAY_IN_SECONDS ); |
| 185 |
} else { |
| 186 |
set_transient( self::CACHE_KEY, $logs_json_str, DAY_IN_SECONDS ); |
| 187 |
} |
| 188 |
|
| 189 |
return $logs_json_str; |
| 190 |
} |
| 191 |
|
| 192 |
/** |
| 193 |
* Clear the stored logs |
| 194 |
*/ |
| 195 |
public function clear_logs() { |
| 196 |
if ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) { |
| 197 |
delete_site_transient( self::CACHE_KEY ); |
| 198 |
} else { |
| 199 |
delete_transient( self::CACHE_KEY ); |
| 200 |
} |
| 201 |
|
| 202 |
/** |
| 203 |
* Perform actions after clearing the logs |
| 204 |
* |
| 205 |
* @hook ep_query_logger_cleared_logs |
| 206 |
* @since 4.4.0 |
| 207 |
*/ |
| 208 |
do_action( 'ep_query_logger_cleared_logs' ); |
| 209 |
} |
| 210 |
|
| 211 |
/** |
| 212 |
* Conditionally display a notice in the admin |
| 213 |
* |
| 214 |
* @param array $notices Current EP notices |
| 215 |
* @return array |
| 216 |
*/ |
| 217 |
public function maybe_add_notice( array $notices ) : array { |
| 218 |
if ( ! current_user_can( Utils\get_capability() ) ) { |
| 219 |
return $notices; |
| 220 |
} |
| 221 |
|
| 222 |
$current_ep_screen = \ElasticPress\Screen::factory()->get_current_screen(); |
| 223 |
if ( 'status-report' === $current_ep_screen ) { |
| 224 |
return $notices; |
| 225 |
} |
| 226 |
|
| 227 |
if ( \ElasticPress\Utils\get_option( 'ep_hide_has_failed_queries_notice' ) ) { |
| 228 |
return $notices; |
| 229 |
} |
| 230 |
|
| 231 |
$logs = $this->get_logs(); |
| 232 |
if ( empty( $logs ) ) { |
| 233 |
return $notices; |
| 234 |
} |
| 235 |
|
| 236 |
$indices_comparison = Elasticsearch::factory()->get_indices_comparison(); |
| 237 |
$present_indices = count( $indices_comparison['present_indices'] ); |
| 238 |
|
| 239 |
if ( 0 === $present_indices ) { |
| 240 |
$message = sprintf( |
| 241 |
/* translators: %s: Sync page link. */ |
| 242 |
esc_html__( 'Your site\'s content is not synced with your %1$s. Please %2$s.', 'elasticpress' ), |
| 243 |
Utils\is_epio() ? __( 'ElasticPress.io account', 'elasticpress' ) : __( 'Elasticsearch server', 'elasticpress' ), |
| 244 |
sprintf( |
| 245 |
'<a href="%1$s">%2$s</a>', |
| 246 |
esc_url( Utils\get_sync_url( true ) ), |
| 247 |
esc_html__( 'sync your content', 'elasticpress' ) |
| 248 |
) |
| 249 |
); |
| 250 |
} else { |
| 251 |
$page = 'admin.php?page=elasticpress-status-report'; |
| 252 |
|
| 253 |
$status_report_url = ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) ? |
| 254 |
network_admin_url( $page ) : |
| 255 |
admin_url( $page ); |
| 256 |
|
| 257 |
$message = sprintf( |
| 258 |
/* translators: Status Report URL */ |
| 259 |
__( 'Some ElasticPress queries failed in the last 24 hours. Please visit the <a href="%s">Status Report page</a> for more details.', 'elasticpress' ), |
| 260 |
$status_report_url . '#failed-queries' |
| 261 |
); |
| 262 |
} |
| 263 |
|
| 264 |
$notices['has_failed_queries'] = [ |
| 265 |
'html' => $message, |
| 266 |
'type' => 'warning', |
| 267 |
'dismiss' => true, |
| 268 |
]; |
| 269 |
|
| 270 |
return $notices; |
| 271 |
} |
| 272 |
|
| 273 |
/** |
| 274 |
* Given a query, return a formatted log entry |
| 275 |
* |
| 276 |
* @param array $query The failed query |
| 277 |
* @param string $type The query type |
| 278 |
* @return array |
| 279 |
*/ |
| 280 |
protected function format_log_entry( array $query, string $type ) : array { |
| 281 |
global $wp; |
| 282 |
|
| 283 |
$query_time = ( ! empty( $query['time_start'] ) && ! empty( $query['time_finish'] ) ) ? |
| 284 |
( $query['time_finish'] - $query['time_start'] ) * 1000 : |
| 285 |
false; |
| 286 |
|
| 287 |
// If the body is too big, trim it down to avoid storing a too big log entry |
| 288 |
$body = ! empty( $query['args']['body'] ) ? $query['args']['body'] : ''; |
| 289 |
if ( strlen( $body ) > 200 * KB_IN_BYTES ) { |
| 290 |
$body = substr( $body, 0, 1000 ) . ' (trimmed)'; |
| 291 |
} else { |
| 292 |
$json_body = json_decode( $body, true ); |
| 293 |
// Bulk indexes are not "valid" JSON, for example. |
| 294 |
if ( json_last_error() === JSON_ERROR_NONE ) { |
| 295 |
$body = wp_json_encode( $json_body ); |
| 296 |
} |
| 297 |
} |
| 298 |
|
| 299 |
$request_id = ( ! empty( $query['args']['headers'] ) && ! empty( $query['args']['headers']['X-ElasticPress-Request-ID'] ) ) ? |
| 300 |
$query['args']['headers']['X-ElasticPress-Request-ID'] : |
| 301 |
null; |
| 302 |
|
| 303 |
$status = wp_remote_retrieve_response_code( $query['request'] ); |
| 304 |
$result = json_decode( wp_remote_retrieve_body( $query['request'] ), true ); |
| 305 |
|
| 306 |
$formatted_log = [ |
| 307 |
'wp_url' => home_url( add_query_arg( [ $_GET ], $wp->request ) ), // phpcs:ignore WordPress.Security.NonceVerification |
| 308 |
'es_req' => $query['args']['method'] . ' ' . $query['url'], |
| 309 |
'request_id' => $request_id ?? '', |
| 310 |
'timestamp' => current_time( 'timestamp' ), |
| 311 |
'query_time' => $query_time, |
| 312 |
'wp_args' => $query['query_args'] ?? [], |
| 313 |
'status_code' => $status, |
| 314 |
'body' => $body, |
| 315 |
'result' => $result, |
| 316 |
]; |
| 317 |
|
| 318 |
/** |
| 319 |
* Filter the formatted query log |
| 320 |
* |
| 321 |
* @since 4.4.0 |
| 322 |
* @hook ep_query_logger_formatted_query |
| 323 |
* @param {array} $formatted_log The log entry |
| 324 |
* @param {array} $query The failed query |
| 325 |
* @param {string} $type The query type |
| 326 |
* @return {array} Changed log entry |
| 327 |
*/ |
| 328 |
return apply_filters( 'ep_query_logger_formatted_query', $formatted_log, $query, $type ); |
| 329 |
} |
| 330 |
|
| 331 |
/** |
| 332 |
* Given a query and its type, check if it should be logged |
| 333 |
* |
| 334 |
* @param array $query The failed query |
| 335 |
* @param string $type The query type |
| 336 |
* @return boolean |
| 337 |
*/ |
| 338 |
protected function should_log_query_type( array $query, string $type ) : bool { |
| 339 |
/** |
| 340 |
* Filter the array with a map from query types to callables. If the callable returns true, |
| 341 |
* the query will be logged. |
| 342 |
* |
| 343 |
* @since 4.4.0 |
| 344 |
* @hook ep_query_logger_allowed_log_types |
| 345 |
* @param {array} $callable_map Array indexed by type and valued by a callable that returns a boolean |
| 346 |
* @param {array} $query Remote request arguments |
| 347 |
* @param {string} $type Request type |
| 348 |
* @return {array} New array |
| 349 |
*/ |
| 350 |
$allowed_log_types = apply_filters( |
| 351 |
'ep_query_logger_allowed_log_types', |
| 352 |
array( |
| 353 |
'put_mapping' => array( $this, 'is_query_error' ), |
| 354 |
'delete_network_alias' => array( $this, 'is_query_error' ), |
| 355 |
'create_network_alias' => array( $this, 'is_query_error' ), |
| 356 |
'bulk_index' => array( $this, 'is_bulk_index_error' ), |
| 357 |
'delete_index' => array( $this, 'maybe_log_delete_index' ), |
| 358 |
'create_pipeline' => array( $this, 'is_query_error' ), |
| 359 |
'get_pipeline' => array( $this, 'is_query_error' ), |
| 360 |
'query' => array( $this, 'is_query_error' ), |
| 361 |
), |
| 362 |
$query, |
| 363 |
$type |
| 364 |
); |
| 365 |
|
| 366 |
$should_log = isset( $allowed_log_types[ $type ] ) ? |
| 367 |
call_user_func( $allowed_log_types[ $type ], $query ) : |
| 368 |
false; |
| 369 |
|
| 370 |
/** |
| 371 |
* Filter the formatted query log |
| 372 |
* |
| 373 |
* @since 4.4.0 |
| 374 |
* @hook ep_query_logger_should_log_query |
| 375 |
* @param {bool} $should_log Whether the query should be logged or not |
| 376 |
* @param {array} $query The failed query |
| 377 |
* @param {string} $type The query type |
| 378 |
* @return {bool} New value of $should_log |
| 379 |
*/ |
| 380 |
return apply_filters( 'ep_query_logger_should_log_query', $should_log, $query, $type ); |
| 381 |
} |
| 382 |
|
| 383 |
/** |
| 384 |
* Check the request body, as usually bulk indexing does not return a status error. |
| 385 |
* |
| 386 |
* @param array $query Remote request arguments |
| 387 |
* @return boolean |
| 388 |
*/ |
| 389 |
protected function is_bulk_index_error( $query ) { |
| 390 |
if ( is_wp_error( $query['request'] ) ) { |
| 391 |
return true; |
| 392 |
} |
| 393 |
|
| 394 |
$response_code = wp_remote_retrieve_response_code( $query['request'] ); |
| 395 |
// Bulk index dynamically will eventually fire a 413 (too big) request but will recover from it |
| 396 |
if ( 413 === $response_code && false !== strpos( wp_debug_backtrace_summary(), 'bulk_index_dynamically' ) ) { // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_wp_debug_backtrace_summary |
| 397 |
return false; |
| 398 |
} |
| 399 |
|
| 400 |
if ( $response_code < 200 || $response_code > 299 ) { |
| 401 |
return true; |
| 402 |
} |
| 403 |
|
| 404 |
$request_body = json_decode( wp_remote_retrieve_body( $query['request'] ), true ); |
| 405 |
return ! empty( $request_body['errors'] ); |
| 406 |
} |
| 407 |
|
| 408 |
/** |
| 409 |
* Only log delete index error if not 2xx AND not 404 |
| 410 |
* |
| 411 |
* @param array $query Remote request arguments |
| 412 |
* @return bool |
| 413 |
*/ |
| 414 |
protected function maybe_log_delete_index( $query ) { |
| 415 |
$response_code = wp_remote_retrieve_response_code( $query['request'] ); |
| 416 |
|
| 417 |
return ( ( $response_code < 200 || $response_code > 299 ) && 404 !== $response_code ); |
| 418 |
} |
| 419 |
|
| 420 |
/** |
| 421 |
* Log all non-200 requests |
| 422 |
* |
| 423 |
* @param array $query Remote request arguments |
| 424 |
* @return bool |
| 425 |
*/ |
| 426 |
protected function is_query_error( $query ) { |
| 427 |
if ( is_wp_error( $query['request'] ) ) { |
| 428 |
return true; |
| 429 |
} |
| 430 |
|
| 431 |
$response_code = wp_remote_retrieve_response_code( $query['request'] ); |
| 432 |
|
| 433 |
return ( $response_code < 200 || $response_code > 299 ); |
| 434 |
} |
| 435 |
} |
| 436 |
|
