Issue #333 Async FileHandler (#334)

* Issue #333 Async FileHandler

* Issue #333 Simplified Async FileHandler

* Issue #333 Use thread ID

Author: gregw

appengine-java-logging/src/main/java/com/google/apphosting/logging/JsonFormatter.java

@@ -52,7 +52,7 @@ public String format(LogRecord record) {
           .value(timestamp.getNano())
           .endObject();
       writer.name("severity").value(severity(record.getLevel()));
-      writer.name("thread").value(Thread.currentThread().getName());
+      writer.name("thread").value(Integer.toHexString(record.getThreadID()));
       writer.name("message").value(formatMessage(record));
 
       // If there is a LogContext associated with this thread then add its properties.

appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java

@@ -48,7 +48,7 @@ public void formatProducesExpectedJsonData() throws Exception {
     assertEquals("INFO", data.severity);
     assertEquals(12345, data.timestamp.seconds);
     assertEquals(678_000_000, data.timestamp.nanos);
-    assertEquals(Thread.currentThread().getName(), data.thread);
+    assertEquals(Long.toHexString(Thread.currentThread().getId()), data.thread);
     assertEquals("logger: message", data.message);
     assertEquals("abcdef", data.traceId);
   }

appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java

@@ -19,18 +19,20 @@
 import com.google.apphosting.logging.JsonFormatter;
 
 import java.io.IOException;
-import java.util.logging.ConsoleHandler;
+import java.util.concurrent.BlockingQueue;
+import java.util.concurrent.LinkedBlockingQueue;
+import java.util.concurrent.TimeUnit;
 import java.util.logging.FileHandler;
 import java.util.logging.Handler;
 import java.util.logging.Level;
 import java.util.logging.LogManager;
+import java.util.logging.LogRecord;
 import java.util.logging.Logger;
 
 /**
  * {@code VmRuntimeFileLogHandler} is installed on the root logger. It converts all messages
  * to the json format understood by the cloud logging agent and logs to a file in a volume shared
  * with the cloud logging agent.
- *
  */
 public class VmRuntimeFileLogHandler extends FileHandler {
 
@@ -45,11 +47,16 @@ public class VmRuntimeFileLogHandler extends FileHandler {
   private static final int LOG_MAX_SIZE = 100 * 1024 * 1024;
   private static final int LOG_MAX_FILES = 3;
   public static final String JAVA_UTIL_LOGGING_CONFIG_PROPERTY = "java.util.logging.config.file";
-
+  
+  private static final LogRecord CLOSE_RECORD = new LogRecord(Level.ALL, "CLOSE");
+  private final BlockingQueue<LogRecord> queue = new LinkedBlockingQueue<>();
+  
+  
   private VmRuntimeFileLogHandler() throws IOException {
     super(fileLogPattern(), LOG_MAX_SIZE, LOG_MAX_FILES, true);
     setLevel(Level.FINEST);
     setFormatter(new JsonFormatter());
+    new LoggerThread().start();
   }
 
   private static String fileLogPattern() {
@@ -102,4 +109,39 @@ private static void reloadLoggingProperties(LogManager logManager) {
       System.err.println(e.getClass().getName() + ": " + e.getMessage());
     }
   }
+
+  @Override
+  public void close() throws SecurityException {
+    super.close();
+    queue.offer(CLOSE_RECORD);
+  }
+
+  @Override
+  public void publish(LogRecord record) {
+    if (isLoggable(record)) {
+      queue.offer(record);
+    }
+  }
+
+  private void superPublish(LogRecord record) {
+    super.publish(record);
+  }
+  
+  class LoggerThread extends Thread {
+    @Override
+    public void run() {
+      while (true) {
+        try {
+          LogRecord record = queue.poll(1, TimeUnit.HOURS);
+          if (record == CLOSE_RECORD) {
+            return;
+          } else {
+            superPublish(record);
+          }
+        } catch (InterruptedException e) {
+          return;
+        }
+      }
+    }
+  }
 }

jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/LoggingIT.java

@@ -52,6 +52,9 @@ public void testGet() throws Exception {
 
     assertTrue(log.exists());
 
+    // wait for async write
+    Thread.sleep(1000);
+    
     // Look for the log entry with our query string
     try (BufferedReader in =
         new BufferedReader(
@@ -71,12 +74,12 @@ public void testGet() throws Exception {
       data = new Gson().fromJson(line, JsonData.class);
       assertThat(data.severity, equalTo("ERROR"));
       assertThat(
-          data.message, org.hamcrest.Matchers.containsString("LoggingServlet doGet: not null"));
+          data.message, org.hamcrest.Matchers.containsString("com.foo.bar: 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.message, org.hamcrest.Matchers.containsString("com.foo.bar: null"));
     }
   }