Browse Recipes

Application Logging in CloudFoundry

logging splunk firehose

All applications that are to be deployed to Cloud Foundry must write all of their log output to either STDOUT or STDERR.

Each application will have its own logging configuration and framework, e.g. log4j, logback, slf4j, etc. As a standard is developed for the right logging framework, configuration, and library to be used, it will be documented here.

The main thing to take away from this recipe is that applications cannot write logs to disk, they must write to STDOUT/STDERR.

Spring Boot Starter, by default will use logback. This requires no further configuration. Logging rules can be added to the application.properties files. But recommended way is to create logback.xml under src/main/resources :

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml"/>
</configuration>

This logback.xml will setup our logging in exact same way as Spring Boot would do for us (if this logback conf file will be missing), but the benefit of this approach is that it protects us from loading and using unwanted logback.xml which can be loaded from some third-party libs.

All loggers should be converted to Slf4j, which is highly configurable and can plug in one of the other logging frameworks as its backing service.

Consider using Project Lombok and the @Slf4j annotation in order to minimize continually creating boilerplate logs in each class.

Configuring CXF logging levels:

By default, CXF uses SLF4J while depending on the jars in the classpath, the framework picks a logging implementation. To configure the logging level on CXF:

  • Add logback.xml to src/main/resources, our recommended approach is to default a logging level, while allowing environment variable to override
  • Add environment variable to manifest.yml to override the logging level

logback.xml, where the ${logback.cxf.level:-WARN} would default to "WARN" if an environment variable "logback.cxf.level" is not set: <configuration> <appender name="STDOUT" class="app.pkg.logback.core.ConsoleAppender"> <encoder> <pattern>%d{yyyy/MM/dd HH:mm:ss.SSS} APP=V9 LVL=%-5level %logger{36} - [%X] %msg%n</pattern> </encoder> </appender> <logger name="org.apache.cxf" level="${logback.cxf.level:-WARN}"> <appender-ref ref="STDOUT" /> </logger> </configuration>

OPTIONALLY in manifest.yml, using environment "logback.cxf.level" to override the log level. Please note that you do not need to do the following if you want to use the default level (in the example, it is at "WARN", and will be overridden with "INFO"). applications: - name: exchange-services-dev env: logback.cxf.level: "INFO"

Change log4j appender to console/stdout

log4j.properties

log4j.rootLogger=debug, stdout

# Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss:SSS} | %m%n

log4j.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
  <Console name="Console" target="SYSTEM_OUT">
  <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
  </Console>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="Console"/>
      </Root>
  </Loggers>
</Configuration>

NOTE: Avoid logging to files. Remove all the FileAppenders and use ConsoleAppenders instead

The logs are buffered in Cloud Foundry, so ensure you have one of the following configured for your application to view logs in a Log viewer like Splunk/ELK etc.

The latter is the preferred approach, as all the applications deployed in Cloud Foundry will drain logs to the log service using the firehose nozzle, avoiding applications from depending on yet another service.

Stack Trace Location with Third-Party Log System

This document provides a brief overview of how to locate and view stack traces for applications that are emitting logs which eventually find their way to a Third-Party Log System. The basic steps required to locate a stack trace for an application are as follows:

  • Narrow the log search to find only the entries that were emitted to STDOUT
  • Further narrow the log search to locate only those entries that belong to the target application
  • Further narrow the log search to locate only those entries within the target time period

Note that all of the steps discussed below assume that you are starting with the version of the log output that has been processed through the firehose-to-syslog nozzle component. This component allows application logs to go to Third-Party Log System without the apps having to explicitly bind to a user-provided syslog drain service, and it augments the application log information by wrapping it in a JSON envelope with a number of useful fields. These events look like this:

2016-03-16T13:38:53Z 19cknobmone doppler[29]: @cee:{"cf_app_id":"0afe2b7c-5601-48dd-bc45-ca567d1513ed","cf_app_name":"foo-app-bar","cf_info":"/foo/bar/baz","cf_org_id":"82d9f86b-5a8d-453d-b5ba-2a7e0b052906","cf_org_name":"foo","cf_origin":"firehose","cf_space_id":"b44f070f-6d5d-48c2-8804-ef7b078539f6","cf_space_name":"demo","event_type":"LogMessage","level":"info","message_type":"ERR","msg":"\t at  sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethod)","origin":"dea_logging_agent","source_instance":"0","source_type":"App","time":"2016-03-16T13:38:53Z","timestamp":1458135533877003031}

There are a couple of fairly important fields that you'll likely want to use for filtering and querying in your Third-Party Log System:

  • cfappname - The name of the application as it would appear in the output of a cf apps command.
  • cforgname - The name of the organization in which the application resides.
  • cfspacename - The name of the space in which the application resides.
  • message_type - The type of message. Will be ERR for messages sent to STDERR and OUT for messages sent to STDOUT
  • msg - The actual message emitted from the source. In the case of application logs, this will be the message emitted by the application.

