<?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 );
}
}