Stackdriver logging #68 #81

gregw · 2016-11-30T23:35:32Z

The implementation of #68 is now working with the latest google-cloud-logging API supporting the changes we requested.

Currently we still have threadlocal loop protection, which I will now test if it is still needed.

Updated to latest gcloud API removed copied LoggingHandlers removed instanceid from monitored resource

gregw · 2016-12-01T00:37:19Z

Note that even with the threadlocal protection, turning logging to FINE globally is preventing deployment, but without an indication why. It may just be load and the instance takes too long to respond.

Note that netty appears to have it's own internal SLF4J logger impl that is correctly getting logged, but is taking its FINE setting from the global setting rather than an io.netty.level=INFO setting?

Selecting turning on FINE logging for some components does work.

gregw · 2016-12-01T07:13:12Z

I have worked out why deployment fails when .level=FINE is set, it is because of an OOM exception. This is probably caused by the vast number of logs from netty, which JUL logging does not appear to be able to suppress. There are many LogRecords with:

loggerName=io.grpc.netty.NettyClientHandler 
SourceClassName=io.netty.util.internal.logging.Slf4JLogger 
SourceClassMethod=debug

Even thought the logging configuration is:

.level = FINE
io.netty.level = INFO
io.gcr.level = INFO

So I may put in an explicit filter to remove those netty debug records?

Also we can consider if we want to monitor low memory and stop generating verbose logs?

thoughts?

gregw · 2016-12-01T21:26:37Z

@meltsufin updated to use the same trace id label as nginx log

meltsufin · 2016-12-05T17:48:25Z

@gregw Even at the default logging level, it looks like we get two log messages from grpc for each log message that we send. I think during the actual remote logging, we should be suppressing all logs from google-cloud-logging. Is this feasible?

Dec 05, 2016 5:22:39 PM org.eclipse.jetty.server.Server doStart INFO: Started @4262ms
Dec 05, 2016 5:27:14 PM com.google.meltsufin.test.MainServletFlex doGet SEVERE: severe level log using JUL
Dec 05, 2016 5:27:14 PM com.google.meltsufin.test.MainServletFlex doGet INFO: info level log using JUL
Dec 05, 2016 5:27:15 PM org.eclipse.jetty.server.handler.ContextHandler$Context log INFO: test_flex: Testing Servlet.log method in Flex.
Dec 05, 2016 5:27:16 PM io.grpc.internal.ManagedChannelImpl <init> INFO: [ManagedChannelImpl@725cba47] Created with target logging.googleapis.com:443
Dec 05, 2016 5:27:16 PM io.grpc.internal.ManagedChannelImpl <init> INFO: [ManagedChannelImpl@346c067c] Created with target logging.googleapis.com:443
Dec 05, 2016 5:27:16 PM io.grpc.internal.ManagedChannelImpl <init> INFO: [ManagedChannelImpl@9329855] Created with target logging.googleapis.com:443
Dec 05, 2016 5:27:18 PM io.grpc.internal.ManagedChannelImpl maybeTerminateChannel INFO: [ManagedChannelImpl@725cba47] Terminated
Dec 05, 2016 5:27:18 PM io.grpc.internal.ManagedChannelImpl maybeTerminateChannel INFO: [ManagedChannelImpl@346c067c] Terminated
Dec 05, 2016 5:27:18 PM io.grpc.internal.ManagedChannelImpl maybeTerminateChannel INFO: [ManagedChannelImpl@9329855] Terminated

meltsufin · 2016-12-05T17:51:55Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/RequestContextScope.java

+  static final Logger logger = Logger.getLogger(RequestContextScope.class.getName());
+
+  private static final String X_CLOUD_TRACE = "x-cloud-trace-context";
+  private static final ThreadLocal<String> traceid = new ThreadLocal<>();


Please use camel case traceId.

meltsufin · 2016-12-05T17:56:41Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/RequestContextScope.java

