How to log Stackdriver log messages correlated by trace id using stdout Go 1.11

Question

I'm using Google App Engine Standard Environment with the Go 1.11 runtime. The documentation for Go 1.11 says "Write your application logs using stdout for output and stderr for errors". The migration from Go 1.9 guide also suggests not calling the Google Cloud Logging library directly but instead logging via stdout. https://cloud.google.com/appengine/docs/standard/go111/writing-application-logs

With this in mind, I've written a small HTTP Service (code below) to experiment logging to Stackdriver using JSON output to stdout.

When I print plain text messages they appear as expected in the Logs Viewer panel under textPayload. When I pass a JSON string they appear under jsonPayload. So far, so good.

So, I added a severity field to the output string and Stackdriver Log Viewer successfully categorizes the message according to the levelled logging NOTICE, WARNING etc. https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry

The docs say to set the trace identifier to correlate log entries with the originating request log. The trace ID is extracted from the X-Cloud-Trace-Context header set by the container.

Simulate it locally using curl -v -H 'X-Cloud-Trace-Context: 1ad1e4f50427b51eadc9b36064d40cc2/8196282844182683029;o=1' http://localhost:8080/

However, this does not cause the messages to be threaded by request, but instead the trace property appears in the jsonPayload object in the logs. (See below).

Notice that severity has been interpreted as expected and does not appear in the jsonPayload. I had expected the same to happen for trace, but instead it appears to be unprocessed.

How can I achieve nested messages within the original request log message? (This must be done using stdout on Go 1.11 as I do not wish to log directly with the Google Cloud logging package).

What exactly is GAE doing to parse the stdout stream from my running process? (In the setup guide for VMs on GCE there is something about installing an agent program to act as a conduit to Stackdriver logging- is this what GAE has installed?)

app.yaml file looks like this:

runtime: go111

handlers:
- url: /.*
  script: auto



package main

import (
    "fmt"
    "log"
    "net/http"
    "os"
    "strings"
)

var projectID = "glowing-market-234808"

func parseXCloudTraceContext(t string) (traceID, spanID, traceTrue string) {
    slash := strings.Index(t, "/")
    semi := strings.Index(t, ";")
    equal := strings.Index(t, "=")
    return t[0:slash], t[slash+1 : semi], t[equal+1:]
}

func sayHello(w http.ResponseWriter, r *http.Request) {
    xTrace := r.Header.Get("X-Cloud-Trace-Context")
    traceID, spanID, _ := parseXCloudTraceContext(xTrace)
    trace := fmt.Sprintf("projects/%s/traces/%s", projectID, traceID)

    warning := fmt.Sprintf(`{"trace":"%s","spanId":"%s", "severity":"WARNING","name":"Andy","age":45}`, trace, spanID)
    fmt.Fprintf(os.Stdout, "%s\n", warning)

    message := "Hello"
    w.Write([]byte(message))
}

func main() {
    http.HandleFunc("/", sayHello)
    port := os.Getenv("PORT")
    if port == "" {
        port = "8080"
    }
    log.Fatal(http.ListenAndServe(fmt.Sprintf(":%s", port), nil))
}

Output shown in the Log viewer:

...,
jsonPayload: {
  age:  45   
  name:  "Andy"   
  spanId:  "13076979521824861986"   
  trace:  "projects/glowing-market-234808/traces/e880a38fb5f726216f94548a76a6e474"   
},
severity:  "WARNING",
...

Answer 1

I have solved this by adjusting the program to use logging.googleapis.com/trace in place of trace and logging.googleapis.com/spanId in place of spanId.

    warning := fmt.Sprintf(`{"logging.googleapis.com/trace":"%s","logging.googleapis.com/spanId":"%s", "severity":"WARNING","name":"Andy","age":45}`, trace, spanID)
    fmt.Fprintf(os.Stdout, "%s\n", warning)

It seems that GAE is using the logging agent google-fluentd (a modified version of the fluentd log data colletor.)

See this link for a full explanation. https://cloud.google.com/logging/docs/agent/configuration#special-fields

[update] June 25th, 2019: I've written a Logrus plugin that will help to thread log entries by HTTP request. It's available under on GitHub https://github.com/andyfusniak/stackdriver-gae-logrus-plugin.

[update]] April 3rd, 2020: I've since switched to using Cloud Run and the Logrus plugin appears to work fine with this platform also.