Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging using the Google Cloud Logging API #4

Closed
meltsufin opened this issue Sep 7, 2016 · 19 comments
Closed

Logging using the Google Cloud Logging API #4

meltsufin opened this issue Sep 7, 2016 · 19 comments
Assignees

Comments

@meltsufin
Copy link
Member

meltsufin commented Sep 7, 2016

The Google Cloud Logging API or the stdout and stderr should be used to send logs to Stackdriver Logging.

@gregw
Copy link
Contributor

gregw commented Sep 7, 2016

So using the LogEntry.builder means that we can remove the JSON formatting classes?

I assume that there will be no local log file, unless configured in the users logging.properties and all logs will be consumed only by this API by default?

Should we also remove the request log file?

@joakime
Copy link
Contributor

joakime commented Sep 8, 2016

A bit concerned about the com.google.cloud.logging.HttpRequest object and what it shows in its testcase.

The Google Cloud Logging is java.util.logging based, so that means the the minimum server logging support level will be java.util.logging, not the Jetty default of StdErrLog

The setup for Google Cloud Logging API seems to be based on setting up the com.google.cloud.logging.LoggingHandler with the correct authentication and whatnot. (unless its auto initialized by the Google Cloud services layer)

Possible setup options:

  1. Use slf4j-api -> slf4j-jdk14 on the server side,
    • Jetty uses its Slf4jLog implementation
  2. Use JavaUtilLog as the Jetty logger implementation.

In either setup, we would need to:

  • bar server org.slf4j from being used by the application.
  • allow java.util.logging to be used by the application, but prevent the application from replacing, resetting, or removing the root handlers (otherwise this will break the Google Cloud API use)

@joakime
Copy link
Contributor

joakime commented Sep 8, 2016

We need to make sure that the Jetty base image does not use etc/jetty-logging.xml as that is not compatible with both the java.util.logging layer, and the Google Cloud Logging API.

@gregw
Copy link
Contributor

gregw commented Sep 8, 2016

Please consider GoogleCloudPlatform/appengine-java-vm-runtime#282 in new logging design

@meltsufin
Copy link
Member Author

Would it make sense to start out by making sure that the Jetty server log is directed to standard error? Standard out/error should automatically be picked up by Stackdriver Logging.

@joakime
Copy link
Contributor

joakime commented Sep 9, 2016

we would still need java.util.logging, as without it, nothing from the google layers would ever show up in the stackdriver logs without it.

the default jetty StdErrLog is multi-line, which the Stackdriver has had problems with in the past, hence all of the effort to make logging more stable with the json format, etc..

to fix StdErrLog would mean a fork of StdErrLog to something like GoogleStackdriverSystemErrLog just to conform to the limits of the Stackdriver standard out/error support

that effort would be better spent in just implementing the java.util.logging layer properly to Google Cloud Logging.

@meltsufin
Copy link
Member Author

we would still need java.util.logging, as without it, nothing from the google layers would ever show up in the stackdriver logs without it.

What do you have in mind when you say "google layers"?

the default jetty StdErrLog is multi-line, which the Stackdriver has had problems with in the past, hence all of the effort to make logging more stable with the json format, etc..

There's work going on to automatically detect multi-line java stack traces in the logs. Is there anything else that's potentially multi-line in the Jetty server logs?

to fix StdErrLog would mean a fork of StdErrLog to something like GoogleStackdriverSystemErrLog just to conform to the limits of the Stackdriver standard out/error support

What limits are you referring to?

that effort would be better spent in just implementing the java.util.logging layer properly to Google Cloud Logging.

There are java.util.logging handlers in the Logging API. Beyond those handlers, what would our logging layer need to do?

@joakime
Copy link
Contributor

joakime commented Sep 9, 2016

Multiline output it very common, and not just for stack traces.

JSP produces multi-line, JSR365 (javax.websocket) does, most datasources, Jersey, Spring, and even the javax.servlet API does too (example: exceptions during startup / deployment are collected into a multi exception which is a single logging event that reports the main deployment concern, and then lists each deployment failure and possible stacktrace for that failure as well)

This is the limits that we refer to with the naive stackdriver parsing of System.err and System.out.

When I say "google layers" I mean any of the google or gcloud classes that operate on the server (or the webapp) would produce no output if using Jetty's default StdErrLog setup (which outputs only Jetty logging events to System.err)

So, we have top level options, and multiple sub-options.

Option 1: Standard Jetty Logging