+          if (id != null) {
+            int slash = id.indexOf('/');
+            if (slash >= 0) {
+              id = id.substring(0, slash);


Are we just dropping the span id? I'm not sure this is what we're supposed to be doing.

I'm also not sure. The compat version we inherited did a scan for the first non hex character and split there, so I just simplified and inherited that behaviour. Can you investigate if we can leave it in.

I will find out.

Got a response from the logging team indicating that we should only log the trace id without the span id. So, this is good.

meltsufin · 2016-12-05T18:01:00Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/RequestContextScope.java

+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+public class RequestContextScope implements ContextHandler.ContextScopeListener {


Can you add some javadocs to explain the purpose of the class?

meltsufin · 2016-12-05T18:10:55Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/RequestContextScope.java

+   * @param traceid The trace ID
+   * @param runnable the runnable
+   */
+  public static void runWith(String traceid, Runnable runnable) {


Is this method used somewhere, or just provided as a utility?

Just a utility that I thought we might need. I will drop for now as it will be trivial to readd if there ever is a need.

meltsufin · 2016-12-05T20:09:32Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/TracingLogHandler.java

+  @Override
+  public synchronized void publish(LogRecord record) {
+    // check we are not already flushing logs
+    if (Boolean.TRUE.equals(flushing.get())) {


It's a matter of style, but I would save a line and write it as:

// check we are not already flushing logs if (!Boolean.TRUE.equals(flushing.get())) { super.publish(record); }

meltsufin · 2016-12-05T20:16:25Z

jetty9-base/src/main/java/com/google/cloud/runtimes/jetty9/TracingLogHandler.java

+   */
+  public TracingLogHandler(String logName, LoggingOptions options, MonitoredResource resource) {
+    super(logName, options, resource);
+    monitored = MonitoredResource.newBuilder("gae_app")


You're sort of overwriting the resource that is passed in here. Maybe create the resource only in the no-arg constructor instead?

meltsufin · 2016-12-05T20:22:11Z

jetty9-base/src/main/jetty-base/etc/java-util-logging.properties

@@ -0,0 +1,9 @@
+.level = INFO
+io.netty.level = INFO
+io.gcr.level = INFO


Why do we need to set log levels for netty and gcr here if we have the flushing guard in TracingLogHandler.publish()?

I added it because netty logs from background threads. However there is still the issue that not all of netty's log mechanism appears not to see these settings anyway, so perhaps we just need an explicit filter in the publish method?

How would an explicit filter work so that it deals with the Netty background threads?

Currently the approach taken by the gcloud-java client library is to have fixed list of known log names that it explicitly scans for and removes the stackdriver handler from.

This is the approach that should also stop looping, but it not.

The same list could simply be applied within the log handler and any logs from those handlers would be discarded. This list could either be a complete list, in which case we would not need either the threadlocal approach nor the handler deregistration.

Alternately the list can just be limited to the loggers that are not reacting to the logging properties configuration.

Currently I don't like any solution. My preference would be to have no filtering and just loop protection. Overly verbose logging should be handled gracefully (with discarded logs and a message to that effect) and then the user can just configure logging to only log what they are interested in.

So I need to investigate why those netty classes are ignoring the properties file.

Code cleanups after review

gregw · 2016-12-05T23:20:53Z

@meltsufin this is still a work in progress as I would like to:

Find a better filter mechanism for netty background logging.
Profile memory usage
Log to StdErr if we can detect problem with logging eg OOM or low memory?
find out if traceId should be trimmed or not
Merge in a fix for Use jetty 9.4 property configuration mechanism #83

gregw · 2016-12-06T02:27:33Z

@meltsufin I measured memory usage more accurately to be around 4KB per log. I have raised googleapis/google-cloud-java#1449 to see if that can be reduced and/or some limits put on the size of the queued logs.

meltsufin · 2016-12-06T21:37:20Z

We're really blocking on 2 things:

LogHandler being re-entrant: LoggingHandler is re-entrant when logging FINE googleapis/google-cloud-java#1386
High memory consumption of the logging library: Large memory usage by gcloud-logging API. googleapis/google-cloud-java#1449

meltsufin · 2016-12-14T14:53:20Z

Noting that a related issue was filed against GRPC: grpc/grpc-java#2515

Removed stackdriver logging, so this just configures JUL to capture the traceid and log to stderr

gregw · 2017-04-20T22:18:06Z

@meltsufin The https://github.com/GoogleCloudPlatform/jetty-runtime/tree/master-68-docker-args branch is based on this branch and now includes:

changes to work with latest openjdk-runtime (not released) entry point
tests to check that logging classes are hidden from the webapp
README updated to suggest that sun.net and io.grpc.netty. logging be kept at INFO when using stackdriver

The #41 branch for sessions is based of this new branch.

meltsufin · 2017-04-21T14:09:59Z

@gregw you can merge the master-68-docker-args branch into here.
@aslo can you do a release of openjdk-runtime?

aslo · 2017-04-21T15:09:09Z

New image has been released and is available at gcr.io/google-appengine/openjdk:8-2017-04-21_15_02.

I just opened #157 to bump the base image.

gregw · 2017-04-23T23:32:07Z

@meltsufin I'm currently seeing problems with the classloading tests when I run them. These tests were passing, but are now failing, so I need to investigate a bit more. Probably wont get a chance until Tuesday.

meltsufin

I think we're ready to update the GaeFlexLoggingEnhancer references.

meltsufin · 2017-04-26T13:44:19Z

jetty9-base/src/main/jetty-base/modules/slf4j-api.mod

+Provides SLF4J API.  Requires a slf4j implementation (eg slf4j-simple-impl)
+otherwise a noop implementation is used.
+
+TODO Remove once jetty-9.5.4 released


Did you mean jetty-9.4.5?

meltsufin · 2017-04-26T14:37:20Z

pom.xml

@@ -29,13 +29,14 @@
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
    <maven.build.timestamp.format>yyyy-MM-dd-HH-mm</maven.build.timestamp.format>
+    <gcloud.api.version>0.13.0-beta</gcloud.api.version>


0.17.1 is out now

OK, on it now. Hopefully ready tomorrow (as will a 9.4.5 release with simpler class hiding)

@meltsufin I can't see a 0.17.1 in maven central. But I can see a 1.0.0! http://repo2.maven.org/maven2/com/google/cloud/google-cloud-logging/

Ah ok, even better! :)

@meltsufin I just tried 1.0.0, but it failed with this issue: googleapis/google-cloud-java#1994

Fix has been merged, please retry when you get a chance.

…ime into master-68

meltsufin · 2017-05-09T20:58:57Z

README.md

+com.google.cloud.logging.LoggingHandler.level=FINE
+com.google.cloud.logging.LoggingHandler.log=gae_app.log
+com.google.cloud.logging.LoggingHandler.resourceType=gae_app
+com.google.cloud.logging.LoggingHandler.enhancers=com.google.cloud.logging.GaeFlexLoggingEnhancer


It should be TraceLoggingEnhancer now.

If this is running on GAE Flex, you no longer need to specify the resourceType and enhancers. it gets auto-detected based on the GAE_INSTANCE env var. TraceLoggingEnhancer is automatically added.

Great! Thanks Jisha!

meltsufin · 2017-05-09T21:02:06Z

tests/test-war-smoke/src/main/webapp/WEB-INF/logging.properties

+sun.net.level=INFO
+
+handlers=com.google.cloud.logging.LoggingHandler
+com.google.cloud.logging.LoggingHandler.level=FINE


Should the TraceLoggingEnhancer be here?

No. It is now automatic and I have updated the README.

gregw · 2017-05-10T11:36:08Z

@meltsufin while this PR is looking close to ready, @janbartel is having problems merging with her session work because of dependency strangeness in google-cloud-java. See googleapis/google-cloud-java#2050
We are trying to manually correct the dependencies.

bmenasha · 2017-05-16T22:40:05Z

Thank you for your hard work on this Greg and Mike! This makes the Flexible experience much better.

meltsufin · 2017-05-23T15:55:04Z

@gregw Something in this PR broke our integration with the cloud debugger. I suspect it's the class hiding. Investigating...

gregw added 10 commits November 9, 2016 15:13

Issue #68 added request context scope

e748691

Issue #68 added request context scope

f6d1488

Issue #68 added skeleton Logging Handler

2ad99b0

Issue #68 work in progress

30b3e80

Issue #68 work in progress

7ec8ff3

working implementation using a threadlocal to stop looping

1d3ca8a

Merge remote-tracking branch 'origin/master' into master-68

3b5c3a7

Issue #68 update to latest google-cloud-java LoggingHandler

aa81e13

Merge branch 'master' into master-68

141bae3

Issue #68

48df809

Updated to latest gcloud API removed copied LoggingHandlers removed instanceid from monitored resource

gregw added 2 commits December 2, 2016 08:19

Issue #68 Use same labels as nginx

1e38c88

Merge branch 'master' into master-68

f19135d

meltsufin suggested changes Dec 5, 2016

View reviewed changes

gregw added 2 commits December 6, 2016 09:42

Merge branch 'master' into master-68

4a0886e

Issue #68

df430d6

Code cleanups after review

gregw added 4 commits December 7, 2016 08:41

Merge branch 'master' into master-68

fe02767

Merge branch 'master' into master-68

2005182

Merge branch 'master' into master-68

3d2baec

Merge branch 'master' into master-68

563140f

gregw mentioned this pull request Dec 22, 2016

How to specify JUL logging configuration properties file #101

Open

gregw added 2 commits December 23, 2016 15:10

Merge branch 'master' into master-68

3206abf

Issue #68

9de4fc1

Removed stackdriver logging, so this just configures JUL to capture the traceid and log to stderr

Updated to lasted openjdk-runtime

4754bc4

fixed classloader test

8615410

meltsufin reviewed Apr 26, 2017

View reviewed changes

fixed TODO

115759a

gregw mentioned this pull request Apr 27, 2017

Fix : moving instance_name logging to log entry label googleapis/google-cloud-java#2011

Merged

gregw and others added 9 commits May 3, 2017 15:19

Merge branch 'master' into master-68

aa91b0b

Update to jetty 9.4.5 and gcloud 1.0.1-SNAPSHOT

91a62d8

Merge branch 'master' into master-68

2f7dc9c

Merge branch 'master' into master-68

ac00fd1

Merge branch 'master-68' of github.com:GoogleCloudPlatform/jetty-runt…

187cac8

…ime into master-68

Merge branch 'master' into master-68

376481f

upgraded to gcloud-logging 1.0.1

4b80727

turn off debug

ae6b9ce

Merge branch 'master' into master-68

21404d7

meltsufin suggested changes May 9, 2017

View reviewed changes

gregw added 2 commits May 10, 2017 12:06

Merge branch 'master' into master-68

de07ed9

updated README for latest 1.0.1 gcloud-logging

df47a07

update classpath exclusion

bfc9e45

meltsufin approved these changes May 11, 2017

View reviewed changes

gregw merged commit 30127c8 into master May 11, 2017

meltsufin deleted the master-68 branch May 11, 2017 17:17

meltsufin mentioned this pull request May 19, 2017

Implement stackdriver logging #68

Closed

meltsufin mentioned this pull request Jul 24, 2017

Logging using the Google Cloud Logging API #4

Closed

Stackdriver logging #68 #81

Stackdriver logging #68 #81

Conversation

gregw commented Nov 30, 2016

gregw commented Dec 1, 2016

gregw commented Dec 1, 2016

gregw commented Dec 1, 2016

meltsufin commented Dec 5, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gregw commented Dec 5, 2016

gregw commented Dec 6, 2016

meltsufin commented Dec 6, 2016

meltsufin commented Dec 14, 2016

gregw commented Apr 20, 2017

meltsufin commented Apr 21, 2017

aslo commented Apr 21, 2017 • edited Loading

gregw commented Apr 23, 2017

meltsufin left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jabubake May 9, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gregw commented May 10, 2017

bmenasha commented May 16, 2017

meltsufin commented May 23, 2017

aslo commented Apr 21, 2017 •

edited

Loading

jabubake May 9, 2017 •

edited

Loading