Stackdriver logging #68

jetty9-base/pom.xml

@@ -26,15 +26,9 @@
   </parent>
   <name>Google App Engine Image Jetty (jetty9-base)</name>
   <artifactId>jetty9-base</artifactId>
-  <packaging>pom</packaging>
+  <packaging>jar</packaging>
 
   <dependencies>
-    <dependency>
-      <groupId>com.google.cloud.runtimes</groupId>
-      <artifactId>logging</artifactId>
-      <version>0.1.0-SNAPSHOT</version>
-      <type>jar</type>
-    </dependency>
     <dependency>
       <groupId>org.eclipse.jetty</groupId>
       <artifactId>jetty-server</artifactId>
@@ -43,15 +37,27 @@
       <scope>provided</scope>
     </dependency>
     <dependency>
-      <groupId>com.google.cloud.runtimes</groupId>
-      <artifactId>openjdk8</artifactId>
-      <version>${project.version}</version>
-      <type>pom</type>
+      <groupId>com.google.cloud</groupId>
+      <artifactId>google-cloud-logging</artifactId>
+      <version>${gcloud.api.version}</version>
+      <exclusions>
+        <exclusion>
+          <groupId>javax.servlet</groupId>
+          <artifactId>servlet-api</artifactId>
+        </exclusion>
+      </exclusions>
     </dependency>
   </dependencies>
 
   <build>
     <plugins>
+      <plugin>
+        <groupId>org.apache.maven.plugins</groupId>
+        <artifactId>maven-jar-plugin</artifactId>
+        <configuration>
+          <outputDirectory>${project.build.directory}/jetty-base/lib/gae</outputDirectory>
+        </configuration>
+      </plugin>
       <plugin>
         <artifactId>maven-resources-plugin</artifactId>
         <executions>
@@ -135,7 +141,9 @@
           <arguments>
             <argument>-jar</argument>
             <argument>../jetty-distribution-${jetty9.version}/start.jar</argument>
-            <argument>--add-to-startd=http,deploy,jsp,jstl,http-forwarded,resources,gae</argument>
+            <argument>--create-startd</argument>
+            <argument>--add-to-start=http,deploy,jsp,jstl,http-forwarded,resources,gae,gcloud,jcl-slf4j,logging-jul</argument>
+            <argument>--approve-all-licenses</argument>
           </arguments>
         </configuration>
       </plugin>
@@ -161,5 +169,6 @@
       </plugin>
     </plugins>
   </build>
+
 </project>
 

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/gae</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,95 @@
+/*
+ * Copyright 2016 Google Inc. All Rights Reserved.
+ *
+ * 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 org.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.handler.ContextHandler;
+import org.eclipse.jetty.server.handler.ContextHandler.Context;
+
+import java.util.ArrayDeque;
+import java.util.Deque;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+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<String> traceid = new ThreadLocal<>();
+  private static final ThreadLocal<Deque<Request>> requestStack = 
+      new ThreadLocal<Deque<Request>>() {
+    @Override
+    protected Deque<Request> initialValue() {
+      return new ArrayDeque<>();
+    }
+  };
+
+  @Override
+  public void enterScope(Context context, Request request, Object reason) {
+    if (request != null) {
+      Deque<Request> stack = requestStack.get();
+      if (stack.isEmpty()) {
+        String id = (String) request.getAttribute(X_CLOUD_TRACE);
+        if (id == null) {
+          id = request.getHeader(X_CLOUD_TRACE);
+          if (id != null) {
+            int slash = id.indexOf('/');
+            if (slash >= 0) {
+              id = id.substring(0, slash);
+            }
+            request.setAttribute(X_CLOUD_TRACE, id);
+          }
+        }
+        traceid.set(id);
+      }
+      stack.push(request);
+    }
+    if (logger.isLoggable(Level.FINE)) {
+      logger.fine("enterScope " + context);
+    }
+  }
+
+  @Override
+  public void exitScope(Context context, Request request) {
+    if (logger.isLoggable(Level.FINE)) {
+      logger.fine("exitScope " + context);
+    }
+    if (request != null) {
+      requestStack.get().pop();
+    }
+  }
+
+  /** Run a Runnable in the scope of a traceid.
+   * @param traceid The trace ID
+   * @param runnable the runnable
+   */
+  public static void runWith(String traceid, Runnable runnable) {
+    String original = RequestContextScope.traceid.get();
+    RequestContextScope.traceid.set(traceid);
+    try {
+      runnable.run();
+    } finally {
+      RequestContextScope.traceid.set(original);
+    }
+  }
+
+  public static Request getCurrentRequest() {
+    return requestStack.get().peek();
+  }
+
+  public static String getCurrentTraceid() {
+    return traceid.get();
+  }
+}

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

