Issue GoogleCloudPlatform#231 - Reworking logging for slfj4 + logback

+ More unit testing resolved updates + jetty9-compat-base now does not modify the maven-dependency-plugin created target/jetty-base instead it copies into target/tests for testing reasons so as to avoid corrupting the target/jetty-base that is eventually assembled in the maven-assembly-plugin
jetty-project · Jun 21, 2016 · 5474ee8 · 5474ee8
1 parent 9ea2654
commit 5474ee8
Show file tree

Hide file tree

Showing 8 changed files with 148 additions and 36 deletions.
diff --git a/appengine-java-logging/src/main/java/com/google/apphosting/logging/JsonEncoder.java b/appengine-java-logging/src/main/java/com/google/apphosting/logging/JsonEncoder.java
@@ -41,6 +41,7 @@ public JsonEncoder() {
 
   @Override public void doEncode(E event) throws IOException {
     writer.write(layout.doLayout(event));
+    writer.flush();
   }
 
   @Override public void close() throws IOException {

diff --git a/...ngine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeLogging.java b/...ngine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeLogging.java
@@ -30,6 +30,7 @@
 
 public class VmRuntimeLogging {
   public static final String LOGGING_CONFIGURATION_KEY = "logback.configurationFile";
+  private static final boolean DEBUG = false;
 
   public static void load(String logbackXmlFile) throws AppEngineConfigException {
     // Establish java.util.logging -> slf4j bridge
@@ -51,7 +52,7 @@ public static void load(String logbackXmlFile) throws AppEngineConfigException {
       System.setProperty(LOGGING_CONFIGURATION_KEY, logbackXmlFile);
       try {
         initializer.autoConfig();
-        System.err.println("## Initialized User Logging from " + logbackXmlFile);
+        debug("Initialized User Logging from %s", logbackXmlFile);
       } catch (JoranException e) {
         throw new AppEngineConfigException(e);
       }
@@ -63,11 +64,17 @@ public static void load(String logbackXmlFile) throws AppEngineConfigException {
           VmRuntimeLogging.class.getClassLoader().getResources("logback.xml");
       while (configUrls.hasMoreElements()) {
         URL url = configUrls.nextElement();
-        System.err.println("## Initialized System Logging from " + url);
         initializer.configureByResource(url);
+        debug("Initialized System Logging from %s", url);
       }
     } catch (JoranException | IOException e) {
       throw new AppEngineConfigException(e);
     }
   }
+
+  private static void debug(String format, Object... args) {
+    if (DEBUG) {
+      System.err.printf("[Logging DEBUG] " + format + "%n", args);
+    }
+  }
 }
diff --git a/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/IntegrationEnv.java b/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/IntegrationEnv.java
@@ -1,11 +1,24 @@
 package com.google.apphosting.vmruntime.jetty9;
 
+import static java.nio.file.FileVisitResult.CONTINUE;
+import static java.nio.file.StandardCopyOption.COPY_ATTRIBUTES;
+import static java.nio.file.StandardCopyOption.REPLACE_EXISTING;
+
+import org.eclipse.jetty.toolchain.test.FS;
 import org.eclipse.jetty.toolchain.test.MavenTestingUtils;
 import org.eclipse.jetty.toolchain.test.PathAssert;
 
-import java.io.File;
 import java.io.IOException;
+import java.nio.file.CopyOption;
+import java.nio.file.FileAlreadyExistsException;
+import java.nio.file.FileSystemLoopException;
+import java.nio.file.FileVisitOption;
+import java.nio.file.FileVisitResult;
+import java.nio.file.FileVisitor;
+import java.nio.file.Files;
 import java.nio.file.Path;
+import java.nio.file.attribute.BasicFileAttributes;
+import java.util.EnumSet;
 
 /**
  * Environment for IT tests.
@@ -15,13 +28,87 @@
  * </p>
  */
 public class IntegrationEnv {
+
+  /**
+   * Create a new copy of the target/jetty-base directory for testing purposes.
+   * <p>
+   * We don't want to modify the target/jetty-base directory directly with
+   * our unit tests.
+   * </p>
+   *
+   * @return the copied jetty-base directory location.
+   * @throws IOException if unable to create the copied directory
+   */
   public static Path getJettyBase() throws IOException {
-    Path jettyBase = MavenTestingUtils.getTargetPath("jetty-base");
-    if (System.getProperty("jetty.base") != null) {
-      jettyBase = new File(System.getProperty("jetty.base")).toPath().toRealPath();
+    // Find source / test
+    Path readOnlyJettyBase = MavenTestingUtils.getTargetPath("jetty-base");
+    PathAssert.assertDirExists("jetty.base", readOnlyJettyBase);
+
+    // Find test / copy of jetty-base
+    Path testJettyBase = MavenTestingUtils.getTargetTestingPath("it-jetty-base");
+    if (Files.exists(testJettyBase) || !Files.isDirectory(testJettyBase)) {
+      FS.ensureEmpty(testJettyBase);
+      copyDirectory(readOnlyJettyBase, testJettyBase, 5);
     }
 
-    PathAssert.assertDirExists("jetty.base", jettyBase);
-    return jettyBase;
+    System.setProperty("jetty.base", testJettyBase.toString());
+
+    return testJettyBase;
+  }
+
+  public static void copyDirectory(Path src, Path dest, int depth) throws IOException {
+    Path absSrc = src.toAbsolutePath();
+    Path absDest = dest.toAbsolutePath();
+    System.err.printf("## Copy Dir %s -> %s%n", absSrc, absDest);
+    EnumSet<FileVisitOption> opts = EnumSet.of(FileVisitOption.FOLLOW_LINKS);
+    FileSystemCopier copier = new FileSystemCopier(absSrc, absDest);
+    Files.walkFileTree(absSrc, opts, depth, copier);
+  }
+
+  private static class FileSystemCopier implements FileVisitor<Path> {
+    private final Path src;
+    private final Path dest;
+    private final CopyOption[] copyDirOpts = new CopyOption[] {COPY_ATTRIBUTES};
+    private final CopyOption[] copyFileOpts = new CopyOption[] {COPY_ATTRIBUTES, REPLACE_EXISTING};
+
+    public FileSystemCopier(Path src, Path dest) {
+      this.src = src;
+      this.dest = dest;
+    }
+
+    @Override
+    public FileVisitResult preVisitDirectory(Path dir, BasicFileAttributes attrs)
+        throws IOException {
+      Path newDir = dest.resolve(src.relativize(dir));
+
+      try {
+        Files.copy(dir, newDir, copyDirOpts);
+      } catch (FileAlreadyExistsException ignore) {
+        /* ignore */
+      }
+      return CONTINUE;
+    }
+
+    @Override
+    public FileVisitResult visitFile(Path file, BasicFileAttributes attrs) throws IOException {
+      Path destFile = dest.resolve(src.relativize(file));
+      Files.copy(file, destFile, copyFileOpts);
+      return CONTINUE;
+    }
+
+    @Override
+    public FileVisitResult visitFileFailed(Path file, IOException exc) throws IOException {
+      System.err.printf("## FAILURE: " + file + " | ");
+      exc.printStackTrace(System.err);
+      if (exc instanceof FileSystemLoopException) {
+        throw exc;
+      }
+      return CONTINUE;
+    }
+
+    @Override
+    public FileVisitResult postVisitDirectory(Path dir, IOException exc) throws IOException {
+      return CONTINUE;
+    }
   }
 }
diff --git a/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/JettyRunner.java b/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/JettyRunner.java
@@ -17,6 +17,8 @@
 package com.google.apphosting.vmruntime.jetty9;
 
 import static com.google.apphosting.vmruntime.jetty9.VmRuntimeTestBase.JETTY_HOME_PATTERN;
+import static org.hamcrest.Matchers.is;
+import static org.junit.Assert.assertThat;
 
 import com.google.apphosting.jetty9.GoogleRequestCustomizer;
 import com.google.apphosting.vmruntime.VmRuntimeLogging;
@@ -39,7 +41,6 @@
 import org.eclipse.jetty.util.component.AbstractLifeCycle;
 import org.eclipse.jetty.util.log.Log;
 import org.eclipse.jetty.util.thread.QueuedThreadPool;
-import org.junit.Assert;
 
 import java.io.File;
 import java.io.IOException;
@@ -110,9 +111,8 @@ public void doStart() throws Exception {
     try {
       Path jettyBase = IntegrationEnv.getJettyBase();
       logs = jettyBase.resolve("logs").toFile();
-      if (logs.exists()) {
-        logs.delete();
-        logs.mkdirs();
+      if (!logs.exists()) {
+        assertThat("Unable to create directory: " + logs, logs.mkdirs(), is(true));
       }
 
       // Set GAE SystemProperties
@@ -202,7 +202,7 @@ public void doStart() throws Exception {
       System.setProperty(
           VmRuntimeLogging.LOGGING_CONFIGURATION_KEY, logging.toRealPath().toString());
 
-      Assert.assertTrue(webAppLocation.toString(), webAppLocation.isDirectory());
+      PathAssert.assertDirExists("WebAppLocation", webAppLocation);
 
       context.setResourceBase(webAppLocation.getAbsolutePath());
       context.init((appengineWebXml == null ? "WEB-INF/appengine-web.xml" : appengineWebXml));

diff --git a/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/LoggingIT.java b/jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/LoggingIT.java
@@ -16,13 +16,17 @@
 
 package com.google.apphosting.vmruntime.jetty9;
 
+import static org.hamcrest.Matchers.containsString;
 import static org.hamcrest.Matchers.equalTo;
+import static org.hamcrest.Matchers.is;
+import static org.hamcrest.Matchers.nullValue;
 import static org.junit.Assert.assertThat;
 
 import com.google.gson.Gson;
 
 import org.apache.commons.httpclient.HttpClient;
 import org.apache.commons.httpclient.methods.GetMethod;
+import org.eclipse.jetty.toolchain.test.PathAssert;
 
 import java.io.BufferedReader;
 import java.io.File;
@@ -38,8 +42,8 @@ public void testGet() throws Exception {
 
     HttpClient httpClient = new HttpClient();
     httpClient.getHttpConnectionManager().getParams().setConnectionTimeout(30000);
-    String query = Long.toHexString(System.nanoTime());
-    GetMethod get = new GetMethod(createUrl("/testLogging?nano=" + query).toString());
+    String query = "nano=" + Long.toHexString(System.nanoTime());
+    GetMethod get = new GetMethod(createUrl("/testLogging?" + query).toString());
     int httpCode = httpClient.executeMethod(get);
 
     assertThat(httpCode, equalTo(200));
@@ -48,49 +52,62 @@ public void testGet() throws Exception {
     assertThat(body, equalTo("FINE\nSEVERE\nfalse\n\n"));
 
     File logs = runner.getLogDir();
-    File log = new File(logs, "log.0");
+    File log = new File(logs, "app.0.log.json");
 
-    assertTrue(log.exists());
+    PathAssert.assertFileExists("JSON Log", log);
 
     // Look for the log entry with our query string
-    try (BufferedReader in =
-        new BufferedReader(
-            new InputStreamReader(new FileInputStream(log), StandardCharsets.ISO_8859_1))) {
+    try (BufferedReader in = new BufferedReader(
+        new InputStreamReader(new FileInputStream(log), StandardCharsets.UTF_8))) {
+      boolean foundServletLog = false;
+      int lineCount = 0;
       String line;
       while ((line = in.readLine()) != null) {
-        if (line.contains(query)) {
+        lineCount++;
+        // Look for line indicating we are in the LoggingServlet
+        if (line.contains("LogTest Hello " + query)) {
+          foundServletLog = true;
           break;
         }
       }
 
+      assertThat(
+          "Servlet Log search (searched " + lineCount + " lines for " + query + ") in log: " + log,
+          foundServletLog, is(true));
+
       JsonData data = new Gson().fromJson(line, JsonData.class);
-      assertThat(data.severity, equalTo("INFO"));
-      assertThat(data.message, org.hamcrest.Matchers.containsString("LogTest Hello nano=" + query));
+      assertThat(data.severity, is("INFO"));
+      assertThat(data.message, containsString("LogTest Hello " + query));
 
       line = in.readLine();
       data = new Gson().fromJson(line, JsonData.class);
-      assertThat(data.severity, equalTo("ERROR"));
-      assertThat(
-          data.message, org.hamcrest.Matchers.containsString("LoggingServlet doGet: not null"));
+      assertThat(data.severity, is("ERROR"));
+      assertThat(data.logger, is("com.foo.bar"));
+      assertThat(data.message, containsString("not null"));
 
       line = in.readLine();
       data = new Gson().fromJson(line, JsonData.class);
-      assertThat(data.severity, equalTo("ERROR"));
-      assertThat(data.message, org.hamcrest.Matchers.containsString("LoggingServlet doGet: null"));
+      assertThat(data.severity, is("ERROR"));
+      assertThat(data.logger, is("com.foo.bar"));
+      assertThat(data.message, nullValue());
     }
   }
 
   // Something that JSON can parser the JSON into
   public static class JsonData {
     public static class LogTimestamp {
       public long seconds;
-      public long nanos;
+      public int nanos;
     }
 
+
     public LogTimestamp timestamp;
     public String severity;
     public String thread;
     public String message;
+    public String logger;
+    public String caller;
     public String traceId;
+    public String throwable;
   }
 }
diff --git a/jetty9-compat-base/src/test/resources/logback.xml b/jetty9-compat-base/src/test/resources/logback.xml
@@ -6,8 +6,8 @@
     </contextListener>
 
     <appender name="CloudDebugger" class="ch.qos.logback.core.rolling.RollingFileAppender">
-        <file>target/jetty-base/logs/app.0.log.json</file>
-        <encoder class="com.google.apphosting.logging.JsonEncoder" />
+        <file>target/tests/test-it-jetty-base/logs/app.0.log.json</file>
+        <encoder class="com.google.apphosting.logging.JsonEncoder"/>
         <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
             <fileNamePattern>app.%i.log.json</fileNamePattern>
             <minIndex>1</minIndex>
@@ -19,7 +19,7 @@
     </appender>
 
     <appender name="Human" class="ch.qos.logback.core.FileAppender">
-        <file>target/jetty-base/logs/app.0.log</file>
+        <file>target/tests/test-it-jetty-base/logs/app.0.log</file>
         <append>true</append>
         <encoder>
             <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>

diff --git a/jetty9-compat-base/src/test/resources/webapp/WEB-INF/logback.xml b/jetty9-compat-base/src/test/resources/webapp/WEB-INF/logback.xml
@@ -6,8 +6,8 @@
         </encoder>
     </appender>
 
-    <logger name="com.foo.level" level="debug"/>
-    <logger name="com.foo.bar.level" level="error"/>
+    <logger name="com.foo" level="debug"/>
+    <logger name="com.foo.bar" level="error"/>
 
     <root level="info">
         <appender-ref ref="STDOUT"/>

diff --git a/testwebapp/src/main/webapp/WEB-INF/logback.xml b/testwebapp/src/main/webapp/WEB-INF/logback.xml
@@ -1,7 +1,7 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <configuration>
-    <logger name="com.foo.level" level="debug"/>
-    <logger name="com.foo.bar.level" level="error"/>
+    <logger name="com.foo" level="debug"/>
+    <logger name="com.foo.bar" level="error"/>
 
     <root level="info">
     </root>