Toward a Standard eXtensible Logfile Format
Jennifer Palonus
Graphical Dynamics, Inc.
Seattle
jpalonus @ graphicaldynamics.com
23apr2007
Ad-hoc log files are everywhere! Logfiles are usually created as an afterthought - especially in smaller shops or in-house projects, but even major applications create log files that look like they could have benefitted from a bit more foresight. Debugging logs are even more ad-hoc, yet are just as important as "official" logs, and often end up with lifespans that are every bit as long.
Programs rarely stand alone anymore - why should their histories be balkanized into incompatible formats? When more than one application has participated in a significant event on your system, ad-hoc logfile formats make it a pain to merge or analyze logs from disparate programs that have participated in some foul-up that you later need to examine.
What we need is a standard logfile format that is simple enough to get used by a majority of real-world projects & products, yet flexible enough to be useful to varied applications with idiosyncratic needs.
Logging an event should be a lightweight activity, so that the act of logging does not itself slow down the program enough to impact its operation or throughput. And writing to a debugging log should not slow down the program enough to mask (or introduce) subtle timing problems that would (or wouldn't) show up in release builds.
The fastest type of logging would be writing text to an in-memory buffer, and then flushing that data to disk later when the program is otherwise quiescent. But with this solution, any unflushed data will be lost if the program crashes. This logfile would be an unreliable record of what led up to the crash.
Because of these constraints, most logging systems simply append log events to the end of the existing logfile and then flush or close it. These constraints would seem to to rule out a fully-enclosed format such as standard XML, since the standard XML libraries cannot simply append a data item to an XML file without first reading in the whole XML file so that they can build up the complete DOM tree. However, experiments have shown that this problem can be accomodated with little loss of performance by "intelligently appending" new log events to a fully enclosed XML file. See Appendix A.
Log events should be simple to construct. This encourages wide implementation, especially for in-house apps.
Log events should be reasonably space-efficient since some logfiles can get huge.
These help explain why simple lines of comma-separated values (CSV) & tab-separated values (TSV) are such common formats for logfiles.
The philosophy behind XML is that the data being exchanged through an XML file or datastream should be rigidly validated at each step so that the next program in the sequence can seamlessly and reliably use it as its input. In a production environment, the cost can quickly grow if program B misinterprets the constant stream of data flowing in from program A. The principle is: It's better for a production system to reject data than to try to blindly continue using the invalid data and propagating it to the next step in the workflow. In this spirit, most XML libraries are rather strict in how they deal with XML data that is somehow noncompliant with the standard or with the particular application's schema.
However, a logfile is an archive of what has happened to a program. This is normally meant to be examined after the fact, usually by a human after a program crashed or otherwise misbehaved. As a rule, the data in a logfile is not meant to be used as the input of the next program in the normal production workflow. (Although some kinds of logfiles are meant to be analyzed by other programs for performance trends - for example, webserver logs).
Log files are often designed as an afterthought in in-house systems - and even in many retail products. Even when it's not strictly an afterthought, the pressure is always greatest to ignore questions of robustness or strict compliance to a specification if fixing the incompatibility will cause the overall schedule to slip. Logfiles are never thought of as "features" to be given priority.
For these reasons, any logfile analyzer program must be forgiving in what it accepts. The standard should likewise be as forgiving of shortcuts in implementation as possible.
Since logfiles tend to be seen only grudgingly as a necessity, it must be as easy as possible for a developer to add logging capability to their program. Therefore the standard libraries and APIs provided to implement the standard should be as easy to use as possible. But a minimal XLF file should also be reasonably easy to generate "by hand" from script languages or other platforms that have limited support for libraries.
We can develop a standard that's impeccably correct by academic standards, but it's a useless exercise unless real-world developers willingly use it in their everyday work.
The overhead of XML boilerplate should be minimal. This tends to imply shorter tag and attribute names, emphasis on attributes instead of a proliferation of child tags, and heavy reliance on default values.
Many apps have already defined their own sets of codes—usually numeric, though sometimes 32-bit hex strings—for identifying different events or error conditions. XLF should be able to accommodate this, with a mechanism to link codes to human-friendly descriptions.
Every app is different in terms of what kind of specialized information they need to log. In some cases the data to be logged can be large and complex. XLF should be extensible to accommodate this diversity, with the ability to write complex log event data as XML fragments.
To help us understand what a logfile format should look like, here are three archetypal scenarios for how logfiles are typically used in a system.
A log event is an individual message written to the logfile. Traditionally each log event starts with a timestamp - the date & time that the event occurred, hopefully in some standard format. (This is usually whatever human-friendly format is easiest for the program to generate given the language it was written in.) Each log event normally corresponds to a single line of text in the file.
For each instance of a program that is logging events to the logfile, we call this a separate logging session. Normally each logging session is delimited by some kind of "Program starting" and "Program ending" (start/end) entries.
In this scenario, a single program generates logfile entries at various points in its execution. Only one copy of the program is running at a time. There may be different programs in the overall system, but each program writes log events to its own logfile. The data in these logfiles may or may not be in the same format.
Logging sessions are naturally segregated from each other in the file as long as only one instance of the program is running at a time. If the program doesn't generate "start" or "end" log events, the start and end of these logging sessions may not be easy to determine.
In this scenario, multiple programs generate log entries at various points in their execution. These may be multiple copies of the same program running or different programs. All the programs write their log events to the same logfile—opening the file in read-only or exclusive mode, appending a line of text, and then closing the file.
Log events from different logging sessions are therefore interspersed with each other in the same logfile. In this case each log events should identify which logging sessions or programs they came from, else the log will be very confusing indeed.
This scenario is similar to 3.2 above, except that the programs send the log events to a common logging service which handles the access to the common logfile (or an opaque database). The only way to write to the logging service is to link to a standard library or COM interface and use their API, and often the only way to read the log is to use a specialized log reader utility. The logging service typically logs the program's name, process ID, user, etc. with each log event.
Windows' event log is an example of this service.
An "XLF Working Group" was announced in 1998, but apparently was not successful in creating and publishing a standard. However, there may be a few instances where their draft 1.0 specification has been used in the wild.
We at Graphical Dynamics developed this logfile format for use in our products, when we discovered the original work, also called "XLF". Some concepts in this draft standard were inspired by the XLF 1.0 draft, especially the concept of logging sessions. But 1.9.1 is simpler and many of the details are different.
So we're calling the new proposed XLF standard "XLF 2.0", and this initial draft proposal is XLF 1.9.1. It's anticipated that XLF may go through several revisions in an open process before we settle on a true dot-zero version.
Some of the original XLF 1.0 working drafts are still available on the web:
XLF 1.9.1 logfiles are currently being implemented by a retail product, Graphical Dynamics' AutoIntern 2.0 job scheduler. XLF was first conceived as an improvement over AutoIntern 1.0's rather simple proprietary log file format.
The simplest valid XLF file is almost as simple to generate as a traditional logfile that timestamps its log events:
XML is designed to be most happy when generated and read by machine. However, logfile entries are often coded by hand, and expected to be read in their raw format by a human. Also, not all platforms have a handy, lightweight XML library available to use to generate the file. So XLF may have some features that are not stricly well-formed or valid XML, and a strict XML parser may end up rejecting an XLF file.
However, XLF needs to be able to be read by enough popular XML parsers if it's going to be widely adopted.
It's possible to "intelligently append" a line of text onto the end of an XML file while keeping the top-level closing tags at the physical end of the file intact. (See Appendix A.) However, the standard should allow for a truly open-ended structure as well, for those platforms that are not able to implement the intelligent appending algorithm.
An event-driven parser, such as SAX or Microsoft's XmlLite, should have no problem reading an XLF file that does not have the top-level closing tags after the last valid log event entry.
To become a truly useful standard, XLF will need the support of a dedicated core of developers who can act as a working group to design new 1.9.x versions, leading up to XLF 2.0.
We'll also need to grow a community of stakeholders in XLF's success.
Although a basic XLF file is simple to generate, it's not quite as easy as generating a traditional ad-hoc CSV file.
A large part of XLF's acceptance by developers will be the availability of standard libraries or classes to implement an XLF writer that can be easily plugged in to an existing program.
The requirements of a valid XML file to be fully-enclosed with both a start and end tag at the top-level, seems to be at odds with the need to simply append new logentries/debugentries to the physical end of a log file. Here is a method for quickly determining where to insert a new entry after the last log entry and before the closing <xlf> tag.
Example:
We need to quickly determine where the existing closing tag starts, since this is where we want to write the new line, and after it the closing "</xlf>". If we assume that the closing tag is well-formed from the tagname (i.e. the closing tag for xlf is written as "</xlf>" with no newlines or other whitespace after it), and that we know the character encoding, then we do this:
Here is step 2 in Microsoft C++. TCHAR is defined as 8- or 16-bit character depending on whether the program is compiled for ASCII or Unicode. (Adapted from the XLFFile sample class):
This technique adds a minimal overhead to simply opening a file and appending the logevent lines. Using the XLFFile C++ class, as exercised by the TestXLF.exe program, we recorded these times for writing out 10,000 logevent lines to separate log files:
| Appending method | Time to write 10,000 lines |
|---|---|
| Simple | 3:25.671 |
| Intelligent | 3:26.563 |