@@ -0,0 +1,103 @@
+/*
+ * Copyright 2016 Google Inc. All Rights Reserved.
+ *
+ * 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 static com.google.common.base.MoreObjects.firstNonNull;
+
+import com.google.cloud.MonitoredResource;
+import com.google.cloud.logging.AsyncLoggingHandler;
+import com.google.cloud.logging.LogEntry.Builder;
+import com.google.cloud.logging.LoggingOptions;
+
+import org.eclipse.jetty.server.Request;
+
+import java.util.logging.LogManager;
+import java.util.logging.LogRecord;
+
+/**
+ * A Google Cloud Logging Handler extended with a request traceid label.
+ */
+public class TracingLogHandler extends AsyncLoggingHandler {
+
+  private final ThreadLocal<Boolean> flushing = new ThreadLocal<>();
+  private final MonitoredResource monitored;
+  private final String instanceid;
+
+  /**
+   * Construct a TracingLogHandler for "jetty.log"
+   */
+  public TracingLogHandler() {
+    this(firstNonNull(
+        LogManager.getLogManager().getProperty(TracingLogHandler.class.getName() + ".log"),
+        "jetty.log"), null, null);
+  }
+
+  /** 
+   * Construct a TracingLogHandler.
+   * 
+   * @param logName Name of the log
+   * @param options LoggingOptions to access Google cloud API
+   * @param resource The resource to log against
+   */
+  public TracingLogHandler(String logName, LoggingOptions options, MonitoredResource resource) {
+    super(logName, options, resource);
+    monitored = MonitoredResource.newBuilder("gae_app")
+        .addLabel("project_id", System.getenv("GCLOUD_PROJECT"))
+        .addLabel("module_id", System.getenv("GAE_SERVICE"))
+        .addLabel("version_id", System.getenv("GAE_VERSION"))
+        .build();
+    instanceid = System.getenv("GAE_INSTANCE");
+  }
+
+  @Override
+  public synchronized void publish(LogRecord record) {
+    // check we are not already flushing logs
+    if (Boolean.TRUE.equals(flushing.get())) {
+      return;
+    }
+    super.publish(record);
+  }
+
+  @Override
+  protected void enhanceLogEntry(Builder builder, LogRecord record) {
+    super.enhanceLogEntry(builder, record);
+    String traceid = RequestContextScope.getCurrentTraceid();
+    builder.setResource(monitored);
+    if (traceid != null) {
+      builder.addLabel("appengine.googleapis.com/trace_id", traceid);
+    } else {
+      Request request = RequestContextScope.getCurrentRequest();
+      if (request != null) {
+        builder.addLabel("http-scheme", request.getScheme());
+        builder.addLabel("http-method", request.getMethod());
+        builder.addLabel("http-uri", request.getOriginalURI());
+        builder.addLabel("http-remote-addr", request.getRemoteAddr());
+      }
+    }
+    if (instanceid != null) {
+      builder.addLabel("appengine.googleapis.com/instance_name", instanceid);
+    }
+  }
+
+  @Override
+  public synchronized void flush() {
+    try {
+      flushing.set(Boolean.TRUE);
+      super.flush();
+    } finally {
+      flushing.set(Boolean.FALSE);
+    }
+  }
+}

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

@@ -1,16 +1,11 @@
 <?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">
-
-  <!-- Protect app.yaml -->
-  <Get id="protected" name="ProtectedTargets"/>
-  <Set name="ProtectedTargets">
-    <Call class="org.eclipse.jetty.util.ArrayUtil" name="addToArray">
-      <Arg><Ref refid="protected"/></Arg>
-      <Arg>/app.yaml</Arg>
-      <Arg></Arg>
-    </Call>
-  </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>
+
 </Configure>
 

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
+
+handlers = com.google.cloud.runtimes.jetty9.TracingLogHandler
+com.google.cloud.runtimes.jetty9.TracingLogHandler.level = INFO
+
+# handlers = com.google.cloud.runtimes.jetty9.TracingLogHandler,java.util.logging.ConsoleHandler
+# java.util.logging.ConsoleHandler.level = INFO

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

@@ -0,0 +1,64 @@
+//
+// ========================================================================
+// Copyright (c) 1995-2016 Mort Bay Consulting Pty. Ltd.
+// ------------------------------------------------------------------------
+// All rights reserved. This program and the accompanying materials
+// are made available under the terms of the Eclipse Public License v1.0
+// and Apache License v2.0 which accompanies this distribution.
+//
+// The Eclipse Public License is available at
+// http://www.eclipse.org/legal/epl-v10.html
+//
+// The Apache License v2.0 is available at
+// http://www.opensource.org/licenses/apache2.0.php
+//
+// You may elect to redistribute this code under either of these licenses.
+// ========================================================================
+//
+
+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");
+  }
+
+  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 e) {
+        throw e;
+      } catch (Throwable e) {
+        throw new ServletException(e);
+      }
+    }
+    response.getWriter().println("Log Test");
+  }
+}