Issue GoogleCloudPlatform#231 - Reworking logging for slfj4 + logback

+ Logging rollover is based on individual file size and rollover count + Checkstyle updates + Better testing
jetty-project · Jun 17, 2016 · 9ea2654 · 9ea2654
1 parent 0baeee5
commit 9ea2654
Show file tree

Hide file tree

Showing 15 changed files with 208 additions and 230 deletions.
diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonLayoutTest.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonLayoutTest.java
@@ -168,7 +168,6 @@ public void testCommonsLogging() {
       if (data.severity.equals("ERROR")) {
         assertThat("throwable", data.throwable,
             startsWith("java.lang.RuntimeException: Generic Error"));
-
       }
     }
   }
@@ -280,7 +279,6 @@ public static class LogTimestamp {
       public int nanos;
     }
 
-
     public LogTimestamp timestamp;
     public String severity;
     public String thread;

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
@@ -41,27 +41,30 @@ public static void load(String logbackXmlFile) throws AppEngineConfigException {
     LoggerContext rootContext =
         (LoggerContext) StaticLoggerBinder.getSingleton().getLoggerFactory();
 
-    // Load user provided logback XML
+    // Reset root
+    rootContext.reset();
+
+    // Load user provided logback XML (aka the User Configuration)
     ContextInitializer initializer = new ContextInitializer(rootContext);
 
     if ((logbackXmlFile != null) && (logbackXmlFile.length() > 0)) {
       System.setProperty(LOGGING_CONFIGURATION_KEY, logbackXmlFile);
       try {
         initializer.autoConfig();
+        System.err.println("## Initialized User Logging from " + logbackXmlFile);
       } catch (JoranException e) {
         throw new AppEngineConfigException(e);
       }
     }
 
-    // Load the system logback XML
+    // Load the system logback XML (aka the System Configuration)
     try {
       Enumeration<URL> configUrls =
-          VmRuntimeLogging.class.getClass().getClassLoader().getResources("logback.xml");
+          VmRuntimeLogging.class.getClassLoader().getResources("logback.xml");
       while (configUrls.hasMoreElements()) {
         URL url = configUrls.nextElement();
-        if (url.toExternalForm().endsWith("resources/logback.xml")) {
-          initializer.configureByResource(url);
-        }
+        System.err.println("## Initialized System Logging from " + url);
+        initializer.configureByResource(url);
       }
     } catch (JoranException | IOException e) {
       throw new AppEngineConfigException(e);

diff --git a/jetty9-base/src/main/jetty-base/resources/logback.xml b/jetty9-base/src/main/jetty-base/resources/logback.xml
@@ -7,12 +7,15 @@
 
     <appender name="CloudDebugger" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <file>/var/log/app_engine/app.%i.log.json</file>
-        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+        <encoder class="com.google.apphosting.logging.JsonEncoder" />
+        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
             <fileNamePattern>app.%i.log.json</fileNamePattern>
-            <maxHistory>30</maxHistory>
+            <minIndex>1</minIndex>
+            <maxIndex>10</maxIndex>
         </rollingPolicy>
-
-        <encoder class="com.google.apphosting.logging.JsonLayout" />
+        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
+            <maxFileSize>5MB</maxFileSize>
+        </triggeringPolicy>
     </appender>
 
     <root level="info">

diff --git a/jetty9-compat-base/pom.xml b/jetty9-compat-base/pom.xml
@@ -77,20 +77,9 @@
     </dependency>
 
     <dependency>
-      <groupId>junit</groupId>
-      <artifactId>junit</artifactId>
-      <scope>test</scope>
-    </dependency>
-    <dependency>
-      <groupId>org.hamcrest</groupId>
-      <artifactId>hamcrest-library</artifactId>
-      <version>1.3</version>
-      <scope>test</scope>
-    </dependency>
-    <dependency>
-      <groupId>org.hamcrest</groupId>
-      <artifactId>hamcrest-core</artifactId>
-      <version>1.3</version>
+      <groupId>org.eclipse.jetty.toolchain</groupId>
+      <artifactId>jetty-test-helper</artifactId>
+      <version>4.0</version>
       <scope>test</scope>
     </dependency>
     <dependency>

diff --git a/...pat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java b/...pat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java
@@ -43,6 +43,7 @@
 import com.google.apphosting.vmruntime.VmRuntimeLogging;
 import com.google.apphosting.vmruntime.VmRuntimeUtils;
 import com.google.apphosting.vmruntime.VmTimer;
+
 import org.eclipse.jetty.quickstart.PreconfigureDescriptorProcessor;
 import org.eclipse.jetty.quickstart.QuickStartDescriptorGenerator;
 import org.eclipse.jetty.security.ConstraintSecurityHandler;
@@ -83,14 +84,10 @@ public class VmRuntimeWebAppContext extends WebAppContext
   // It's undesirable to have the user app override classes provided by us.
   // So we mark them as Jetty system classes, which cannot be overridden.
   private static final String[] SYSTEM_CLASSES = {
-    // The trailing dot means these are all Java packages, not individual classes.
-    "com.google.appengine.api.",
-    "com.google.appengine.tools.",
-    "com.google.apphosting.",
-    "com.google.cloud.sql.jdbc.",
-    "com.google.protos.cloud.sql.",
-    "com.google.storage.onestore.",
-  };
+      // The trailing dot means these are all Java packages, not individual classes.
+      "com.google.appengine.api.", "com.google.appengine.tools.", "com.google.apphosting.",
+      "com.google.cloud.sql.jdbc.", "com.google.protos.cloud.sql.",
+      "com.google.storage.onestore.",};
   // constant. If it's much larger than this we may need to
   // restructure the code a bit.
   protected static final int MAX_RESPONSE_SIZE = 32 * 1024 * 1024;
@@ -108,34 +105,32 @@ public class VmRuntimeWebAppContext extends WebAppContext
 
   static {
     // Set SPI classloader priority to prefer the WebAppClassloader.
-    System.setProperty(
-        ServiceFactoryFactory.USE_THREAD_CONTEXT_CLASSLOADER_PROPERTY, Boolean.TRUE.toString());
+    System.setProperty(ServiceFactoryFactory.USE_THREAD_CONTEXT_CLASSLOADER_PROPERTY,
+        Boolean.TRUE.toString());
     // Use thread context class loader for memcache deserialization.
-    System.setProperty(
-        MemcacheSerialization.USE_THREAD_CONTEXT_CLASSLOADER_PROPERTY, Boolean.TRUE.toString());
+    System.setProperty(MemcacheSerialization.USE_THREAD_CONTEXT_CLASSLOADER_PROPERTY,
+        Boolean.TRUE.toString());
   }
 
   // List of Jetty configuration only needed if the quickstart process has been
   // executed, so we do not need the webinf, wedxml, fragment and annotation configurations
   // because they have been executed via the SDK.
-  private static final String[] quickstartConfigurationClasses = {
-    org.eclipse.jetty.quickstart.QuickStartConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.plus.webapp.EnvConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.plus.webapp.PlusConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.webapp.JettyWebXmlConfiguration.class.getCanonicalName()
-  };
+  private static final String[] quickstartConfigurationClasses =
+      {org.eclipse.jetty.quickstart.QuickStartConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.plus.webapp.EnvConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.plus.webapp.PlusConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.webapp.JettyWebXmlConfiguration.class.getCanonicalName()};
 
   // List of all the standard Jetty configurations that need to be executed when there
   // is no quickstart-web.xml.
-  private static final String[] preconfigurationClasses = {
-    org.eclipse.jetty.webapp.WebInfConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.webapp.WebXmlConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.webapp.MetaInfConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.webapp.FragmentConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.plus.webapp.EnvConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.plus.webapp.PlusConfiguration.class.getCanonicalName(),
-    org.eclipse.jetty.annotations.AnnotationConfiguration.class.getCanonicalName()
-  };
+  private static final String[] preconfigurationClasses =
+      {org.eclipse.jetty.webapp.WebInfConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.webapp.WebXmlConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.webapp.MetaInfConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.webapp.FragmentConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.plus.webapp.EnvConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.plus.webapp.PlusConfiguration.class.getCanonicalName(),
+          org.eclipse.jetty.annotations.AnnotationConfiguration.class.getCanonicalName()};
 
   public String getQuickstartWebXml() {
     return quickstartWebXml;
@@ -147,7 +142,7 @@ public VmMetadataCache getMetadataCache() {
 
   /**
    * Set the quickstart WebXml.
-   *
+   * <p>
    * <p> If set, this context will not start, rather it will generate the
    * quickstart-web.xml file and then stop the server. If not set, the context will start normally
    * </p>
@@ -237,11 +232,10 @@ DatastoreService getDatastoreService() {
    * @return A List of SessionStores in write order.
    */
   private static List<SessionStore> createSessionStores(AppEngineWebXml appEngineWebXml) {
-    DatastoreSessionStore datastoreSessionStore =
-        appEngineWebXml.getAsyncSessionPersistence()
-            ? new DeferredDatastoreSessionStore(
-                appEngineWebXml.getAsyncSessionPersistenceQueueName())
-            : new DatastoreSessionStore();
+    DatastoreSessionStore datastoreSessionStore = appEngineWebXml.getAsyncSessionPersistence()
+                                                  ? new DeferredDatastoreSessionStore(
+        appEngineWebXml.getAsyncSessionPersistenceQueueName())
+                                                  : new DatastoreSessionStore();
     // Write session data to the datastore before we write to memcache.
     return Arrays.asList(datastoreSessionStore, new MemcacheSessionStore());
   }
@@ -255,8 +249,8 @@ public VmRuntimeWebAppContext() {
 
     // Configure the Jetty SecurityHandler to understand our method of authentication
     // (via the UserService). Only the default ConstraintSecurityHandler is supported.
-    AppEngineAuthentication.configureSecurityHandler(
-        (ConstraintSecurityHandler) getSecurityHandler(), this);
+    AppEngineAuthentication
+        .configureSecurityHandler((ConstraintSecurityHandler) getSecurityHandler(), this);
 
     setMaxFormContentSize(MAX_RESPONSE_SIZE);
     setConfigurationClasses(preconfigurationClasses);
@@ -271,7 +265,7 @@ public VmRuntimeWebAppContext() {
 
   /**
    * Initialize the WebAppContext for use by the VmRuntime.
-   *
+   * <p>
    * <p>
    * This method initializes the WebAppContext by setting the context path and
    * application folder. It will also parse the appengine-web.xml file provided to
@@ -280,19 +274,14 @@ public VmRuntimeWebAppContext() {
    *
    * @param appengineWebXmlFile The appengine-web.xml file path (relative to appDir).
    * @throws AppEngineConfigException If there was a problem finding or parsing the
-   *         appengine-web.xml configuration.
-   * @throws IOException If the runtime was unable to find/read appDir.
+   *                                  appengine-web.xml configuration.
+   * @throws IOException              If the runtime was unable to find/read appDir.
    */
   public void init(String appengineWebXmlFile) throws AppEngineConfigException, IOException {
     String appDir = getBaseResource().getFile().getCanonicalPath();
-    defaultEnvironment =
-        VmApiProxyEnvironment.createDefaultContext(
-            System.getenv(),
-            metadataCache,
-            VmRuntimeUtils.getApiServerAddress(),
-            wallclockTimer,
-            VmRuntimeUtils.ONE_DAY_IN_MILLIS,
-            appDir);
+    defaultEnvironment = VmApiProxyEnvironment
+        .createDefaultContext(System.getenv(), metadataCache, VmRuntimeUtils.getApiServerAddress(),
+            wallclockTimer, VmRuntimeUtils.ONE_DAY_IN_MILLIS, appDir);
     ApiProxy.setEnvironmentForCurrentThread(defaultEnvironment);
     if (ApiProxy.getEnvironmentFactory() == null) {
       // Need the check above since certain unit tests initialize the context multiple times.
@@ -364,15 +353,10 @@ class RequestContext extends HttpServletRequestAdapter {
 
     RequestContext(Request request) {
       super(request);
-      requestSpecificEnvironment =
-          VmApiProxyEnvironment.createFromHeaders(
-              System.getenv(),
-              metadataCache,
-              this,
-              VmRuntimeUtils.getApiServerAddress(),
-              wallclockTimer,
-              VmRuntimeUtils.ONE_DAY_IN_MILLIS,
-              defaultEnvironment);
+      requestSpecificEnvironment = VmApiProxyEnvironment
+          .createFromHeaders(System.getenv(), metadataCache, this,
+              VmRuntimeUtils.getApiServerAddress(), wallclockTimer,
+              VmRuntimeUtils.ONE_DAY_IN_MILLIS, defaultEnvironment);
       if (requestSpecificEnvironment.isRequestTicket()) {
         final HttpOutput httpOutput = request.getResponse().getHttpOutput();
         final HttpOutput.Interceptor nextOutput = httpOutput.getInterceptor();
@@ -386,21 +370,17 @@ VmApiProxyEnvironment getRequestSpecificEnvironment() {
 
     @Override
     public String toString() {
-      return String.format(
-          "RequestContext@%x %s==%s",
-          hashCode(),
-          request.getRequestURI(),
+      return String.format("RequestContext@%x %s==%s", hashCode(), request.getRequestURI(),
           requestSpecificEnvironment);
     }
   }
 
+
   public class ContextListener
       implements ContextHandler.ContextScopeListener, ServletRequestListener {
     @Override
-    public void enterScope(
-        org.eclipse.jetty.server.handler.ContextHandler.Context context,
-        Request baseRequest,
-        Object reason) {
+    public void enterScope(org.eclipse.jetty.server.handler.ContextHandler.Context context,
+        Request baseRequest, Object reason) {
       RequestContext requestContext = getRequestContext(baseRequest);
       if (requestContext == null) {
         logger.fine("enterScope no request");
@@ -439,32 +419,32 @@ public void requestDestroyed(ServletRequestEvent sre) {
         logger.fine("requestDestroyed " + getRequestContext(baseRequest));
       }
       if (request.isAsyncStarted()) {
-        request
-            .getAsyncContext()
-            .addListener(
-                new AsyncListener() {
-                  @Override
-                  public void onTimeout(AsyncEvent event) throws IOException {}
-
-                  @Override
-                  public void onStartAsync(AsyncEvent event) throws IOException {}
-
-                  @Override
-                  public void onError(AsyncEvent event) throws IOException {}
-
-                  @Override
-                  public void onComplete(AsyncEvent event) throws IOException {
-                    complete(baseRequest);
-                  }
-                });
+        request.getAsyncContext().addListener(new AsyncListener() {
+          @Override
+          public void onTimeout(AsyncEvent event) throws IOException {
+          }
+
+          @Override
+          public void onStartAsync(AsyncEvent event) throws IOException {
+          }
+
+          @Override
+          public void onError(AsyncEvent event) throws IOException {
+          }
+
+          @Override
+          public void onComplete(AsyncEvent event) throws IOException {
+            complete(baseRequest);
+          }
+        });
       } else {
         complete(baseRequest);
       }
     }
 
     @Override
-    public void exitScope(
-        org.eclipse.jetty.server.handler.ContextHandler.Context context, Request baseRequest) {
+    public void exitScope(org.eclipse.jetty.server.handler.ContextHandler.Context context,
+        Request baseRequest) {
       if (logger.isLoggable(Level.FINE)) {
         if (baseRequest == null) {
           logger.fine("exitScope");
@@ -499,8 +479,8 @@ private void complete(Request baseRequest) {
       }
 
       // Interrupt all API calls
-      VmRuntimeUtils.interruptRequestThreads(
-          env, VmRuntimeUtils.MAX_REQUEST_THREAD_INTERRUPT_WAIT_TIME_MS);
+      VmRuntimeUtils
+          .interruptRequestThreads(env, VmRuntimeUtils.MAX_REQUEST_THREAD_INTERRUPT_WAIT_TIME_MS);
       env.waitForAllApiCallsToComplete(VmRuntimeUtils.MAX_REQUEST_THREAD_API_CALL_WAIT_MS);
     }
 
@@ -510,19 +490,14 @@ void handleAbandonedTxns(Collection<Transaction> txns) {
       for (Transaction txn : txns) {
         try {
           logger.warning(
-              "Request completed without committing or rolling back transaction with id "
-                  + txn.getId()
-                  + ".  Transaction will be rolled back.");
+              "Request completed without committing or rolling back transaction with id " + txn
+                  .getId() + ".  Transaction will be rolled back.");
           txn.rollback();
         } catch (Exception e) {
           // We swallow exceptions so that there is no risk of our cleanup
           // impacting the actual result of the request.
-          logger.log(
-              Level.WARNING,
-              "Swallowing an exception we received while trying to rollback "
-                  + "abandoned transaction with id "
-                  + txn.getId(),
-              e);
+          logger.log(Level.WARNING, "Swallowing an exception we received while trying to rollback "
+              + "abandoned transaction with id " + txn.getId(), e);
         }
       }
     }

diff --git a/jetty9-compat-base/src/main/jetty-base/resources/logback.xml b/jetty9-compat-base/src/main/jetty-base/resources/logback.xml
@@ -7,12 +7,15 @@
 
     <appender name="CloudDebugger" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <file>/var/log/app_engine/app.%i.log.json</file>
-        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+        <encoder class="com.google.apphosting.logging.JsonEncoder" />
+        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
             <fileNamePattern>app.%i.log.json</fileNamePattern>
-            <maxHistory>30</maxHistory>
+            <minIndex>1</minIndex>
+            <maxIndex>10</maxIndex>
         </rollingPolicy>
-
-        <encoder class="com.google.apphosting.logging.JsonLayout" />
+        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
+            <maxFileSize>5MB</maxFileSize>
+        </triggeringPolicy>
     </appender>
 
     <root level="info">