This would be Jetty setup for StdErrLog and without etc/jetty-logging.xml.

  • Only Jetty logging events at INFO level are produced on System.err.
  • No other output is produced.
  • Nothing on System.out
  • Nothing from java.util.logging
  • Application logging does not exist and is not configured
  • No JSP logging events
  • No 3rd party events
  • This setup is known to produce horrible results in the console loggers

Option 2: Jetty uses java.util.logging

Technique A: Jetty uses its JavaUtilLog implementation

  • Server side would setup a Handler to output its events somewhere
  • Application logging for java.util.logging works
  • Application configuration of levels works
  • Application configuration of custom j.u.l handlers work
  • Google APIs / classes can participate in logging
  • JSP logging events supported
  • Limited 3rd party support (as we are stuck on java.util.logging only)

Technique B: Jetty uses its Slf4jLog implementation

  • Server side would setup a Handler to output its events somewhere
  • Application logging for java.util.logging works
  • Application configuration of levels works
  • Application configuration of custom j.u.l handlers work
  • Google APIs / classes can participate in logging
  • JSP logging events supported
  • Full 3rd party logging support (as we can now support any logging events from anywhere: system, server classloader, jndi, applications, etc..)

In either technique, since we are using java.util.logging now, using the Google Cloud Logging API is attainable, and preferred over the System.out and System.err parsing.

However, as noted before, we still need to be careful to not allow the application to remove/reset/change the Google Cloud Logging Handlers at the java.util.logging root context. (configuring the Google Cloud Logging, such as setting the named logger levels is very much supported)

Using the Google Cloud Logging API also means we have preliminary support for associating the HttpRequest (via the traceid or similar information), something that the Stackdriver support for system.out and system.err has historically never been able to do.

@gregw
Copy link
Contributor

gregw commented Sep 9, 2016

For the sake of clarity, I think I should prepare a PR for Joakim's Option 1: all the logging in jetty stripped back to the minimal: no request log and stderr log for the container. I'll add a simple test webapp that generates errors and/or causes errors within the container and we can see how the logging looks in the cloud console.

We can then see exactly what needs to be fixed and that will guide us in choosing between status quo, Technique A, Technique B, logging API or something else.

@gregw gregw self-assigned this Sep 9, 2016
@meltsufin
Copy link
Member Author

Yes, sounds good!

gregw added a commit to jetty-project/gcloud-jetty-runtime that referenced this issue Sep 14, 2016
gregw added a commit to jetty-project/gcloud-jetty-runtime that referenced this issue Sep 14, 2016
gregw added a commit to jetty-project/gcloud-jetty-runtime that referenced this issue Sep 14, 2016
gregw added a commit to jetty-project/gcloud-jetty-runtime that referenced this issue Sep 14, 2016
deleted jetty-loggin.properties file
gregw added a commit that referenced this issue Sep 15, 2016
* Issue #4 Revert to default jetty logging

* Issue #4 Revert to default jetty logging

deleted jetty-loggin.properties file
@gregw
Copy link
Contributor

gregw commented Sep 16, 2016

@meltsufin I've been looking at the cloud logging API and have a number of questions: about it should be used in the Flex environment; and how we would like to set it up.

So firstly, we need to know how traceid should be added to a LogEntry? I assume it is something like entry.addLabel("traceid",traceid); but it would be good to have this confirmed (and in any documentation of the contract that is being developed).

Having added a traceid, it is not clear if that is sufficient, or if we should also add a HttpRequest to the log entry? While this can be done, I'm hoping that it is not necessary, as it appears to be redundant information with what is available via the trace id?

So is there somebody we can talk to who can assist with these questions? if not, we can just experiment, but as the console is a moving target that may not be productive.

Eitherway, we are going to need to add scoping information ( traceid and/or httprequest ) to every LogEntry generated. This is easy enough to do, but there are many options for doing so:

  1. We could write a Jetty specific log sink, that has a ThreadLocal scope, so that all jetty logs would be sent to the cloud API with the addition of scope information. Currently the compat image has listeners that maintain a logging scope, so we would have to do a similar listener in jetty-runtime that maintains request specific logging scope. However, this would only work for jetty logging and we would not be able to plumb other logging into it.
  2. The cloud logging comes with a java.util.logging.Handler(JUL), which would be a more portable way to plug into the cloud logging. We would need to extend the libraries handler so we could override the entryFor method to implement a request scope as above. Jetty logging would then be piped into (JUL). Any other application logging frameworks could also be optionally piped to JUL.
  3. The need for a scoping traceid and/or HttpRequest is probably sufficiently generic that would could make a pull request back to google-cloud-java. This would put the ThreadLocal code into the API code, but we would still need to create listeners to maintain the request scope.

