CloudFoundry: Logging for the spring-music webapp, Part 4

Cloud Foundry is an opinionated Platform-as-a-Service that allows you to manage applications at scale. This article is part of a series that explores different facets of a Cloud Foundry deployment using the spring-music project as an example.

This article is Part 4 of a series on Cloud Foundry concepts:

In this particular article, we will look at the Cloud Foundry log types, how to configure logback for spring-music, and then how to inject those events into a log pipeline.

Previous articles in the series describe basic deployment of the spring-music application, and we pick up from there. If you just went through article 3 on scaling, go ahead and scale down to only a single instance of the application to keep things simple.

$ cf scale spring-music -i 1 -m 1024M -f

Cloud Foundry Logging

Let’s start with looking at the type of log events visible when we perform actions in the spring-music application. Tail the logs using the following command:

$ cf logs spring-music

Each line has the following syntax as formatted by the loggregator traffic controller component:

Timestamp
[Log type/Instance#]
stdout or stderr channel
Custom application message

The log type can be one of the following values: API, STG, RTR, LGR, APP, SSH, CELL. Each denotes the component where the event is originating. Below is an example of a log event coming from the spring-music application when pulling up the main page.

2017-12-01T13:11:21.76-0500 [APP/PROC/WEB/0] OUT 2018-03-08T13:13:15.860+0000 INFO http-nio-8080-exec-2 o.c.s.m.w.AlbumController:25 [app_name=spring-music;app_version=1.0;instance_id=0] Getting all albums at INFO level MULTIEXCEPTION

The first 3 columns contain the loggregator timestamp, log type/app instance, then indication the message is coming from stdout. The rest is the custom application message and formatted as determined by Spring and it’s logging configuration.

Spring Boot Logging

By default, Spring Boot redirects all logs sent from Apache Commons Logging (JCL), Log4J and Java Util Logging (JUL) APIs to SLF4J. And Logback is used as the SLF4J implementation.

Although Spring boot has no mandatory dependency on any of the logging implementations, the spring boot starter projects do have a dependency on spring-boot-starter-logging which does have a dependency on Logback.

Configuring logging for spring-music

The application logging for spring-music can be configured just like any other Spring Boot application. Log levels can be manipulated by simple entries in application.properties or application.yml, or more complex formatting and control can be exerted by using a custom logback.xml file.

To gain even more control over the logging, we will use “logback-spring.xml” which is drop-in replacement and supports logging logic based on profile and also resource injection.

Simple level changes

The simplest way to define log levels in a Spring Boot application is to set the log level in application.properties or application.yml, which are found in the directory “src/main/resources”.

In application.properties, setting the root level and org.springframework.web package to WARN, while setting the package org.cloudfoundry.samples.music.web to DEBUG looks like this:

logging.level.root=WARN
logging.level.org.springframework.web=WARN
logging.level.org.cloudfoundry.samples.music.web=DEBUG

In application.yml, the syntax would be:

logging.level.root: WARN
logging.level.org.springframework.web: WARN
logging.level.org.cloudfoundry.samples.music.web: INFO

Custom logback-spring.xml

But often time, you will want full control of the outputs and format. And for that, you need to add a custom logback configuration file. Instead of logback.xml, we are using logback-spring.xml that enables enhanced control for properties and profiles.

Here is an example of what a very simple logback.xml or logback-spring.xml would look like:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
 <encoder>
 <pattern>%d{yy-MMMM-dd HH:mm:ss:SSS} %5p %t %c{4}:%L - %m%n</pattern>
 </encoder>
 </appender>

<logger name="org.springframework.web" level="warn" />
<logger name="org.cloudfoundry.samples.music" level="debug" />

<root level="WARN">
 <appender-ref ref="stdout"/>
 </root>

</configuration>

logback-spring.xml allows us to enhance this by pulling in the properties from resource files like ‘application.properties’.

<include resource="classpath:/application.properties"/>

 <springProperty scope="context" name="APP_NAME" source="APP_NAME" defultValue="unknown"/> 
<springProperty scope="context" name="APP_VERSION" source="APP_VERSION" defaultValue="unknown" /> 
<springProperty scope="context" name="CF_INSTANCE_INDEX" source="CF_INSTANCE_INDEX" defaultValue="0" />

Then these properties can be used when defining the log pattern.

<pattern>%date{"yyyy-MM-dd'T'HH:mm:ss.SSSZ", UTC} %5p %t %c{5}:%L [app_name=${APP_NAME};app_version=${APP_VERSION};instance_id=${CF_INSTANCE_INDEX}] %m</pattern>

The formatting of the logs is now under our full control. Here is the full version of our logback-spring.xml.

You may notice that in the full version of logback-spring we have formatted exceptions so that exception traces are collapsed to a single line by replacing the newline character with its Unicode representation.

%replace(%xException){'\n','\u2028'}%nopex%n

This is for consumption by logging solutions such as ELK or Graylog where you don’t want the 50 separate lines of a stack trace being separate logging events, and you want it instead to be sent as a single event.

Modifying log levels in spring-music

Feel free to change these levels in our spring-music project by modifying “src/main/resources/logback-spring.xml”, then rebuilding and pushing the application.

$ ./gradlew clean assemble
$ cf push spring-music

With logging levels are set to DEBUG for our web package, you should see the following output in the logs when pulling up the main URL and getting a list of albums.

2017-12-06T08:20:46.88-0500 [APP/PROC/WEB/0] OUT 2018-03-08T13:13:15.860+0000 INFO http-nio-8080-exec-2 o.c.s.m.w.AlbumController:25 [app_name=spring-music;app_version=1.0;instance_id=0] Getting all albums at INFO level MULTIEXCEPTION 

2017-12-06T08:20:46.89-0500 [APP/PROC/WEB/0] OUT 2018-03-08T13:13:15.860+0000 INFO http-nio-8080-exec-2 o.c.s.m.w.AlbumController:25 [app_name=spring-music;app_version=1.0;instance_id=0] Getting all albums at INFO level MULTIEXCEPTION

When set at DEBUG level, you get both the logger.info() as well as the logger.debug() output from src/main/java/org/cloudfoundry/samples/music/web/AlbumController.albums()

public Iterable<Album> albums() {
   logger.info("Getting all albums at INFO level");
   logger.debug("Getting all albums at DEBUG level");
   return repository.findAll();
}

If you set the level to INFO in logback.xml and rebuilt/repushed the application, you would only see the info level log message.

Loggregator to external logging pipeline

If you are using containers, it is highly likely that you will want to take this log output and feed it to an external logging solution like ELK, loggly, etc.

The general steps are to Create a User Defined Service (cups) that points to the syslog server where you want to send log events. Then bind the application to this log service, and finally restage the application.

$ cf cups <syslogServicename> -l syslog://<syslogServer>:<syslogPort>

$ cf bind-service spring-music <syslogServiceName>

$ cf restage spring-music

In a local development environment like PCF Dev, you could enable the Ubuntu host syslog server. But in this series of articles we have been focused on deploying containers to the public Pivotal platform. So we need to send the log events to an internet accessible syslog listener.

There are many SaaS providers that can ingest syslog events, but let’s choose Papertrail. Creating a trial account on papertrail is easy, and does not require a credit card. Click “Sign Up” and create a trial account. From the dashboard, click on “Add Systems” and you will see a message that indicates your exact syslog server name and port (which you should replace when issuing the commands below).

$ cf cups publicsyslog -l syslog-tls://logsN.papertrailapp.com:XXXX $ cf bind-service spring-music publicsyslog $ cf restage spring-music

Notice we use ‘syslog-tls’ as the protocol because we want to send these events securely.

In about 30-60 seconds, you should see events going to the live events board, and if you refresh your browser at the main albums page, you can see the same log events we saw earlier from “cf logs”.