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. diff --git a/includes/admin/class-wc-rest-payments-timeline-controller.php b/includes/admin/class-wc-rest-payments-timeline-controller.php index c2c0f5ac87a..7207007755b 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. */ diff --git a/includes/class-logger-context.php b/includes/class-logger-context.php new file mode 100644 index 00000000000..584d44e7045 --- /dev/null +++ b/includes/class-logger-context.php @@ -0,0 +1,29 @@ +get( InternalLoggerContext::class )->set_value( $key, $value ); + } +} diff --git a/includes/class-logger.php b/includes/class-logger.php index 1ce8ae255ab..6e03f8ac4ca 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, $level ); + public static function log( $message, $level = 'info', $context = [] ) { + wcpay_get_container()->get( InternalLogger::class )->log( $message, $level, $context ); } /** @@ -119,4 +120,20 @@ 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 ) { + 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 (JSON): %s', $label, $encoded ); + } } diff --git a/includes/class-wc-payments.php b/includes/class-wc-payments.php index 17300478794..53fcdd06963 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/includes/wc-payment-api/class-wc-payments-api-client.php b/includes/wc-payment-api/class-wc-payments-api-client.php index b3adf5bf7eb..62d3eceb9b4 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; @@ -2158,31 +2159,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::log( "REQUEST $method $redacted_url" ); - Logger::log( - 'HEADERS: ' - . var_export( $headers, true ) // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_var_export - ); - - if ( null !== $body ) { - Logger::log( - 'BODY: ' - . var_export( $redacted_params, 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 ); $headers = apply_filters( 'wcpay_api_request_headers', $headers ); $stop_trying_at = time() + self::API_TIMEOUT_SECONDS; @@ -2196,19 +2179,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', array_merge( $request_args, [ 'url' => $redacted_url ] ) ) ); + 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 ); @@ -2256,10 +2241,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/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 a9d96fa5533..8665d6bd428 100644 --- a/src/Internal/Logger.php +++ b/src/Internal/Logger.php @@ -48,22 +48,24 @@ public function __construct( WC_Logger_Interface $wc_logger, Mode $mode ) { /** * 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. + * @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' ): void { + public function log( $message, $level = 'info', $context = [] ): void { if ( ! $this->can_log() ) { return; } - $this->wc_logger->log( $level, $message, [ 'source' => self::LOG_FILENAME ] ); + $context = array_merge( $context, [ 'source' => self::LOG_FILENAME ] ); + $this->wc_logger->log( $level, $message, $context ); } /** diff --git a/src/Internal/LoggerContext.php b/src/Internal/LoggerContext.php new file mode 100644 index 00000000000..40aabc85805 --- /dev/null +++ b/src/Internal/LoggerContext.php @@ -0,0 +1,141 @@ + + */ + private $context = []; + + /** + * Whether the hooks have been set. + * + * @var bool + */ + 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->entry_number = 0; + + $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 void + */ + public function set_value( $key, $value ) { + if ( null === $value && array_key_exists( $key, $this->context ) ) { + unset( $this->context[ $key ] ); + } else { + $this->context[ $key ] = (string) $value; + } + $this->context_updated = true; + } + + /** + * 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 ) || Logger::LOG_FILENAME !== $entry_context['source'] ) { + return $entry; + } + + $entry_number = ++$this->entry_number; + $time_string = gmdate( 'c', $context['timestamp'] ); + $level_string = strtoupper( $context['level'] ); + $format_string = sprintf( '%s %s %s-%04d %%s', $time_string, $level_string, $this->request_id, $entry_number ); + + $entries = [ $context['message'] ]; + + if ( $this->context_updated ) { + $entries[] = LoggerWrapper::format_object( 'CONTEXT', $this->context ); + $this->context_updated = false; + } + + return implode( + "\n", + array_map( + function ( $entry ) use ( $format_string ) { + return implode( + "\n", + array_map( + function ( $line ) use ( $format_string ) { + return sprintf( $format_string, $line ); + }, + explode( "\n", $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; + } +} diff --git a/tests/unit/src/Internal/LoggerContextTest.php b/tests/unit/src/Internal/LoggerContextTest.php new file mode 100644 index 00000000000..0a2327b594d --- /dev/null +++ b/tests/unit/src/Internal/LoggerContextTest.php @@ -0,0 +1,150 @@ +sut = new LoggerContext(); + } + + /** + * Test that the logger context is initialized correctly. + * + * @dataProvider provider_logger_context_applied + * @return void + */ + 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; + + $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' ); + } + } + + /** + * 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 ) { + wcpay_get_container()->get( LoggerContext::class )->init(); + 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' ); + }, + ], + ]; + } + + /** + * 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' ); + + $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 ); + } } 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..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,43 +799,15 @@ public function redacting_params_data() { return [ 'delete' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'DELETE' ], - 4, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], - [ - $this->anything(), - $this->anything(), - ], + 2, ], 'get' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'GET' ], - 4, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], - [ - $this->anything(), - $this->anything(), - ], + 2, ], 'post' => [ [ [ 'client_secret' => 'some-secret' ], 'abc', 'POST' ], - 5, - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], - [ - $this->anything(), - $this->callback( $string_should_not_include_secret ), - ], - [ - $this->anything(), - $this->anything(), - ], + 3, ], ]; }