User:BDavis (WMF)/Projects/Structured logging

This is a collection of ideas about Structured logging in MediaWiki and related software projects. For the purposes of this discussion "logging" refers to wfErrorLog() and it's related family of functions and not audit logs stored in the database by Special:Log or similar systems.

Problem edit

Logging in MediaWiki (and WMF in general?) is optimized for human consumption. This works well for local development and testing and can scale to management of a small to mid size wiki depending on the number of eyes applied to the logs and the acumen of the operational support personnel with grep, cut, sed, awk and other text processing tools.

Unfortunately what works well for a single developer doesn't work as well for analyzing the log output of a large production site.

  • need better tools for wider audience
  • aggregation
  • de-dup
  • cross system correlation
  • alerting
  • reporting

This is not a wholly new idea. Let's look at what's out there and see if we can find a solution or at least borrow the best bits.

Current logging edit

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 wfErrorLog()
wfDebugMem( $exact = false )
Uses wfDebug() to log "Memory usage: N (kilo)?bytes"
wfDebugLog( $logGroup, $text, $public = true)
Logs either to a custom log sink defined in $wgDebugLogGroups or via wfDebug()
Prepends "[$logGroup] " to message
Custom sink
May log only a fraction of occurrences via mt_rand() sampling
Prepends wfTimestamp( TS_DB ) wfWikiID() wfHostname(): to message
Delegates to wfErrorLog() to actually write to sink
wfLogDBError( $text )
Enabled/disabled with $wgDBerrorLog sink location
Logs "$date\t$host\t$wiki\$text" via wfErrorLog() to $wgDBerrorLog sink
Date format is 'D M j G:i:s T Y' with possible custom timezone specified by $wgDBerrorLogTZ
wfErrorLog( $text, $file )
Writes $text to either a local file or a UDP packet depending on the value of $file
If $file ends with a string following the host name/IP it will be used as a prefix to $text
The final message with optional prefix added will be trimmed to 65507 bytes and a trailing newline may be added
$text will be appended to file unless the resulting file size would be >= 0x7fffffff bytes (~2G)
Delegates to wfErrorLog() using $wgDebugLogFile 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 gmdate( 'YmdHis' )

Structured logging standards edit

Graylog Extended Log Format (GELF) edit


"The Graylog Extended Log Format (GELF) avoids the shortcomings of classic plain syslog:

- Limited to length of 1024 byte - Not much space for payloads like backtraces

- Unstructured. You can only build a long message string and define priority, severity etc."

Structured logs messages sent via UDP as gzip'd json with chunking support.

  • client libraries in PHP, Ruby, Java, Python, etc
  • native input for graylog, plugin for logstash
GELF spec version ("1.0")
hostname sending message
short descriptive message
long message (eg backtrace, env vars)
UNIX microsecond timestamp
numeric syslog level
event generator label
source file line
source file
sender specified field

Metlog edit


"The Metlog project is part of Project Sagrada, providing a service for applications to capture and inject arbitrary data into a back end storage suitable for out-of-band analytics and processing."

3-tier architecture: generator (eg an app), router (logstash), endpoints (back end event destinations: statsd, Sentry, HDFS, Esper, OpenTSDB, ...)

  • python and node.js client libs for formatting and emitting messages.
  • logstash plugins for input processing and output to backends
  • json serialized messages
time message generated
message generator (eg app name)
type of message payload
(application defined; correlated with payload and fields)
rfc5424 numeric code (syslog level)
message contents
arbitrary key/value pairs
message envelope version (0.8)

Common Event Expression (CEE) edit


"Common Event Expression (CEE™) improves the audit process and the ability of users to effectively interpret and analyze event log and audit data. This is accomplished by defining an extensible unified event structure, which users and developers can leverage to describe, encode, and exchange their CEE Event Records."

Other ideas edit

Proposal edit

Serialization Format edit

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 edit

Here's a list of the data points that I think we should definitely have:

Local system time that event occurred either as UNIX epoch timestamp or ISO 8601 formatted string
date( 'c' )
FQDN of system where event occurred
php_uname( 'n' )
Name of application generating events; correlates to APP-NAME of RFC 5424
Unix process id, thread id, thread name or other process identifier
Message severity (RFC 5424 levels)
Log channel. Often the function/module/class creating message (similar to wgDebugLogGroups groups)
get_class( $this )
Message body
"Help! I'm trapped in a logger factory!"

Additionally I would suggest that we add 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. In the past I have found it useful to have 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.

Source file triggering message
Source line triggering message
Numeric or string identifier for the error
Live exception object to be stringified by the log event emitter
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:

Apache vhost processing request
Requesting ip address
Authenticated user identity
Request ID; UUID or similar token that can be used to correlate all log messages connected to a given request

There are obvious privacy concerns with some of these data fields. Careful thought will need to be given to designing a system such that wikis can choose whether or not to log any of these fields.

Not collected (rejected fields) edit

User agent


Application session ID (or a proxy token that can be used to correlate events connected to the session)

API edit

FIXME: Propose a PHP API for logging and a migration plan for existing wfErrorLog() calls

See Also edit