I believe we should initially develop option 2., but with the intention of donating the log context code back to the API project once we happy it is fit for purpose.

Finally, I assume we should be doing this logging using the async writer option?

@meltsufin
Copy link
Member Author

The trace id should be read from the x-cloud-trace-context HTTP header and provided in the traceId attribute of the log message.
The general structure of the log message should be something like this:

{
    "severity" : <severity code>,
    "timestamp": <timestamp>,
    "message": <log message>,
            "sourceLocation": {
        "filename": <filename>
        "line": <line number>
            }
           "serviceContext": {
                "service": <service name>
                "version": <version identifier, e.g. Git version SHA>
            }
    "traceId" : <trace id>
}

@joakime
Copy link
Contributor

joakime commented Sep 16, 2016

@meltsufin i think greg is asking where to put the traceId in the LogEntry object (from the Google Cloud Logging API).

See: https://github.com/GoogleCloudPlatform/google-cloud-java/blob/master/google-cloud-logging/src/main/java/com/google/cloud/logging/LogEntry.java

From my reading of the API, I think greg could use the LogEntry.insertId(String)

@meltsufin
Copy link
Member Author

I would think entry.addLabel() should work as Greg mentioned, but insertId() looks promising too. I guess we need to experiment with these.

@gregw
Copy link
Contributor

gregw commented Sep 16, 2016

OK I will experiment... my reading of insertId is that is a unique id for the log entry, which is not the traceid as that is shared by many log entries.

I hoping that by the lack of response regarding HttpRequest, that means we don't need to complete that object and associate it with LogEntries.... but I guess experimentation will reveal that.

standby...

@gregw
Copy link
Contributor

gregw commented Sep 21, 2016

I'm looking at testing the google logging APIs and the first thing I've noticed is how large the client library and their dependencies are! Over 21MB of jars in the dependencies listed below.

I'm a bit concerned that this represents significant bloat in every image just to do logging! I'm sure the size and scope of these dependencies can be trimmed with maven exclusions, but such an approach is inherently fragile. We also will need to undertake extra efforts to sanitize the container classpath, specially as dependencies such as commons logging are included which have been historically problematic with classloading hiding.

I guess we could use shading and hope that static dependency resolution will be sufficient?

Anyway, just wanted to raise the issue of size early, as the current approach of pulling logs from a known file has the benefit of having the logging code external to the images. Making the images responsible for their own logging is going to result in lots of duplicate code in every instance.

