Golang Structured Logging w/ Google Cloud Logging (2)

UPDATE There’s an issue with my naive implementation of RenderValuesHook as described in this post. I summarized the problem in this issue where I’ve outlined (hopefully) a more robust solution.

Recently, I described how to configure Golang logging so that user-defined key-values applied to the logs are parsed when ingested by Google Cloud Logging.

Here’s an example of what we’re trying to achieve. This is an example Cloud Logging log entry that incorporates user-defined labels (see dog:freddie and foo:bar) and a readily-querable jsonPayload:

insertId: 616dbf8e000892de40c4cc4e
jsonPayload:
  level: 0
  logger: MyName
  msg: something
  ts: '2021-10-18 00:00:00.000000'
labels:
  dog: freddie
  foo: bar
  instanceId: 00bf4bf0...
logName: projects/.../logs/run.googleapis.com%2Fstdout
receiveTimestamp: '2021-10-18T00:00:00.000000000Z'
resource:
  labels:
    configuration_name: structured-logging
    location: us-west2
    project_id: ...
    revision_name: ...
    service_name: structured-logging
  type: cloud_run_revision
timestamp: '2021-10-18T00:00:00.000000Z'

Since the last post (see this issue), the helpful developers of go-logr have revised funcr’s implementation (see release: v1.2.0-rc1) so that it enables:

• outputting logs as JSON; and
• enables the use of hooks to configure the logs so that these support e.g. the Cloud Logging agent’s special fields (e.g.logging.googleapis.com/labels). This is advantageous because it enables us to support the Cloud Logging agent’s requirements through configuration rather than changing log statements.

The motivation for all of these solutions is that they enable (JSON) structured (rather than raw text string) logs to be ingested by Cloud Logging.

With structured logging, logs can be filtered (queried) using user-defined metadata. Without structured logs, the majority of a log statement is stored as a text string which, not only requires on-the-fly parsing, but is less-precise.

In the previous post, go-logr and its LogSink zerologr were used to ouput logs (mostly¹) correctly formatted for the Cloud Logging agent to parse on ingestion.

Because it’s a standalone module, we needed to import zerologr. In order to use Cloud Logging’s special fields, we must use these special fields as the keys in log statements directly, e.g.:

package main

import (
	"os"

	"github.com/go-logr/logr"
	"github.com/go-logr/zerologr"

    // Import zerolog
	"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",
	}

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

funcr is part of the go-logr/logr module and so there are no additional imports. Using funcr’s hooks, we can also reflect the Cloud Logging agent’s special fields in the log configuration rather than in each log statement:

package main

import (
	"fmt"
	"net/http"
	"runtime"
	"time"

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

const (
	loggingLabels         = "logging.googleapis.com/labels"
	loggingSourceLocation = "logging.googleapis.com/sourceLocation"
)

func main() {
	renderSourceLocation := func(kvList []interface{}) []interface{} {
		// Range over keys
		for i := 0; i < len(kvList); i += 2 {
			k, _ := kvList[i].(string)
			// Rename struct
			if k == "caller" {
				kvList[i] = loggingSourceLocation
			}
		}
		return kvList
	}
	renderLabels := func(kvList []interface{}) []interface{} {
		return []interface{} {
            loggingLabels,
            funcr.PseudoStruct(kvList),
        }
	}

    log := funcr.NewJSON(
		func(obj string) {
			fmt.Println(obj)
		},
		funcr.Options{
			LogCaller:     funcr.All,
			LogCallerFunc: true,
			LogTimestamp:  true,
			RenderBuiltinsHook: renderSourceLocation,
			RenderValuesHook: renderLabels,
		})

	log = log.WithName("MyName")

	log = log.WithValues(
		"foo", "bar",
		"dog", "freddie",
	)

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

See how log statements no longer need to reflect the Cloud Logging special fields. To create Cloud Logging labels, we need only log.WithValues(). To emit Cloud Logging sourceLocation, the structure called caller (that results from including LogCaller) is renamed.

To implement this using funcr, we need only define 3 things:

1. A fn that takes JSON strings (obj) and outputs them. In this case, we can just fmt.Println the obj as-is
2. A RenderValuesHook that takes any key-value pairs applied using WithValues() and puts them in a struct called logging.googleapis.com/labels. This satisfies the Cloud Logging agent’s special fields requirement for Labels. Using WithValues() to represent labels is an implementation choice. We could have used RenderArgsHook instead. See Options for more details.
3. A RenderBuiltinsHook that renames the caller structure to logging.googleapis.com/sourceLocation to satisfy the Cloud Logging agents’s special fields for sourceLocation. Conveniently go-logr’s caller struct’s fields match those needed for sourceLocation so a simple rename is all that’s required. An example is included in the package docs.

This time, I deployed the sample to Cloud Run.

NOTE Because Cloud Run expects an HTTP server running on :8080, I added, but don’t show in the code above, a no-op server to satisfy this Cloud Run requirement.

Once the service is deployed, we can query its logs:

FILTER=""\
"resource.type=\"cloud_run_revision\" "\
"resource.labels.service_name=\"structured-logging\" "\
"labels.dog=\"freddie\" "\
"sourceLocation.line=\"76\" "\
"jsonPayload.logger=\"MyName\""

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

The resource.type and resource.labels are standard Cloud Logging metadata.

But we can now also filter logs by our user-defined key-value pairs that were produced by funcr, i.e.:

• labels.dog="freddie" which result from the log.WithValues key-value pairs we provided and were remapped onto the special fields that Cloud Logging expects for labels.
• sourceLocation is the remapped caller.
• jsonPayload represents everything else that was provided as key-value (now JSON) pairs and, because this JSON has been parsed too, any of its fields e.g. logger are accessible for filtering.

Yields:

insertId: 616dbf8e000892de40c4cc4e
jsonPayload:
  level: 0
  logger: MyName
  msg: something
  ts: '2021-10-18 00:00:00.000000'
labels:
  dog: freddie
  foo: bar
  instanceId: 00bf4bf0...
logName: projects/.../logs/run.googleapis.com%2Fstdout
receiveTimestamp: '2021-10-18T00:00:00.000000000Z'
resource:
  labels:
    configuration_name: structured-logging
    location: us-west2
    project_id: ...
    revision_name: ...
    service_name: structured-logging
  type: cloud_run_revision
sourceLocation:
  file: main.go
  function: main.main
  line: '76'
timestamp: '2021-10-18T00:00:00.000000Z'

• Golang
• Cloud-Logging
• Logr
• Go-Logr