Make app logging available via request log - 13170

[gregw]

Raised in https://code.google.com/p/googleappengine/issues/detail?id=13170

Since migrating to Flexible using Java FROM gcr.io/google_appengine/jetty9-compat:githubheadasync image we noticed the application java logs (from logging.properties loggers) aren't available anymore in 'request_log'.

We can find them in 'app', however in 'app', we miss a lot of metadata: we don't have the request context, no request method, no request path, no request duration, no user agent, no ip address, no response size.
Moreover, when there are multiple log entries within the same request, in the 'app' section, we can't really link them together whereas in request_log they were all linked to their parent request.

Monitoring and debugging using logs was a lot easier and user-friendly with the logs in 'request_log'.

[joakime]

Seems like a bunch of this is already addressed in PR #295 from Issue #231

[gregw]

So the OP on 13170 has given some more information about the issue. Apparently with standard and flexible runtimes, the app logs lines have a link to the corresponding request log entry and the request log entry is displayed with the matching request log entries underneath.

The OP is not seeing this as well with jetty9-compat and not at all with jetty9-compat:githubheadasync.
Interestingly I'm not seeing it at all with my own built jetty9-compat from the current HEAD of master.

@ludoch do we have a tag on the master branch for the current released jetty9-compat image so I can compare?

@ludoch Is there a spec/description/information about how this matching is done? The request log in the console does not appear based on the request log that we generate within the image (raising the question that do we need both?). Is the traceid that is put in the request id used to do this matching? If so, is there an precise place that we are meant to put it in the app log json?

@joakime I'm currently not seeing traceid in the app logs that we generate in either async-support version tested. Can you investigate to see if that is because we've stopped adding it to the app log or if the infrastructure has stopped providing it to our images.

I will investigate why we are not getting any app logs from the master image I have built.

[gregw]

In my deployed master image, I can see traceid within the protoPayload in the request_log, but no app logs are produced, so I can't see if they have that traceid in them or not.

In my deployed async-support images, there is no traceid in the protoPayload in the request_log? Which suggests that it is may not have been provided in the request, which would explain why it is not in the app log, hence it cannot be matched?

[gregw]

@joakime our async-support images are receiving traceids in request headers like:

X-Cloud-Trace-Context: e6434ae4c61a453eda6dc869508c50ce/7290978425029206014;o=1

Yet for the same request, in the console request log I see the traceid reported as only the part before the slash:

traceId: "e6434ae4c61a453eda6dc869508c50ce"

So perhaps we should be stripping the part after the / before logging? The current code is doing some hex digit filtering, but looks complex and needs review

[gregw]

Once we work out exactly how traceid should be handled, I think it may be worthwhile changing where it is calculated, as I think that it is currently recreated for every API call, which calls getTraceID. We should probably determine it once and cache the value. I have a diff, but lets defer that change until we have solved the greater problem

[gregw]

issue replaced by GoogleCloudPlatform/jetty-runtime#4

[erugeri]

Link is 404. Is it a private repo? Thanks!

[meltsufin]

I just made it public. Try now.

[erugeri]

it works, thanks!