Google Stackdriver / GKE Logging Demo

Demo and best practices for logging from your GKE-hosted app to Stackdriver. Also applies to apps running on GCP AppEngine and Cloud Functions.

Languages demoed

• C# / ASP.NET
• Go

See below for instructions on how to build and deploy the demo apps on GKE.

How to log to Stackdriver from your GCP-hosted app

If your app runs on GKE (with Kubernetes Monitoring enabled), AppEngine or Cloud Functions, logs writen by your app will be automatically shipped to Stackdriver. There is no need to use the Stackdriver logging libraries.

Use your favourite logging library and configure it to:

• Write logs to the standard output.
• Format logs in either plain-text or JSON.

If formatting logs in JSON:

• Write the log message to a top-level message property (pay attention to the case. It's message, not Message).
• Write the log level to a top-level severity property and set it to one of the values recognized by Stackdriver.
• Write the timestamp to a top-level timestamp property and format it in the RFC3339 UTC "Zulu" format, accurate to nanoseconds (e.g. 2019-02-02T15:01:23.045123456Z).
• When logging an error, write the exception / error details in either a message or exception top-level property and follow the format documented for the message property here.

This will ensure that Stackdriver displays your logs correctly in its UI and that Stackdriver Error Reporting correctly picks up your error logs.

Example Stackdriver-friendly log entry:

{
    "timestamp" = "2019-02-02T15:01:23.045123456Z",
    "severity" = "ERROR",
    "message" = "Failed to place order ID 123",
    "exception" = "System.ArgumentException: invalid amount. Expected: greater than 0. Got: -1.
   at Shopping.Controllers.HomeController.Foo.PlaceOrder() in /app/Controllers/HomeController.cs:line 62
   at Shopping.Controllers.HomeController.Home() in /app/Controllers/HomeController.cs:line 33",
    [...] // Anything else you feel like adding... 
}

In practice

Configuring your logger to log in a Stackdriver-friendly format

.NET using Serilog

Serilog's built-in JSON formatters don't allow customizing the JSON output. In order to format your logs in the Stackdriver-friendly format shown above, you'll have to write your own Serilog JSON formatter.

Thankfully this is a straightforward task. Here's an example Serilog JSON formatter for Stackdriver.

You can then configure Serilog with it:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    // Exclude debug logs coming from the ASP.NET runtime 
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .Enrich.FromLogContext()
    .WriteTo.Console(new StackdriverJsonFormatter())
    .CreateLogger();

Working example.

Go using Logrus

Logrus makes configuring it to output logs in a Stackdriver-friendly format easy:

log = logrus.New()
log.Level = logrus.DebugLevel
log.Out = os.Stdout

log.Formatter = &logrus.JSONFormatter{
	FieldMap: logrus.FieldMap{
		logrus.FieldKeyTime:  "timestamp",
		logrus.FieldKeyLevel: "severity",
		logrus.FieldKeyMsg:   "message",
	},
	TimestampFormat: time.RFC3339Nano,
}

Working example.

Unfortunately, Logrus doesn't allow customizing its log levels. You should avoid using Logrus' Trace, Fatal and Panic log levels as they won't be recognized by Stackdriver. Stackdriver will display logs written at those levels under a generic "Any" level and won't display them when filtering by log level.

Logging errors

For errors to be picked up by the Stackdriver Error Reporting feature, they must be formatted in a way that Stackdriver understands.

.NET with Serilog

Log exceptions normally. Serilog will do the right thing (stringify the exception with its stack trace and output it in a exception property):

// Beware that with Serilog, the first parameter of the Error() 
// method is the exception, not the log message. This is unlike
// most other logging libraries that do it the other way around.
logger.Error(ex, "Coulnd't do the thing.");

Go with Logrus

Go errors don't include a stack trace. Since Stackdriver Error Reporting requires a stack trace to be included (in the format returned by runtime.Stack()), you must ensure that you always manually include it in your error logs:

log.Errorf("Doing the thing failed: %v\n%v", err, string(debug.Stack()))

Not including the stack trace in your error logs will result in errors logged by your Go app to be missing from the Stackdriver Error Reporting page.

Misc

For everything else, log as usual. And of course, use structured logging liberally to make querying your logs and troubleshooting issues easier.

Demo Apps: Pre-Requisites

• Docker Desktop (enable Kubernetes in Preferences -> Kubenetes -> Enable Kubernetes)
• skaffold

If you don't yet have a GKE cluster, create one (using preemptible VMs to keep the costs down):

# Enable Google Kubernetes Engine
gcloud services enable container.googleapis.com

gcloud beta container clusters create personal \
--zone=europe-west1-b \
--preemptible \
--num-nodes=1 \
--enable-autoscaling \
--min-nodes=1 \
--max-nodes=6 \
--maintenance-window=03:00 \
--enable-ip-alias \
--enable-autoupgrade \
--enable-autorepair \
--enable-stackdriver-kubernetes \
--no-enable-basic-auth

# Check if it worked
kubectl get nodes

You'll also need to enable a few Google Cloud services:

# Enable Google Cloud Registry and Google Cloud Build 
# so that we can build on GCB an deploy to GKE.
gcloud services enable containerregistry.googleapis.com
gcloud services enable cloudbuild.googleapis.com

# Configure the user that Docker and Skaffold will use 
# to access Google Cloud services.
gcloud auth configure-docker
gcloud auth application-default login

Demo Apps: Build & Run

Option 1: Build & Run locally with Docker Desktop

Make sure that kubectl is pointing to your local cluster. Then, at the root of the repo:

# Build all the Docker images and deploy them to the local K8S cluster.
skaffold run

# You should now see the pods running on your K8S cluster:
kubectl get pods

NOTE: When running locally, logs won't be forwaded to Stackdriver.

To view the logs written the demo apps, use kubectl logs to view the logs of the running K8S pods.

Alternatively, run the apps using skaffold run --tail or skaffold dev. This will output the logs to the console.

Option 2: Build locally & run on Google Kubernetes Engine (GKE)

With this option, you'll still need to have Docker Desktop to build the Docker images. But you don't need to have K8S running locally.

Make sure that your kubectl context is pointing to your GKE cluster. Then, at the root of the repo:

# PROJECT_ID is your GCP project ID
skaffold run --default-repo=gcr.io/PROJECT_ID

# You should now see the pods running on your GKE cluster:
kubectl get pods

Then, in the GCP Console:

• Search for dotnetlogdemo or golanglogdemo on the Stackdriver Logging page to view the logs.
• Go to Stackdriver Error Reporting to view the errors logged by the demo apps.

Option 3: Build on Google Cloud Build (GCB) & run on Google Kubernetes Engine (GKE)

With this option, you don't need to have either Docker Desktop nor Kubernetes running locally. Everything happens in the cloud.

Make sure that your kubectl context is pointing to your GKE cluster. Then, at the root of the repo:

# Build and run.
# PROJECT_ID is your GCP project ID.
skaffold run --profile gcb --default-repo=gcr.io/PROJECT_ID

Then, in the GCP Console:

• Go to Stackdriver Logging and search for dotnetlogdemo or golanglogdemo to view the logs written by the demo apps.
• Go to Stackdriver Error Reporting to view the errors logged by the demo apps.

Our Skaffold config doesn't currently use image caching when building on Google Cloud Build. As a result, each build will start from scratch and will be slow.

Option 4: Build with Kaniko on GKE and run on GKE

[TODO (the build works but pushing the built image to GCR fails for an unknown reason)]

Demo Apps: What they do

The Demo apps are Hello World web apps that write info, warning and error logs when their home page is accessed.

Kukernetes has been configured to use their home page as its liveness probe once a second. This means that as soon as the demo apps are deployed, they'll start continuously writing logs and errors.

Access the running apps

Either run the apps with skaffold dev to automatically forward ports on your local machine to the running K8S pods. Or forward ports manually:

kubectl port-forward deployment/dotnetlogdemo 6100:6100
kubectl port-forward deployment/golanglogdemo 6200:6200

Then access the demo apps at:

http://localhost:6100

http://localhost:6200

Viewing the logs

In the GCP Console:

• Search for dotnetlogdemo or golanglogdemo on the Stackdriver Logging page to view the logs.
• On the logging page, expand the jsonPayload properties of the log entries written by the demo apps to see the structured log they wrote.
• Go to Stackdriver Error Reporting to view the errors logged by the demo apps.

Skaffold tips & tricks

If this is your first time using skaffold:

# Builds the app and deploys (or re-deploys) it to the K8S cluster
skaffold run

# Same but also displays the logs from the app's pods in real-time
skaffold run --tail

# Stops and deletes your app from the K8S cluster
skaffold delete

# Builds and deploys the app. Automatically forwards ports exposed by
# pods to your local machine so that you can access the app locally.
#
# Then watches for any code file changes and automically re-builds 
# and re-deploys on any change. 
#
# This is what you'd typically use when developing. 
skaffold dev

If you don't feel like typing your GCR URL everything you run skaffold, you can set it in the SKAFFOLD_DEFAULT_REPO env var instead:

export SKAFFOLD_DEFAULT_REPO="gcr.io/PROJECT_ID"

# You might want to set it in your .bash_profile and/or .bashrc as well
echo 'export SKAFFOLD_DEFAULT_REPO="gcr.io/PROJECT_ID"' >> ~/.bash_profile

# You can now omit the --default-repo arg when running skaffold
skaffold run

Alternatively, you can set the default image repo in Skaffold's global config, which allows you to have a different GCR URL per kubectl context.