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 2768409..9d983d9 100644 (file)
--- 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 );
        }
 
        /**