Introduction

This article examines the dismal state of application-layer logging as observed from the authors’ years of experience in performing source code security analysis on millions of lines of code. It argues that effective logging is often ignored in the push for application security and demonstrates how applications can benefit from a real-time detection of attacks. An idea of a practical implementation is discussed, along with an examination of some of the associated risks and costs.

The application security push

Development and security staff alike are beginning to place a great deal of emphasis on secure coding practices. Indeed, vendors are capitalizing on the trend by promising secure off-the-shelf applications and infrastructure. Unfortunately, many people consider access control and encryption to more or less comprise the domain of application security.

In reality, several other domains are integral to application security. The OWASP Guide is often considered a good starting point for identifying these domains. Development teams in industry have varying awareness of the OWASP-identified domains. Most developers, for example, understand that they should not be coding their own encryption algorithms, yet relatively few realize the problem with creating their own session IDs with a standard Pseudo Random Number Generator (i.e. java.util.Random). One particular domain that has a consistent, dismal record is logging and monitoring.

Detecting application-level attacks

Few applications in a typical corporate environment are built with the ability to detect and notify staff of potentially malicious activity, relying instead on infrastructure devices and appliances such as firewalls to perform this function. Yet there are some attacks that will inevitably bypass these protection mechanisms: Denial of Service attacks from within the internal network, for instance, or attacks that bypass client-side validation yet still appear as legitimate traffic to the corporate network. Certainly some of these vectors appear to be the responsibility of intrusion detection and prevention systems at the network level, but with the advent of web services, growth of internal networks and federated access across enterprise boundaries, IDS/IPS systems alone may not be enough to detect these attacks.

It is certainly not feasible or even desirable for every application to include its own custom-built intrusion detection engine. Indeed, that is a monolithic task which contradicts the application security principle of, “securely coding instead of coding security.” A more viable solution is to leverage an existing log file analysis engine to read log files in real-time and, using intelligent rules, looking for attack patterns. Several tools exist, such as Sawmill and Network Intelligence that, while not designed specifically for custom application log file analysis, are configurable enough to meet those needs. An in-depth discussion of these tools is beyond the scope of this article; the focus here is enabling applications to feed into these tools. What most applications are lacking is a consistent approach to logging, in a standard format, allowing the analysis engine to extract meaningful values from log files.

Application logging in practice: Authentication

Many applications, including those in CMM Level 5 organizations, employ fairly inconsistent logging patterns. The following example shows a sample Java application logging an invalid authentication request using Log4J. Note that in the C# .Net world, the same example would apply using the Log4net tool. This article assumes some sort of logging tool is already in use – configuration and deployment of such a tool is not discussed.

if (!request.password.equals(result.password)) 
     { //user supplied wrong p/w
     log.debug("Invalid access attempt for " + request.usernane + "
     with password " + 	request.password);
...

The same application might have something like this in a user authentication module using a different interface:

if (myRequest.getPassword() != data.getPassword()) {
     log.info("Login failed");
...

Apart from the obvious security vulnerability of logging an unencrypted password, there are several problems with the scenario given above:

• Both cases use different logging levels (“debug” and “info”) to register a failed authentication attempt. This is indicative of the fact that each programmer has to make his/her own decision regarding the sensitivity of a particular logging event. While one programmer feels this is a debugging event, another feels it is slightly more important and records it in the second level “info” log. Depending on the implementation, this may mean that these events are written to different log files. Correlation and analysis of failed authentication attempts is at best complicated and maybe even impossible.
• Each case uses a different syntax. Again, this is attributed to each developer’s personal preference on how to log. Many developers think of low-level logging as an extension of debugging messages and do not see the need to follow any particular standard. This example shows output from only two different developers; in a real world application there are potentially dozens, hundreds, or in some cases thousands of developers employing their own syntax - keeping track of these messages is a daunting task. For even medium sized applications it is difficult to perform meaningful log-file analysis with such inconsistent syntax. There is also no guarantee that the analysis will remain meaningful if log messages change during future releases.
• Log4J, Log4Net, and most other related utilities will log exactly the messages that the callers pass as parameters. If the application employs a log file analysis tool that expects a particular syntax (such as, “AppName, LogMessage, TimeStamp, Date”) then developers are forced to use that syntax for all logging events. If at some point a new analysis tools is used or the tool’s required syntax changes, then developers will need to update every call to the logging tool in the application.
• There is no distinction here that the given events are security relevant. They will be entered into log files along with true debugging information (e.g. uninitialized variables), business logic errors (e.g. a form field is not filled), and system errors (e.g. the database sever is down)

Application logging in practice: SQL Injection

Let’s consider another example – one in which an input validation routine finds a character potentially being used for SQL Injection. Note that this example uses “blacklisting” or “known-bad validation”, which is a less-than-ideal approach to input validation but one used often nonetheless:

if (!request.desc.indexOf(‘;’) != 0) 
     { //possible SQL Injection character
     log.fine("Possible SQL injection character ';' in request.desc
value of " + request.desc);

Here again the severity of the attack is at the developer’s discretion. Moreover, there is no standardized message that would allow an automated engine to easily determine the presence of an input validation type of attack. While a single malicious character may be an accident, several such instances is likely a cause for concern. Without being able to correlate the several such incidences in real-time, the operational team’s ability to respond appropriately (such as, to block the offending IP) is significantly hampered.

The need for consistent logging is even greater in this example. Imagine an attacker trying to perform SQL Injection on a variety of different fields. Often these fields will map to different objects at the Data Access Object layer of the middle tier (e.g. CustomerDAO.java, OrderDAO.java, etc.). If these objects are written by different developers, there is a good chance that the syntax in the logs will also very. This is possible output in a regular log file:

Here there is a good chance that somebody is either manually or automatically fuzzing the fields and this should set off a warning to the operations team that the application may be under attack. Yet examining this output, how could any analysis tool correlate these two events without knowing exactly what syntax each developer uses to describe the possible SQL injection attempt?