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.
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:
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"
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.
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:
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:
cf apps
command.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.
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.
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.
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.
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.
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.
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:
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.
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)' ]
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)
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