App Logging in TAS for VMs

Loggregator, the VMware Tanzu Application Service for VMs (TAS for VMs) component responsible for logging, provides a stream of log output from your app and from TAS for VMs system components that interact with your app during updates and execution.

Overview

By default, Loggregator streams logs to your terminal. If you want to persist more than the limited amount of logging information that Loggregator can buffer, you can drain logs to a third-party log management service. For more information, see Third-Party Log Management Services.

TAS for VMs gathers and stores logs in a best-effort manner. If a client cannot consume log lines quickly enough, the Loggregator buffer may need to overwrite some lines before the client has consumed them. A syslog drain or a command-line interface (CLI) tail can usually keep up with the flow of app logs.

Contents of a log line

Every log line contains four fields:

Timestamp
Log type, or origin code
Channel: either OUT, for logs emitted on stdout, or ERR, for logs emitted on stderr
Message

Loggregator assigns the timestamp when it receives log data. The log data is opaque to Loggregator, which only puts it in the message field of the log line. Apps or system components sending log data to Loggregator may include their own timestamps, which then appear in the message field.

Many TAS for VMs components include the option to use human-readable timestamps in log messages. To configure TAS for VMs to use human-readable timestamps when possible, see Configure System Logging in Configuring TAS for VMs. For more information about human-readable timestamps, see RFC 3339.

Origin codes distinguish the different log types. Origin codes from system components have three letters. The app origin code is APP, followed by slash and a digit that indicates the app instance.

Many frameworks write to an app log that is separate from stdout and stderr. This is not supported by Loggregator. Your app must write to stdout or stderr for its logs to be included in the Loggregator stream. Check the buildpack your app uses to determine whether it automatically ensures that your app correctly writes logs to stdout and stderr only. Some buildpacks do this, and some do not.

Log types and their messages

Different types of logs have different message formats, as shown in the examples below. The digit appended to the code indicates the instance index: 0 is the first instance, 1 is the second, and so on.

API

Users make API calls to request changes in app state. The Cloud Controller, the TAS for VMs component responsible for the API, logs the actions that the Cloud Controller takes in response.

For example:

2016-06-14T14:10:05.36-0700 [API/0]      OUT Updated app with guid cdabc600-0b73-48e1-b7d2-26af2c63f933 ({"name"=>"spring-music", "instances"=>1, "memory"=>512, "environment_json"=>"PRIVATE DATA HIDDEN"})

STG

The Diego Cell or the Droplet Execution Agent emits STG logs when staging or restaging an app. These actions implement the desired state requested by the user. After the droplet has been uploaded, STG messages end and CELL messages begin. For STG, the instance index is almost always 0.

For example:

2016-06-14T14:10:27.91-0700 [STG/0]      OUT Staging...

RTR

The Gorouter emits RTR logs when it routes HTTP requests to the app. Gorouter messages include the app name followed by a Gorouter timestamp and selections from the HTTP request.

For example:

2016-06-14T10:51:32.51-0700 [RTR/1]      OUT www.example.com - [14/06/2016:17:51:32.459 +0000] "GET /user/ HTTP/1.1" 200 0 103455 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.123 Safari/537.30" 192.0.2.132:46359 x_forwarded_for:"198.51.100.120" x_forwarded_proto:"http" vcap_request_id:9365d216-623a-45cb-6ef6-eba495c19fa8 response_time:0.059468637 app_id:79cc58aa-3737-43ae-ac71-39a2843b5178

Zipkin trace logging

If Zipkin trace logging is allowed in TAS for VMs, Gorouter access log messages contain Zipkin HTTP headers.

The following is an example access log message containing Zipkin headers:

2016-11-23T16:04:01.49-0800 [RTR/0]      OUT www.example.com - [24/11/2016:00:04:01.227 +0000] "GET / HTTP/1.1" 200 0 109 "-" "curl/7.43.0" 10.0.2.150:4070 10.0.48.66:60815 x_forwarded_for:"198.51.100.120" x_forwarded_proto:"http" vcap_request_id:87f9d899-c7a4-46cd-7b76-4ec35ce9921b response_time:0.263000966 app_id:8e5d6451-b369-4423-bce8-3a7a9e479dbb app_index:0 x_b3_traceid:"2d5610bf5e0f7241" x_b3_spanid:"2d5610bf5e0f7241" x_b3_parentspanid:"-"

For more information about Zipkin tracing, see Zipkin Tracking in HTTP Headers in HTTP Routing.

LGR

Loggregator emits LGR logs to indicate problems with the logging process. Examples include can't reach syslog drain url and dropped log messages due to high rate.

APP

Every app emits APP logs to Loggregator.

For example:

2016-06-14T14:10:15.18-0700 [APP/0]      OUT Exit status 0

The logs allow you to determine the particular revision and process of the application instance logging.

For example, below shows the log line from two different revisions and web instances.

2022-09-15T01:59:33.99+0000 [APP/PROC/REV/2/WEB/0] OUT hello world from new
2022-09-15T01:59:34.99+0000 [APP/PROC/REV/1/WEB/1] OUT hello world from old

Note Logs with revision id are only available if the application uses revisions and it is enabled in the platform

Each app might have a configured log rate limit. If the app logs exceed the configured log rate limit, you see a log entry indicating that the limit was exceeded.

For example:

2022-09-15T01:59:33.99+0000 [APP/PROC/WEB/0] OUT app instance exceeded log rate limit (16384 bytes/sec)

SSH

The Diego Cell emits SSH logs when a user accesses an app container through SSH by using the Cloud Foundry Command Line Interface (cf CLI) cf ssh command.

For example:

2016-06-14T14:16:11.49-0700 [SSH/0]      OUT Successful remote access by 192.0.2.33:7856

