Enhance plugin logging to provide more context information and request IDs

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.

includes/class-logger-context.php

@@ -0,0 +1,29 @@
+<?php
+/**
+ * Class LoggerContext
+ *
+ * @package WooCommerce\Payments
+ */
+
+namespace WCPay;
+
+use WCPay\Internal\LoggerContext as InternalLoggerContext;
+
+defined( 'ABSPATH' ) || exit; // block direct access.
+
+/**
+ * A wrapper class for accessing LoggerContext as a singletone.
+ */
+class Logger_Context {
+	/**
+	 * 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 static function set_value( $key, $value ) {
+		wcpay_get_container()->get( InternalLoggerContext::class )->set_value( $key, $value );
+	}
+}

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<string, string> $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 );
+	}
 }

includes/class-wc-payments.php

@@ -418,6 +418,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';
@@ -510,6 +511,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_hooks();
+
 		self::$woopay_checkout_service = new Checkout_Service();
 		self::$woopay_checkout_service->init();
 

includes/wc-payment-api/class-wc-payments-api-client.php

@@ -2159,32 +2159,6 @@ 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
-			);
-		}
-
 		$headers        = apply_filters( 'wcpay_api_request_headers', $headers );
 		$stop_trying_at = time() + self::API_TIMEOUT_SECONDS;
 		$retries        = 0;
@@ -2197,19 +2171,29 @@ 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,
+			];
+
+			$log_request_id = uniqid();
+
+			Logger::log(
+				Logger::format_object(
+					'REQUEST_' . $log_request_id,
+					array_merge(
+						$request_args,
+						[ 'url' => $redacted_url ],
+						null !== $body ? [ '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 );
@@ -2258,8 +2242,10 @@ protected function request( $params, $api, $method, $is_site_specific = true, $u
 		}
 
 		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::format_object(
+				'RESPONSE_' . $log_request_id,
+				WC_Payments_Utils::redact_array( $response_body, self::API_KEYS_TO_REDACT )
+			)
 		);
 
 		return $response_body;

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 )

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<string, string> $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 );
 	}
 
 	/**