Logging may be used for the purposes of:

• Debugging & Error Reporting
• System Administration & Dev Ops
• QA insights
• Performance monitoring
• Business Intelligence
• Security

Section missing id

The sad reality of logging is that most existing systems are not following "the best practices" nor are they following "YOUR logging practices". In fact, there are no existing universally accepted guidelines for logging^{improving-devops-logging}. Unlike feature code, which is sometimes tested for correctness, it is very unlikely that anyone tests the the correctness of their logging code.

You have little or no control over what is and what is not reported by other people's software. Most logging messages are written by developers to help them debug their code.

Developers insert logging statements in an ad-hoc manner, producing logs that are completely cryptic to the outsiders (and to the developers themselves after a passage of time), and mostly useless for other purposes.

The good news is that you have have full control over logging information that YOU write and there are tools that can process the unholy mess produced by others.

One fourth (27%) of the log modifications are to variable logging. Majority (62%) of them are adding new variables that are causally related to the log message. It indicates that developers often need additional runtime information to understand how a failure occurred.

Suppose you have the following snippet in your code,

if(message instanceof TextMessage)
    //...
else
    log.error("Unknown message type");

The moment you see this error actually appearing in the logs, you will want to know the actual message type, message id, etc. Something went wrong, but what? What was the context?

If possible, always log enough context for a complete picture of what happened from a single log event. This is not always possible as the full context may be too large, but when it is possible, it will save you a huge amount of time when things do go wrong.

You should log:

• All relevant variable values.
• Timestamps.
• User or request identity: user ids, order ids, transaction ids, request ids, ip addresses, user-agents.
• Logical location: host names, node names, service ids.
• Flow identifiers: correlation ids, span ids.
• Sourcecode location: file name, function, method, class, file line.
• Elapsed times.

08/12/2014:09:16:35.842 GMT INFO key1=value1 key2=value2

Across 250 randomly sampled reported failures, we first identify that more than half of the failures could not be diagnosed well using existing log data. Surprisingly, we find that majority of these unreported failures are manifested via a common set of generic error patterns (e.g., system call return errors) that, if logged, can significantly ease the diagnosis of these unreported failure cases.

If you encounter a minor problem that can be automatically resolved, log it. A minor hiccup might be a symptom of a bigger problem. Masking the effects of an error by patching it is known in the parlance as a 'kludge'. It is not a compliment.

If you encounter a major but resolvable problem, you may attempt to resolve it, but make sure to log it ASAP.

• Your resolution may impair system performance.
• Your resolution or the original problem itself may result in future problems.
• The underlying problem may be a usability issue that is annoying to the users.
• It may be a symptom of a bigger problem.
• Your resolution may not go as planned, and it will be nice to have a log to refer to.

Log any unresolvable errors.

def foo: F[Unit] = for {
  _   <- log "hello"
  foo <- funcThatMayFail
} yield foo + 1

// BAD: Logging and rethrowing.
try{ /* do some work */ }
catch (Exception ex) {
    logger.log("error occured", ex);
    throw ex;
}

// GOOD: Logging & recovering.
try {
    doSomething();
} catch (Exception e) {
    log.Info("Couldn't do something", e);
    doSomethingElse();
}

// GOOD: leaving a comment explaining why ignoring an exception is okay.
try {
    context.DrawLine(x1,y1, x2,y2);
} catch (OutOfMemoryException) {
    // WinForms throws OutOfMemory if the figure you are attempting to
    // draw takes up less than one pixel (true story)
}

// GOOD: Adding additional context and throwing a wrapped exception.
try {
    doSomething(line);
} catch (Exception e) {
    throw new MyApplicationException(filename, line, e);
}

// GOOD: Cleaning up.
try {
    doSomething();
} finally {
  // Cleanup resources but let the exception percolate.
}

> Heuristic H1: If the verb [describing an action] involves creating, reading, updating, or deleting resource data in the software system, then the event must be logged.
[...]
If the verb can be accurately rephrased in terms of creating, reading, updating, or deleting resource data in the software system, then the event must be logged.
[...]
The unconstrained natural language used (specifically in use-case based requirements and user guides) may not easily map to the core CRUD actions. For example, "designate" appears in the iTrust use-case based requirements and OCS user guide. In these cases, we attempt to mentally rephrase the action using a core CRUD action. For example, "A patient designates a patient representative" can be mentally rephrased as "create a patient representative in the patient's list of patient representatives".

