Stackdriver logging #68 (#81)

* Issue #68 added request context scope

* Issue #68 added request context scope

* Issue #68 added skeleton Logging Handler

* Issue #68 work in progress

* Issue #68 work in progress

* working implementation using a threadlocal to stop looping

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

* Issue #68

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

* Issue #68 Use same labels as nginx

* Issue #68

Code cleanups after review

* Issue #68

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

* renamed traceid to traceId

* gcloud api not currently used

* Tunnel traceId in parameters #68

* Simplified with traceId lookup in formatter #68

* Use 8.2 beta stackdriver

* Improved formatting

* use logger name rather than source

* run jetty from the webapp working directory so logging configuration may be relative

* Testing logging

Test googleapis/google-cloud-java#1535 and jetty-9.4.1-SNAPSHOT

* use released 9.4.1

* Issue #68

minor clean ups

* Do not CD to non existant directory

* improved README

* fixed Cloud SDK

* Released beta of google-cloud-logging

* updated google-cloud API to 0.8.3-beta

* added remote test to check logging

* Stackdriver logging testing

improved comments
check for traceid

* upgrade to 0.9.2

* Test for zone

* upgrade to 10.0 gcloud API

* enable gae module only of GAE_INSTANCE environment variable is set

* improved gae.mod documentation

* GCP module

Rename gae module and configuration to gcp
Split the jetty.commands into jetty.commands and gcp.commands
moved commands file to jetty-base/config-scripts
updated setup-env-ext to run the gcp.commands when image is run with a GAE_INSTANCE set

* fixed warnings

* turn off stackdriver logging by default. Added instructions to enable.

* Updates

Update to latest openjdk-runtime with setup-env.d
Update to latest jetty release

* Use the PLATFORM env var

* Improved jetty startup

Added JETTY_PROPERTIES, JETTY_MODULES_ENABLE & JETTY_MODULES_DISABLE
Removed duplicate code fron 50-jetty.bash

* use launcher URL

* Trimmed GCP specific configuration

* Added structure tests for jetty setup script

Also fixed unpack bug found as a result

* Support passing just args

* fix merge

* Fixed test workspace paths for cloud build

* review feedback

* working directory is the root webapp

* Improve handling of various types of command line.

Fixed problem with handling of command line like "ls /var"
Requires duplication of test for java from openjdk-runtime docker-entrypoint.bash,
which should be modified to avoid the duplication.

* upgrade cgloud API version to 0.13.0-beta

* use package target

* tested with FINE log level

* Simplify entrypoint args processing

The $@ arg array is kept complete between all scripts.

* remove debug

* remove debug

* Test that the logging dependencies are hidden from webapp classpath

* update README.md with instructions to keep INFO level on io.grpc.netty.level=INFO

* Updated to lasted openjdk-runtime

* fixed classloader test

* fixed TODO

* Update to jetty 9.4.5 and gcloud 1.0.1-SNAPSHOT

* upgraded to gcloud-logging 1.0.1

* turn off debug

* updated README for latest 1.0.1 gcloud-logging

* update classpath exclusion


\o/

Author: gregw

README.md

