Robust event logging with Syslog

Syslog is a fast, flexible, and easily extendable logging system

1 2 3 Page 2
Page 2 of 3

The Syslog class itself is a singleton -- that is, there is only one instance of it per VM. It contains all configuration information related to where messages route, who listens for those messages, and so forth. Because of its nature, the Syslog jar file should be included in the system CLASSPATH so that only one instance of it exists (app servers commonly use many classloaders), and the class garbage collection should be turned off in the VM (using the -Xnoclassgc argument). Clever configurations can take advantage of the structure of class loaders in application servers to complete more complicated tasks, but that subject reaches outside this article's scope. If you cannot turn off class garbage collection, then you should retrieve Syslog's internal instance using the Syslog.getInstance() method and store it somewhere to prevent the class from unloading.

The following abbreviated diagram illustrates how Syslog looks from the inside. I have omitted many of the provided logger, policy, and text format implementations for clarity.

Abbreviated Syslog architecture diagram

Syslog maintains a list of objects that implement the Syslogger interface, which is mainly the log(SyslogMessage message) method. Once the log() method is called on the Syslogger, Syslogger should quickly decide if it should react to the sent message. If the message is relevant, then the logger writes the message to a file or does whatever it wants with it.

Default implementations

The default implementation of the Syslogger interface is the BasicLogger abstract class. It is the superclass for all the loggers that are included with Syslog and should be used as the superclass for any custom loggers.

BasicLogger delegates the decision about paying attention to a given message to an implementation of the LogPolicy interface. LogPolicy's default implementation is the SimpleLogPolicy class, which knows about log message severity levels and log channels. You can configure a LogPolicy to concentrate only on messages at a certain level, set of levels, or the default mask set overall in Syslog, and to focus only on messages arriving on a certain channel or set of channels.

The BasicLogger also delegates its message-formatting duties to an implementation of the SyslogTextFormatter interface. The default implementation of that interface is the SimpleSyslogTextFormatter class, which can be configured to format log messages in various ways. Refer to the class's Javadoc for specific configuration information.

During initialization -- in the configure() method, part of the Syslogger interface -- BasicLogger passes part of its configuration on the specified log policy and text-formatting modules along to the configure() method. You can plug in custom LogPolicy and SyslogTextFormatter implementations with any logger that extends BasicLogger. Refer to each class's Javadoc for more information about extending or replacing a policy or text formatter.

Performance

The main task that applications perform is usually not logging. Therefore, logging should not take up a significant amount of the system's resources nor interfere with its operation. The default implementations of loggers, log policies, and text formatters included with Syslog have all been written with performance in mind. Individual Syslogger implementations perform three operations when writing a message to a log file:

Policy check

Syslog asks the policy if it should log a given message or not. This operation occurs most often. Assuming the use of the SimpleLogPolicy policy, the policy check consists of integer bitmask operations and, if channel sets are involved, a HashMap lookup. A policy check runs extremely fast in modern VMs -- on the order of millions of calls per second -- and inflicts almost no overhead even with extremely high message volumes. If that performance level isn't satisfactory, set the policy to accept the ALL_CHANNEL channel, and no HashMap lookup will occur. It is also common to use a static final boolean constant around debugging calls so that those calls can turn off completely at compile time, like this:

  public interface DebugFlag
  {
    public static final boolean DEBUG = true; // or false
  }
  ...
  if (DebugFlag.DEBUG)
    Syslog.debug(this, "Here is a debug message.");
Format call
The format call converts a log message to text. The default log formatter has been specifically optimized for speed. It uses StringBuffer objects and generally copies character arrays into those buffers for formatting, caching date format instances, and so forth.
Message write
The logger actually writes the formatted message to a file, sends email, and so forth. Actually writing the message to its final destination can be expensive. The file-based loggers all use buffered streams and have been extensively tested for speed. In addition, they are all necessarily thread-safe, so in the case of multithreaded applications, there can exist some unavoidable contention. Other loggers depend on other systems for their performance -- RemoteLog relies on the RMI implementation, and JMSLog depends on the JMS implementation -- so if the API providers are slow, the logger will be slow. The MailLog logger uses a background thread to connect to SMTP servers because this operation is generally quite slow.

Syslog includes a performance testing harness for determining the logger speed on a given system. It can test each of the above operations independently and as a whole in single-threaded and multithreaded environments. That proves extremely useful when developing custom loggers, policies, and formatters. Running a multithreaded test on a 700-MHz PIII, JDK 1.3 on Windows NT 4 yields the following performance numbers:

OperationAverage TimeCalls Per Second
Policy check (no channel check)Very small23.7 million
Policy check (with channel check)0.5 µs1.9 million
Message format3.8 µs265,000
Aggregate Syslog.log() call, including file write57.5 µs17,400
Syslog performance statistics

Running a single-threaded aggregate log() call test produced an average time of 34.6 µs for a rate of roughly 29,000 calls per second. Writing larger messages will obviously take more time. A message like the one tested above with a larger 200-byte body takes roughly 72 µs for a total rate of around 14,000 calls per second. Thread contention will always remain an issue with multithreaded applications, and Syslog is no exception. The only operation subject to thread contention is the log write; no other operation involves locking.

Syslog for operations

The operations staff also interacts with Syslog. These unsung heroes of production systems are the first people to learn about and handle any problems. Syslog allows the operations staff to completely customize the way they manage messages without changing any source code.

Included loggers

Syslog includes a handful of logger implementations that cover most of the bases as far as log functionality is concerned:

