From 1854c5e9db17042b25bb0bf4f6a52cf3069f7d43 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Mon, 2 Dec 2024 16:01:18 +0100 Subject: [PATCH 01/21] Initial attempt to add request IDs and context to the messages --- includes/class-logger.php | 25 ++++---- src/Internal/Logger.php | 126 +++++++++++++++++++++++++++++++++----- 2 files changed, 124 insertions(+), 27 deletions(-) diff --git a/includes/class-logger.php b/includes/class-logger.php index 3384d0fe443..663698b2afb 100644 --- a/includes/class-logger.php +++ b/includes/class-logger.php @@ -23,20 +23,21 @@ class Logger { * we need this to access the plugins debug setting to figure out if the setting * is turned on. * - * @param string $message Log message. + * @param string $message Log message. * - * @param string $level One of the following: - * 'emergency': System is unusable. - * 'alert': Action must be taken immediately. - * 'critical': Critical conditions. - * 'error': Error conditions. - * 'warning': Warning conditions. - * 'notice': Normal but significant condition. - * 'info': Informational messages. - * 'debug': Debug-level messages. + * @param string $level One of the following: + * 'emergency': System is unusable. + * 'alert': Action must be taken immediately. + * 'critical': Critical conditions. + * 'error': Error conditions. + * 'warning': Warning conditions. + * 'notice': Normal but significant condition. + * 'info': Informational messages. + * 'debug': Debug-level messages. + * @param array $context Context data. */ - public static function log( $message, $level = 'info' ) { - wcpay_get_container()->get( InternalLogger::class )->log( $message ); + public static function log( $message, $level = 'info', $context = [] ) { + wcpay_get_container()->get( InternalLogger::class )->log( $message, $level, $context ); } /** diff --git a/src/Internal/Logger.php b/src/Internal/Logger.php index a9d96fa5533..7545440849c 100644 --- a/src/Internal/Logger.php +++ b/src/Internal/Logger.php @@ -34,6 +34,27 @@ class Logger { */ private $mode; + /** + * Request identifier. + * + * @var string + */ + private $request_id; + + /** + * Context data. + * + * @var array + */ + private $context = []; + + /** + * Flag to determine if the logger has been initialized. + * + * @var bool + */ + private $initialized = false; + /** * Logger constructor. * @@ -41,29 +62,54 @@ class Logger { * @param Mode $mode Mode. */ public function __construct( WC_Logger_Interface $wc_logger, Mode $mode ) { - $this->wc_logger = $wc_logger; - $this->mode = $mode; + $this->wc_logger = $wc_logger; + $this->mode = $mode; + $this->request_id = uniqid(); + } + + /** + * Initialize the logger. + * + * @return void + */ + public function init() { + if ( $this->initialized ) { + return; + } + + add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); + + $this->initialized = true; } /** * Add a log entry. * - * @param string $message Log message. - * @param string $level One of the following: - * 'emergency': System is unusable. - * 'alert': Action must be taken immediately. - * 'critical': Critical conditions. - * 'error': Error conditions. - * 'warning': Warning conditions. - * 'notice': Normal but significant condition. - * 'info': Informational messages. - * 'debug': Debug-level messages. - */ - public function log( $message, $level = 'info' ): void { + * @param string $message Log message. + * @param string $level One of the following: + * 'emergency': System is unusable. + * 'alert': Action must be taken immediately. + * 'critical': Critical conditions. + * 'error': Error conditions. + * 'warning': Warning conditions. + * 'notice': Normal but significant condition. + * 'info': Informational messages. + * 'debug': Debug-level messages. + * @param array $context Context data. + */ + public function log( $message, $level = 'info', $context = [] ): void { if ( ! $this->can_log() ) { return; } - $this->wc_logger->log( $level, $message, [ 'source' => self::LOG_FILENAME ] ); + $this->init(); + $context = array_merge( + $context, + [ + 'woopayments' => $this->context, + 'source' => self::LOG_FILENAME, + ] + ); + $this->wc_logger->log( $level, $message, $context ); } /** @@ -158,4 +204,54 @@ public function info( $message ): void { public function debug( $message ): void { $this->log( $message, WC_Log_Levels::DEBUG ); } + + /** + * Set the request ID. + * + * @param string $request_id Request ID. + */ + public function set_request_id( $request_id ): void { + $this->request_id = $request_id; + } + + /** + * Filter the log entry to include the request ID and context. + * + * @param string $entry Log entry. + * @param array $context Log entry context. + * @return string + */ + public function filter_log_entry( $entry, $context ): string { + $entry_context = is_array( $context ) && array_key_exists( 'context', $context ) + ? $context['context'] + : []; + if ( array_key_exists( 'woopayments', $entry_context ) ) { + $time_string = gmdate( 'c', $context['timestamp'] ); + $level_string = strtoupper( $context['level'] ); + $format_string = sprintf( '%s %s %s %%s', $time_string, $level_string, $this->request_id ); + + $entries = []; + + if ( is_array( $entry_context['woopayments'] ) ) { + $encoded = wp_json_encode( $entry_context['woopayments'] ); + if ( false !== $encoded ) { + $entries[] = sprintf( 'CONTEXT: %s', $encoded ); + } + } + + $entries[] = $context['message']; + + return implode( + "\n", + array_map( + function ( $entry ) use ( $format_string ) { + return sprintf( $format_string, $entry ); + }, + $entries + ) + ); + } else { + return $entry; + } + } } From e02b9fd291ff406f264ad373cb7ea8043b354171 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Tue, 3 Dec 2024 14:07:57 +0100 Subject: [PATCH 02/21] Split responsibilities by adding a Logger Context management class --- includes/class-logger-context.php | 38 ++++++ includes/class-wc-payments.php | 3 + .../GenericServiceProvider.php | 4 + src/Internal/Logger.php | 100 +-------------- src/Internal/LoggerContext.php | 117 ++++++++++++++++++ 5 files changed, 165 insertions(+), 97 deletions(-) create mode 100644 includes/class-logger-context.php create mode 100644 src/Internal/LoggerContext.php diff --git a/includes/class-logger-context.php b/includes/class-logger-context.php new file mode 100644 index 00000000000..1ae0361d9eb --- /dev/null +++ b/includes/class-logger-context.php @@ -0,0 +1,38 @@ +get( InternalLoggerContext::class )->init(); + } + + /** + * Sets a context value. + * + * @param string $key The key to set. + * @param string|int|float|bool|null $value The value to set. Null removes value. + * + * @return mixed The value. + */ + public static function set_value( $key, $value ) { + wcpay_get_container()->get( InternalLoggerContext::class )->set_value( $key, $value ); + } +} diff --git a/includes/class-wc-payments.php b/includes/class-wc-payments.php index 66e72bb8dbf..8c770d35a21 100644 --- a/includes/class-wc-payments.php +++ b/includes/class-wc-payments.php @@ -417,6 +417,7 @@ public static function init() { include_once __DIR__ . '/class-wc-payments-account.php'; include_once __DIR__ . '/class-wc-payments-customer-service.php'; include_once __DIR__ . '/class-logger.php'; + include_once __DIR__ . '/class-logger-context.php'; include_once __DIR__ . '/class-session-rate-limiter.php'; include_once __DIR__ . '/class-wc-payment-gateway-wcpay.php'; include_once __DIR__ . '/class-wc-payments-checkout.php'; @@ -509,6 +510,8 @@ public static function init() { include_once __DIR__ . '/compat/multi-currency/class-wc-payments-currency-manager.php'; include_once __DIR__ . '/class-duplicates-detection-service.php'; + wcpay_get_container()->get( \WCPay\Internal\LoggerContext::class )->init(); + self::$woopay_checkout_service = new Checkout_Service(); self::$woopay_checkout_service->init(); diff --git a/src/Internal/DependencyManagement/ServiceProvider/GenericServiceProvider.php b/src/Internal/DependencyManagement/ServiceProvider/GenericServiceProvider.php index 9d11140d15a..dacb4046995 100644 --- a/src/Internal/DependencyManagement/ServiceProvider/GenericServiceProvider.php +++ b/src/Internal/DependencyManagement/ServiceProvider/GenericServiceProvider.php @@ -12,6 +12,7 @@ use WCPay\Core\Mode; use WCPay\Internal\DependencyManagement\AbstractServiceProvider; use WCPay\Internal\Logger; +use WCPay\Internal\LoggerContext; use WCPay\Internal\Proxy\HooksProxy; use WCPay\Internal\Proxy\LegacyProxy; use WCPay\Internal\Service\Level3Service; @@ -30,6 +31,7 @@ class GenericServiceProvider extends AbstractServiceProvider { */ protected $provides = [ Logger::class, + LoggerContext::class, OrderService::class, Level3Service::class, TranslationsLoader::class, @@ -47,6 +49,8 @@ public function register(): void { ->addArgument( 'wc_get_logger' ) ->addArgument( Mode::class ); + $container->addShared( LoggerContext::class ); + $container->addShared( OrderService::class ) ->addArgument( WC_Payments_Order_Service::class ) ->addArgument( LegacyProxy::class ) diff --git a/src/Internal/Logger.php b/src/Internal/Logger.php index 7545440849c..8665d6bd428 100644 --- a/src/Internal/Logger.php +++ b/src/Internal/Logger.php @@ -34,27 +34,6 @@ class Logger { */ private $mode; - /** - * Request identifier. - * - * @var string - */ - private $request_id; - - /** - * Context data. - * - * @var array - */ - private $context = []; - - /** - * Flag to determine if the logger has been initialized. - * - * @var bool - */ - private $initialized = false; - /** * Logger constructor. * @@ -62,24 +41,8 @@ class Logger { * @param Mode $mode Mode. */ public function __construct( WC_Logger_Interface $wc_logger, Mode $mode ) { - $this->wc_logger = $wc_logger; - $this->mode = $mode; - $this->request_id = uniqid(); - } - - /** - * Initialize the logger. - * - * @return void - */ - public function init() { - if ( $this->initialized ) { - return; - } - - add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); - - $this->initialized = true; + $this->wc_logger = $wc_logger; + $this->mode = $mode; } /** @@ -101,14 +64,7 @@ public function log( $message, $level = 'info', $context = [] ): void { if ( ! $this->can_log() ) { return; } - $this->init(); - $context = array_merge( - $context, - [ - 'woopayments' => $this->context, - 'source' => self::LOG_FILENAME, - ] - ); + $context = array_merge( $context, [ 'source' => self::LOG_FILENAME ] ); $this->wc_logger->log( $level, $message, $context ); } @@ -204,54 +160,4 @@ public function info( $message ): void { public function debug( $message ): void { $this->log( $message, WC_Log_Levels::DEBUG ); } - - /** - * Set the request ID. - * - * @param string $request_id Request ID. - */ - public function set_request_id( $request_id ): void { - $this->request_id = $request_id; - } - - /** - * Filter the log entry to include the request ID and context. - * - * @param string $entry Log entry. - * @param array $context Log entry context. - * @return string - */ - public function filter_log_entry( $entry, $context ): string { - $entry_context = is_array( $context ) && array_key_exists( 'context', $context ) - ? $context['context'] - : []; - if ( array_key_exists( 'woopayments', $entry_context ) ) { - $time_string = gmdate( 'c', $context['timestamp'] ); - $level_string = strtoupper( $context['level'] ); - $format_string = sprintf( '%s %s %s %%s', $time_string, $level_string, $this->request_id ); - - $entries = []; - - if ( is_array( $entry_context['woopayments'] ) ) { - $encoded = wp_json_encode( $entry_context['woopayments'] ); - if ( false !== $encoded ) { - $entries[] = sprintf( 'CONTEXT: %s', $encoded ); - } - } - - $entries[] = $context['message']; - - return implode( - "\n", - array_map( - function ( $entry ) use ( $format_string ) { - return sprintf( $format_string, $entry ); - }, - $entries - ) - ); - } else { - return $entry; - } - } } diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php new file mode 100644 index 00000000000..72721767d54 --- /dev/null +++ b/src/Internal/LoggerContext.php @@ -0,0 +1,117 @@ + + */ + private $context = []; + + /** + * Whether the hooks have been set. + * + * @var bool + */ + private $hooks_set = false; + + /** + * Initialises the logger context. + * + * @return void + */ + public function init() { + $this->request_id = uniqid(); + $this->context = []; + + $this->setup_hooks(); + } + + /** + * Sets a context value. + * + * @param string $key The key to set. + * @param string|int|float|bool|null $value The value to set. Null removes value. + * + * @return mixed The value. + */ + public function set_value( $key, $value ) { + if ( null === $value && array_key_exists( $key, $this->context ) ) { + unset( $this->context[ $key ] ); + } else { + $this->context[ $key ] = $value; + } + } + + /** + * Filter the log entry to include the request ID and context. + * + * @param string $entry Log entry. + * @param array $context Log entry context. + * @return string + */ + public function filter_log_entry( $entry, $context ): string { + $entry_context = is_array( $context ) && array_key_exists( 'context', $context ) + ? $context['context'] + : []; + if ( ! array_key_exists( 'source', $entry_context ) || 'woopayments' !== $entry_context['source'] ) { + return $entry; + } + + $time_string = gmdate( 'c', $context['timestamp'] ); + $level_string = strtoupper( $context['level'] ); + $format_string = sprintf( '%s %s %s %%s', $time_string, $level_string, $this->request_id ); + + $entries = []; + + if ( is_array( $this->context ) && [] !== $this->context ) { + $encoded = wp_json_encode( $this->context ); + if ( false !== $encoded ) { + $entries[] = sprintf( 'CONTEXT: %s', $encoded ); + } + } + + $entries[] = $context['message']; + + return implode( + "\n", + array_map( + function ( $entry ) use ( $format_string ) { + return sprintf( $format_string, $entry ); + }, + $entries + ) + ); + } + + /** + * Adds hooks to filter and enhance log entries. + * + * @return void + */ + private function setup_hooks() { + if ( $this->hooks_set ) { + return; + } + + add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); + $this->hooks_set = true; + } +} From 62a094d6991f997d93fe4e53af60bc1dce300c6b Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Tue, 3 Dec 2024 14:17:02 +0100 Subject: [PATCH 03/21] Update type hints --- includes/class-logger-context.php | 2 +- src/Internal/LoggerContext.php | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/includes/class-logger-context.php b/includes/class-logger-context.php index 1ae0361d9eb..000b220c148 100644 --- a/includes/class-logger-context.php +++ b/includes/class-logger-context.php @@ -30,7 +30,7 @@ public static function init() { * @param string $key The key to set. * @param string|int|float|bool|null $value The value to set. Null removes value. * - * @return mixed The value. + * @return void */ public static function set_value( $key, $value ) { wcpay_get_container()->get( InternalLoggerContext::class )->set_value( $key, $value ); diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index 72721767d54..eb7e6be8724 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -50,13 +50,13 @@ public function init() { * @param string $key The key to set. * @param string|int|float|bool|null $value The value to set. Null removes value. * - * @return mixed The value. + * @return void */ public function set_value( $key, $value ) { if ( null === $value && array_key_exists( $key, $this->context ) ) { unset( $this->context[ $key ] ); } else { - $this->context[ $key ] = $value; + $this->context[ $key ] = (string) $value; } } From c7399492e9b2dd5b7ec1c1e09ac4e9aaeef59edf Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Tue, 3 Dec 2024 17:23:45 +0100 Subject: [PATCH 04/21] Example usage and simplification of checks --- includes/admin/class-wc-rest-payments-timeline-controller.php | 3 +++ src/Internal/LoggerContext.php | 2 +- 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/includes/admin/class-wc-rest-payments-timeline-controller.php b/includes/admin/class-wc-rest-payments-timeline-controller.php index c2c0f5ac87a..d50a389a9f1 100644 --- a/includes/admin/class-wc-rest-payments-timeline-controller.php +++ b/includes/admin/class-wc-rest-payments-timeline-controller.php @@ -7,6 +7,8 @@ defined( 'ABSPATH' ) || exit; +use WCPay\Logger_Context; + /** * REST controller for the timeline, which includes all events related to an intention. */ @@ -40,6 +42,7 @@ public function register_routes() { */ public function get_timeline( $request ) { $intention_id = $request->get_param( 'intention_id' ); + Logger_Context::set_value( 'intention_id', $intention_id ); return $this->forward_request( 'get_timeline', [ $intention_id ] ); } } diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index eb7e6be8724..db4e098142c 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -81,7 +81,7 @@ public function filter_log_entry( $entry, $context ): string { $entries = []; - if ( is_array( $this->context ) && [] !== $this->context ) { + if ( [] !== $this->context ) { $encoded = wp_json_encode( $this->context ); if ( false !== $encoded ) { $entries[] = sprintf( 'CONTEXT: %s', $encoded ); From f48b47095139778825ec670fc0ab79760c942fa6 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Tue, 3 Dec 2024 19:33:44 +0100 Subject: [PATCH 05/21] Log context only if it is updated, improve log line readability, add entry number --- src/Internal/LoggerContext.php | 42 ++++++++++++++++++++++++++-------- 1 file changed, 33 insertions(+), 9 deletions(-) diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index db4e098142c..cc6c79e9b0b 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -32,14 +32,29 @@ class LoggerContext { */ private $hooks_set = false; + /** + * If context has been updated. + * + * @var bool + */ + private $context_updated = false; + + /** + * Sequential number for the log entry. + * + * @var int + */ + private $entry_number = 0; + /** * Initialises the logger context. * * @return void */ public function init() { - $this->request_id = uniqid(); - $this->context = []; + $this->request_id = uniqid(); + $this->context = []; + $this->entry_number = 0; $this->setup_hooks(); } @@ -58,6 +73,7 @@ public function set_value( $key, $value ) { } else { $this->context[ $key ] = (string) $value; } + $this->context_updated = true; } /** @@ -75,26 +91,34 @@ public function filter_log_entry( $entry, $context ): string { return $entry; } + $entry_number = ++$this->entry_number; $time_string = gmdate( 'c', $context['timestamp'] ); $level_string = strtoupper( $context['level'] ); - $format_string = sprintf( '%s %s %s %%s', $time_string, $level_string, $this->request_id ); + $format_string = sprintf( '%s %s %s-%04d %%s', $time_string, $level_string, $this->request_id, $entry_number ); - $entries = []; + $entries = [ $context['message'] ]; - if ( [] !== $this->context ) { - $encoded = wp_json_encode( $this->context ); + if ( $this->context_updated ) { + $encoded = wp_json_encode( $this->context, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE ); if ( false !== $encoded ) { $entries[] = sprintf( 'CONTEXT: %s', $encoded ); } + $this->context_updated = false; } - $entries[] = $context['message']; - return implode( "\n", array_map( function ( $entry ) use ( $format_string ) { - return sprintf( $format_string, $entry ); + return implode( + "\n", + array_map( + function ( $line ) use ( $format_string ) { + return sprintf( $format_string, $line ); + }, + explode( "\n", $entry ) + ) + ); }, $entries ) From 82602b9c90957c82b3fb2f05873a028421ed5ee5 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Tue, 3 Dec 2024 19:43:45 +0100 Subject: [PATCH 06/21] Minor improvements and one more suggested application --- .../class-wc-payments-api-client.php | 20 ++++++++----------- src/Internal/LoggerContext.php | 4 +++- 2 files changed, 11 insertions(+), 13 deletions(-) diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index 13b25e07dd6..ab995e4a3fe 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -15,6 +15,7 @@ use WCPay\Fraud_Prevention\Fraud_Prevention_Service; use WCPay\Fraud_Prevention\Buyer_Fingerprinting_Service; use WCPay\Logger; +use WCPay\Logger_Context; use Automattic\WooCommerce\Admin\API\Reports\Customers\DataStore; use WCPay\Constants\Currency_Code; use WCPay\Database_Cache; @@ -2098,18 +2099,13 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u } } - $env = []; - $env['WP_User'] = is_user_logged_in() ? wp_get_current_user()->user_login : 'Guest (non logged-in user)'; - $env['HTTP_REFERER'] = sanitize_text_field( wp_unslash( $_SERVER['HTTP_REFERER'] ?? '--' ) ); - $env['HTTP_USER_AGENT'] = sanitize_text_field( wp_unslash( $_SERVER['HTTP_USER_AGENT'] ?? '--' ) ); - $env['REQUEST_URI'] = sanitize_text_field( wp_unslash( $_SERVER['REQUEST_URI'] ?? '--' ) ); - $env['DOING_AJAX'] = defined( 'DOING_AJAX' ) && DOING_AJAX; - $env['DOING_CRON'] = defined( 'DOING_CRON' ) && DOING_CRON; - $env['WP_CLI'] = defined( 'WP_CLI' ) && WP_CLI; - Logger::log( - 'ENVIRONMENT: ' - . var_export( $env, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export - ); + Logger_Context::set_value( 'WP_User', is_user_logged_in() ? wp_get_current_user()->user_login : 'Guest (non logged-in user)' ); + Logger_Context::set_value( 'HTTP_REFERER', sanitize_text_field( wp_unslash( $_SERVER['HTTP_REFERER'] ?? '--' ) ) ); + Logger_Context::set_value( 'HTTP_USER_AGENT', sanitize_text_field( wp_unslash( $_SERVER['HTTP_USER_AGENT'] ?? '--' ) ) ); + Logger_Context::set_value( 'REQUEST_URI', sanitize_text_field( wp_unslash( $_SERVER['REQUEST_URI'] ?? '--' ) ) ); + Logger_Context::set_value( 'DOING_AJAX', defined( 'DOING_AJAX' ) && DOING_AJAX ); + Logger_Context::set_value( 'DOING_CRON', defined( 'DOING_CRON' ) && DOING_CRON ); + Logger_Context::set_value( 'WP_CLI', defined( 'WP_CLI' ) && WP_CLI ); Logger::log( "REQUEST $method $redacted_url" ); Logger::log( diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index cc6c79e9b0b..86a4de9a9b6 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -7,6 +7,8 @@ namespace WCPay\Internal; +use WCPay\Internal\Logger; + /** * Logger Context class. */ @@ -87,7 +89,7 @@ public function filter_log_entry( $entry, $context ): string { $entry_context = is_array( $context ) && array_key_exists( 'context', $context ) ? $context['context'] : []; - if ( ! array_key_exists( 'source', $entry_context ) || 'woopayments' !== $entry_context['source'] ) { + if ( ! array_key_exists( 'source', $entry_context ) || Logger::LOG_FILENAME !== $entry_context['source'] ) { return $entry; } From 819ef177ad242c13a26493d6e071fd2d15e210c2 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Wed, 4 Dec 2024 11:40:51 +0100 Subject: [PATCH 07/21] Fix unit tests after moving environment data into context --- .../test-class-wc-payments-api-client.php | 18 +++--------------- 1 file changed, 3 insertions(+), 15 deletions(-) diff --git a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php index 3fc4a56c8f6..32c3caebb7e 100644 --- a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php +++ b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php @@ -791,31 +791,23 @@ public function redacting_params_data() { return [ 'delete' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'DELETE' ], - 4, + 3, [ $this->anything(), $this->callback( $string_should_not_include_secret ), ], - [ - $this->anything(), - $this->anything(), - ], ], 'get' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'GET' ], - 4, + 3, [ $this->anything(), $this->callback( $string_should_not_include_secret ), ], - [ - $this->anything(), - $this->anything(), - ], ], 'post' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'POST' ], - 5, + 4, [ $this->anything(), $this->callback( $string_should_not_include_secret ), @@ -824,10 +816,6 @@ public function redacting_params_data() { $this->anything(), $this->callback( $string_should_not_include_secret ), ], - [ - $this->anything(), - $this->anything(), - ], ], ]; } From 708e13f155789109d259c419fd8bc51c6b5f9f10 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Wed, 4 Dec 2024 19:22:55 +0100 Subject: [PATCH 08/21] Initial test suite for logger context --- tests/unit/src/Internal/LoggerContextTest.php | 100 ++++++++++++++++++ 1 file changed, 100 insertions(+) create mode 100644 tests/unit/src/Internal/LoggerContextTest.php diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php new file mode 100644 index 00000000000..af0e053fee5 --- /dev/null +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -0,0 +1,100 @@ +sut = new LoggerContext(); + } + + /** + * Test that the logger context is initialized correctly. + * + * @return void + */ + public function test_logger_context_applied() { + $this->sut->init(); + + $entry_time = '2021-01-01 00:00:00 UTC'; + $timestamp = strtotime( $entry_time ); + $message = "Test log entry...\non two lines"; + $level = WC_Log_Levels::INFO; + + $this->sut->set_value( 'foo', 'bar' ); + + $filtered_entry = apply_filters( + 'woocommerce_format_log_entry', + $message, + [ + 'timestamp' => $timestamp, + 'level' => $level, + 'message' => $message, + 'context' => [ 'source' => Logger::LOG_FILENAME ], + ] + ); + + $this->assertEquals( 5, count( explode( "\n", $filtered_entry ) ), 'Filtered entry contains 3 lines with the context and 2 with the original message' ); + + foreach ( explode( "\n", $filtered_entry ) as $line ) { + $this->assertTrue( strpos( $line, '2021-01-01T00:00:00+00:00 INFO' ) === 0, 'Each line starts with the timestamp and log level' ); + $this->assertTrue( preg_match( '/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\+\d{2}:\d{2} [A-Z]+ [a-f0-9]+-(\d{4}) /', $line, $matches ) === 1, 'Each line contains timestamp, log level, request identifier and entry number' ); + $entry_number = (int) ltrim( $matches[1], '0' ); + $this->assertTrue( $entry_number > 0, 'Entry number is a positive integer' ); + } + } + + /** + * Test that logger filters are not active for other log sources. + * + * @return void + */ + public function test_logger_context_not_applied() { + $this->sut->init(); + + $entry_time = '2021-01-01 00:00:00 UTC'; + $timestamp = strtotime( $entry_time ); + $message = "Test log entry...\non two lines"; + $level = WC_Log_Levels::INFO; + + $this->sut->set_value( 'foo', 'bar' ); + + $filtered_entry = apply_filters( + 'woocommerce_format_log_entry', + $message, + [ + 'timestamp' => $timestamp, + 'level' => $level, + 'message' => $message, + 'context' => [], + ] + ); + + $this->assertSame( $message, $filtered_entry, 'Filtered entry is the same as the original message' ); + } +} From 7f5955dd8a68e9e1e5a4a776c7eb643d4825f6c2 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Thu, 5 Dec 2024 09:26:16 +0100 Subject: [PATCH 09/21] Test both options of working with Logger Context --- tests/unit/src/Internal/LoggerContextTest.php | 30 ++++++++++++++++--- 1 file changed, 26 insertions(+), 4 deletions(-) diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php index af0e053fee5..c4324f385ef 100644 --- a/tests/unit/src/Internal/LoggerContextTest.php +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -14,6 +14,7 @@ use WCPay\Internal\LoggerContext; use WCPay\Internal\Logger; use WC_Log_Levels; +use WCPay\Logger_Context; /** * Internal Logger Context tests. @@ -36,18 +37,17 @@ public function setUp(): void { /** * Test that the logger context is initialized correctly. * + * @dataProvider provider_logger_context_applied * @return void */ - public function test_logger_context_applied() { - $this->sut->init(); + public function test_logger_context_applied( $setup_callback ) { + $setup_callback( $this->sut ); $entry_time = '2021-01-01 00:00:00 UTC'; $timestamp = strtotime( $entry_time ); $message = "Test log entry...\non two lines"; $level = WC_Log_Levels::INFO; - $this->sut->set_value( 'foo', 'bar' ); - $filtered_entry = apply_filters( 'woocommerce_format_log_entry', $message, @@ -69,6 +69,28 @@ public function test_logger_context_applied() { } } + /** + * Data provider for test_logger_context_applied. + * + * @return array + */ + public function provider_logger_context_applied() { + return [ + [ + function ( $instance ) { + $instance->init(); + $instance->set_value( 'foo', 'bar' ); + }, + ], + [ + function ( $instance ) { + Logger_Context::init(); + Logger_Context::set_value( 'foo', 'bar' ); + }, + ], + ]; + } + /** * Test that logger filters are not active for other log sources. * From fdbcfd72fea928a7e6fa752f63807ccba59fdfa0 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Thu, 5 Dec 2024 10:50:12 +0100 Subject: [PATCH 10/21] Update tests to ensure full code paths coverage --- includes/class-logger.php | 15 ++++++++++ .../class-wc-payments-api-client.php | 17 +++-------- tests/unit/src/Internal/LoggerContextTest.php | 28 +++++++++++++++++++ tests/unit/src/Internal/LoggerTest.php | 14 ++++++++++ 4 files changed, 61 insertions(+), 13 deletions(-) diff --git a/includes/class-logger.php b/includes/class-logger.php index 663698b2afb..e880303e7ba 100644 --- a/includes/class-logger.php +++ b/includes/class-logger.php @@ -120,4 +120,19 @@ public static function info( $message ) { public static function debug( $message ) { self::log( $message, 'debug' ); } + + /** + * Formats an object for logging. + * + * @param string $label Label for the object. + * @param mixed $object Object to format. + * @return string + */ + public static function format_object( $label, $object ) { + $encoded = wp_json_encode( $object, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE ); + if ( false === $encoded ) { + return sprintf( 'Error encoding object "%s": %s', $label, json_last_error_msg() ); + } + return sprintf( '%s: %s', $label, $encoded ); + } } diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index 5bed7d00429..f3601e7b8a2 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -2107,20 +2107,14 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u Logger_Context::set_value( 'DOING_CRON', defined( 'DOING_CRON' ) && DOING_CRON ); Logger_Context::set_value( 'WP_CLI', defined( 'WP_CLI' ) && WP_CLI ); + $headers = apply_filters( 'wcpay_api_request_headers', $headers ); Logger::log( "REQUEST $method $redacted_url" ); - Logger::log( - 'HEADERS: ' - . var_export( $headers, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export - ); + Logger::log( Logger::format_object( 'HEADERS', $headers ) ); if ( null !== $body ) { - Logger::log( - 'BODY: ' - . var_export( $redacted_params, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export - ); + Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); } - $headers = apply_filters( 'wcpay_api_request_headers', $headers ); $stop_trying_at = time() + self::API_TIMEOUT_SECONDS; $retries = 0; $retries_limit = array_key_exists( 'Idempotency-Key', $headers ) ? self::API_RETRIES_LIMIT : 0; @@ -2192,10 +2186,7 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u $response_body = $response; } - Logger::log( - 'RESPONSE: ' - . var_export( WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT ), true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export - ); + Logger::log( Logger::format_object( 'RESPONSE', WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT ) ) ); return $response_body; } diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php index c4324f385ef..bbe75b31704 100644 --- a/tests/unit/src/Internal/LoggerContextTest.php +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -88,6 +88,22 @@ function ( $instance ) { Logger_Context::set_value( 'foo', 'bar' ); }, ], + [ + function ( $instance ) { + $instance->init(); + $instance->set_value( 'foo', 'bar' ); + // Set a value to be removed. + $instance->set_value( 'baz', 'qux' ); + $instance->set_value( 'baz', null ); + }, + ], + [ + function ( $instance ) { + $instance->init(); + $instance->init(); + $instance->set_value( 'foo', 'bar' ); + }, + ], ]; } @@ -118,5 +134,17 @@ public function test_logger_context_not_applied() { ); $this->assertSame( $message, $filtered_entry, 'Filtered entry is the same as the original message' ); + + $filtered_entry = apply_filters( + 'woocommerce_format_log_entry', + $message, + [ + 'timestamp' => $timestamp, + 'level' => $level, + 'message' => $message, + ] + ); + + $this->assertSame( $message, $filtered_entry, 'Filtered entry is the same as the original message' ); } } diff --git a/tests/unit/src/Internal/LoggerTest.php b/tests/unit/src/Internal/LoggerTest.php index 97765d6a8ea..2baaea5db3d 100644 --- a/tests/unit/src/Internal/LoggerTest.php +++ b/tests/unit/src/Internal/LoggerTest.php @@ -16,6 +16,8 @@ use WCPay\Internal\Logger; use PHPUnit\Framework\MockObject\MockObject; +use WCPay\Logger as LoggerWrapper; + /** * Internal Logger tests. * @@ -191,4 +193,16 @@ public function test_can_log_enabled() { update_option( 'woocommerce_woocommerce_payments_settings', [ 'enable_logging' => 'yes' ] ); $this->assertTrue( $this->sut->can_log() ); } + + /** + * Test that format_object method can handle failures. + */ + public function test_format_object_failure() { + $recursive_array = []; + $recursive_array['foo'] = &$recursive_array; + + $formatted_object = LoggerWrapper::format_object( 'TEST', $recursive_array ); + + $this->assertStringContainsString( 'Recursion detected', $formatted_object ); + } } From e4b1b1174bfd2e0d9eea01975838a797deb78798 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Thu, 5 Dec 2024 11:33:26 +0100 Subject: [PATCH 11/21] Better handling JSON encoding errors --- includes/class-logger.php | 7 ++++--- src/Internal/LoggerContext.php | 5 +---- 2 files changed, 5 insertions(+), 7 deletions(-) diff --git a/includes/class-logger.php b/includes/class-logger.php index e880303e7ba..f1e16cb84d0 100644 --- a/includes/class-logger.php +++ b/includes/class-logger.php @@ -129,9 +129,10 @@ public static function debug( $message ) { * @return string */ public static function format_object( $label, $object ) { - $encoded = wp_json_encode( $object, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE ); - if ( false === $encoded ) { - return sprintf( 'Error encoding object "%s": %s', $label, json_last_error_msg() ); + try { + $encoded = wp_json_encode( $object, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE | JSON_THROW_ON_ERROR ); + } catch ( \JsonException $e ) { + return sprintf( 'Error encoding object "%s": %s', $label, $e->getMessage() ); } return sprintf( '%s: %s', $label, $encoded ); } diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index 86a4de9a9b6..b9e90ab283a 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -101,10 +101,7 @@ public function filter_log_entry( $entry, $context ): string { $entries = [ $context['message'] ]; if ( $this->context_updated ) { - $encoded = wp_json_encode( $this->context, JSON_PRETTY_PRINT | JSON_UNESCAPED_UNICODE ); - if ( false !== $encoded ) { - $entries[] = sprintf( 'CONTEXT: %s', $encoded ); - } + $entries[] = Logger::format_object( 'CONTEXT', $this->context ); $this->context_updated = false; } From 6dd09ed6facd4f487bfa07683c9c466e8f9bbb21 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Thu, 5 Dec 2024 11:38:10 +0100 Subject: [PATCH 12/21] Fix incorrect class usage --- src/Internal/LoggerContext.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index b9e90ab283a..40aabc85805 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -8,6 +8,7 @@ namespace WCPay\Internal; use WCPay\Internal\Logger; +use WCPay\Logger as LoggerWrapper; /** * Logger Context class. @@ -101,7 +102,7 @@ public function filter_log_entry( $entry, $context ): string { $entries = [ $context['message'] ]; if ( $this->context_updated ) { - $entries[] = Logger::format_object( 'CONTEXT', $this->context ); + $entries[] = LoggerWrapper::format_object( 'CONTEXT', $this->context ); $this->context_updated = false; } From 7e203215fc83a7aaf9cbc9974d7a6510c3e1f52e Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Thu, 5 Dec 2024 11:47:05 +0100 Subject: [PATCH 13/21] Changelog entry --- changelog/dev-hack-logging-enhancements | 4 ++++ 1 file changed, 4 insertions(+) create mode 100644 changelog/dev-hack-logging-enhancements diff --git a/changelog/dev-hack-logging-enhancements b/changelog/dev-hack-logging-enhancements new file mode 100644 index 00000000000..a6cc923041c --- /dev/null +++ b/changelog/dev-hack-logging-enhancements @@ -0,0 +1,4 @@ +Significance: minor +Type: dev + +Enhance log file format to provide more information about the request flow. From d16d5c55e074c53f37e4adf984f7d2ad66bb26c8 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Fri, 6 Dec 2024 12:06:32 +0100 Subject: [PATCH 14/21] Group logging of the request arguments --- ...s-wc-rest-payments-timeline-controller.php | 1 - .../class-wc-payments-api-client.php | 35 ++++++++----------- 2 files changed, 15 insertions(+), 21 deletions(-) diff --git a/includes/admin/class-wc-rest-payments-timeline-controller.php b/includes/admin/class-wc-rest-payments-timeline-controller.php index d50a389a9f1..7207007755b 100644 --- a/includes/admin/class-wc-rest-payments-timeline-controller.php +++ b/includes/admin/class-wc-rest-payments-timeline-controller.php @@ -42,7 +42,6 @@ public function register_routes() { */ public function get_timeline( $request ) { $intention_id = $request->get_param( 'intention_id' ); - Logger_Context::set_value( 'intention_id', $intention_id ); return $this->forward_request( 'get_timeline', [ $intention_id ] ); } } diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index f3601e7b8a2..fa9f69ba3fe 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -2107,14 +2107,7 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u Logger_Context::set_value( 'DOING_CRON', defined( 'DOING_CRON' ) && DOING_CRON ); Logger_Context::set_value( 'WP_CLI', defined( 'WP_CLI' ) && WP_CLI ); - $headers = apply_filters( 'wcpay_api_request_headers', $headers ); - Logger::log( "REQUEST $method $redacted_url" ); - Logger::log( Logger::format_object( 'HEADERS', $headers ) ); - - if ( null !== $body ) { - Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); - } - + $headers = apply_filters( 'wcpay_api_request_headers', $headers ); $stop_trying_at = time() + self::API_TIMEOUT_SECONDS; $retries = 0; $retries_limit = array_key_exists( 'Idempotency-Key', $headers ) ? self::API_RETRIES_LIMIT : 0; @@ -2126,19 +2119,21 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u // The header intention is to give us insights into request latency between store and backend. $headers['X-Request-Initiated'] = microtime( true ); + $request_args = [ + 'url' => $url, + 'method' => $method, + 'headers' => $headers, + 'timeout' => self::API_TIMEOUT_SECONDS, + 'connect_timeout' => self::API_TIMEOUT_SECONDS, + ]; + + Logger::log( Logger::format_object( 'REQUEST_ARGS', $request_args ) ); + if ( null !== $body ) { + Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); + } + try { - $response = $this->http_client->remote_request( - [ - 'url' => $url, - 'method' => $method, - 'headers' => $headers, - 'timeout' => self::API_TIMEOUT_SECONDS, - 'connect_timeout' => self::API_TIMEOUT_SECONDS, - ], - $body, - $is_site_specific, - $use_user_token - ); + $response = $this->http_client->remote_request( $request_args, $body, $is_site_specific, $use_user_token ); $response = apply_filters( 'wcpay_api_request_response', $response, $method, $url, $api ); $response_code = wp_remote_retrieve_response_code( $response ); From c47ea0c1be90f1e9636d9cdb01f63e08781c6ca9 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Fri, 6 Dec 2024 14:27:17 +0100 Subject: [PATCH 15/21] Ensure data is redacted before being logged and update tests --- .../class-wc-payments-api-client.php | 2 +- .../test-class-wc-payments-api-client.php | 38 ++++++++----------- 2 files changed, 16 insertions(+), 24 deletions(-) diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index fa9f69ba3fe..a6859d7e8c1 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -2127,7 +2127,7 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u 'connect_timeout' => self::API_TIMEOUT_SECONDS, ]; - Logger::log( Logger::format_object( 'REQUEST_ARGS', $request_args ) ); + Logger::log( Logger::format_object( 'REQUEST_ARGS', array_merge( $request_args, [ 'url' => $redacted_url ] ) ) ); if ( null !== $body ) { Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); } diff --git a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php index 32c3caebb7e..db4d31da813 100644 --- a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php +++ b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php @@ -12,6 +12,7 @@ use WCPay\Exceptions\Connection_Exception; use WCPay\Fraud_Prevention\Fraud_Prevention_Service; use WCPay\Fraud_Prevention\Buyer_Fingerprinting_Service; +use PHPUnit\Framework\MockObject\MockObject; /** * WC_Payments_API_Client unit tests. @@ -28,14 +29,14 @@ class WC_Payments_API_Client_Test extends WCPAY_UnitTestCase { /** * Mock HTTP client. * - * @var WC_Payments_Http|PHPUnit_Framework_MockObject_MockObject + * @var WC_Payments_Http&MockObject */ private $mock_http_client; /** * Mock DB wrapper. * - * @var WC_Payments_DB|PHPUnit_Framework_MockObject_MockObject + * @var WC_Payments_DB&MockObject */ private $mock_db_wrapper; @@ -736,7 +737,7 @@ public function test_cancel_subscription() { * @dataProvider redacting_params_data * @throws Exception - In the event of test failure. */ - public function test_redacting_params( $request_arguments, $logger_num_calls, ...$logger_expected_arguments ) { + public function test_redacting_params( $request_arguments, $logger_num_calls ) { $mock_logger = $this->getMockBuilder( 'WC_Logger' ) ->setMethods( [ 'log' ] ) ->getMock(); @@ -748,7 +749,14 @@ public function test_redacting_params( $request_arguments, $logger_num_calls, .. $mock_logger ->expects( $this->exactly( $logger_num_calls ) ) ->method( 'log' ) - ->withConsecutive( ...$logger_expected_arguments ); + ->with( + $this->anything(), + $this->callback( + function ( $message ) { + return false === strpos( $message, 'some-secret' ); + } + ) + ); $this->mock_http_client ->expects( $this->once() ) @@ -791,31 +799,15 @@ public function redacting_params_data() { return [ 'delete' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'DELETE' ], - 3, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], + 2, ], 'get' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'GET' ], - 3, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], + 2, ], 'post' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'POST' ], - 4, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], + 3, ], ]; } From 13933bbb83c45307cb2719254083951ae916db39 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Fri, 6 Dec 2024 14:33:47 +0100 Subject: [PATCH 16/21] Add indicator that object data is JSON-encoded and remove redundant method --- includes/class-logger-context.php | 9 --------- includes/class-logger.php | 2 +- tests/unit/src/Internal/LoggerContextTest.php | 2 +- 3 files changed, 2 insertions(+), 11 deletions(-) diff --git a/includes/class-logger-context.php b/includes/class-logger-context.php index 000b220c148..584d44e7045 100644 --- a/includes/class-logger-context.php +++ b/includes/class-logger-context.php @@ -15,15 +15,6 @@ * A wrapper class for accessing LoggerContext as a singletone. */ class Logger_Context { - /** - * Initialises the logger context. - * - * @return void - */ - public static function init() { - wcpay_get_container()->get( InternalLoggerContext::class )->init(); - } - /** * Sets a context value. * diff --git a/includes/class-logger.php b/includes/class-logger.php index f1e16cb84d0..6e03f8ac4ca 100644 --- a/includes/class-logger.php +++ b/includes/class-logger.php @@ -134,6 +134,6 @@ public static function format_object( $label, $object ) { } catch ( \JsonException $e ) { return sprintf( 'Error encoding object "%s": %s', $label, $e->getMessage() ); } - return sprintf( '%s: %s', $label, $encoded ); + return sprintf( '%s (JSON): %s', $label, $encoded ); } } diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php index bbe75b31704..0a2327b594d 100644 --- a/tests/unit/src/Internal/LoggerContextTest.php +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -84,7 +84,7 @@ function ( $instance ) { ], [ function ( $instance ) { - Logger_Context::init(); + wcpay_get_container()->get( LoggerContext::class )->init(); Logger_Context::set_value( 'foo', 'bar' ); }, ], From aeefacbd393b78b5ec967cfa6b809eebf3a30bd5 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Fri, 10 Jan 2025 13:40:15 +0100 Subject: [PATCH 17/21] Clean-up and minor improvements in log structure --- ...s-wc-rest-payments-timeline-controller.php | 2 -- .../class-wc-payments-api-client.php | 23 +++++++++++++++---- .../test-class-wc-payments-api-client.php | 2 +- 3 files changed, 19 insertions(+), 8 deletions(-) diff --git a/includes/admin/class-wc-rest-payments-timeline-controller.php b/includes/admin/class-wc-rest-payments-timeline-controller.php index 7207007755b..c2c0f5ac87a 100644 --- a/includes/admin/class-wc-rest-payments-timeline-controller.php +++ b/includes/admin/class-wc-rest-payments-timeline-controller.php @@ -7,8 +7,6 @@ defined( 'ABSPATH' ) || exit; -use WCPay\Logger_Context; - /** * REST controller for the timeline, which includes all events related to an intention. */ diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index 6cc1dec041d..2fab01eb092 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -2188,10 +2188,18 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u 'connect_timeout' => self::API_TIMEOUT_SECONDS, ]; - Logger::log( Logger::format_object( 'REQUEST_ARGS', array_merge( $request_args, [ 'url' => $redacted_url ] ) ) ); - if ( null !== $body ) { - Logger::log( Logger::format_object( 'BODY', $redacted_params ) ); - } + $request_id = uniqid(); + + Logger::log( + Logger::format_object( + 'REQUEST_' . $request_id, + array_merge( + $request_args, + [ 'url' => $redacted_url ], + null !== $body ? [ 'body' => $redacted_params ] : [] + ) + ) + ); try { $response = $this->http_client->remote_request( $request_args, $body, $is_site_specific, $use_user_token ); @@ -2242,7 +2250,12 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u $response_body = $response; } - Logger::log( Logger::format_object( 'RESPONSE', WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT ) ) ); + Logger::log( + Logger::format_object( + 'RESPONSE_' . $request_id, + WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT ) + ) + ); return $response_body; } diff --git a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php index a2265844403..2fbd9c027d6 100644 --- a/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php +++ b/tests/unit/wc-payment-api/test-class-wc-payments-api-client.php @@ -809,7 +809,7 @@ public function redacting_params_data() { ], 'post' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'POST' ], - 3, + 2, ], ]; } From 2848fa1ab248cad4dfb4c23f3bb4cb4c4be38a13 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Fri, 10 Jan 2025 15:16:17 +0100 Subject: [PATCH 18/21] Minor clean-ups --- includes/wc-payment-api/class-wc-payments-api-client.php | 6 +++--- tests/unit/src/Internal/LoggerTest.php | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index 2fab01eb092..973adc45da1 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -2188,11 +2188,11 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u 'connect_timeout' => self::API_TIMEOUT_SECONDS, ]; - $request_id = uniqid(); + $log_request_id = uniqid(); Logger::log( Logger::format_object( - 'REQUEST_' . $request_id, + 'REQUEST_' . $log_request_id, array_merge( $request_args, [ 'url' => $redacted_url ], @@ -2252,7 +2252,7 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u Logger::log( Logger::format_object( - 'RESPONSE_' . $request_id, + 'RESPONSE_' . $log_request_id, WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT ) ) ); diff --git a/tests/unit/src/Internal/LoggerTest.php b/tests/unit/src/Internal/LoggerTest.php index 2baaea5db3d..5bf27d15ffd 100644 --- a/tests/unit/src/Internal/LoggerTest.php +++ b/tests/unit/src/Internal/LoggerTest.php @@ -38,7 +38,7 @@ class LoggerTest extends WCPAY_UnitTestCase { private $mock_wc_logger; /** - * Holds the underlying WC_Logger + * Holds the Mode class * * @var Mode|MockObject */ From 23ca72ed444355318f7be97d3d00059e231d00c7 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Mon, 13 Jan 2025 16:01:52 +0100 Subject: [PATCH 19/21] Move logger context initialization to a proper place --- .../class-wc-payments-api-client.php | 9 ------ src/Internal/LoggerContext.php | 28 ++++++++++++++++++- tests/unit/src/Internal/LoggerContextTest.php | 2 +- 3 files changed, 28 insertions(+), 11 deletions(-) diff --git a/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index 973adc45da1..9854bb4137c 100644 --- a/includes/wc-payment-api/class-wc-payments-api-client.php +++ b/includes/wc-payment-api/class-wc-payments-api-client.php @@ -16,7 +16,6 @@ use WCPay\Fraud_Prevention\Fraud_Prevention_Service; use WCPay\Fraud_Prevention\Buyer_Fingerprinting_Service; use WCPay\Logger; -use WCPay\Logger_Context; use Automattic\WooCommerce\Admin\API\Reports\Customers\DataStore; use WCPay\Constants\Currency_Code; use WCPay\Database_Cache; @@ -2160,14 +2159,6 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u } } - Logger_Context::set_value( 'WP_User', is_user_logged_in() ? wp_get_current_user()->user_login : 'Guest (non logged-in user)' ); - Logger_Context::set_value( 'HTTP_REFERER', sanitize_text_field( wp_unslash( $_SERVER['HTTP_REFERER'] ?? '--' ) ) ); - Logger_Context::set_value( 'HTTP_USER_AGENT', sanitize_text_field( wp_unslash( $_SERVER['HTTP_USER_AGENT'] ?? '--' ) ) ); - Logger_Context::set_value( 'REQUEST_URI', sanitize_text_field( wp_unslash( $_SERVER['REQUEST_URI'] ?? '--' ) ) ); - Logger_Context::set_value( 'DOING_AJAX', defined( 'DOING_AJAX' ) && DOING_AJAX ); - Logger_Context::set_value( 'DOING_CRON', defined( 'DOING_CRON' ) && DOING_CRON ); - Logger_Context::set_value( 'WP_CLI', defined( 'WP_CLI' ) && WP_CLI ); - $headers = apply_filters( 'wcpay_api_request_headers', $headers ); $stop_trying_at = time() + self::API_TIMEOUT_SECONDS; $retries = 0; diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index 40aabc85805..f47176ff657 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -35,6 +35,13 @@ class LoggerContext { */ private $hooks_set = false; + /** + * If context has been initialized. + * + * @var bool + */ + private $context_initialized = false; + /** * If context has been updated. * @@ -56,7 +63,6 @@ class LoggerContext { */ public function init() { $this->request_id = uniqid(); - $this->context = []; $this->entry_number = 0; $this->setup_hooks(); @@ -101,6 +107,9 @@ public function filter_log_entry( $entry, $context ): string { $entries = [ $context['message'] ]; + if ( ! $this->context_initialized ) { + $this->init_context(); + } if ( $this->context_updated ) { $entries[] = LoggerWrapper::format_object( 'CONTEXT', $this->context ); $this->context_updated = false; @@ -138,4 +147,21 @@ private function setup_hooks() { add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); $this->hooks_set = true; } + + /** + * Initialises the context. + * + * @return void + */ + private function init_context() { + $this->set_value( 'WP_User', is_user_logged_in() ? wp_get_current_user()->user_login : 'Guest (non logged-in user)' ); + $this->set_value( 'HTTP_REFERER', sanitize_text_field( wp_unslash( $_SERVER['HTTP_REFERER'] ?? '--' ) ) ); + $this->set_value( 'HTTP_USER_AGENT', sanitize_text_field( wp_unslash( $_SERVER['HTTP_USER_AGENT'] ?? '--' ) ) ); + $this->set_value( 'REQUEST_URI', sanitize_text_field( wp_unslash( $_SERVER['REQUEST_URI'] ?? '--' ) ) ); + $this->set_value( 'DOING_AJAX', defined( 'DOING_AJAX' ) && DOING_AJAX ); + $this->set_value( 'DOING_CRON', defined( 'DOING_CRON' ) && DOING_CRON ); + $this->set_value( 'WP_CLI', defined( 'WP_CLI' ) && WP_CLI ); + + $this->context_initialized = true; + } } diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php index 0a2327b594d..7b682860f67 100644 --- a/tests/unit/src/Internal/LoggerContextTest.php +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -59,7 +59,7 @@ public function test_logger_context_applied( $setup_callback ) { ] ); - $this->assertEquals( 5, count( explode( "\n", $filtered_entry ) ), 'Filtered entry contains 3 lines with the context and 2 with the original message' ); + $this->assertEquals( 12, count( explode( "\n", $filtered_entry ) ), 'Filtered entry contains 3 lines with the context and 2 with the original message' ); foreach ( explode( "\n", $filtered_entry ) as $line ) { $this->assertTrue( strpos( $line, '2021-01-01T00:00:00+00:00 INFO' ) === 0, 'Each line starts with the timestamp and log level' ); From 2053c1bdc5e9fc23443bcaeae9a601df86fc5d18 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Mon, 13 Jan 2025 16:23:32 +0100 Subject: [PATCH 20/21] Split initialization steps for clarity --- includes/class-wc-payments.php | 2 +- src/Internal/LoggerContext.php | 35 +++++++++++++++------------------- 2 files changed, 16 insertions(+), 21 deletions(-) diff --git a/includes/class-wc-payments.php b/includes/class-wc-payments.php index e9518324132..afae955e5e5 100644 --- a/includes/class-wc-payments.php +++ b/includes/class-wc-payments.php @@ -511,7 +511,7 @@ public static function init() { include_once __DIR__ . '/compat/multi-currency/class-wc-payments-currency-manager.php'; include_once __DIR__ . '/class-duplicates-detection-service.php'; - wcpay_get_container()->get( \WCPay\Internal\LoggerContext::class )->init(); + wcpay_get_container()->get( \WCPay\Internal\LoggerContext::class )->init_hooks(); self::$woopay_checkout_service = new Checkout_Service(); self::$woopay_checkout_service->init(); diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php index f47176ff657..1f07033947e 100644 --- a/src/Internal/LoggerContext.php +++ b/src/Internal/LoggerContext.php @@ -57,17 +57,26 @@ class LoggerContext { private $entry_number = 0; /** - * Initialises the logger context. - * - * @return void + * LoggerContext constructor. */ - public function init() { + public function __construct() { $this->request_id = uniqid(); $this->entry_number = 0; - - $this->setup_hooks(); } + /** + * Adds hooks to filter and enhance log entries. + * + * @return void + */ + public function init_hooks() { + if ( $this->hooks_set ) { + return; + } + + add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); + $this->hooks_set = true; + } /** * Sets a context value. * @@ -134,20 +143,6 @@ function ( $line ) use ( $format_string ) { ); } - /** - * Adds hooks to filter and enhance log entries. - * - * @return void - */ - private function setup_hooks() { - if ( $this->hooks_set ) { - return; - } - - add_filter( 'woocommerce_format_log_entry', [ $this, 'filter_log_entry' ], 10, 2 ); - $this->hooks_set = true; - } - /** * Initialises the context. * From ed0b58cda9797dc9d99cb82c4de0db26c722c2d8 Mon Sep 17 00:00:00 2001 From: Valery Sukhomlinov <683297+dmvrtx@users.noreply.github.com> Date: Mon, 13 Jan 2025 16:34:16 +0100 Subject: [PATCH 21/21] Properly update tests --- tests/unit/src/Internal/LoggerContextTest.php | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php index 7b682860f67..edd127ba676 100644 --- a/tests/unit/src/Internal/LoggerContextTest.php +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -78,19 +78,19 @@ public function provider_logger_context_applied() { return [ [ function ( $instance ) { - $instance->init(); + $instance->init_hooks(); $instance->set_value( 'foo', 'bar' ); }, ], [ function ( $instance ) { - wcpay_get_container()->get( LoggerContext::class )->init(); + wcpay_get_container()->get( LoggerContext::class )->init_hooks(); Logger_Context::set_value( 'foo', 'bar' ); }, ], [ function ( $instance ) { - $instance->init(); + $instance->init_hooks(); $instance->set_value( 'foo', 'bar' ); // Set a value to be removed. $instance->set_value( 'baz', 'qux' ); @@ -99,8 +99,8 @@ function ( $instance ) { ], [ function ( $instance ) { - $instance->init(); - $instance->init(); + $instance->init_hooks(); + $instance->init_hooks(); $instance->set_value( 'foo', 'bar' ); }, ], @@ -113,7 +113,7 @@ function ( $instance ) { * @return void */ public function test_logger_context_not_applied() { - $this->sut->init(); + $this->sut->init_hooks(); $entry_time = '2021-01-01 00:00:00 UTC'; $timestamp = strtotime( $entry_time );