For more information about the cf ssh command, see the Cloud Foundry CLI Reference Guide.

CELL

The Diego Cell emits CELL logs when it starts or stops the app. These actions implement the desired state requested by the user. The Diego Cell also emits messages when an app crashes.

For example:

2016-06-14T13:44:38.14-0700 [CELL/0]     OUT Successfully created container

The Diego Cell also emits a CELL log message when an app instance exceeds the max_log_lines_per_second limit, which is configured on the platform.

For example:

2020-01-13T16:12:25.86-0800 [APP/PROC/WEB/0] OUT app instance exceeded log rate limit (100 log-lines/sec) set by platform operator

This message only appears if the limit has been set by a platform operator. For more information, see App Log Rate Limiting.

Writing to the log from your app

Your app must write logs to stderr or stdout. Both are typically buffered, and you should flush the buffer before delivering the message to Loggregator.

You can write log messages to stderr or stdout synchronously. This approach is mainly used for debugging because it affects app performance.

Including container metrics in syslog drains

By default, app logs are included in syslog drains. Syslog Agents forward logs to configured syslog drains and Loggregator. For more information about Syslog Agents, see Loggregator Architecture and Components in Loggregator Architecture.

Viewing logs

To view logs, run the cf logs command. You can tail, dump, or filter log output. For more information about the cf logs command, see the Cloud Foundry CLI Reference Guide.

Tailing logs

To stream Loggregator output to the terminal:

Run:

cf logs APP-NAME

Where APP-NAME is the name of your app. The command returns output similar to the following example:

Connected, tailing logs for app spring-music in org example / space development as [email protected]...

2016-06-14T15:16:12.70-0700 [RTR/4]      OUT www.example.com - [14/06/2016:22:16:12.582 +0000] "GET / HTTP/1.1" 200 0 103455 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 Safari/537.36" 192.0.2.206:27743 x_forwarded_for:"203.0.113.222" x_forwarded_proto:"http" vcap_request_id:bd3e6ed1-5dd0-43ab-70ed-5d232b577b09 response_time:0.12050583 app_id:79bb58ab-3737-43be-ac70-39a2843b5177
2016-06-14T15:16:20.06-0700 [RTR/4]      OUT www.example.com - [14/06/2016:22:16:20.034 +0000] "GET /test/ HTTP/1.1" 200 0 6879 "http://www.example.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 Safari/537.36" 192.0.2.206:2228 x_forwarded_for:"203.0.113.222" x_forwarded_proto:"http" vcap_request_id:a31f0b1d-3827-4b8f-57e3-6f42d189f025 response_time:0.033311281 app_id:79bb58aa-3747-43be-ac70-39a3843b5178
2016-06-14T15:16:22.44-0700 [RTR/4]      OUT www.example.com - [14/06/2016:22:17:22.415 +0000] "GET /test5/ HTTP/1.1" 200 0 5461 "http://www.example.com/test5" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 Safari/537.36" 192.0.2.206:2228 x_forwarded_for:"203.0.113.322" x_forwarded_proto:"http" vcap_request_id:5d6855a2-4a79-4432-7927-de8215f5a2c7 response_time:0.029211609 app_id:79bb58aa-3737-43bb-ac70-39a2943b5178
    ...

Press Ctrl+C or Command+C on your keyboard to exit the real-time stream.

Dump logs

To display all of the lines in the Loggregator buffer:

Run:
```
cf logs APP-NAME --recent
```
Where APP-NAME is the name of your app.

Filter logs

To view some subset of log output, run cf logs APP-NAME in conjunction with filtering commands of your choice, where APP-NAME is the name of your app. In the example below, running cf logs spring-music --recent | grep -v RTR excludes all Gorouter logs:

2016-06-14T14:10:05.36-0700 [API/0]      OUT Updated app with guid cdabc604-0b73-47e1-a7d5-24af2c63f723 ({"name"=>"spring-music", "instances"=>1, "memory"=>512, "environment_json"=>"PRIVATE DATA HIDDEN"})
2016-06-14T14:10:14.52-0700 [APP/0]      OUT - Gracefully stopping, waiting for requests to finish
2016-06-14T14:10:14.52-0700 [CELL/0]     OUT Exit status 0
2016-06-14T14:10:14.54-0700 [APP/0]      OUT === puma shutdown: 2016-06-14 21:10:14 +0000 ===
2016-06-14T14:10:14.54-0700 [APP/0]      OUT - Goodbye!
2016-06-14T14:10:14.56-0700 [CELL/0]     OUT Creating container
    ...

Log ordering

Ensuring log ordering in drains can be an important consideration for both operators and developers.

Diego uses a nanosecond-based timestamp that can be ingested properly by Splunk. For more information, see the Splunk documentation.
The Elastic Stack can ingest the nanosecond timestamps but only supports millisecond precision, so timestamps are truncated. For more information, see the Elasticsearch documentation and Date type has not enough precision for the logging use case on GitHub.

If you are developing a client that displays a stream of TAS for VMs logs to users, you can order the logs to improve the debugging experience for your user. The following are general tips for ordering logs:

For CLIs, batch the logs and display the logs you have in that timeframe, sorted by timestamp.
For web clients, use dynamic HTML to insert older logs into the sorting as they appear. This creates complete, ordered logs.
Java app developers might want to convert stack traces into a single log entity. To simplify log ordering for Java apps, use the multi-line Java message workaround to convert your multi-line stack traces into a single log entity. For more information, see Multi-line Java message workaround.

By modifying the Java log output, you can force your app to reformat stack trace messages, replacing newline characters with a token. Set your log parsing code to replace that token with newline characters again to display the logs properly in Kibana.