[INFO] \- com.google.cloud:google-cloud:jar:0.3.0:compile
[INFO]    +- com.google.cloud:google-cloud-bigquery:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-bigquery:jar:v2-rev303-1.22.0:compile
[INFO]    |     \- com.google.api-client:google-api-client:jar:1.22.0:compile
[INFO]    +- com.google.cloud:google-cloud-compute:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-compute:jar:v1-rev103-1.21.0:compile
[INFO]    +- com.google.cloud:google-cloud-core:jar:0.3.0:compile
[INFO]    |  +- com.google.auth:google-auth-library-credentials:jar:0.3.1:compile
[INFO]    |  +- com.google.auth:google-auth-library-oauth2-http:jar:0.3.1:compile
[INFO]    |  |  \- com.google.http-client:google-http-client-jackson2:jar:1.19.0:compile
[INFO]    |  |     \- com.fasterxml.jackson.core:jackson-core:jar:2.1.3:compile
[INFO]    |  +- com.google.http-client:google-http-client:jar:1.21.0:compile
[INFO]    |  |  +- com.google.code.findbugs:jsr305:jar:1.3.9:compile
[INFO]    |  |  \- org.apache.httpcomponents:httpclient:jar:4.0.1:compile
[INFO]    |  |     +- org.apache.httpcomponents:httpcore:jar:4.0.1:compile
[INFO]    |  |     +- commons-logging:commons-logging:jar:1.1.1:compile
[INFO]    |  |     \- commons-codec:commons-codec:jar:1.3:compile
[INFO]    |  +- com.google.oauth-client:google-oauth-client:jar:1.21.0:compile
[INFO]    |  +- com.google.guava:guava:jar:19.0:compile
[INFO]    |  +- com.google.api-client:google-api-client-appengine:jar:1.21.0:compile
[INFO]    |  |  +- com.google.oauth-client:google-oauth-client-appengine:jar:1.21.0:compile
[INFO]    |  |  |  +- com.google.oauth-client:google-oauth-client-servlet:jar:1.21.0:compile
[INFO]    |  |  |  |  \- com.google.http-client:google-http-client-jdo:jar:1.21.0:compile
[INFO]    |  |  |  \- javax.servlet:servlet-api:jar:2.5:provided
[INFO]    |  |  +- com.google.api-client:google-api-client-servlet:jar:1.21.0:compile
[INFO]    |  |  |  \- javax.jdo:jdo2-api:jar:2.3-eb:compile
[INFO]    |  |  |     \- javax.transaction:transaction-api:jar:1.1:compile
[INFO]    |  |  \- com.google.http-client:google-http-client-appengine:jar:1.21.0:compile
[INFO]    |  +- com.google.http-client:google-http-client-jackson:jar:1.21.0:compile
[INFO]    |  |  \- org.codehaus.jackson:jackson-core-asl:jar:1.9.11:compile
[INFO]    |  +- joda-time:joda-time:jar:2.9.2:compile
[INFO]    |  +- org.json:json:jar:20151123:compile
[INFO]    |  +- com.google.protobuf:protobuf-java:jar:3.0.0-beta-3:compile
[INFO]    |  +- com.google.api:gax:jar:0.0.16:compile
[INFO]    |  |  \- com.google.inject:guice:jar:4.0:compile
[INFO]    |  |     +- javax.inject:javax.inject:jar:1:compile
[INFO]    |  |     \- aopalliance:aopalliance:jar:1.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-common-protos:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-datastore:jar:0.3.0:compile
[INFO]    |  +- com.google.cloud.datastore:datastore-v1-protos:jar:1.0.1:compile
[INFO]    |  \- com.google.cloud.datastore:datastore-v1-proto-client:jar:1.1.0:compile
[INFO]    |     \- com.google.http-client:google-http-client-protobuf:jar:1.20.0:compile
[INFO]    +- com.google.cloud:google-cloud-dns:jar:0.3.0:compile
[INFO]    |  +- com.google.apis:google-api-services-dns:jar:v1-rev7-1.21.0:compile
[INFO]    |  \- commons-fileupload:commons-fileupload:jar:1.3.1:compile
[INFO]    |     \- commons-io:commons-io:jar:2.2:compile
[INFO]    +- com.google.cloud:google-cloud-errorreporting:jar:0.3.0:compile
[INFO]    |  +- io.netty:netty-tcnative-boringssl-static:jar:1.1.33.Fork17:compile
[INFO]    |  +- com.google.api.grpc:grpc-google-devtools-clouderrorreporting-v1beta1:jar:0.0.7:compile
[INFO]    |  +- io.grpc:grpc-all:jar:0.15.0:compile
[INFO]    |  |  +- io.grpc:grpc-auth:jar:0.15.0:compile
[INFO]    |  |  +- io.grpc:grpc-netty:jar:0.15.0:compile
[INFO]    |  |  |  \- io.netty:netty-codec-http2:jar:4.1.1.Final:compile (version selected from constraint [4.1.1.Final,4.1.1.Final])
[INFO]    |  |  |     +- io.netty:netty-codec-http:jar:4.1.1.Final:compile
[INFO]    |  |  |     |  \- io.netty:netty-codec:jar:4.1.1.Final:compile
[INFO]    |  |  |     \- io.netty:netty-handler:jar:4.1.1.Final:compile
[INFO]    |  |  |        +- io.netty:netty-buffer:jar:4.1.1.Final:compile
[INFO]    |  |  |        |  \- io.netty:netty-common:jar:4.1.1.Final:compile
[INFO]    |  |  |        \- io.netty:netty-transport:jar:4.1.1.Final:compile
[INFO]    |  |  |           \- io.netty:netty-resolver:jar:4.1.1.Final:compile
[INFO]    |  |  +- io.grpc:grpc-okhttp:jar:0.15.0:compile
[INFO]    |  |  |  +- com.squareup.okio:okio:jar:1.6.0:compile
[INFO]    |  |  |  \- com.squareup.okhttp:okhttp:jar:2.5.0:compile
[INFO]    |  |  +- io.grpc:grpc-protobuf-nano:jar:0.15.0:compile
[INFO]    |  |  |  \- com.google.protobuf.nano:protobuf-javanano:jar:3.0.0-alpha-5:compile
[INFO]    |  |  +- io.grpc:grpc-stub:jar:0.15.0:compile
[INFO]    |  |  +- io.grpc:grpc-protobuf:jar:0.15.0:compile
[INFO]    |  |  |  \- com.google.protobuf:protobuf-java-util:jar:3.0.0-beta-3:compile
[INFO]    |  |  |     \- com.google.code.gson:gson:jar:2.3:compile
[INFO]    |  |  +- io.grpc:grpc-protobuf-lite:jar:0.15.0:compile
[INFO]    |  |  \- io.grpc:grpc-core:jar:0.15.0:compile (version selected from constraint [0.15.0,0.15.0])
[INFO]    |  \- com.google.auto.value:auto-value:jar:1.1:compile
[INFO]    +- com.google.cloud:google-cloud-language:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-cloud-language-v1beta1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-logging:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-logging-v2:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-pubsub:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-pubsub-v1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-resourcemanager:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-cloudresourcemanager:jar:v1beta1-rev10-1.21.0:compile
[INFO]    +- com.google.cloud:google-cloud-speech:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-cloud-speech-v1beta1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-storage:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-storage:jar:v1-rev62-1.21.0:compile
[INFO]    +- com.google.cloud:google-cloud-trace:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-devtools-cloudtrace-v1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-translate:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-translate:jar:v2-rev47-1.22.0:compile
[INFO]    \- com.google.cloud:google-cloud-vision:jar:0.3.0:compile
[INFO]       \- com.google.api.grpc:grpc-google-cloud-vision-v1:jar:0.0.7:compile

