From: Erik Bernhardson <ebernhardson@wikimedia.org>
Date: Wed, 23 Sep 2015 23:37:06 +0000 (-0700)
Subject: Add structured API request debug logging
X-Git-Tag: 1.31.0-rc.0~8970
X-Git-Url: https://git.cyclocoop.org/%27%20.%20%24this-%3EgetSkin%28%29-%3EescapeSearchLink%28%29%20.%20%27?a=commitdiff_plain;h=0d7385a87ced5cbf5f9e1c2909d66e29f873cd19;p=lhc%2Fweb%2Fwiklou.git

Add structured API request debug logging

Add a new "ApiRequest" PSR-3 logging channel for messages that describe
an Action API request as structured data. This logging channel can be
routed to a storage service to facilitate analysis of the requests.

The logging context is designed to match the following avro schema:

  {
      "type": "record",
      "name": "ApiRequest",
      "namespace": "org.wikimedia.mediawiki.api",
      "doc": "Describes an API request made via mediawiki ApiMain",
      "fields": [
          { "name": "dt",              "type": "string" },
          { "name": "client_ip",       "type": "string" },
          { "name": "user_agent",      "type": "string" },
          { "name": "wiki",            "type": "string" },
          { "name": "time_backend_ms", "type": "int" },
          { "name": "params",          "type": {
              "type": "map", "values": "string"
          } }
      ]
  }

Co-Author: Bryan Davis <bd808@wikimedia.org>
Bug: T108618
Change-Id: I38f5cdb288f332f75adca8a2d03fbe0fc36ab936
---

diff --git a/includes/api/ApiMain.php b/includes/api/ApiMain.php
index 27684096e8..9d983d9a4f 100644
--- a/includes/api/ApiMain.php
+++ b/includes/api/ApiMain.php
@@ -1289,31 +1289,45 @@ class ApiMain extends ApiBase {
 
 	/**
 	 * Log the preceding request
-	 * @param int $time Time in seconds
+	 * @param float $time Time in seconds
 	 */
 	protected function logRequest( $time ) {
 		$request = $this->getRequest();
-		$milliseconds = $time === null ? '?' : round( $time * 1000 );
-		$s = 'API' .
-			' ' . $request->getMethod() .
-			' ' . wfUrlencode( str_replace( ' ', '_', $this->getUser()->getName() ) ) .
-			' ' . $request->getIP() .
-			' T=' . $milliseconds . 'ms';
+		$logCtx = array(
+			'dt' => date( 'c' ),
+			'client_ip' => $request->getIP(),
+			'user_agent' => $this->getUserAgent(),
+			'wiki' => wfWikiId(),
+			'time_backend_ms' => round( $time * 1000 ),
+			'params' => array(),
+		);
+
+		// Construct space separated message for 'api' log channel
+		$msg = "API {$request->getMethod()} " .
+			wfUrlencode( str_replace( ' ', '_', $this->getUser()->getName() ) ) .
+			" {$logCtx['client_ip']} " .
+			"T={$logCtx['time_backend_ms']}ms";
+
 		foreach ( $this->getParamsUsed() as $name ) {
 			$value = $request->getVal( $name );
 			if ( $value === null ) {
 				continue;
 			}
-			$s .= ' ' . $name . '=';
+
 			if ( strlen( $value ) > 256 ) {
-				$encValue = $this->encodeRequestLogValue( substr( $value, 0, 256 ) );
-				$s .= $encValue . '[...]';
+				$value = substr( $value, 0, 256 );
+				$encValue = $this->encodeRequestLogValue( $value ) . '[...]';
 			} else {
-				$s .= $this->encodeRequestLogValue( $value );
+				$encValue = $this->encodeRequestLogValue( $value );
 			}
+
+			$logCtx['params'][$name] = $value;
+			$msg .= " {$name}={$encValue}";
 		}
-		$s .= "\n";
-		wfDebugLog( 'api', $s, 'private' );
+
+		wfDebugLog( 'api', $msg, 'private' );
+		// ApiRequest channel is for structured data consumers
+		wfDebugLog( 'ApiRequest', '', 'private', $logCtx );
 	}
 
 	/**