Always record CRUD actions (create, read, update, delete).

If the verb implies the system displaying or printing resource data that is capable of being viewed in the user interface or on paper, then the event must be logged.

Logging browser http requests and responses is an extension to logging the data that is communicated between your services. Seeing what a user has been doing makes it easier for a developer to determine what exactly went wrong for the user and is especially useful for front end errors.

If the verb expresses the granting or revocation of access privileges in the software system, then the event must be logged.
[...]
In "allow doctors to edit immunizations", the edit action is classified as a mandatory log event. However, the term "allow" suggests the use of an access control security mechanism in the software system. In this example, and based on prior research on security events that should be logged, we consider "allow" equivalent to "grant a user privilege" in an access control mechanism in the software.

If the verb involves the creation or termination of a user session, then the event must be logged.

Section missing id

System metrics are a way to monitor the health and performance of a system at any given time, such as CPU usage, RAM usage and request durations. Mostly these metrics are used to monitor performance in real time and up or down scale the system when needed.

Developers seldom delete or move logging code, accounting for only 2% of all the log modifications. Almost all (98%) of the log modifications are to the content of the log messages.

Most logging "frameworks" force you to use regular strings in your log statements:

LOG.error("Could not get invocation handler " + invocationHandler +
" for proxy " + proxy + ", or invocation handler is not closeable.");

This is not machine-friendly, and it is difficult to process such a message in an automated fashion without essentially retroactively typing them. You should make your log format structured - machine (and ideally human) readable

Consider using developer, human, and machine readable formats, such as JSON. This will further reduce the number of unnecessary log modifications due to the reduced ambiguity of structured messages.

Section missing id

Log.debug("orderstatus=error, errorcode=454, user=%d, transactionid=%s", userId, transId)

Section missing id

If a single application has to output events in different formats, separate them into individual files.

If your logs are consumed by multiple different parties, e.g. system administrators and business analysts, it is best to produce a separate log file for each group (this can be done by an automated log aggregator as well). They have different needs, and appropriate log files will have different "expiration times". Support logs might be kept for a week, marketing logs might be rotated every day, audit logs might be kept for years. Keeping all these messages in a single file makes it impossible to archive only audit logs, and will typically make automated parsing much harder.

Developers spend significant efforts on adjusting the verbosity level of log messages, accounting for 26% of all the log improvements. Majority (72%) of them reflect the changes in developers' judgement about the criticality of an error event.
[...]
In 28% of verbosity level modifications, developers reconsider the trade-off between multiple verbosities. It might indicate that developers are often confused when estimating the cost (e.g., excessive messages, overhead) and benefit afforded by each verbosity level.

Most logging libraries have a fixed set of severity levels, usually some combination of these:

