Stackdriver logging #68

README.md

@@ -92,8 +92,8 @@ Additional environment variables are used/set including:
 |`JETTY_BASE`      |`jetty.base`     |`/var/lib/jetty`                                      |
 |`TMPDIR`          |                 |`/tmp/jetty`                                          |
 |`JETTY_PROPERTIES`|                 |Comma separated list of `name=value` pairs appended to `$JETTY_ARGS` |
-|`JETTY_MODULES_ENABLED`|            |Comma separated list of modules to enable by appending to `$JETTY_ARGS` |
-|`JETTY_MODULES_DISABLED`|           |Comma separated list of modules to disable by removing from `$JETTY_BASE/start.d` |
+|`JETTY_MODULES_ENABLE`|             |Comma separated list of modules to enable by appending to `$JETTY_ARGS` |
+|`JETTY_MODULES_DISABLE`|            |Comma separated list of modules to disable by removing from `$JETTY_BASE/start.d` |
 |`JETTY_ARGS`      |                 |`-Djetty.base=$JETTY_BASE -jar $JETTY_HOME/start.jar` |
 |`ROOT_WAR`        |                 |`$JETTY_BASE/webapps/root.war`                        |
 |`ROOT_DIR`        |                 |`$JETTY_BASE/webapps/root`                            |
@@ -112,15 +112,88 @@ 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.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
+
+```
+This uses the [GaeFlexLoggingEnhancer](http://googlecloudplatform.github.io/google-cloud-java/0.10.0/apidocs/com/google/cloud/logging/GaeFlexLoggingEnhancer.html) to enhances the logs generated be linking them to the `nginx` request log in the logging console by `traceid` (The traceId for a request on a Google Cloud Platform is obtained from the `setCurrentTraceId` HTTP header as the first field of the `'/'` delimited value).
+
+When an image so configured is deployed on a GCP environment, then the `gcp` module will automatically call the [setCurrentTraceId](http://googlecloudplatform.github.io/google-cloud-java/0.10.0/apidocs/com/google/cloud/logging/GaeFlexLoggingEnhancer.html#setCurrentTraceId-java.lang.String-) for any thread handling a request.
+
+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.GaeFlexLoggingEnhancer;
+
+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);
+            GaeFlexLoggingEnhancer.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();
+        GaeFlexLoggingEnhancer.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+=,file://${jetty.base}/lib/gcp/

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

@@ -0,0 +1,44 @@
+[description]
+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
+
+[tags]
+logging
+slf4j
+internal
+
+[files]
+maven://org.slf4j/slf4j-api/${slf4j.version}|lib/slf4j/slf4j-api-${slf4j.version}.jar
+
+[lib]
+lib/slf4j/slf4j-api-${slf4j.version}.jar
+
+[ini]
+slf4j.version=1.7.21
+jetty.webapp.addServerClasses+=,file://${jetty.base}/lib/slf4j/
+
+[license]
+SLF4J is distributed under the MIT License.
+Copyright (c) 2004-2013 QOS.ch
+All rights reserved.
+
+Permission is hereby granted, free  of charge, to any person obtaining
+a  copy  of this  software  and  associated  documentation files  (the
+"Software"), to  deal in  the Software without  restriction, including
+without limitation  the rights to  use, copy, modify,  merge, publish,
+distribute,  sublicense, and/or sell  copies of  the Software,  and to
+permit persons to whom the Software  is furnished to do so, subject to
+the following conditions:
+
+The  above  copyright  notice  and  this permission  notice  shall  be
+included in all copies or substantial portions of the Software.
+
+THE  SOFTWARE IS  PROVIDED  "AS  IS", WITHOUT  WARRANTY  OF ANY  KIND,
+EXPRESS OR  IMPLIED, INCLUDING  BUT NOT LIMITED  TO THE  WARRANTIES OF
+MERCHANTABILITY,    FITNESS    FOR    A   PARTICULAR    PURPOSE    AND
+NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
+LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
+OF CONTRACT, TORT OR OTHERWISE,  ARISING FROM, OUT OF OR IN CONNECTION
+WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.