Missing Documentation for per-request Cloud Logging in Flex.

[danjacques]

I'm converting an AppEngine classic environment service over to AppEngine Flex environment. One of the services that I'm trying to port is logging. In Classic, one uses the logger as follows:

import "google.golang.org/appengine/log"
log.Infof(ctx, "Doing something.")
log.Errorf(ctx, "Something went wrong!")

When viewing AppEngine's logs, these logs will be grouped under a request, like:

HTTP 200 /
\- (I) Doing something.
\- (E) Something went wrong!

In Flex environment, however, there are multiple ways to log. The simplest is to use os.Stderr to log to STDERR; however, this just shows up as a series of top-level logs, not related by HTTP request. One is better off using the Cloud Logging package. However, I can't seem to find the right combination of settings to cause logs emitted with this package to group by request.

The Logger is very configurable, and documentation in the package suggests that leaving fields as default will automatically detect and populate them, and looking at the logging UI, this seems true to some extent. However, the default configuration in a Flex environment seems to still not group logs by request.

I stumbled upon an issue that suggests that it is possible, and that populating the HTTPRequest field and/or the appengine.googleapis.com/trace_id label will accomplish this, but it doesn't seem to be working for me.

With respect to this repository, I'd like to request an example be included in the Go documentation detailing how to setup a logger instance that will operate in a Flex environment in a manner similar to AppEngine Classic. Specifically, how should one populate:

• LogID
• HTTPRequest
• MonitoredResource
• Labels
• Payload

[jba]

Can you try this:

1. The "parent" log entry must have httpRequest.requestUrl populated (i.e., it should be a HTTP request-style entry)
2. The "child" log entry must be in a different log stream (logName) than the parent, in the same project, and have the exact same resource.type and resource.labels values
3. The child entry's timestamp must be within the time interval covered by the parent request (i.e., older than parent.timestamp, and newer than parent.timestamp - parent.httpRequest.latency) -- this assumes that the timestamp of the "request" entry is the end time, not the start time
4. The trace field must be populated in all of the entries and match exactly

Please let us know whether that works or doesn't.

[danjacques]

Thanks for the info! After some tweaking, I have gotten HTTP request logs to group together:

client, _ := logging.NewClient(context.Background(), probedGCEProjectID)
logger := client.Logger(
	"stderr",
	logging.CommonLabels(map[string]string{
		"appengine.googleapis.com/trace_id": extractTraceIDFromHeader(req),
	}),
	logging.CommonResource(&mrpb.MonitoredResource{
		Labels: map[string]string{
			"module_id":  probedGCEServiceName,
			"project_id": probedGCEProjectID,
			"version_id": probedGCEVersionName,
		},
		Type: "gae_app",
	}),
)

This is all very manual. The default MonitoredResource uses different labels ("project_id", "instance_id", "zone") and type ("gce_instance"). The trace ID has to be parsed from the X-Cloud-Trace-Context HTTP header. Am I missing a helper library, or is this WAI?

I also note that the overall request's severity icon, which is usually the highest child log severity, is not being updated based on child contents. Is there some additional information that I can add to make this work?

[jba]

Glad you got it to work (mostly). I've contacted the log team internally about the severity.

/cc @rakyll for propagating trace.
/cc @pongad @zombiezen @adams-sarah for whether it makes sense to simplify this.

[danjacques]

Any update on this? I'd like to solve this if possible, since the lack of top-level messages is a regression from my Managed VM code. An example of what I'm experiencing is:

The code that sets up logging is here if that is useful.

Filtering logs by minimum level also doesn't seem to be working, for what I'm assuming right now is the same reason. Thoughts?

[zombiezen]

@danjacques: Thanks for the feedback. We're aware that this is a painpoint and we're looking into how to simplify this common case. The difficulty in creating a simple API is that we want stderr to be usable (since many things log there and it's the easiest thing that shows up in GKE) and we don't want to duplicate log messages (logging to stderr and to Stackdriver with structured severity would duplicate).

In the nearer term, we know that monitored resource auto-detection could be better. Subscribe to #650 for updates.

[danjacques]

Agreed on API, and it would be interesting to see where you go with that.

WRT nearer term and resource detection - I'm 100% fine with manually entering the resource fields. Is there a field that I'm missing that would cause the top-level log entries to display and be recognized at the level of their highest sub-log? Is there an example of a application that uses cloud logging and achieves this effect?

The way I see things, I'm either not doing this properly, or this feature is not supported at the moment. Can you clarify which is the case?

[zombiezen]

We would have to do more investigation to determine which of those is the case. AFAIK right now, you are using the API properly. This may be a logs UI issue.

[danjacques]

OK cool, thanks for the information. Please let me know if there's anything that I can do to help test!

ATM this is a non-blocking but pretty obvious regression from the GAE environment. I'm migrating from Managed VM (deprecated) to Flex (new hotness) and this specifically stands out as a shortcoming.

[vadimsht]

Note that constructing Logger per request (to have trace_id in CommonLabels) leads to a rapid goroutine (and memory) leaks, since Client "remembers" all Loggers until it itself is closed. In particular, goroutines get blocked on https://github.com/GoogleCloudPlatform/google-cloud-go/blob/d30a909c68aade42fadac37751a1ba349dac77e4/logging/logging.go#L398

So either requests must reuse Loggers, or they must not share Clients. (Or it's a bug and it should be fixed...).

[derekperkins]

@danjacques I got logging working on Flex pretty much the same way it used to work. My implementation details are here: #448 (comment)

[jba]

As of 7f7e4d3 the logging client automatically sets Entry.Trace to the value of the X-Cloud-Trace-Context header if it isn't already set.

[jba]

Please let me know if https://code-review.googlesource.com/c/gocloud/+/31310 explains this clearly.

With that addition to the docs, I'm going to close this issue. I don't think there's anything more to be done with this client.

[derekperkins]

Parent entries must have HTTPRequest.Request populated

@jba Is that strictly necessary? We're moving from a request driven task queue to a long-running worker system, and I would still like to group each individual unit of work by a unique trace id. Is that not possible without creating an http request object?

[jba]

@derekperkins You do need the request URL to enable grouping, but not the whole request, and the URL doesn't have to be real:

parentLogger.Log(logging.Entry{
        HTTPRequest: &logging.HTTPRequest{Request: &http.Request{
            URL: &url.URL{Path: "dummy/path"},
        }},
        Payload: "whatever",
        Trace:   traceID,
    })

Non-request log entries with the same trace ID will group with this one. The text payload won't be visible on the log line, but is visible once you click the entry to open it.