Effective Go on GCP: Structured Logging
Alex Mammay
Posted on August 19, 2021
Structured Logging
Structured logging is a way to level up your insights into your application that is running on cloud run. Within this
example we will go over 3 different styles of logging and the incremental benefits you would get for each one.
Source code is here -> https://github.com/amammay/effectivecloudrun
Standard library logging
Our basic logging approach is as simple as it gets, we will use the golang std library logger under the log package. If
you are new to go, this is most likely what you have been using so far. It is as simple as
package main
import (
"log"
)
func main() {
log.Printf("hello %q", "alex")
}
When you use this logger, the output will be directed to STDERR and cloud run will pick up the log statement and add a
tiny bit of information around it, here is an example of what is produced by gcp logging when we would log
this log.Printf("hello %q! im an standard logger from the golang standard library", request.UserAgent())
{
// text payload is our actual log message
"textPayload": "2021/08/18 01:30:11 hello \"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36\"! im an standard logger from the golang standard library",
// insert id is automatically calculated
"insertId": "611c62a30008cc0be6f91983",
// resource is automatically inferred due to the log entry being written to STDERR
"resource": {
"type": "cloud_run_revision",
"labels": {
"service_name": "logging",
"project_id": "mammay-labs",
"revision_name": "logging-00003-wil",
"location": "us-central1",
"configuration_name": "logging"
}
},
// timestamp is auto calculated
"timestamp": "2021-08-18T01:30:11.576523Z",
// instance id label is automatically added
"labels": {
"instanceId": "00bf4bf02dd076018e4f332daec97d8ebce3bb2a4da1d941bc9f30e3773efd19ff329eb7e3778f1461e05af587de3d79095acfe02468a6d875c5552845"
},
// gcp will monitor stdout and stderr
"logName": "projects/mammay-labs/logs/run.googleapis.com%2Fstderr",
// another timestamp that is auto calculated
"receiveTimestamp": "2021-08-18T01:30:11.829264005Z"
}
So what we have shown for the standard library logger is the most primitive way that you log something on gcp, but you
are running this on gcp! You might as well get the most bang for your buck and beef it up with some structured logging
statements.
Basic Structured logging
Our basic structured logging implementation is very flexible with regard to how you would want to implement it. If your
team needs a large amount of flexibility/control over a logger that you would be distributing to other teammates this
would be a building block to achieve such a goal.
The gist of what you want to accomplish is to write your logs as json to STDERR. There is a schema you must follow when
writing the entries, and you can view the requirements
here gcp structured-logging
The most basic way you can implement something that would adhere to the structured logging schema would be like...
package logx
import (
"fmt"
"net/http"
)
func info(r *http.Request, message interface{}, projectID string) {
get := r.Header.Get("X-Cloud-Trace-Context")
traceID, spanID, traceSampled := deconstructXCloudTraceContext(get)
traceID = fmt.Sprintf("projects/%s/traces/%s", projectID, traceID)
entry := logEntry{
Severity: "INFO",
Message: message,
HttpRequest: &httpRequest{
RequestMethod: r.Method,
RequestUrl: r.URL.String(),
UserAgent: r.UserAgent(),
RemoteIp: r.RemoteAddr,
Referer: r.Referer(),
},
Timestamp: time.Now(),
Labels: map[string]string{"labels": "rock"},
SpanID: spanID,
TraceID: traceID,
TraceSampled: traceSampled,
}
writelog(&entry)
}
func writelog(entry *logEntry) {
if err := json.NewEncoder(os.Stderr).Encode(entry); err != nil {
fmt.Printf("failure to write structured log entry: %v", err)
}
}
// taken from https://github.com/googleapis/google-cloud-go/blob/master/logging/logging.go#L774
var reCloudTraceContext = regexp.MustCompile(
// Matches on "TRACE_ID"
`([a-f\d]+)?` +
// Matches on "/SPAN_ID"
`(?:/([a-f\d]+))?` +
// Matches on ";0=TRACE_TRUE"
`(?:;o=(\d))?`)
func deconstructXCloudTraceContext(s string) (traceID, spanID string, traceSampled bool) {
// As per the format described at https://cloud.google.com/trace/docs/setup#force-trace
// "X-Cloud-Trace-Context: TRACE_ID/SPAN_ID;o=TRACE_TRUE"
// for example:
// "X-Cloud-Trace-Context: 105445aa7843bc8bf206b120001000/1;o=1"
//
// We expect:
// * traceID (optional): "105445aa7843bc8bf206b120001000"
// * spanID (optional): "1"
// * traceSampled (optional): true
matches := reCloudTraceContext.FindStringSubmatch(s)
traceID, spanID, traceSampled = matches[1], matches[2], matches[3] == "1"
if spanID == "0" {
spanID = ""
}
return
}
This accomplishes a number of things. First lets look at what the output looks like in gcp logging
- Severity mapping, can be easily used for cloud monitoring to send notifications based on reported severity from log statements.
- Decorate log message with http request data for advanced logging queries.
- Provide structured json as a log message that can be as complex as needed. This also provides opportunity for advanced logging queries.
- Trace ID + Span ID support, this will allow us to correlate log entries to cloud trace for better insight to
fine-grained application behavior.
{
// auto generated insert ID
"insertId": "611c679300037f00b8a3abce",
// our log message gets wrapped in json payload if you send in a json friendly message
"jsonPayload": {
"timestamp": "2021-08-18T01:51:15.228952576Z",
"message": "information message"
},
// fill in the http request to give extra context around what our application is handling
"httpRequest": {
"requestMethod": "GET",
"requestUrl": "/structuredlogger",
"userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36",
"remoteIp": "------"
},
// auto generated due to the nature that we are writing to STDERR
"resource": {
"type": "cloud_run_revision",
"labels": {
"project_id": "mammay-labs",
"configuration_name": "logging",
"revision_name": "logging-00003-wil",
"location": "us-central1",
"service_name": "logging"
}
},
"timestamp": "2021-08-18T01:51:15.229120Z",
// pure info severity message, can be anything from https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity
"severity": "INFO",
"labels": {
// custom label we added
"labels": "rock",
"instanceId": "00bf4bf02d728741a6c4e41e7cabe309fe6857d005b0a31df24a74786e7f909f47e95c96545a213ea7789f7016f8e2ff0b47fc2732718fe030372f2792"
},
"logName": "projects/mammay-labs/logs/run.googleapis.com%2Fstderr",
// add cloud trace id
"trace": "projects/mammay-labs/traces/c83f888de20ad443abe581370e2a3beb",
"receiveTimestamp": "2021-08-18T01:51:15.474376268Z",
// add our span id
"spanId": "3688206018754987042",
// notify gcp that we should sample this trace and aggregate data into cloud trace
"traceSampled": true
}
Now within gcp here is an example of what log entries with various severities looks like.
As you can see the value-add structured logging has here is pretty awesome. In addition, adding the cloud trace and span
id's into the log statements even powers up more gcp products to work in a more insightful way. We will cover cloud
trace + open telemetry in a latter post to get even more quality of life upgrades.
Third party structured logger (Uber Zap)
Using a third party logger such as uber zap + zapdriver provides us with a really nice developer experience. We get the
best of both worlds around ease of use + structured log output. It will produce the same structured log output like
before, but just provide an easier way to configure its behavior without you having to write a whole bunch of custom
code for it.
To setup uber zap lets take a look at some code
package main
import (
"fmt"
"github.com/blendle/zapdriver"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"log"
"net/http"
)
func uberzaplogger(projectID string, onGCE bool) http.HandlerFunc {
var config zap.Config
// if on the cloud we will use a production config
if onGCE {
// create our uber zap configuration
config = zapdriver.NewProductionConfig()
// set the min logging level to debug for this demo
config.Level = zap.NewAtomicLevelAt(zap.DebugLevel)
} else {
// running locally we will use a human-readable output
config = zapdriver.NewDevelopmentConfig()
config.Encoding = "console"
config.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
}
// creates our logger instance
clientLogger, err := config.Build()
if err != nil {
log.Fatalf("zap.config.Build(): %v", err)
}
wrapTraceContext := func(header string) *zap.SugaredLogger {
traceID, spanID, sampled := deconstructXCloudTraceContext(header)
fields := zapdriver.TraceContext(traceID, spanID, sampled, projectID)
setFields := clientLogger.With(fields...)
return setFields.Sugar()
}
return func(writer http.ResponseWriter, request *http.Request) {
logger := wrapTraceContext(request.Header.Get("X-Cloud-Trace-Context"))
logger.Debug("debug message")
logger.Info("info message")
logger.Warn("warn message")
logger.Error("error message")
// calling any below will cause application to quite from the behavior of uber zap
// logger.DPanic("critical message")
// logger.Panic("alert message")
// logger.Fatal("EMERGENCY message")
fmt.Fprintf(writer, "<h1> uber zap is saying hello %q", request.UserAgent())
}
}
Overall at the end of the day my goal is to be the most productive and efficient as possible, I heavily lean to option 3
with using uber zap for all of my logging needs due to ease of configuration and integration into gcp.
Posted on August 19, 2021
Join Our Newsletter. No Spam, Only the good stuff.
Sign up to receive the latest update from our blog.
Related