Golang Structured Logging w/ Google Cloud Logging

- 4 minutes read - 725 words

I’ve multiple components in an app and these are deployed across multiple Google Cloud Platform (GCP) services: Kubernetes Engine, Cloud Functions, Cloud Run, etc. Almost everything is written in Golang and I started the project using go-logr.

logr is in two parts: a Logger that you use to write log entries; a LogSink (adaptor) that consumes log entries and outputs them to a specific log implementation.

Initially, I defaulted to using stdr which is a LogSink for Go’s standard logging implementation. Something similar to the module’s example:

package main

import (
	stdlog "log"
	"os"

	"github.com/go-logr/logr"
	"github.com/go-logr/stdr"
)

func main() {
	log := stdr.NewWithOptions(
        stdlog.New(
            os.Stdout,
            "",
            stdlog.LstdFlags,
        ),
        stdr.Options{
            LogCaller: stdr.All,
        })
	log = log.WithName("MyName")

    log.Info("something",
        "k1", "v1",
        "k2", "v2",
    )

See: https://play.golang.org/p/m5QQbJqFMKc

NOTE Using os.Stdout avoids sending everything to stderr and having Cloud Logging mark all log lines with severity: "ERROR"

NOTE I’m using strings but the key values are interface{} and slices, maps and structs all work too.

Outputs:

2021/09/28 17:37:45 MyName: "caller"={"file":"prog.go","line":22} "level"=0 "msg"="something" "k1"="v1" "k2"="v2"

It works very well. However, log entries are encapsulated as textPayload (i.e. text strings not parsed JSON) values in Google Cloud Logging, something similar to:

insertId: ""
labels:
  compute.googleapis.com/resource_name: ""
  k8s-pod/run: ""
logName: logs/stdout
receiveTimestamp: '2021-09-28T17:37:45.727687564Z'
resource:
  labels:
    cluster_name: ""
    container_name: ""
    location: ""
    namespace_name: ""
    pod_name: ""
    project_id: ""
  type: k8s_container
severity: INFO
textPayload: >
    2021/09/28 17:37:45 MyName 
    "caller"={"file":"prog.go","line":22} 
    "level"=0 
    "msg"="something" "k1"="v1" "k2"="v2"    
timestamp: "2021-09-28T17:37:45.009974311Z"

NOTE Yes, I’m talking about JSON and then presenting log entries as YAML. This is the default format used by gcloud logging and is easier to read. When we get to the conclusion, using YAML for the log helps highlight what’s possible.

With the exception of Cloud Functions, my other app components are deployed as containers and Google Cloud Platform uses a logging agent (built upon fluentd) to obtain container logs and ship these to Cloud Logging. In order to get the logs parsed as JSON, they need to:

logr includes a LogSink zerologr which uses zerolog and zerolog “provides a fast and simple logger dedicated to JSON output.”

We can revise the code to use zerologr:

package main

import (
	"os"

	"github.com/go-logr/logr"
	"github.com/go-logr/zerologr"
	"github.com/rs/zerolog"
)

func main() {
  zerologr.NameFieldName = "logger"
  zerologr.NameSeparator = "/"

  zl := zerolog.New(os.Stdout).With().Caller().Timestamp().Logger()
  var log logr.Logger = zerologr.New(&zl)
	log = log.WithName("MyName")

  log.Info("something",
    "k1", "v1",
    "k2", "v2",
  )
}

NOTE The use of With() followed by Caller() which adds the file and line number of the log’s caller and Timestamp().

See: https://play.golang.org/p/pQEfBA0mAco

Outputs (formatted for ease of viewing):

{
    "v":0,
    "logger":"MyName",
    "k1":"v1",
    "k2":"v2",
    "caller":"/path/to/main.go:68",
    "time":"2021-09-28T00:00:00-07:00",
    "message":"something"
}

This triggers the Cloud Logging agent and Cloud Logging to consume the log entries as JSON, use jsonPayload rather than textPayload but, most importantly, surface our user-defined log entry keys as values by which we can query logs. Before we try that, let’s apply the special fields.

We’re going to use logging.googleapis.com/labels which is a simple map of key:value pairs and logging.googleapis.com/sourceLocation which is a simple struct:

package main

import (
	"os"

	"github.com/go-logr/logr"
	"github.com/go-logr/zerologr"
	"github.com/rs/zerolog"
)

func main() {
	zerologr.NameFieldName = "logger"
	zerologr.NameSeparator = "/"

	zl := zerolog.New(os.Stdout).With().Caller().Timestamp().Logger()
	var log logr.Logger = zerologr.New(&zl)
	log = log.WithName("MyName")

	labels := map[string]string{
		"foo": "bar",
		"dog": "Freddie",
	}

	log.Info("something",
		"logging.googleapis.com/labels", labels,
		"k1", "v1",
		"k2", "v2",
	)
}

See: https://play.golang.org/p/xTyYwP0DumS

Outputs (formatted for ease of viewing):

{
    "v":0,
    "logger":"MyName",
    "logging.googleapis.com/labels":{
        "dog":"Freddie",
        "foo":"bar"
    },
    "k1":"v1",
    "k2":"v2",
    "caller":"/path/to/main.go:68",
    "time":"2021-09-28T00:00:00-07:00",
    "message":"something"
}

NOTE This example demonstrates the use of a map and a struct as label values too.

But, the magic happens when we deploy this code to e.g. Google Kubernetes Engine. Now we get log entries of the form:

insertId: iqz96zqax8g7f32x
jsonPayload:
  logger: MyName
  message: something
  k1: v1
  k2: v2
  v: 0
  caller: "/path/to/main.go:68"
  time: "2021-09-28T00:00:00-07:00"
labels:
  compute.googleapis.com/resource_name: ""
  dog: Freddie
  foo: bar
  k8s-pod/run: ""
logName: logs/stdout
receiveTimestamp: "2021-09-28T00:00:00.000000000Z"
resource:
  labels:
    cluster_name: ""
    container_name: ""
    location: ""
    namespace_name: ""
    pod_name: ""
    project_id: ""
  type: k8s_container
severity: INFO
timestamp: "2021-09-28T00:00:00.000000000Z"

NOTE See how "logging.googleapis.com/labels" is added to the root’s labels.

Not only does this look useful but it is useful because we can now use the Cloud Console’s log viewer to query by these values or:

FILTER=""\
"resource.type=\"k8s_container\" "\
"resource.labels.namespace_name=\"${NAMESPACE}\" "\
"resource.labels.pod_name=\"${NAME}\" "\
"labels.dog=\"Freddie\" "\
"jsonPayload.logger=\"MyName\""

gcloud logging read "${FILTER}" \
--project=${PROJECT} \
--limit=1

Which I used to return the previous result ;-)

How good is that!?