• Fatal/Critical – overall application or system failure that should be investigated immediately. This severity should be used very infrequently. Typically, a Fatal error is the last message in the log, since any error on this level will likely force a shutdown of the service or application to prevent data loss.
• Error – any error which is fatal to the operation, but not the service or application (can't open a required file, missing data, etc.). Definitely a problem that should be investigated, but not immediately. By filtering a log to look at log messages of level Error and above, you get an overview of error frequency and can quickly identify the initiating failure that might have resulted in a cascade of additional errors.
• Warning –- the process might be continued, but take extra caution. Anything that can potentially cause application oddities, but for which there is an automatic resolution procedure, such as switching from a primary to a backup server, retrying an operation, skipping over some non-essential data, etc.
• Information -– general information about the operation of an application or a service. Each action that changes the state of the application significantly (database update, external system request) should be logged with this level.
• Trace –- very detailed information, intended only for development. You might keep trace messages for a short period of time after deployment on production environment, but treat these log statements as temporary, that should or might be turned-off eventually. They should be generally discouraged, and eventually removed. Allowing tracing messages tends to lead to more and more Trace messages being added and none ever removed. In time, this makes log files almost useless because it's too hard to filter signal from noise. Pruning Trace messages eliminates the possibility of bugs introduced because of needed side-effects in debug code that should not be included in the release build.

The list above is just a suggestion, you can create your own set of instructions to follow, but it is important to have some. Having the ability to quickly filter logs and extract the information with proper detail level might be a life-saver.

LOG.info("DEBUG - Container FINISHED: " + containerId);
//  ^^^^  ^^^^^

LOG.debug("DEBUG - Container FINISHED: " + containerId);
//  ^^^^^  ^^^^^

LOG.debug("Container FINISHED: " + containerId);

Every time you write (or review) a log statement, check if there are any potential NullPointerExceptions like:

log.debug("Processing request with id: {}", request.getId());

or unsafe casts like

DataNode.LOG.warn("Added missing block to memory " + (Block)diskBlockInfo);

Note that

try {
  log.trace("Id=" + request.getUser().getId() +
            " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

is not a good solution either.

Be careful with side-effects in your logging statements. If you fetch a "collection" of domain objects from the database using Hibernate and carelessly log them:

Extra attributes on snippet: XmlAttr(name=type, value=String(value=source))

log.debug("Returning users: {}", users);

You will be inadvertendly calling toString() on this "collection", which might result in a variety of problems such as OOM, N+1 select problem, thread starvation (logging is synchronous!), lazy initialization exception, etc.

Each logging statement should represent a single execution event.

log.debug("Message processed");
log.debug(message.getJMSMessageID());

should be rewritten as:

log.debug("Message with id '{}' processed", message.getJMSMessageID());

In log4j, isLogLevelEnabled methods, or similar methods in other logging frameworks.

Since Java before Java 8 does not have any form of convenient way to suspend evaluation of an expression, any expression passed to the logger methods is executed even if the logger just ignores the String that is created. This is a waste when doing things like logging complex data structures.

// GOOD enough.
if (logger.isDebugEnabled()) {
    logger.debug("data structure: " + dumpDataStructure(object));
}

Of course, in languages supporting some form of by-name parameters, it is much more preferable to just use those facilities.

A common example is logging a SQL command after the execution. In case of an exception, the log entry might not be written, so the audit log will not provide relevant contextual information for the exception. Audit log entries should be written before an action - not after.

One has to go through the pain of analyzing debug output looking like:

step #1
x
2 - true
step #2
step #3

to deeply appreciate their inherent ugliness.

If you have to log in to each individual server to read logs, you will spend more time trying to correlate problems than if you just had one location where you could access all the logs.

Logs may contain sensitive data, like personal data of your clients or internal access keys for APIs. Make sure that sensitive data gets anonymized or encrypted before you ship logs to any third party.

Logs from different sources might require different retention times. Some applications are only relevant for troubleshooting for a few days. Security-related or business transaction logs require longer retention times. Therefore, a retention policy should be flexible, depending on the log origin and intention.

Planning the capacity for log storage should consider high load peaks. When systems run well, the amount of data produced per day is nearly constant and depends mainly on the system utilization and amount of transactions per day. In the case of critical system errors, we typically see accelerated growth in the log volume. If the log storage hits storage limits, you lose the latest logs, which are essential to fix system errors. The log storage must work as a cyclic buffer, which deletes the oldest data first before any storage limit is applied.

Design your log storage so that it is scalable and reliable – there is nothing worse than having system downtimes and a lack of information for troubleshooting, which in turn, can elongate downtime.

Log storage should have a separate security policy. Every attacker will try to avoid or delete his traces in log files. Therefore you should ship security logs in real-time to a secure log storage. If the attacker has access to your infrastructure, sending logs off-site, e.g., using a logging SaaS will help keep evidence untampered.

Unmaintained log data could lead to longer troubleshooting times, risks of exposing sensitive data or higher costs for log storage. Review the log output of your applications and adjust it to your needs. Reviews should cover usability, operational and security aspects.

Some applications logs are too verbose and other application logs don't provide enough information about the activities. Adjustable log levels are the key to configure the verbosity of logs.

Acting on security issues is crucial – so you should always have an eye on audit logs. Setup security tools such as auditd or OSSEC agents. The tools implement real-time log analysis and generate alert logs pointing to potential security issues. On top of such audit logs, you should define alerts on logs in order to be notified quickly on any suspicious activity.

The most critical events are those that impact business revenue. These events are the ones you should monitor closely and send alerts to the right response team.

It shouldn't be your customers calling to tell you that there are bugs in your application. You want to find them before they do, and many customers will just bounce to another vendor if you have too many bugs. Many of your customers won't report application issues at all, so you could be losing sales every hour and never know it.

When you build a shopping cart, you should have a point where you ask a visitor for a way to contact them. Usually, email is a common input field during account creation. With an alert on failed shopping cart activity, you have a way to contact a customer should they receive an error and bail on the shopping experience. Alerts are a great tool to salvage a lost customer due to application bugs.

But you also need alerts to tell you when components of your application are creating obstacles for customer shopping experiences. It could be an alert for performance (similar to the previous example), or your customers could be dropping at a specific point in the sales funnel.

Alerts may also help you pinpoint components of your application that could be causing performance degradation. Your developers would need to set a baseline, but – for instance – you could set an alert for any event that takes longer than 100 milliseconds to process.

When CPU usage spikes to over 80%, set an alert to inform administrators. It could be something as simple as upgrading RAM or even your server's CPU, but having these log alerts will give you the ability to analyze the time of day and any patterns surrounding application lifetime.

My main problem with logging levels is that they are non-compositional: only the caller knows whether a failure in a function is a "critical failure" in the context of the surrounding computation.

If you're a new developer working on this project for the first time, or a client who is testing my software, it is reasonable to think that something terrible has happened. Since the log file looks so concerning, you might spend an hour or two investigating these errors before realizing that these I2C write failures are expected and acceptable.
This particular program supports dynamic detection of connected sensors using an I2C write. If the sensor is not connected, the write will fail and we will move on to the next slot. Even worse, the same I2C error spew occurs if you try to run an I2C bus sweep to detect connected devices. The log becomes practically worthless in such a situation, as each I2C sweep call would generate up to 128 I2C error prints. The obvious answer is to disable the log statement, but the underlying I2C layer was provided to us as a pre-compiled library.
This example is hardly a shining beacon of useful error logging, but is indicative of typical logging experiences.

Furthermore, it is not always clear whether a particular event should be logged or not. Consider a situation where you are opening thousands of files and the vast majority of them do not exist. Your code may look like this (ZIO):

IO.foreach_(files)(fn => doSomething(fn))

Clearly, in this particular case it would be unwise to record every single file that was not found assuming that that is the expected situation. Instead only the general statistics such as the number of files found vs not found should be logged. But that in turn means that doSomething can not log anything on its own.

A good functional solution to the problem of log non-compositionality is to pass a function into doSomething that will be called whenever a file is not found:

def doSomething[E](path: Path)(notFound: => IO[E, Unit] = IO.unit): IO[E, Unit]

This can be further generalized with a concept of a probe, a collection of callbacks that will be called from the function whenever it goes through particular internal state transitions:

trait DoSomethingProbe[-R, +E] {
    def openingFile(file: Path): ZIO[R, Nothing, Unit]
    def fileNotFound(file: Path): ZIO[R, E, Unit]
    def closingFile(file: Path): ZIO[R, Nothing, Unit]
}
object DoSomethingProbe {
    // A probe that does nothing.
    val nop : DoSomethingProbe[Any, Nothing] =
        new DoSomethingProbe[Any, Nothing] { ... }
}

def doSomething[R, E](path: Path)(probe: DoSomethingProbe[R, E] = DoSomethingProbe.nop): ZIO[R, E, Unit]

With this probing mechanism in place, the caller can decide whether doSomething should log anything, what level it should log failures at, etc.

Adherents of pure functional programming may find themselves in a difficult situation where something needs to be logged inside a pure function for debugging purposes but there is no monadic context available.

You can rewrite your pure functions in a final tagless manner, but only at a significant price in terms of performance and clarity. You can put all of your code into an IO-like monad, but you lose a lot of reasoning tools that come with precise types and colloquial "purity".

One potential solution is to have a way of probing pure code... using impure callbacks:

trait TransposeProbe {
    def beforeTranspose(matrix: Matrix): Unit
    def afterTranspose(old: Matrix, new: Matrix): Unit
}

def transpose(m: Matrix)(probe: TransposeProbe = TransposeProbe.nop): Matrix = ...

This is not completely satisfactory, but does side-step the reasoning issue – the function is not side-effectful as long as the probe isn't. The fact that we sometimes sequence innocuous calls to functions returning Unit does not make the reasoning any more difficult as long as we assume they are pure & total. Those who are familiar with Haskell may think of it as seqing unsafeInterleavedIO'd thunks of ().

Unfortunately this approach does not work well if our logging is inherently asynchronous.