PrintWriterLog
Attached to an instance of java.io.PrintWriter, System.out, or System.err, it mostly writes messages to a console, although it can write to any PrintWriter.
TimeRolloverLog
Perhaps the most widely used logger, it writes to a file that rotates on the minute, hour, day, or month.
LengthRolloverLog
Writes to a file that rotates before it reaches a certain length.
FileLog
Simply writes to a file.
OpenFileLog
Identical to the FileLog in that it writes to a file, except the file opens before and closes after it writes each message. OpenFileLog is a relatively slow logger; you should only use it if there's a good reason to justify it -- such as a third-party log rotating system.
DatabaseLog
Writes messages to a table in a database. It's useful when multiple machines are involved on a project and you need a unified view from all machines.
MailLog
Connects directly to an SMTP server to send email. It can either send plain text messages -- good for pagers -- or HTML-formatted messages. Since sending email is a relatively slow operation, this logger uses a background thread to complete the bulk of its work.
JMSLog
Publishes messages to a JMS topic and obeys any transaction context present. You can use JMSLog to send transactional-bounded messages to a remote log server.
RemoteLog
Sends messages to objects bound under the com.protomatter.syslog.remote location in JNDI that implement the RemoteLogReceiver interface. You can use it as a nontransactional transport for messages to remote log servers. RemoteLog includes a default implementation of the RemoteLogReceiver interface and a log server harness.

Each of the above loggers extends BasicLogger and supports pluggable log policies and text-formatting modules. For more information on how to configure these loggers, refer to the Javadoc for each.

Syslog and BEA WebLogic Server

Application servers have become one of the most popular and valuable tools for quickly building Web-based applications. Most, if not all, provide very little in the way of useful logging systems. For several years I have worked with BEA WebLogic Server, which can be configured to initialize Syslog when the server boots. Syslog will work with any Java software and is not tied to WebLogic in any way. Since source code is provided for Syslog, the following example can be easily adapted to work with other application server software.

The Syslog distribution provides a startup class for BEA WebLogic Server, which allows Syslog to initialize when WebLogic boots. To configure WebLogic (4.x or 5.x) to initialize Syslog when it starts, add the following line to the weblogic.properties file:

  weblogic.system.startupClass.Syslog=    com.protomatter.syslog.SyslogT3Startup
  java.system.property.Syslog.config.xml=PathToConfigurationFile

The SyslogT3Startup class reads the configuration file based on the Syslog.config.xml system property. Set the property by specifying it in the weblogic.properties file -- as shown above -- or by adding -DSyslog.config.xml=PathToConfigurationFile as a command line argument to the JVM in the startup script.

The SyslogT3Startup class implements the weblogic.common.T3StartupDef interface required for startup classes in WebLogic Server. It also implements the weblogic.common.T3ShutdownDef interface and will wait for all loggers to gracefully close their logs when WebLogic shuts down. To configure that behavior, add the following line to the weblogic.properties file:

  weblogic.system.shutdownClass.Syslog=    com.protomatter.syslog.SyslogT3Startup

The Startup & Shutdown link can be accessed through the WebLogic Console in order to configure WebLogic Server 6 to start Syslog when it boots.

If a startup class needs to ensure that Syslog has been configured before it starts, include the following code in the startup() method of the T3StartupDef implementation:

  SyslogT3Startup syslogStartup = new SyslogT3Startup();
  syslogStartup.startup(services);

Syslog and J2EE application servers

Java 2 Platform, Enterprise Edition (J2EE) is an increasingly popular platform for developing enterprise class applications, and Syslog has been developed to integrate with that platform. The J2EE platform provides services not found in regular Java applications; Syslog adaptations that capitalize on J2EE services take the form of custom logger implementations. Although the use of a J2EE-compliant application server brings out extra functionality in Syslog, J2EE is not required.

Using the JMSLog or RemoteLog loggers and the com.protomatter.syslog.SyslogServer command line application, you can route messages to a remote log server for processing. If you use the JMSLog logger, the logging of those messages will obey transactions operating inside the application server.

This is a complicated matter. With that complexity, however, comes a great deal of flexibility. Consider this: A cluster of application servers wants to relay transactionally correct usage information to a remote log server, which will separate messages into different log files and roll them over every hour. However, each machine in the cluster also wants to log all errors locally and send emails to administrators when certain conditions occur. Syslog can do this ... here's how:

Application server(s)

Syslog is configured to start when the application server boots. Its configuration includes the following loggers:

TimeRolloverLog
Configured to write all messages at or above the WARNING severity to a file on the local filesystem and roll it on the hour.
PrintWriterLog
Configured to write all messages at or above the WARNING severity out to the console.
JMSLog
Configured to forward all messages at or above the INFO severity to a JMS topic for further processing on another machine.
MailLog
Configured to send email to an email alias for the on-call operations pager when a message at or above the ERROR severity is logged.
Log server

Runs the com.protomatter.syslog.SyslogServer standalone log server and connects to the JMS topic hosted by the application server cluster. Syslog's local configuration includes the following loggers:

TimeRolloverLog#1
Several instances of this logger listen to a different log channel -- one for each hosted application -- and write all messages at or above the WARNING severity out to a file on the local filesystem.
TimeRolloverLog#2
Several instances of this logger listen to a different log channel -- one for each hosted application -- and write all messages at the INFO severity out to system usage logs on the local filesystem. This TimeRolloverLog could also be a custom logger implementation that collates statistics into reports.
PrintWriterLog#1
Configured to write all messages at or above the WARNING severity out to the console.
PrintWriterLog#2
Configured to write all messages at the INFO severity out to the console, along with the channel and hostname from which each message comes. That produces a unified view of all system activity in the cluster.

Also note that Syslog uses a JMS topic, rather than a queue. Because of that, you could configure multiple log servers to handle different sets of messages or the same messages. Split up the messages either by specifying log policies on each server that select the messages or by using a JMS message selector (or both).

1 2 3 Page 2
Page 2 of 3