@@ -112,15 +112,90 @@ java $JAVA_OPTS \
      -jar $JETTY_HOME/start.jar \
      "$@"
 ```
+## Logging
+This image is configured to use [Java Util Logging](https://docs.oracle.com/javase/8/docs/api/java/util/logging/package-summary.html)(JUL) to capture all logging from 
+the container and its dependencies.  Applications that also use the JUL API will inherit the same logging configuration.
 
-The configuration of the jetty container in this image can be viewed by running the image locally:
+By default JUL is configured to use a [ConsoleHandler](https://docs.oracle.com/javase/8/docs/api/java/util/logging/ConsoleHandler.html) to send logs to the `stderr` of the container process. When run on as a GCP deployment, all output to `stderr` is captured and is available via the Stackdriver logging console, however more detailed and integrated logs are available if the Stackdriver logging mechanism is used directly (see below).
+
+To alter logging configuration a new `logging.properties` file must be provided to the image that among other things can: alter log levels generated by Loggers; alter log levels accepted by handlers; add/remove/configure log handlers. 
+
+
+### Providing `logging.properties` via the web application
+A new logging configuration file can be provided as part of the application (typically at `WEB-INF/logging.properties`)
+and the Java System Property `java.util.logging.config.file` updated to reference it.
+
+When running in a GCP environment, the system property can be set in `app.yaml`:
+```yaml
+env_variables:
+  JAVA_USER_OPTS: -Djava.util.logging.config.file=WEB-INF/logging.properties
 ```
-docker run --rm -it launcher.gcr.io/google/jetty --list-config --list-modules
+
+If the image is run directly, then a `-e` argument to the `docker run` command can be used to set the system property:
+
+```bash
+docker run \
+  -e JAVA_USER_OPTS=-Djava.util.logging.config.file=WEB-INF/logging.properties \
+  ...
+```
+
+### Providing `logging.properties` via a custom image
+If this image is being used as the base of a custom image, then the following `Dockerfile` commands can be used to add either replace the existing logging configuration file or to add a new  `logging.properties` file.
+
+The default logging configuration file is located at `/var/lib/jetty/etc/java-util-logging.properties`, which can be replaced in a custom image is built. The default configuration can be replaced with a `Dockerfile` like:
+
+```Dockerfile
+FROM gcr.io/google-appengine/jetty
+ADD logging.properties /var/lib/jetty/etc/java-util-logging.properties
+...
 ```
 
+Alternately an entirely new location for the file can be provided and the environment amended in a `Dockerfile` like:
+
+```Dockerfile
+FROM gcr.io/google-appengine/jetty
+ADD logging.properties /etc/logging.properties
+ENV JAVA_USER_OPTS -Djava.util.logging.config.file=/etc/logging.properties
+...
+```
+
+### Providing `logging.properties` via docker run 
+A `logging.properties` file may be added to an existing images using the `docker run` command if the deployment environment allows for the run arguments to be modified. The `-v` option can be used to bind a new `logging.properties` file to the running instance and the `-e` option can be used to set the system property to point to it:
+```shell 
+docker run -it --rm \
+-v /mylocaldir/logging.properties:/etc/logging.properties \
+-e JAVA_USER_OPTS="-Djava.util.logging.config.file=/etc/logging.properties" \
+...
+```
+
+### Enhanced Stackdriver Logging (BETA!)
+When running on the Google Cloud Platform Flex environment, the Java Util Logging can be configured to send logs to Google Stackdriver Logging by providing a `logging.properties` file that configures a [LoggingHandler](http://googlecloudplatform.github.io/google-cloud-java/0.10.0/apidocs/com/google/cloud/logging/LoggingHandler.html) as follows:
+```
+.level=INFO
+io.grpc.netty.level=INFO
+sun.net.level=INFO
+
+handlers=com.google.cloud.logging.LoggingHandler
+com.google.cloud.logging.LoggingHandler.level=FINE
+com.google.cloud.logging.LoggingHandler.log=gae_app.log
+com.google.cloud.logging.LoggingHandler.formatter=java.util.logging.SimpleFormatter
+java.util.logging.SimpleFormatter.format=%3$s: %5$s%6$s
+
+```
+When deployed on the GCP Flex environment, an image so configured will automatically be configured with:
+* a [LabelLoggingEnhancer](https://github.com/GoogleCloudPlatform/google-cloud-java/blob/v0.17.2/google-cloud-logging/src/main/java/com/google/cloud/logging/MonitoredResourceUtil.java#L224) instance, that will add labels from the monitored resource to each log entry.
+* a [TraceLoggingEnhancer](https://github.com/GoogleCloudPlatform/google-cloud-java/blob/v0.17.2/google-cloud-logging/src/main/java/com/google/cloud/logging/TraceLoggingEnhancer.java) instance that will add any trace-id set to each log entry.
+* the `gcp` module will be enabled that configures jetty so that the [setCurrentTraceId](https://github.com/GoogleCloudPlatform/google-cloud-java/blob/v0.17.2/google-cloud-logging/src/main/java/com/google/cloud/logging/TraceLoggingEnhancer.java#L40) method is called for any thread handling a request.
+
+When deployed in other environments, logging enhancers can be manually configured by setting a comma separated list of class names as the
+`com.google.cloud.logging.LoggingHandler.enhancers` property.
+
+When using Stackdriver logging, it is recommended that `io.grpc` and `sun.net` logging level is kept at INFO level, as both these packages are used by Stackdriver internals and can result in verbose and/or initialisation problems. 
+
+
 ## Extending the image
 The image produced by this project may be automatically used/extended by the Cloud SDK and/or App Engine maven plugin. 
-Alternately it may be explicitly extended with a custom Dockerfile.  
+Alternately it may be explicitly extended with a custom Dockerfile.
 
 The latest released version of this image is available at `launcher.gcr.io/google/jetty`, alternately you may 
 build and push your own version with the shell commands:

jetty9-base/pom.xml

@@ -36,6 +36,17 @@
       <type>jar</type>
       <scope>provided</scope>
     </dependency>
+    <dependency>
+      <groupId>com.google.cloud</groupId>
+      <artifactId>google-cloud-logging</artifactId>
+      <version>${gcloud.api.version}</version>
+      <exclusions>
+        <exclusion>
+          <groupId>commons-logging</groupId>
+          <artifactId>commons-logging</artifactId>
+        </exclusion>
+      </exclusions>
+    </dependency>
   </dependencies>
 
   <build>
@@ -96,7 +107,7 @@
           </execution>
           <execution>
             <id>gcp-jars</id>
-            <phase>pre-integration-test</phase>
+            <phase>package</phase>
             <goals>
               <goal>copy-dependencies</goal>
             </goals>
@@ -118,7 +129,7 @@
         <executions>
           <execution>
             <id>add-jetty-modules</id>
-            <phase>pre-integration-test</phase>
+            <phase>package</phase>
             <goals>
               <goal>exec</goal>
             </goals>
@@ -139,7 +150,7 @@
         <artifactId>maven-assembly-plugin</artifactId>
         <executions>
           <execution>
-            <phase>pre-integration-test</phase>
+            <phase>package</phase>
             <goals>
               <goal>single</goal>
             </goals>

jetty9-base/src/main/assembly/assembly.xml

@@ -33,12 +33,5 @@
         <exclude>**/META-INF/**</exclude>
       </excludes>
     </fileSet>
-    <fileSet>
-      <directory>${project.build.directory}</directory>
-      <outputDirectory>jetty-base/lib/gcp</outputDirectory>
-      <includes>
-        <include>${artifactId}-${version}.jar</include>
-      </includes>
-    </fileSet>
   </fileSets>
 </assembly>

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

@@ -0,0 +1,85 @@
+/*
+ * Copyright (C) 2016 Google Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.google.cloud.runtimes.jetty9;
+
+import com.google.cloud.logging.TraceLoggingEnhancer;
+
+import org.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.handler.ContextHandler;
+import org.eclipse.jetty.server.handler.ContextHandler.Context;
+import org.eclipse.jetty.server.handler.ContextHandler.ContextScopeListener;
+
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+/**
+ * A Jetty {@link ContextScopeListener} that is called whenever
+ * a container managed thread enters or exits the scope of a context and/or request.
+ * Used to maintain {@link ThreadLocal} references to the current request and 
+ * Google traceID, primarily for logging.
+ * @see TracingLogHandler
+ */
+public class RequestContextScope implements ContextHandler.ContextScopeListener {
+  static final Logger logger = Logger.getLogger(RequestContextScope.class.getName());
+
+  private static final String X_CLOUD_TRACE = "x-cloud-trace-context";
+  private static final ThreadLocal<Integer> contextDepth = new ThreadLocal<>();
+
+  @Override
+  public void enterScope(Context context, Request request, Object reason) {
+    if (logger.isLoggable(Level.FINE)) {
+      logger.fine("enterScope " + context);
+    }
+    if (request != null) {
+      Integer depth = contextDepth.get();
+      if (depth == null || depth.intValue() == 0) {
+        depth = 1;
+        String traceId = (String) request.getAttribute(X_CLOUD_TRACE);
+        if (traceId == null) {
+          traceId = request.getHeader(X_CLOUD_TRACE);
+          if (traceId != null) {
+            int slash = traceId.indexOf('/');
+            if (slash >= 0) {
+              traceId = traceId.substring(0, slash);
+            }
+            request.setAttribute(X_CLOUD_TRACE, traceId);
+            TraceLoggingEnhancer.setCurrentTraceId(traceId);
+          }
+        } else {
+          depth = depth + 1;
+        }
+        contextDepth.set(depth);
+      }
+    }
+  }
+
+  @Override
+  public void exitScope(Context context, Request request) {
+    if (logger.isLoggable(Level.FINE)) {
+      logger.fine("exitScope " + context);
+    }
+    Integer depth = contextDepth.get();
+    if (depth != null) {
+      if (depth > 1) {
+        contextDepth.set(depth - 1);
+      } else {
+        contextDepth.remove();
+        TraceLoggingEnhancer.setCurrentTraceId(null);
+      }
+    }
+  }
+}

jetty9-base/src/main/jetty-base/config-scripts/jetty.commands

@@ -1,4 +1,4 @@
 --create-startd
-
---add-to-start=server,webapp,http,deploy,jsp,jstl,resources
+--approve-all-licenses
+--add-to-start=server,webapp,http,deploy,jsp,jstl,resources,logging-jul,jcl-slf4j
 

jetty9-base/src/main/jetty-base/etc/gcp-web.xml

@@ -1,10 +1,15 @@
 <?xml version="1.0"?>
 <!DOCTYPE Configure PUBLIC "-//Jetty//Configure//EN" "http://www.eclipse.org/jetty/configure_9_3.dtd">
 <Configure class="org.eclipse.jetty.webapp.WebAppContext">
-
+ 
   <!-- Allow start exceptions to propagate -->
   <Set name="throwUnavailableOnStartupException">true</Set>
 
+  <!-- Add listener to capture request context to be used by logging  -->
+  <Call name="addEventListener">
+    <Arg><New class="com.google.cloud.runtimes.jetty9.RequestContextScope"/></Arg>
+  </Call>
+
   <!-- Protect app.yaml -->
   <Get id="protected" name="ProtectedTargets"/>
   <Set name="ProtectedTargets">
@@ -16,6 +21,5 @@
   </Set>
 
   <Set name="overrideDescriptor"><Property name="jetty.base"/>/etc/gcp-override-web.xml</Set>
-  
+ 
 </Configure>
-

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

@@ -0,0 +1,14 @@
+.level=INFO
+
+handlers=java.util.logging.ConsoleHandler
+java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
+java.util.logging.SimpleFormatter.format=%3$s: %5$s%6$s%n
+
+## To use Stackdriver Logging replace the configuration above with the configuration below:
+# handlers=com.google.cloud.logging.LoggingHandler
+# 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
+# com.google.cloud.logging.LoggingHandler.formatter=java.util.logging.SimpleFormatter
+# java.util.logging.SimpleFormatter.format=%3$s: %5$s%6$s

jetty9-base/src/main/jetty-base/modules/gcp.mod

@@ -44,3 +44,6 @@ jetty.httpConfig.sendServerVersion?=true
 
 # Don't send date header
 jetty.httpConfig.sendDateHeader?=false
+
+# Hide the gcloud libraries from deployed webapps
+jetty.webapp.addServerClasses+=,${jetty.base.uri}/lib/gcp/

jetty9-base/src/test/java/com/google/cloud/runtimes/jetty9/TestServlet.java

@@ -0,0 +1,63 @@
+/*
+ * Copyright (C) 2016 Google Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.google.cloud.runtimes.jetty9;
+
+import java.io.IOException;
+import java.util.logging.Logger;
+
+import javax.annotation.PostConstruct;
+import javax.servlet.ServletException;
+import javax.servlet.annotation.WebServlet;
+import javax.servlet.http.HttpServlet;
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+
+
+@SuppressWarnings("serial")
+@WebServlet(urlPatterns = {"/", "/test/*"}, name = "TestServlet")
+public class TestServlet extends HttpServlet {
+  static final Logger log = Logger.getLogger(TestServlet.class.getName());
+
+  @PostConstruct
+  private void myPostConstructMethod() {
+    log.info("preconstructed");
+  }
+
+  @Override
+  public void init() throws ServletException {
+    log.info("init info");
+    getServletContext().log("init ServletContext.log");
+  }
+
+  @Override
+  public void doGet(HttpServletRequest request, HttpServletResponse response)
+      throws ServletException, IOException {
+    log.info("doGet info");
+    getServletContext().log("doGet ServletContext.log");
+
+    if (request.getParameter("ex") != null) {
+      try {
+        throw (Throwable) Class.forName(request.getParameter("ex")).newInstance();
+      } catch (ServletException | IOException ex) {
+        throw ex;
+      } catch (Throwable th) {
+        throw new ServletException(th);
+      }
+    }
+    response.getWriter().println("Log Test");
+  }
+}

jetty9/src/main/docker/50-jetty.bash

@@ -19,15 +19,14 @@ if [ ! -e "$ROOT_DIR" -a -d /app ]; then
   ln -s /app "$ROOT_DIR"
 fi
 
-# move command line args to $JETTY_ARGS
-export JETTY_ARGS="${@/$1/}"
-set - "$1"
-
-# Check for start.jar
-if [ "$(echo $JETTY_ARGS | egrep start.jar | wc -l )" = "0" ]; then
-  JETTY_ARGS="-Djetty.base=${JETTY_BASE} -jar ${JETTY_HOME}/start.jar $JETTY_ARGS"
+# If a webapp root directory exist, use it as the work directory
+if [ -d "$ROOT_DIR" ]; then
+  cd "$ROOT_DIR"
 fi
 
+# Calculate the Jetty args
+export JETTY_ARGS
+
 # Add any Jetty properties to the JETTY_ARGS
 if [ "$JETTY_PROPERTIES" ]; then
   JETTY_ARGS="$JETTY_ARGS ${JETTY_PROPERTIES//,/ }"
@@ -52,7 +51,18 @@ if [ "$PLATFORM" = "gae" ]; then
   JETTY_ARGS="$JETTY_ARGS --module=gcp"
 fi
 
-# add the JETTY_ARGS to the JAVA_OPTS
-export JAVA_OPTS="$JAVA_OPTS $JETTY_ARGS"
+# If command line is running java, then assume it is jetty and mix in JETTY_ARGS
+if [ "$1" = "java" ]; then
+  # Check for jetty start.jar and prepend if missing
+  if [ "$(echo $@ | egrep start.jar | wc -l )" = "0" ]; then
+    shift
+    set -- java -Djetty.base=${JETTY_BASE} -jar ${JETTY_HOME}/start.jar $@
+  fi
 
+  # Append JETTY_ARGS
+  if [ -n "$JETTY_ARGS" ]; then
+    shift
+    set -- java $@ $JETTY_ARGS
+  fi
+fi