444 lines
13 KiB
PHP
444 lines
13 KiB
PHP
<?php
|
|
/**
|
|
* Query Logger class
|
|
*
|
|
* phpcs:disable WordPress.DateTime.CurrentTimeTimestamp.Requested
|
|
*
|
|
* @since 4.4.0
|
|
* @package elasticpress
|
|
*/
|
|
|
|
namespace ElasticPress;
|
|
|
|
defined( 'ABSPATH' ) || exit;
|
|
|
|
/**
|
|
* Query Logger class
|
|
*
|
|
* @package ElasticPress
|
|
*/
|
|
class QueryLogger {
|
|
/**
|
|
* String used to get and update the transient.
|
|
*/
|
|
const CACHE_KEY = 'ep_query_log';
|
|
|
|
/**
|
|
* Setup the logging functionality
|
|
*/
|
|
public function setup() {
|
|
add_action( 'ep_remote_request', [ $this, 'log_query' ], 10, 2 );
|
|
add_filter( 'ep_admin_notices', [ $this, 'maybe_add_notice' ] );
|
|
|
|
add_action( 'ep_sync_start_index', [ $this, 'clear_logs' ] );
|
|
}
|
|
|
|
/**
|
|
* Conditionally save a query to the log which is stored in options. This is a big performance hit so be careful.
|
|
*
|
|
* @param array $query Remote request arguments
|
|
* @param string $type Request type
|
|
*/
|
|
public function log_query( $query, $type ) {
|
|
$last_sync = Utils\get_option( 'ep_last_sync', false );
|
|
if ( empty( $last_sync ) ) {
|
|
return;
|
|
}
|
|
|
|
$logs = $this->get_logs();
|
|
|
|
/**
|
|
* Filter the number of queries to keep in the log
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_queries_to_keep
|
|
* @param {int} $keep Number of queries to keep in the log
|
|
* @param {array} $query Remote request arguments
|
|
* @param {string} $type Request type
|
|
* @return {int} New number
|
|
*/
|
|
$keep = apply_filters( 'ep_query_logger_queries_to_keep', 5, $query, $type );
|
|
|
|
if ( $keep > 0 && count( $logs ) >= $keep ) {
|
|
return;
|
|
}
|
|
|
|
if ( ! $this->should_log_query_type( $query, (string) $type ) ) {
|
|
return;
|
|
}
|
|
|
|
array_unshift( $logs, $this->format_log_entry( $query, $type ) );
|
|
|
|
$logs_json_str = $this->update_logs( $logs );
|
|
|
|
/**
|
|
* Perform actions after a new query is logged
|
|
*
|
|
* @hook ep_query_logger_logged_query
|
|
* @since 4.4.0
|
|
* @param {string} $logs_json_str The JSON string as stored in the transient
|
|
* @param {array} $query Remote request arguments
|
|
* @param {string} $type Request type
|
|
*/
|
|
do_action( 'ep_query_logger_logged_query', $logs_json_str, $query, $type );
|
|
}
|
|
|
|
/**
|
|
* Return logged failed queries.
|
|
*
|
|
* @param bool $should_filter_old Whether it should filter out old entries or not. Default to true, only return entries newer than the limit
|
|
* @return array
|
|
*/
|
|
public function get_logs( bool $should_filter_old = true ) : array {
|
|
$logs = ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) ?
|
|
get_site_transient( self::CACHE_KEY, [] ) :
|
|
get_transient( self::CACHE_KEY, [] );
|
|
|
|
$logs = (array) json_decode( (string) $logs, true );
|
|
|
|
if ( $should_filter_old ) {
|
|
$current_time = current_time( 'timestamp' );
|
|
|
|
/**
|
|
* Filter the period to keep queried logs. Defaults to DAY_IN_SECONDS
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_time_to_keep
|
|
* @param {int} $period_to_keep The period to keep queried logs, in seconds
|
|
* @return {int} New period
|
|
*/
|
|
$period_to_keep = apply_filters( 'ep_query_logger_time_to_keep', DAY_IN_SECONDS );
|
|
|
|
$time_limit = $current_time - $period_to_keep;
|
|
|
|
$logs = array_filter(
|
|
(array) $logs,
|
|
function ( $log ) use ( $time_limit ) {
|
|
return ! empty( $log['timestamp'] ) && $log['timestamp'] > $time_limit;
|
|
}
|
|
);
|
|
}
|
|
|
|
/**
|
|
* Filter the logs
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_logs
|
|
* @param {int} $logs The logs array
|
|
* @return {int} New array
|
|
*/
|
|
$logs = apply_filters( 'ep_query_logger_logs', $logs );
|
|
|
|
return $logs;
|
|
}
|
|
|
|
/**
|
|
* Update the logs array in the transient
|
|
*
|
|
* @param array $logs New logs array
|
|
*/
|
|
public function update_logs( array $logs ) {
|
|
/**
|
|
* Filter the max cache size. Defaults to MB_IN_BYTES
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_max_cache_size
|
|
* @param {int} $max_cache_size The max cache size in bytes
|
|
* @return {int} New size
|
|
*/
|
|
$max_cache_size = apply_filters( 'ep_query_logger_max_cache_size', MB_IN_BYTES );
|
|
|
|
$logs_json_str = wp_json_encode( $logs );
|
|
$logs_json_str_size = strlen( $logs_json_str );
|
|
|
|
// If the logs size is too big, remove older entries (except the newest one)
|
|
if ( $logs_json_str_size >= $max_cache_size ) {
|
|
$logs_count = count( $logs );
|
|
for ( $i = 0; $i < ( $logs_count - 1 ); $i++ ) {
|
|
array_pop( $logs );
|
|
|
|
$logs_json_str = wp_json_encode( $logs );
|
|
$logs_json_str_size = strlen( $logs_json_str );
|
|
|
|
if ( $logs_json_str_size < $max_cache_size ) {
|
|
break;
|
|
}
|
|
}
|
|
}
|
|
|
|
// If even removing older entries, it is still too big, try to limit some of its info
|
|
if ( $logs_json_str_size >= $max_cache_size ) {
|
|
$logs[0]['body'] = '(removed due to its size)';
|
|
|
|
$logs_json_str = wp_json_encode( $logs );
|
|
$logs_json_str_size = strlen( $logs_json_str );
|
|
|
|
if ( $logs_json_str_size >= $max_cache_size ) {
|
|
$logs[0]['result'] = '(removed due to its size)';
|
|
}
|
|
}
|
|
|
|
\ElasticPress\Utils\delete_option( 'ep_hide_has_failed_queries_notice' );
|
|
|
|
if ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) {
|
|
set_site_transient( self::CACHE_KEY, $logs_json_str, DAY_IN_SECONDS );
|
|
} else {
|
|
set_transient( self::CACHE_KEY, $logs_json_str, DAY_IN_SECONDS );
|
|
}
|
|
|
|
return $logs_json_str;
|
|
}
|
|
|
|
/**
|
|
* Clear the stored logs
|
|
*/
|
|
public function clear_logs() {
|
|
if ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) {
|
|
delete_site_transient( self::CACHE_KEY );
|
|
} else {
|
|
delete_transient( self::CACHE_KEY );
|
|
}
|
|
|
|
/**
|
|
* Perform actions after clearing the logs
|
|
*
|
|
* @hook ep_query_logger_cleared_logs
|
|
* @since 4.4.0
|
|
*/
|
|
do_action( 'ep_query_logger_cleared_logs' );
|
|
}
|
|
|
|
/**
|
|
* Conditionally display a notice in the admin
|
|
*
|
|
* @param array $notices Current EP notices
|
|
* @return array
|
|
*/
|
|
public function maybe_add_notice( array $notices ) : array {
|
|
if ( ! current_user_can( Utils\get_capability() ) ) {
|
|
return $notices;
|
|
}
|
|
|
|
$current_ep_screen = \ElasticPress\Screen::factory()->get_current_screen();
|
|
if ( 'status-report' === $current_ep_screen ) {
|
|
return $notices;
|
|
}
|
|
|
|
if ( \ElasticPress\Utils\get_option( 'ep_hide_has_failed_queries_notice' ) ) {
|
|
return $notices;
|
|
}
|
|
|
|
$logs = $this->get_logs();
|
|
if ( empty( $logs ) ) {
|
|
return $notices;
|
|
}
|
|
|
|
$indices_comparison = Elasticsearch::factory()->get_indices_comparison();
|
|
$present_indices = count( $indices_comparison['present_indices'] );
|
|
|
|
if ( 0 === $present_indices ) {
|
|
$message = sprintf(
|
|
/* translators: %s: Sync page link. */
|
|
esc_html__( 'Your site\'s content is not synced with your %1$s. Please %2$s.', 'elasticpress' ),
|
|
Utils\is_epio() ? __( 'ElasticPress.io account', 'elasticpress' ) : __( 'Elasticsearch server', 'elasticpress' ),
|
|
sprintf(
|
|
'<a href="%1$s">%2$s</a>',
|
|
esc_url( Utils\get_sync_url( true ) ),
|
|
esc_html__( 'sync your content', 'elasticpress' )
|
|
)
|
|
);
|
|
} else {
|
|
$page = 'admin.php?page=elasticpress-status-report';
|
|
|
|
$status_report_url = ( defined( 'EP_IS_NETWORK' ) && EP_IS_NETWORK ) ?
|
|
network_admin_url( $page ) :
|
|
admin_url( $page );
|
|
|
|
$message = sprintf(
|
|
/* translators: Status Report URL */
|
|
__( 'Some ElasticPress queries failed in the last 24 hours. Please visit the <a href="%s">Status Report page</a> for more details.', 'elasticpress' ),
|
|
$status_report_url . '#failed-queries'
|
|
);
|
|
}
|
|
|
|
$notices['has_failed_queries'] = [
|
|
'html' => $message,
|
|
'type' => 'warning',
|
|
'dismiss' => true,
|
|
];
|
|
|
|
return $notices;
|
|
}
|
|
|
|
/**
|
|
* Given a query, return a formatted log entry
|
|
*
|
|
* @param array $query The failed query
|
|
* @param string $type The query type
|
|
* @return array
|
|
*/
|
|
protected function format_log_entry( array $query, string $type ) : array {
|
|
global $wp;
|
|
|
|
$query_time = ( ! empty( $query['time_start'] ) && ! empty( $query['time_finish'] ) ) ?
|
|
( $query['time_finish'] - $query['time_start'] ) * 1000 :
|
|
false;
|
|
|
|
// If the body is too big, trim it down to avoid storing a too big log entry
|
|
$body = ! empty( $query['args']['body'] ) ? $query['args']['body'] : '';
|
|
if ( strlen( $body ) > 200 * KB_IN_BYTES ) {
|
|
$body = substr( $body, 0, 1000 ) . ' (trimmed)';
|
|
} else {
|
|
$json_body = json_decode( $body, true );
|
|
// Bulk indexes are not "valid" JSON, for example.
|
|
if ( json_last_error() === JSON_ERROR_NONE ) {
|
|
$body = wp_json_encode( $json_body );
|
|
}
|
|
}
|
|
|
|
$request_id = ( ! empty( $query['args']['headers'] ) && ! empty( $query['args']['headers']['X-ElasticPress-Request-ID'] ) ) ?
|
|
$query['args']['headers']['X-ElasticPress-Request-ID'] :
|
|
null;
|
|
|
|
$status = wp_remote_retrieve_response_code( $query['request'] );
|
|
if ( is_wp_error( $query['request'] ) ) {
|
|
$result = [
|
|
'is_wp_error' => true,
|
|
'code' => $query['request']->get_error_code(),
|
|
'message' => $query['request']->get_error_message(),
|
|
'data' => $query['request']->get_error_data(),
|
|
];
|
|
} else {
|
|
$result = json_decode( wp_remote_retrieve_body( $query['request'] ), true );
|
|
}
|
|
|
|
$formatted_log = [
|
|
'wp_url' => home_url( add_query_arg( [ $_GET ], $wp->request ) ), // phpcs:ignore WordPress.Security.NonceVerification
|
|
'es_req' => $query['args']['method'] . ' ' . $query['url'],
|
|
'request_id' => $request_id ?? '',
|
|
'timestamp' => current_time( 'timestamp' ),
|
|
'query_time' => $query_time,
|
|
'wp_args' => $query['query_args'] ?? [],
|
|
'status_code' => $status,
|
|
'body' => $body,
|
|
'result' => $result,
|
|
];
|
|
|
|
/**
|
|
* Filter the formatted query log
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_formatted_query
|
|
* @param {array} $formatted_log The log entry
|
|
* @param {array} $query The failed query
|
|
* @param {string} $type The query type
|
|
* @return {array} Changed log entry
|
|
*/
|
|
return apply_filters( 'ep_query_logger_formatted_query', $formatted_log, $query, $type );
|
|
}
|
|
|
|
/**
|
|
* Given a query and its type, check if it should be logged
|
|
*
|
|
* @param array $query The failed query
|
|
* @param string $type The query type
|
|
* @return boolean
|
|
*/
|
|
protected function should_log_query_type( array $query, string $type ) : bool {
|
|
/**
|
|
* Filter the array with a map from query types to callables. If the callable returns true,
|
|
* the query will be logged.
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_allowed_log_types
|
|
* @param {array} $callable_map Array indexed by type and valued by a callable that returns a boolean
|
|
* @param {array} $query Remote request arguments
|
|
* @param {string} $type Request type
|
|
* @return {array} New array
|
|
*/
|
|
$allowed_log_types = apply_filters(
|
|
'ep_query_logger_allowed_log_types',
|
|
array(
|
|
'put_mapping' => array( $this, 'is_query_error' ),
|
|
'delete_network_alias' => array( $this, 'is_query_error' ),
|
|
'create_network_alias' => array( $this, 'is_query_error' ),
|
|
'bulk_index' => array( $this, 'is_bulk_index_error' ),
|
|
'delete_index' => array( $this, 'maybe_log_delete_index' ),
|
|
'create_pipeline' => array( $this, 'is_query_error' ),
|
|
'get_pipeline' => array( $this, 'is_query_error' ),
|
|
'query' => array( $this, 'is_query_error' ),
|
|
),
|
|
$query,
|
|
$type
|
|
);
|
|
|
|
$should_log = isset( $allowed_log_types[ $type ] ) ?
|
|
call_user_func( $allowed_log_types[ $type ], $query ) :
|
|
false;
|
|
|
|
/**
|
|
* Filter the formatted query log
|
|
*
|
|
* @since 4.4.0
|
|
* @hook ep_query_logger_should_log_query
|
|
* @param {bool} $should_log Whether the query should be logged or not
|
|
* @param {array} $query The failed query
|
|
* @param {string} $type The query type
|
|
* @return {bool} New value of $should_log
|
|
*/
|
|
return apply_filters( 'ep_query_logger_should_log_query', $should_log, $query, $type );
|
|
}
|
|
|
|
/**
|
|
* Check the request body, as usually bulk indexing does not return a status error.
|
|
*
|
|
* @param array $query Remote request arguments
|
|
* @return boolean
|
|
*/
|
|
protected function is_bulk_index_error( $query ) {
|
|
if ( is_wp_error( $query['request'] ) ) {
|
|
return true;
|
|
}
|
|
|
|
$response_code = wp_remote_retrieve_response_code( $query['request'] );
|
|
// Bulk index dynamically will eventually fire a 413 (too big) request but will recover from it
|
|
if ( 413 === $response_code && false !== strpos( wp_debug_backtrace_summary(), 'bulk_index_dynamically' ) ) { // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_wp_debug_backtrace_summary
|
|
return false;
|
|
}
|
|
|
|
if ( $response_code < 200 || $response_code > 299 ) {
|
|
return true;
|
|
}
|
|
|
|
$request_body = json_decode( wp_remote_retrieve_body( $query['request'] ), true );
|
|
return ! empty( $request_body['errors'] );
|
|
}
|
|
|
|
/**
|
|
* Only log delete index error if not 2xx AND not 404
|
|
*
|
|
* @param array $query Remote request arguments
|
|
* @return bool
|
|
*/
|
|
protected function maybe_log_delete_index( $query ) {
|
|
$response_code = wp_remote_retrieve_response_code( $query['request'] );
|
|
|
|
return ( ( $response_code < 200 || $response_code > 299 ) && 404 !== $response_code );
|
|
}
|
|
|
|
/**
|
|
* Log all non-200 requests
|
|
*
|
|
* @param array $query Remote request arguments
|
|
* @return bool
|
|
*/
|
|
protected function is_query_error( $query ) {
|
|
if ( is_wp_error( $query['request'] ) ) {
|
|
return true;
|
|
}
|
|
|
|
$response_code = wp_remote_retrieve_response_code( $query['request'] );
|
|
|
|
return ( $response_code < 200 || $response_code > 299 );
|
|
}
|
|
}
|
