Requests for comment/Structured logging

2018-12-24T17:05:13Z

98.222.146.27:

{{RFC
| created = 2013-12-03
| authors = [[User:BDavis (WMF)|Bryan Davis]], [[User:Ori.livneh|Ori Livneh]], [[User:Aaron Schulz|Aaron Schulz]]
| status = implemented
| extrastatus = This RfC was never formally approved, but the [[#Implementation|gerrit changes to implement PSR-3 support]] have been merged --[[User:BDavis (WMF)|BDavis (WMF)]] ([[User talk:BDavis (WMF)|talk]]) 15:44, 10 April 2015 (UTC)
}}

This is a '''request for comment''' about adding '''Structured logging''' to MediaWiki. It specifies a data model for MediaWiki log messages and an interface for generating log messages that conform to the model.

By "data model" we simply mean an agreed-upon set of fields containing metadata that describes the context in which the log message was generated. The model specifies the name of each field and the value it can hold. Log messages generated via the interface that we propose below would conform to this model, allowing them to be serialized to a machine-readable format.A standard for machine-readable metadata common to all log messages would make it possible to query, collate, and summarize operational data in ways that are currently very difficult to achieve.

We think that the ability to cross-reference logs and query by context will make troubleshooting bugs easier. We also think that ongoing analysis of aggregated log data would reveal which files, interfaces, and code paths are especially prone to bugs or poor performance, and that this information would help us make MediaWiki more reliable and performant.

=== Problems with the current interface ===
Most operational logging in MediaWiki is done via <code>wfDebugLog</code> calls. Messages logged via <code>wfDebugLog</code> specify a topic name (or a log bucket). This name usually identifies the name of the component that is emitting the log message. Some parts of the code which generate different kinds of log messages have compound topic names that describe the type of log message being logged, usually in terms of severity ("memcached-serious", for example). The ad hoc overloading of the log group property to encode severity is a good example of existing usage that is twisting the interface to overcome its limitations. This is a good indication that the current interface is inadequate.

Because there is no established standard for encoding severity, the density of logging calls in MediaWiki code varies greatly. Access to the production logs is limited, and many developers will only ever review logs generated on their development instance and consequently fail to appreciate the cost of excessively verbose logging at scale. The instrumentation of code is often pitched to its initial development rather than its ongoing maintenance.

To keep chatty code from drowning out important log data, the logging setup on the Wikimedia production cluster does not automatically transmit all logging topics to the log processor. A developer must first manually enroll the log bucket by adding it to the <code>$wgDebugLogGroups</code> configuration var. The problem with this approach is that the absence of log data from a particular component is typically noticed when it is needed the most: that is, when the component is suspected of misbehaving in ways that are difficult to reproduce or reason about. Thus log buckets are usually enabled to help solve a particular bug, and they are commonly left enabled long after the motivation for enabling them has ceased to be relevant. The overall effect is that Wikimedia's logs are curated on the basis of historic interest rather than abiding relevance.

== Current logging ==
; wfDebug( $text, $logonly = false )
: Logs developer provided free-form text + optional global prefix string
: Possibly has time-elapsed since start of request and real memory usage inserted between prefix and message
: Delegates to <code>wfErrorLog()</code>

; wfDebugMem( $exact = false )
: Uses <code>wfDebug()</code> to log "Memory usage: N (kilo)?bytes"

; wfDebugLog( $logGroup, $text, $public = true)
: Logs either to a custom log sink defined in <code>$wgDebugLogGroups</code> or via <code>wfDebug()</code>
: '''Default'''
:: Prepends "[$logGroup] " to message
: '''Custom sink'''
:: May log only a fraction of occurrences via <code>mt_rand()</code> sampling
:: Prepends <code>wfTimestamp( TS_DB ) wfWikiID() wfHostname(): </code> to message
:: Delegates to <code>wfErrorLog()</code> to actually write to sink

; wfLogDBError( $text )
: Enabled/disabled with <code>$wgDBerrorLog</code> sink location
: Logs "$date\t$host\t$wiki\$text" via <code>wfErrorLog()</code> to <code>$wgDBerrorLog</code> sink
: Date format is <code>'D M j G:i:s T Y'</code> with possible custom timezone specified by <code>$wgDBerrorLogTZ</code>

; wfErrorLog( $text, $file )
: Writes <code>$text</code> to either a local file or a UDP packet depending on the value of <code>$file</code>
: '''UDP'''
:: If <code>$file</code> ends with a string following the host name/IP it will be used as a prefix to <code>$text</code>
:: The final message with optional prefix added will be trimmed to 65507 bytes and a trailing newline may be added
: '''FILE'''
:: <code>$text</code> will be appended to file unless the resulting file size would be >= 0x7fffffff bytes (~2G)

; wfLogProfilingData()
: Delegates to <code>wfErrorLog()</code> using <code>$wgDebugLogFile</code> sink
: Creates a tab delimited log message including timestamp, elapsed request time, requesting IPs, and request URL followed by a newline and the profiler output.
: Date is from <code>gmdate( 'YmdHis' )</code>

; Recent changes logging
; Transport and serialization format may be specified via <code>$wgRCFeeds</code>
; Various implementations in <code>includes/rcfeeds/</code>, including IRC, UDP & Redis.

== Proposal ==

=== Serialization Format ===
Rather than dive down a rabbit hole of trying to find a universal spec for log file formats let's just keep things simple. PHP loves dictionaries (well they call them arrays but whatever; key=value collections) and has a pretty fast json formatter. So the simplest thing that will work reasonably well would be to keep log events internally as PHP arrays and serialize them as json objects. This will be relatively easy to recreate on other internally developed applications as well with the possible exception of apps written in low level languages such as C that don't have ready made key=value data structures.

=== Data collected ===
Here's a list of the data points that we should definitely have:
; timestamp
: Local system time that event occurred either as UNIX epoch timestamp or [[:en:ISO_8601|ISO 8601]] formatted string
: <code>date( 'c' )</code>
; host
: FQDN of system where event occurred
: <code>php_uname( 'n' )</code>
; source
: Name of application generating events; correlates to '''APP-NAME''' of [https://tools.ietf.org/html/rfc5424#section-6.2.5 RFC 5424]
: <code>'Mediawiki'</code>
; pid
: Unix process id, thread id, thread name or other process identifier
: <code>getmypid()</code>
; severity
: Message severity ([[:en:Syslog#Severity_levels|RFC 5424 levels]])
: <code>'WARN'</code>
; channel
: Log channel. Often the function/module/class creating message (similar to <code>wgDebugLogGroups</code> groups)
: <code>get_class( $this )</code>
; message
: Message body
: <code>"Help! I'm trapped in a logger factory!"</code>

Additionally we suggest adding a semi-structured "context" component to logs. This would be a collection of key=value pairs that the developers determine to be useful for debugging. There should be two different methods available to add such data. The first is as an optional argument to the logging method itself and the second is a global collection patterned after the Log4J Mapped Diagnostic Context (MDC).

The local collection is useful for obvious reasons such as attaching class/method state data to the log output and deferring stringification of resources in the event that runtime configuration is ignoring messages of the provided level.

; file
: Source file triggering message
; line
: Source line triggering message
; errcode
: Numeric or string identifier for the error
; exception
: Live exception object to be stringified by the log event emitter
; args
: key=value map of method arguments

The global collection is very useful for attaching global application state data to all log messages that may be emitted. Examples of data that could be included:
; vhost
: Apache vhost processing request
: <code>$_SERVER['HTTP_HOST']</code>
; ip
: Requesting ip address
: <code>$_SERVER['REMOTE_ADDR']</code>
; user
: Authenticated user identity
; req
: Request ID; UUID or similar token that can be used to correlate all log messages connected to a given request

=== API ===
The developer facing API is the [https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md PSR-3 logging interface standard].

<source lang="php">
<?php

namespace Psr\Log;

/**
* Describes a logger instance
*
* The message MUST be a string or object implementing __toString().
*
* The message MAY contain placeholders in the form: {foo} where foo
* will be replaced by the context data in key "foo".
*
* The context array can contain arbitrary data, the only assumption that
* can be made by implementors is that if an Exception instance is given
* to produce a stack trace, it MUST be in a key named "exception".
*
* See https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md
* for the full interface specification.
*/
interface LoggerInterface
{
/**
* System is unusable.
*
* @param string $message
* @param array $context
* @return null
*/
public function emergency($message, array $context = array());

/**
* Action must be taken immediately.
*
* Example: Entire website down, database unavailable, etc. This should
* trigger the SMS alerts and wake you up.
*
* @param string $message
* @param array $context
* @return null
*/
public function alert($message, array $context = array());

/**
* Critical conditions.
*
* Example: Application component unavailable, unexpected exception.
*
* @param string $message
* @param array $context
* @return null
*/
public function critical($message, array $context = array());

/**
* Runtime errors that do not require immediate action but should typically
* be logged and monitored.
*
* @param string $message
* @param array $context
* @return null
*/
public function error($message, array $context = array());

/**
* Exceptional occurrences that are not errors.
*
* Example: Use of deprecated APIs, poor use of an API, undesirable things
* that are not necessarily wrong.
*
* @param string $message
* @param array $context
* @return null
*/
public function warning($message, array $context = array());

/**
* Normal but significant events.
*
* @param string $message
* @param array $context
* @return null
*/
public function notice($message, array $context = array());

/**
* Interesting events.
*
* Example: User logs in, SQL logs.
*
* @param string $message
* @param array $context
* @return null
*/
public function info($message, array $context = array());

/**
* Detailed debug information.
*
* @param string $message
* @param array $context
* @return null
*/
public function debug($message, array $context = array());

/**
* Logs with an arbitrary level.
*
* @param mixed $level
* @param string $message
* @param array $context
* @return null
*/
public function log($level, $message, array $context = array());
}
</source>

'''MediaWiki\Logger\LoggerFactory''' provides static methods for registering PSR-3 providers and getting PSR-3 Logger instances from the current provider:

<source lang="php">
/**
* Get a named logger instance from the currently configured logger factory.
*
* @param string $channel Logger channel (name)
* @return Psr\Log\LoggerInterface
*/
public static function getInstance( $channel );

/**
* Register a service provider to create new \Psr\Log\LoggerInterface
* instances.
*
* @param \MediaWiki\Logger\Spi $provider Provider to register
*/
public static function registerProvider( Spi $provider );
</source>

The <code>MediaWiki\Logger\LoggerFactory::getInstance()</code> method is the means by which most code would acquire an Psr\Log\LoggerInterface instance. It will in turn delegate the creation of Psr\Log\LoggerInterface to a class implementing the <code>MediaWiki\Logger\Spi</code> interface:

<source lang="php">
namespace MediaWiki\Logger;
interface Spi {

/**
* Get a logger instance.
*
* @param string $channel Logging channel
* @return Psr\Log\LoggerInterface Logger instance
*/
public function getLogger( $channel );

}
</source>

This service provider interface will allow the backend logging library to implemented in multiple ways. The <code>$wgMWLoggerDefaultSpi</code> global provides the class name of the default <code>MediaWiki\Logger\Spi</code> implementation. This can be altered via the normal means. Alternately <code>MediaWiki\Logger\LoggerFactory::registerProvider()</code> can be invoked early in the application setup to inject an alternate SPI implementation.

=== Managing third-party libraries ===
The use of [http://www.php-fig.org/psr/psr-3 PSR-3] and [https://github.com/Seldaek/monolog monolog] introduces the need to manage third-party code dependencies for MediaWiki core. Although there are some third-party components in includes/libs, to my knowledge this is the first large scale use of external PHP code by MediaWiki core.

In a more perfect world, MediaWiki would already be a system that assembled a collection of libraries using a well defined dependency management system. This has actually been envisioned in at least two RFCs ([[../MediaWiki libraries/]] and [[../Third-party components/]]).

Several possible solutions were examined and ultimately the use of [https://getcomposer.org/ Composer] as a dependency management system was chosen. The use of [http://www.php-fig.org/psr/psr-3 PSR-3] is mandatory so this library was added to the "require" section of <code>composer.json</code> in the mediawiki/core.git repository. The use of [https://github.com/Seldaek/monolog monolog] is optional, so it was added to the "suggest" section. Since this <code>composer.json</code> file is in the root of the MediaWiki core project, it does to some extent conflict with the [[../Extension management with Composer/]] RFC. Additional work is being done to mitigate this problem for users who were already making use of <code>composer.json</code> ([[phab:T67188]]).

The [[../Composer managed libraries for use on WMF cluster/]] RFC was written and subsequently approved to deal with the process of staging and deploying Composer managed content in the WMF production environment. Installations of MediaWiki via git clones are expected to manage libraries themselves by using the <code>mediawiki/vendor.git</code> repo, using Composer directly, or creating a <code>mediawiki/vendor.git</code> work-alike for their particular deployment. Releases will be expected to include the required libraries in the official tarball.

== Implementation ==
An original proof of concept implementation was submitted as {{gerrit|112699}}. The approach of using Composer to manage external dependencies was given a '''+1''' by Tim. The monolithic patch was then split into four smaller patches for closer review and approval:

; {{gerrit|119939}} Add Composer managed libraries {{done}}
: Require Psr\Log and suggest Monolog libraries to MW-Core via <code>composer.json</code>.
; {{gerrit|119940}} Add a PSR-3 based logging interface {{done}}
: The MWLogger class is actually a thin wrapper around any PSR-3 LoggerInterface implementation. Named MWLogger instances can be obtained from the MWLogger::getInstance() static method. MWLogger expects a class implementing the MWLoggerSpi interface to act as a factory for new MWLogger instances. A concrete MWLoggerSpi implementation using the Monolog library is also provided.
; {{gerrit|119941}} Enable MWLogger logging for legacy logging methods {{done}}
: Introduces the <code>MWLoggerLegacyLogger</code> logger to mimic legacy logging behavior as a PSR-3 compliant logger component and sets it as the default <code>$wgMWLoggerDefaultSpi</code> implementation. wfDebug, wfDebugLog and wfLogDBError are changed to use <code>MWLogger</code>.
; {{gerrit|119942}} Enable MWLogger logging for wfLogProfilingData {{done}}
: Output structured profiling report data from wfLogProfilingData.
; {{gerrit|184830}} Replace MWLogger with MWLoggerFactory
: Design change to replace MWLogger with direct use of PSR-3 interfaces in MediaWiki. {{done}}
; {{gerrit|198674}} Move MWLogger classes to MediaWiki\Logger namespace
: Move the MWLogger PSR-3 logging related classes into the MediaWiki\Logger namespace. Create shim classes to ease migration of existing MWLoggerFactory usage to the namespaced classes. {{done}}

== See Also ==
; Relevant bugs
:* {{bug|14601|Use wfDebugLog instead of wfDebug by default}}
:* {{bug|49757|Better monitoring and error reporting of Errors and Exceptions}}

; Related RFCs
:* [[../Third-party components/]]
:*[[../MediaWiki libraries/]]
:*[[../Composer managed libraries for use on WMF cluster/]]

; RFC Review
:* [[Architecture_meetings/RFC_review_2013-12-04|2013-12-04]]
:* [[Architecture_meetings/RFC_review_2014-03-19|2013-03-19]]

; Logging standards
:* https://github.com/php-fig/fig-standards/blob/master/accepted/PSR-3-logger-interface.md
:* http://www.graylog2.org/about/gelf
:* https://wiki.mozilla.org/Services/Sagrada/Metlog
:* http://cee.mitre.org/

; Additional commentary on logging
:* [[User:BDavis_(WMF)/Projects/Structured_logging]]
:* http://gregoryszorc.com/blog/2012/12/06/thoughts-on-logging---part-1---structured-logging/
:* https://journal.paul.querna.org/articles/2011/12/26/log-for-machines-in-json/
:* http://carolina.mff.cuni.cz/~trmac/blog/2011/structured-logging/
:* http://dev.splunk.com/view/logging-best-practices/SP-CAAADP6
:* https://delicious.com/bd808/logging

MediaWiki - User contributions [en]

Requests for comment/Structured logging