Narrow the Search by Message Type

There are a number of ways to search for something that looks like a stack trace. However, the most reliable method for looking for a stack trace involves filtering the log stream such that you are only looking for messages that we emitted to STDERR.

Create a Message Type Field

If you do not already have a field extracted from the log events that corresponds to the JSON message_type field, then you'll need to extract it before you can filter. To do this, double-click the text ERR in the raw JSON for the message and choose extract field. Call the field Message Type. The pre-context regex should be message_type":" and the post-context regex should be "\,"msg. Feel free to change the regular expressions however you like.

Once have access to this field, you should now be able to see a histogram showing the ERR messages and the OUT messages. This histogram is available in the query window simply by clicking the plus (+) sign next to the message_type field.

Clicking on the ERR bar in the histogram is an easy way to add the filter to your query that shows only messages emitted for errors.

NOTE that this type of filtering implies that applications are emitting errors and trapped exceptions to STDERR and not to STDOUT. This may require some refactoring within the application to conform to this assumption.

Create a Message Text Field

Once we've extracted the message type (ERR or OUT), we want the raw text from the original log output. This will make it easier to read in context later when narrowing the columns viewed.

To do this, you can either highlight text inside the messagetext_ JSON field, or you can manually create a field. The regular expressions we used were:

  • msg":"
  • "\,"origin

This should now give you a field that contains the extracted raw message contents. By default, you'll see a large number in this field that contains the raw message's original timestamp. You can write a more elaborate regular expression that strips out this number.

Narrow the Results to an Application

With your results already filtered by message type, you can then use whatever mechanism you're already using to limit the log messages to those that belong to a given application. An easy mechanism would be to extract the cfappname field from the JSON and just use that as a filter.

Narrow Results to a Specific Time Period

If you're working on a particular issue that occurred within a known period of time, you can add a time filter to your query. For more information on how to sort logs in chronological order, use the "View in Context" feature, and use start and end times in your query filters, consult the Third-Party Log System documentation.

Use the Table View to Narrow Columns to Message Text, TimeStamp

Using the table view on the filtered results, you can select just the message text and timestamp fields so that you can look at the raw messages. This will give you the ability to scroll through the log stream and see stack traces. Keep in mind that each line of a lot emitted produces an individual log entry within Third-Party Log System. This is a fairly common pattern among log aggregation systems.

Appendix - Application Requirements

In order for the instructions above to work in a real production deployment, application developers must agree to a few minimum requirements. Thankfully, these requirements are already covered by the 12 Factors so this should not be new to anyone:

  • Applications must emit ALL log information to either STDOUT or STDERR
  • Applications must emit all exceptions, errors, and failures to STDERR
  • Applications must not emit harmless or informational messages to STDERR
  • Applications must not suppress stack traces from trapped exceptions, and must instead emit those stack traces to STDERR

Appendix - Stack Trace Samples

As mentioned above, there is no single uniform pattern to which all application stack traces conform. Even within a particular language or runtime, it is entirely possible to have multiple different formats or even customized formats for stack traces. That said, there are some characteristics that humans (as opposed to regular expression parsers) can often use to detect stack traces.

NodeJS Stack Trace

The following stack trace has been split and prettied up. A regular Node stack trace would be harder to read and likely condensed into a single line of text.

[Error] [ 'Error',
  '    at repl:1:7',
  '    at REPLServer.self.eval (repl.js:110:21)',
  '    at Interface.<anonymous> (repl.js:239:12)',
  '    at Interface.EventEmitter.emit (events.js:95:17)',
  '    at Interface._onLine (readline.js:202:10)',
  '    at Interface._line (readline.js:531:8)',
  '    at Interface._ttyWrite (readline.js:760:14)',
  '    at ReadStream.onkeypress (readline.js:99:10)',
  '    at ReadStream.EventEmitter.emit (events.js:98:17)',
  '    at emitKey (readline.js:1095:12)' ]

Java Stack Trace

There are an infinite number of ways to see a Java stack trace. However, many of them look similar to what you see below.

Exception in thread "main" java.lang.NullPointerException
        at com.example.myproject.Book.getTitle(Book.java:16)
        at com.example.myproject.Author.getBookTitles(Author.java:25)
        at com.example.myproject.Bootstrap.main(Bootstrap.java:14)

.NET Stack Trace

The following is a release mode .NET stack trace. This means that line numbers within code are available, and the positive offset numbers in this stack trace refer to offsets within a call stack of assembly code in the generated native code from the compiled artifact.

[NullReferenceException: Object reference not set to an instance of an object.]
   aspnet.debugging.BadForm.Page_Load(Object sender, EventArgs e) +34
   System.Web.UI.Control.OnLoad(EventArgs e) +67
   System.Web.UI.Control.LoadRecursive() +35
   System.Web.UI.Page.ProcessRequestMain() +720