@joakime
Copy link
Contributor

joakime commented Sep 21, 2016

21MB is a pittance in today's world. That's only 30% of the size of your average web page today! (60MB is the average amount of content a single web page downloads in 2016)

That being said, there's seems to be a few obvious things in that list of dependencies that really are not needed to do logging.

My take on not needed deps (for features in google cloud that are not logging):

[INFO]    +- com.google.cloud:google-cloud-bigquery:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-bigquery:jar:v2-rev303-1.22.0:compile
[INFO]    |     \- com.google.api-client:google-api-client:jar:1.22.0:compile
[INFO]    +- com.google.cloud:google-cloud-compute:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-compute:jar:v1-rev103-1.21.0:compile
[INFO]    +- com.google.cloud:google-cloud-datastore:jar:0.3.0:compile
[INFO]    |  +- com.google.cloud.datastore:datastore-v1-protos:jar:1.0.1:compile
[INFO]    |  \- com.google.cloud.datastore:datastore-v1-proto-client:jar:1.1.0:compile
[INFO]    |     \- com.google.http-client:google-http-client-protobuf:jar:1.20.0:compile
[INFO]    +- com.google.cloud:google-cloud-dns:jar:0.3.0:compile
[INFO]    |  +- com.google.apis:google-api-services-dns:jar:v1-rev7-1.21.0:compile
[INFO]    |  \- commons-fileupload:commons-fileupload:jar:1.3.1:compile
[INFO]    |     \- commons-io:commons-io:jar:2.2:compile
[INFO]    +- com.google.cloud:google-cloud-speech:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-cloud-speech-v1beta1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-storage:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-storage:jar:v1-rev62-1.21.0:compile
[INFO]    +- com.google.cloud:google-cloud-trace:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-devtools-cloudtrace-v1:jar:0.0.7:compile
[INFO]    +- com.google.cloud:google-cloud-translate:jar:0.3.0:compile
[INFO]    |  \- com.google.apis:google-api-services-translate:jar:v2-rev47-1.22.0:compile
[INFO]    \- com.google.cloud:google-cloud-vision:jar:0.3.0:compile
[INFO]       \- com.google.api.grpc:grpc-google-cloud-vision-v1:jar:0.0.7:compile

and two that feel like they are possible not needed:

[INFO]    +- com.google.cloud:google-cloud-language:jar:0.3.0:compile
[INFO]    |  \- com.google.api.grpc:grpc-google-cloud-language-v1beta1:jar:0.0.7:compile

gregw added a commit that referenced this issue Sep 28, 2016
remove XML reference
gregw added a commit that referenced this issue Sep 28, 2016
* Issue #4 removed unused JUL file

* Issue #4 removed unused JUL file

remove XML reference
@bbassingthwaite
Copy link

@gregw Did you ever figure out where to put the traceId in your LogEntry? Thanks!

@meltsufin
Copy link
Member Author

Fxed in #81

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants