diff --git a/appengine-java-logging/pom.xml b/appengine-java-logging/pom.xml index 2a4db97..80c4b17 100644 --- a/appengine-java-logging/pom.xml +++ b/appengine-java-logging/pom.xml @@ -29,12 +29,46 @@ jar Support code for writing log files compatible with Google App Engine + + 1.7.16 + + + + + org.slf4j + slf4j-api + ${slf4j.version} + + + + org.slf4j + jcl-over-slf4j + ${slf4j.version} + + + org.slf4j + log4j-over-slf4j + ${slf4j.version} + + + + org.slf4j + slf4j-jdk14 + ${slf4j.version} + + com.google.code.gson gson + + org.hamcrest + hamcrest-library + test + + junit junit diff --git a/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java b/appengine-java-logging/src/main/java/com/google/apphosting/logging/CloudLoggingFileHandler.java similarity index 51% rename from appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java rename to appengine-java-logging/src/main/java/com/google/apphosting/logging/CloudLoggingFileHandler.java index 0fd07a7..4ab3fc9 100644 --- a/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java +++ b/appengine-java-logging/src/main/java/com/google/apphosting/logging/CloudLoggingFileHandler.java @@ -14,44 +14,45 @@ * limitations under the License. */ -package com.google.apphosting.vmruntime; - -import com.google.apphosting.logging.JsonFormatter; +package com.google.apphosting.logging; import java.io.IOException; -import java.util.logging.ConsoleHandler; import java.util.logging.FileHandler; import java.util.logging.Handler; import java.util.logging.Level; -import java.util.logging.LogManager; 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. - * + * A root level {@link java.util.logging.FileHandler} for interfacing with the GCloud logging + * console. It converts all logging events 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 { - +public class CloudLoggingFileHandler extends FileHandler implements SystemLogger { // This exists for testing purposes only. If set, the cloud logger may lose logs. public static final String LOG_DIRECTORY_PROPERTY = "com.google.apphosting.logs"; public static final String LOG_PATTERN_CONFIG_PROPERTY = - "com.google.apphosting.vmruntime.VmRuntimeFileLogHandler.pattern"; + CloudLoggingFileHandler.class.getName() + ".pattern"; // Log files to /var/log/app_engine/app.[0-2].log.json private static final String DEFAULT_LOG_DIRECTORY = "/var/log/app_engine"; - private static final String DEFAULT_LOG_PATTERN = "app.%g.log.json"; + private static final String DEFAULT_LOG_PATTERN = "app.%u.%g.log.json"; private static final String APP_ENGINE_LOG_CONFIG_PATTERN_ENV = "APP_ENGINE_LOG_CONFIG_PATTERN"; - 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 int LOG_PER_FILE_SIZE = getConfigInt("limit", 100 * 1024 * 1024); + private static final int LOG_MAX_FILES = getConfigInt("count", 3); - private VmRuntimeFileLogHandler() throws IOException { - super(fileLogPattern(), LOG_MAX_SIZE, LOG_MAX_FILES, true); + public CloudLoggingFileHandler() throws IOException { + super(fileLogPattern(), LOG_PER_FILE_SIZE, LOG_MAX_FILES, true); setLevel(Level.FINEST); setFormatter(new JsonFormatter()); } + private static int getConfigInt(String suffix, int defValue) { + String val = System.getProperty(CloudLoggingFileHandler.class.getName() + '.' + suffix); + if (val == null) { + return defValue; + } + return Integer.parseInt(val); + } + private static String fileLogPattern() { String pattern = System.getenv(APP_ENGINE_LOG_CONFIG_PATTERN_ENV); // For Cloud SDK usage only for local Jetty processes. @@ -72,34 +73,18 @@ private static String fileLogPattern() { return directory + "/" + DEFAULT_LOG_PATTERN; } - /** - * Initialize the {@code VmRuntimeFileLogHandler} by installing it on the root logger. - */ - public static void init() throws IOException { - reloadLoggingProperties(LogManager.getLogManager()); + @Override + public void configure() throws IOException { Logger rootLogger = Logger.getLogger(""); + + // Look for the expected Handlers for (Handler handler : rootLogger.getHandlers()) { - if (handler instanceof VmRuntimeFileLogHandler) { - return; // Already installed. + if (handler instanceof CloudLoggingFileHandler) { + // Nothing else to do, return + return; } } - rootLogger.addHandler(new VmRuntimeFileLogHandler()); - } - /** - * Reloads logging to pick up changes to the java.util.logging.config.file system property. - */ - private static void reloadLoggingProperties(LogManager logManager) { - String logging = System.getProperty(VmRuntimeFileLogHandler.JAVA_UTIL_LOGGING_CONFIG_PROPERTY); - if (logging == null) { - return; - } - try { - logManager.readConfiguration(); - } catch (SecurityException | IOException e) { - e.printStackTrace(); - System.err.println("Warning: caught exception when reading logging properties."); - System.err.println(e.getClass().getName() + ": " + e.getMessage()); - } + rootLogger.addHandler(new CloudLoggingFileHandler()); } } diff --git a/appengine-java-logging/src/main/java/com/google/apphosting/logging/CoreLogging.java b/appengine-java-logging/src/main/java/com/google/apphosting/logging/CoreLogging.java new file mode 100644 index 0000000..5cbe1e1 --- /dev/null +++ b/appengine-java-logging/src/main/java/com/google/apphosting/logging/CoreLogging.java @@ -0,0 +1,149 @@ +/* + * 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.apphosting.logging; + +import java.io.File; +import java.io.FileInputStream; +import java.io.IOException; +import java.util.ServiceLoader; +import java.util.logging.LogManager; + +/** + * Logging Core behavior. + */ +public class CoreLogging { + public static final String JAVA_UTIL_LOGGING_CONFIG_PROPERTY = "java.util.logging.config.file"; + private static final boolean DEBUG = Boolean.getBoolean("com.google.apphosting.logging.DEBUG"); + + /** + * Initialize the java.util.logging Environment. + *

+ * Order is: + *

    + *
  1. Apply App (User) Configuration
    2. + *
  2. Apply System Mandated Configuration
    3. + *
+ *

+ * + * @param appConfigFile the filename for the (optional) app specific java.util.logging + * properties file configuration. + */ + public static void init(File appConfigFile) throws IOException { + // Use App (User) Configuration specified as a file parameter + if (appConfigFile != null && appConfigFile.exists()) { + debug("Loading App Config (from file): %s", appConfigFile); + appConfig(appConfigFile); + } else { + // Use App (User) Configuration specified as a System property + String julConfigFile = System.getProperty(JAVA_UTIL_LOGGING_CONFIG_PROPERTY); + if (julConfigFile != null) { + File configFile = new File(julConfigFile); + if (configFile.exists()) { + debug("Loading App Config (from property): %s", appConfigFile); + appConfig(configFile); + } else { + warning("Config System Property (%s) points to invalid file: %s", + JAVA_UTIL_LOGGING_CONFIG_PROPERTY, appConfigFile.getAbsolutePath()); + } + } else { + debug("No App Config"); + } + } + + // Manually Adjust Configuration to support System Logging Requirements + systemConfig(); + } + + /** + * Convenience method for {@link #init(File)}. + * + * @param appConfigFilename the filename of the config file (or null) + * @throws IOException if unable to configure the logging + */ + public static void init(String appConfigFilename) throws IOException { + File appConfigFile = null; + if (appConfigFilename != null) { + appConfigFile = new File(appConfigFilename); + } + init(appConfigFile); + } + + private static void appConfig(File configFile) { + try (FileInputStream is = new FileInputStream(configFile)) { + LogManager logManager = LogManager.getLogManager(); + logManager.reset(); // close & remove existing handlers, reset existing logger levels + logManager.readConfiguration(is); + } catch (SecurityException | IOException e) { + warning("Caught exception when reading logging properties: %s", configFile + .getAbsolutePath()); + e.printStackTrace(System.err); + } + } + + /** + * Manually Configure the System Level requirements for java.util.logging. + */ + private static void systemConfig() throws IOException { + // Since System Loggers can arrive from deep within the various compat layers, it + // makes sense to use the ServiceLoader to obtain references to specific System loggers + // that need to be initialized during this step in the logging initialization. + + int count = 0; + ServiceLoader serviceLoader = ServiceLoader.load(SystemLogger.class); + for (SystemLogger systemLogger : serviceLoader) { + debug("Executing SystemLogger: %s", systemLogger.getClass().getName()); + systemLogger.configure(); + count++; + } + debug("Initialized %d SystemLogger(s)", count); + } + + /** + * Non JUL debug logging. + *

+ * As this class sets up the java.util.logging, + * we can't reliable start using logging yet. + *

+ *

+ * Note: by default this does not produce any output. + * Set the System.property {@code com.google.apphosting.logging.DEBUG} to + * true to see this output. + *

+ * + * @param format the format of the debug line + * @param args the arguments of the debug line + */ + private static void debug(String format, Object... args) { + if (DEBUG) { + System.err.printf("[CoreLogging:DEBUG] " + format + "%n", args); + } + } + + /** + * Non JUL warnings logging. + *

+ * As this class sets up the java.util.logging, + * we can't reliable start using logging yet. + *

+ * + * @param format the format of the debug line + * @param args the arguments of the debug line + */ + private static void warning(String format, Object... args) { + System.err.printf("[CoreLogging:WARNING] " + format + "%n", args); + } +} diff --git a/appengine-java-logging/src/main/java/com/google/apphosting/logging/LogContext.java b/appengine-java-logging/src/main/java/com/google/apphosting/logging/LogContext.java index 7640f47..59b55db 100644 --- a/appengine-java-logging/src/main/java/com/google/apphosting/logging/LogContext.java +++ b/appengine-java-logging/src/main/java/com/google/apphosting/logging/LogContext.java @@ -23,8 +23,9 @@ /** * The context for logging information associated with the current Thread. *

- *

This is an implementation of a Mapped Diagnostic Context for use with the java.util.logging + * This is an implementation of a Mapped Diagnostic Context for use with the java.util.logging * framework. + *

*/ public class LogContext extends ConcurrentHashMap { diff --git a/appengine-java-logging/src/main/java/com/google/apphosting/logging/SystemLogger.java b/appengine-java-logging/src/main/java/com/google/apphosting/logging/SystemLogger.java new file mode 100644 index 0000000..0060e36 --- /dev/null +++ b/appengine-java-logging/src/main/java/com/google/apphosting/logging/SystemLogger.java @@ -0,0 +1,32 @@ +/* + * 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.apphosting.logging; + +import java.io.IOException; + +/** + * Interface for any component wanting to participate in the System Logging level + * configuration. + */ +public interface SystemLogger { + /** + * Configure your System Level Logger on this event. + * + * @throws IOException if unable to configure the System Level Logger + */ + void configure() throws IOException; +} diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/CommonsLoggingExample.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/CommonsLoggingExample.java new file mode 100644 index 0000000..304280e --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/CommonsLoggingExample.java @@ -0,0 +1,37 @@ +/* + * 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.apphosting.logging; + +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + +import java.util.concurrent.ThreadLocalRandom; + +class CommonsLoggingExample implements Runnable { + private static final Log logger = LogFactory.getLog(CommonsLoggingExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + logger.trace(String.format("A CommonsLogging Trace Event: %d", rand.nextInt())); + logger.debug(String.format("A CommonsLogging Debug Event: %d", rand.nextInt())); + logger.info(String.format("A CommonsLogging Info Event: %d", rand.nextInt())); + logger.warn(String.format("A CommonsLogging Warn Event: %d", rand.nextInt())); + logger.error(String.format("A CommonsLogging Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonCaptureHandler.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonCaptureHandler.java new file mode 100644 index 0000000..013f1df --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonCaptureHandler.java @@ -0,0 +1,44 @@ +/* + * 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.apphosting.logging; + +import java.util.ArrayList; +import java.util.List; +import java.util.logging.Handler; +import java.util.logging.LogRecord; + +public final class JsonCaptureHandler extends Handler { + private final JsonFormatter formatter = new JsonFormatter(); + private List events = new ArrayList<>(); + + @Override + public void publish(LogRecord record) { + events.add(formatter.format(record)); + } + + @Override + public void flush() { + } + + @Override + public void close() { + } + + public List getEvents() { + return events; + } +} diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java index 45cdc55..10bc694 100644 --- a/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java @@ -16,6 +16,10 @@ package com.google.apphosting.logging; +import static org.hamcrest.Matchers.containsString; +import static org.hamcrest.Matchers.greaterThanOrEqualTo; +import static org.hamcrest.Matchers.is; +import static org.hamcrest.Matchers.startsWith; import static org.hamcrest.core.StringEndsWith.endsWith; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertThat; @@ -23,17 +27,32 @@ import com.google.gson.Gson; +import org.junit.Before; import org.junit.Test; import java.io.BufferedReader; import java.io.StringReader; +import java.time.Instant; +import java.util.List; import java.util.logging.Level; import java.util.logging.LogRecord; +import java.util.logging.Logger; public class JsonFormatterTest { private JsonFormatter formatter = new JsonFormatter(); + private JsonCaptureHandler capturingHandler; + + @Before + public void initLoggingCapture() { + Logger root = Logger.getLogger(""); + root.setLevel(Level.FINE); + + capturingHandler = new JsonCaptureHandler(); + root.addHandler(capturingHandler); + } + @Test public void formatProducesExpectedJsonData() throws Exception { LogRecord record = new LogRecord(Level.INFO, "message"); @@ -85,17 +104,152 @@ public void messageIncludesStackTrace() throws Exception { BufferedReader reader = new BufferedReader(new StringReader(message)); assertEquals("logger: message", reader.readLine()); assertEquals("java.lang.Throwable: thrown", reader.readLine()); - assertTrue( - reader - .readLine() - .startsWith("\tat " + getClass().getName() + ".messageIncludesStackTrace")); + assertTrue(reader.readLine() + .startsWith("\tat " + getClass().getName() + ".messageIncludesStackTrace")); } + @Test + public void testCommonsLogging() { + Instant now = Instant.now(); + String expectedThreadName = Thread.currentThread().getName(); + + // Generate Events from Commons Logging + new CommonsLoggingExample().run(); + + // Verify that event was captured by slf4j -> java.util.logging + String[][] expected = new String[][] {{"DEBUG", "A CommonsLogging Debug Event: "}, + {"INFO", "A CommonsLogging Info Event: "}, {"WARNING", "A CommonsLogging Warn Event: "}, + {"ERROR", "A CommonsLogging Error Event: "}}; + + List events = capturingHandler.getEvents(); + assertThat("Events", events.size(), is(expected.length)); + + for (int i = 0; i < events.size(); i++) { + String logLine = events.get(i); + JsonData data = new Gson().fromJson(logLine, JsonData.class); + assertThat("severity", data.severity, is(expected[i][0])); + assertThat("timestamp.seconds", data.timestamp.seconds, + greaterThanOrEqualTo(now.getEpochSecond())); + assertThat("timestamp.nanos", data.timestamp.nanos, greaterThanOrEqualTo(now.getNano())); + assertThat("thread name", data.thread, is(expectedThreadName)); + assertThat("logger message", data.message, + startsWith(CommonsLoggingExample.class.getName() + " run: " + expected[i][1])); + if (data.severity.equals("ERROR")) { + assertThat("throwable", data.message, + containsString("java.lang.RuntimeException: Generic Error")); + } + } + } + + @Test + public void testJavaUtilLogging() { + Instant now = Instant.now(); + String expectedThreadName = Thread.currentThread().getName(); + + // Generate Events from java.util.logging + new JulExample().run(); + + // Verify that event was captured by slf4j -> java.util.logging + String[][] expected = + new String[][] {{"DEBUG", "A JUL Fine Event: "}, {"DEBUG", "A JUL Config Event: "}, + {"INFO", "A JUL Info Event: "}, {"WARNING", "A JUL Warning Event: "}, + {"ERROR", "A JUL Severe Event: "}}; + + List events = capturingHandler.getEvents(); + assertThat("Events", events.size(), is(expected.length)); + + for (int i = 0; i < events.size(); i++) { + String logLine = events.get(i); + System.out.printf("logLine[%d] = %s", i, logLine); + JsonData data = new Gson().fromJson(logLine, JsonData.class); + assertThat("severity", data.severity, is(expected[i][0])); + assertThat("timestamp.seconds", data.timestamp.seconds, + greaterThanOrEqualTo(now.getEpochSecond())); + assertThat("timestamp.nanos", data.timestamp.nanos, greaterThanOrEqualTo(now.getNano())); + assertThat("thread name", data.thread, is(expectedThreadName)); + assertThat("logger message", data.message, + startsWith(JulExample.class.getName() + " run: " + expected[i][1])); + if (data.severity.equals("ERROR")) { + assertThat("throwable", data.message, + containsString("java.lang.RuntimeException: Generic Error")); + } + } + } + + @Test + public void testLog4jLogging() { + Instant now = Instant.now(); + String expectedThreadName = Thread.currentThread().getName(); + + // Generate Events from Apache Log4j Logging + new Log4jExample().run(); + + // Verify that event was captured by slf4j -> java.util.logging + String[][] expected = + new String[][] {{"DEBUG", "A Log4j Debug Event: "}, {"INFO", "A Log4j Info Event: "}, + {"WARNING", "A Log4j Warn Event: "}, {"ERROR", "A Log4j Error Event: "}}; + + List events = capturingHandler.getEvents(); + assertThat("Events", events.size(), is(expected.length)); + + for (int i = 0; i < events.size(); i++) { + String logLine = events.get(i); + System.out.printf("logLine[%d] = %s", i, logLine); + JsonData data = new Gson().fromJson(logLine, JsonData.class); + assertThat("severity", data.severity, is(expected[i][0])); + assertThat("timestamp.seconds", data.timestamp.seconds, + greaterThanOrEqualTo(now.getEpochSecond())); + assertThat("timestamp.nanos", data.timestamp.nanos, greaterThanOrEqualTo(now.getNano())); + assertThat("thread name", data.thread, is(expectedThreadName)); + assertThat("logger message", data.message, + startsWith(Log4jExample.class.getName() + " run: " + expected[i][1])); + if (data.severity.equals("ERROR")) { + assertThat("throwable", data.message, + containsString("java.lang.RuntimeException: Generic Error")); + } + } + } + + @Test + public void testSlf4jLogging() { + Instant now = Instant.now(); + String expectedThreadName = Thread.currentThread().getName(); + + // Generate Events from Slf4j Logging + new Slf4jExample().run(); + + // Verify that event was captured by slf4j -> java.util.logging + String[][] expected = + new String[][] {{"DEBUG", "A Slf4j Debug Event: "}, {"INFO", "A Slf4j Info Event: "}, + {"WARNING", "A Slf4j Warn Event: "}, {"ERROR", "A Slf4j Error Event: "}}; + + List events = capturingHandler.getEvents(); + assertThat("Events", events.size(), is(expected.length)); + + for (int i = 0; i < events.size(); i++) { + String logLine = events.get(i); + System.out.printf("logLine[%d] = %s", i, logLine); + JsonData data = new Gson().fromJson(logLine, JsonData.class); + assertThat("severity", data.severity, is(expected[i][0])); + assertThat("timestamp.seconds", data.timestamp.seconds, + greaterThanOrEqualTo(now.getEpochSecond())); + assertThat("timestamp.nanos", data.timestamp.nanos, greaterThanOrEqualTo(now.getNano())); + assertThat("thread name", data.thread, is(expectedThreadName)); + assertThat("logger message", data.message, + startsWith(Slf4jExample.class.getName() + " run: " + expected[i][1])); + if (data.severity.equals("ERROR")) { + assertThat("throwable", data.message, + containsString("java.lang.RuntimeException: Generic Error")); + } + } + } + + // 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; diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/JulExample.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JulExample.java new file mode 100644 index 0000000..35c7998 --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JulExample.java @@ -0,0 +1,38 @@ +/* + * 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.apphosting.logging; + +import java.util.concurrent.ThreadLocalRandom; +import java.util.logging.Level; +import java.util.logging.Logger; + +class JulExample implements Runnable { + public static final Logger logger = Logger.getLogger(JulExample.class.getName()); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + logger.log(Level.FINEST, "A JUL Finest Event: {0}", rand.nextInt()); + logger.log(Level.FINER, "A JUL Finer Event: {0}", rand.nextInt()); + logger.log(Level.FINE, "A JUL Fine Event: {0}", rand.nextInt()); + logger.log(Level.CONFIG, "A JUL Config Event: {0}", rand.nextInt()); + logger.log(Level.INFO, "A JUL Info Event: {0}", rand.nextInt()); + logger.log(Level.WARNING, "A JUL Warning Event: {0}", rand.nextInt()); + logger.log(Level.SEVERE, String.format("A JUL Severe Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/Log4jExample.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/Log4jExample.java new file mode 100644 index 0000000..df43747 --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/Log4jExample.java @@ -0,0 +1,36 @@ +/* + * 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.apphosting.logging; + +import org.apache.log4j.Logger; + +import java.util.concurrent.ThreadLocalRandom; + +class Log4jExample implements Runnable { + private static final Logger logger = Logger.getLogger(Log4jExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + logger.trace(String.format("A Log4j Trace Event: %d", rand.nextInt())); + logger.debug(String.format("A Log4j Debug Event: %d", rand.nextInt())); + logger.info(String.format("A Log4j Info Event: %d", rand.nextInt())); + logger.warn(String.format("A Log4j Warn Event: %d", rand.nextInt())); + logger.error(String.format("A Log4j Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} diff --git a/appengine-java-logging/src/test/java/com/google/apphosting/logging/Slf4jExample.java b/appengine-java-logging/src/test/java/com/google/apphosting/logging/Slf4jExample.java new file mode 100644 index 0000000..1af3563 --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/Slf4jExample.java @@ -0,0 +1,37 @@ +/* + * 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.apphosting.logging; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.util.concurrent.ThreadLocalRandom; + +class Slf4jExample implements Runnable { + private static final Logger logger = LoggerFactory.getLogger(Slf4jExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + logger.trace("A Slf4j Trace Event: {}", rand.nextInt()); + logger.debug("A Slf4j Debug Event: {}", rand.nextInt()); + logger.info("A Slf4j Info Event: {}", rand.nextInt()); + logger.warn("A Slf4j Warn Event: {}", rand.nextInt()); + logger.error(String.format("A Slf4j Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} diff --git a/appengine-managed-runtime/pom.xml b/appengine-managed-runtime/pom.xml index aa857c9..2959b33 100644 --- a/appengine-managed-runtime/pom.xml +++ b/appengine-managed-runtime/pom.xml @@ -53,11 +53,12 @@ org.apache.httpcomponents httpclient 4.4.1 - - - commons-logging - commons-logging - 1.2 + + + commons-logging + commons-logging + + commons-codec diff --git a/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmAppLogsWriter.java b/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmAppLogsWriter.java deleted file mode 100644 index 1600c7c..0000000 --- a/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmAppLogsWriter.java +++ /dev/null @@ -1,352 +0,0 @@ -/* - * 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.apphosting.vmruntime; - -import com.google.appengine.repackaged.com.google.common.base.Stopwatch; -import com.google.apphosting.api.ApiProxy; -import com.google.apphosting.api.ApiProxy.ApiConfig; -import com.google.apphosting.api.ApiProxy.LogRecord; -import com.google.apphosting.api.logservice.LogServicePb.FlushRequest; -import com.google.apphosting.api.logservice.LogServicePb.UserAppLogGroup; -import com.google.apphosting.api.logservice.LogServicePb.UserAppLogLine; - -import java.util.LinkedList; -import java.util.List; -import java.util.concurrent.ExecutionException; -import java.util.concurrent.Future; -import java.util.concurrent.TimeUnit; -import java.util.concurrent.TimeoutException; -import java.util.logging.Level; -import java.util.logging.Logger; - -/** - * {@code AppsLogWriter} is responsible for batching application logs - * for a single request and sending them back to the AppServer via the - * LogService.Flush API call. - * - *

The current algorithm used to send logs is as follows: - *

- * - *

This class is also responsible for splitting large log entries - * into smaller fragments, which is unrelated to the batching - * mechanism described above but is necessary to prevent the AppServer - * from truncating individual log entries. - * - *

This class is thread safe and all methods accessing local state are - * synchronized. Since each request have their own instance of this class the - * only contention possible is between the original request thread and and any - * child RequestThreads created by the request through the threading API. - * - */ -@Deprecated -class VmAppLogsWriter { - private static final Logger logger = Logger.getLogger(VmAppLogsWriter.class.getName()); - - // (Some constants below package scope for testability) - static final String LOG_CONTINUATION_SUFFIX = "\n"; - static final int LOG_CONTINUATION_SUFFIX_LENGTH = LOG_CONTINUATION_SUFFIX.length(); - static final String LOG_CONTINUATION_PREFIX = "\n"; - static final int LOG_CONTINUATION_PREFIX_LENGTH = LOG_CONTINUATION_PREFIX.length(); - static final int MIN_MAX_LOG_MESSAGE_LENGTH = 1024; - // Log flushes generally complete fast (6 ms at the median, 46ms at the 99th percentile). - static final int LOG_FLUSH_TIMEOUT_MS = 2000; - - private final int maxLogMessageLength; - private final int logCutLength; - private final int logCutLengthDiv10; - private final List buffer; - private final long maxBytesToFlush; - private long currentByteCount; - private final int maxSecondsBetweenFlush; - private int flushCount = 0; - private Future currentFlush; - private Stopwatch stopwatch; - - /** - * Construct an AppLogsWriter instance. - * - * @param buffer Buffer holding messages between flushes. - * @param maxBytesToFlush The maximum number of bytes of log message to - * allow in a single flush. The code flushes any cached logs before - * reaching this limit. If this is 0, AppLogsWriter will not start - * an intermediate flush based on size. - * @param maxLogMessageLength The maximum length of an individual log line. - * A single log line longer than this will be written as multiple log - * entries (with the continuation prefix/suffixes added to indicate this). - * @param maxFlushSeconds The amount of time to allow a log line to sit - * cached before flushing. Once a log line has been sitting for more - * than the specified time, all currently cached logs are flushed. If - * this is 0, no time based flushing occurs. - * N.B. because we only check the time on a log call, it is possible for - * a log to stay cached long after the specified time has been reached. - * Consider this example (assume maxFlushSeconds=60): the app logs a message - * when the handler starts but then does not log another message for 10 - * minutes. The initial log will stay cached until the second message - * is logged. - */ - public VmAppLogsWriter( - List buffer, - long maxBytesToFlush, - int maxLogMessageLength, - int maxFlushSeconds) { - this.buffer = buffer; - this.maxSecondsBetweenFlush = maxFlushSeconds; - - if (maxLogMessageLength < MIN_MAX_LOG_MESSAGE_LENGTH) { - String message = - String.format( - "maxLogMessageLength silly small (%s); setting maxLogMessageLength to %s", - maxLogMessageLength, - MIN_MAX_LOG_MESSAGE_LENGTH); - logger.warning(message); - this.maxLogMessageLength = MIN_MAX_LOG_MESSAGE_LENGTH; - } else { - this.maxLogMessageLength = maxLogMessageLength; - } - logCutLength = maxLogMessageLength - LOG_CONTINUATION_SUFFIX_LENGTH; - logCutLengthDiv10 = logCutLength / 10; - - // This should never happen, but putting here just in case. - if (maxBytesToFlush < this.maxLogMessageLength) { - String message = - String.format( - "maxBytesToFlush (%s) smaller than maxLogMessageLength (%s)", - maxBytesToFlush, - this.maxLogMessageLength); - logger.warning(message); - this.maxBytesToFlush = this.maxLogMessageLength; - } else { - this.maxBytesToFlush = maxBytesToFlush; - } - - // Always have a stopwatch even if we're not doing time based flushing - // to keep code a bit simpler - stopwatch = Stopwatch.createUnstarted(); - } - - /** - * Add the specified {@link LogRecord} for the current request. If - * enough space (or in the future, time) has accumulated, an - * asynchronous flush may be started. If flushes are backed up, - * this method may block. - */ - synchronized void addLogRecordAndMaybeFlush(LogRecord fullRecord) { - for (LogRecord record : split(fullRecord)) { - UserAppLogLine logLine = new UserAppLogLine(); - logLine.setLevel(record.getLevel().ordinal()); - logLine.setTimestampUsec(record.getTimestamp()); - logLine.setMessage(record.getMessage()); - // Use maxEncodingSize() here because it's faster and accurate - // enough for us. It uses the maximum possible size for varint - // values, but the real size of strings. - int maxEncodingSize = logLine.maxEncodingSize(); - if (maxBytesToFlush > 0 && (currentByteCount + maxEncodingSize) > maxBytesToFlush) { - logger.info(currentByteCount + " bytes of app logs pending, starting flush..."); - waitForCurrentFlushAndStartNewFlush(); - } - if (buffer.size() == 0) { - // We only want to flush once a log message has been around for - // longer than maxSecondsBetweenFlush. So, we only start the timer - // when we add the first message so we don't include time when - // the queue is empty. - stopwatch.start(); - } - buffer.add(logLine); - currentByteCount += maxEncodingSize; - } - - if (maxSecondsBetweenFlush > 0 - && stopwatch.elapsed(TimeUnit.SECONDS) >= maxSecondsBetweenFlush) { - waitForCurrentFlushAndStartNewFlush(); - } - } - - /** - * Starts an asynchronous flush. This method may block if flushes - * are backed up. - * - * @return The number of times this AppLogsWriter has initiated a flush. - */ - synchronized int waitForCurrentFlushAndStartNewFlush() { - waitForCurrentFlush(); - if (buffer.size() > 0) { - currentFlush = doFlush(); - } - return flushCount; - } - - /** - * Initiates a synchronous flush. This method will always block - * until any pending flushes and its own flush completes. - */ - synchronized int flushAndWait() { - waitForCurrentFlush(); - if (buffer.size() > 0) { - currentFlush = doFlush(); - waitForCurrentFlush(); - } - return flushCount; - } - - /** - * This method blocks until any outstanding flush is completed. This method - * should be called prior to {@link #doFlush()} so that it is impossible for - * the appserver to process logs out of order. - */ - private void waitForCurrentFlush() { - if (currentFlush != null) { - logger.info("End of request or previous flush has not yet completed, blocking."); - try { - // VMApiProxyDelegate adds 1000 ms extra to the http connection deadline. - currentFlush.get( - VmApiProxyDelegate.ADDITIONAL_HTTP_TIMEOUT_BUFFER_MS + LOG_FLUSH_TIMEOUT_MS, - TimeUnit.MILLISECONDS); - } catch (InterruptedException ex) { - logger.warning( - "Interruped while blocking on a log flush, setting interrupt bit and " - + "continuing. Some logs may be lost or occur out of order!"); - Thread.currentThread().interrupt(); - } catch (TimeoutException e) { - logger.log( - Level.WARNING, - "Timeout waiting for log flush to complete. " - + "Log messages may have been lost/reordered!", - e); - } catch (ExecutionException ex) { - logger.log( - Level.WARNING, "A log flush request failed. Log messages may have been lost!", ex); - } - currentFlush = null; - } - } - - private Future doFlush() { - UserAppLogGroup group = new UserAppLogGroup(); - for (UserAppLogLine logLine : buffer) { - group.addLogLine(logLine); - } - buffer.clear(); - currentByteCount = 0; - flushCount++; - stopwatch.reset(); - FlushRequest request = new FlushRequest(); - request.setLogsAsBytes(group.toByteArray()); - // This assumes that we are always doing a flush from the request - // thread. See the TODO above. - ApiConfig apiConfig = new ApiConfig(); - apiConfig.setDeadlineInSeconds(LOG_FLUSH_TIMEOUT_MS / 1000.0); - return ApiProxy.makeAsyncCall("logservice", "Flush", request.toByteArray(), apiConfig); - } - - /** - * Because the App Server will truncate log messages that are too - * long, we want to split long log messages into mutliple messages. - * This method returns a {@link List} of {@code LogRecord}s, each of - * which have the same {@link LogRecord#getLevel()} and - * {@link LogRecord#getTimestamp()} as - * this one, and whose {@link LogRecord#getMessage()} is short enough - * that it will not be truncated by the App Server. If the - * {@code message} of this {@code LogRecord} is short enough, the list - * will contain only this {@code LogRecord}. Otherwise the list will - * contain multiple {@code LogRecord}s each of which contain a portion - * of the {@code message}. Additionally, strings will be - * prepended and appended to each of the {@code message}s indicating - * that the message is continued in the following log message or is a - * continuation of the previous log mesage. - */ - List split(LogRecord aRecord) { - // This method is public so it is testable. - LinkedList theList = new LinkedList(); - String message = aRecord.getMessage(); - if (null == message || message.length() <= maxLogMessageLength) { - theList.add(aRecord); - return theList; - } - String remaining = message; - while (remaining.length() > 0) { - String nextMessage; - if (remaining.length() <= maxLogMessageLength) { - nextMessage = remaining; - remaining = ""; - } else { - int cutLength = logCutLength; - boolean cutAtNewline = false; - // Try to cut the string at a friendly point - int friendlyCutLength = remaining.lastIndexOf('\n', logCutLength); - // But only if that yields a message of reasonable length - if (friendlyCutLength > logCutLengthDiv10) { - cutLength = friendlyCutLength; - cutAtNewline = true; - } - nextMessage = remaining.substring(0, cutLength) + LOG_CONTINUATION_SUFFIX; - remaining = remaining.substring(cutLength + (cutAtNewline ? 1 : 0)); - // Only prepend the continuation prefix if doing so would not push - // the length of the next message over the limit. - if (remaining.length() > maxLogMessageLength - || remaining.length() + LOG_CONTINUATION_PREFIX_LENGTH <= maxLogMessageLength) { - remaining = LOG_CONTINUATION_PREFIX + remaining; - } - } - theList.add(new LogRecord(aRecord, nextMessage)); - } - return theList; - } - - /** - * Sets the stopwatch used for time based flushing. - * - * This method is not simply visible for testing, it only exists for testing. - * - * @param stopwatch The {@link Stopwatch} instance to use. - */ - void setStopwatch(Stopwatch stopwatch) { - this.stopwatch = stopwatch; - } - - /** - * Get the max length of an individual log message. - * - * This method is not simply visible for testing, it only exists for testing. - */ - int getMaxLogMessageLength() { - return maxLogMessageLength; - } - - /** - * Get the maximum number of log bytes that can be sent at a single time. - * - * This code is not simply visible for testing, it only exists for testing. - */ - long getByteCountBeforeFlushing() { - return maxBytesToFlush; - } -} diff --git a/appengine-managed-runtime/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger b/appengine-managed-runtime/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger new file mode 100644 index 0000000..9187909 --- /dev/null +++ b/appengine-managed-runtime/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger @@ -0,0 +1 @@ +com.google.apphosting.logging.CloudLoggingFileHandler diff --git a/jetty9-base/pom.xml b/jetty9-base/pom.xml index 5cdd3c3..b76027e 100644 --- a/jetty9-base/pom.xml +++ b/jetty9-base/pom.xml @@ -52,6 +52,9 @@ + + ${project.basedir}/src/main/resources + ${project.build.directory}/jetty-base false diff --git a/jetty9-base/src/main/jetty-base/etc/gae.xml b/jetty9-base/src/main/jetty-base/etc/gae.xml index 8f88e3f..ccca81b 100644 --- a/jetty9-base/src/main/jetty-base/etc/gae.xml +++ b/jetty9-base/src/main/jetty-base/etc/gae.xml @@ -57,10 +57,7 @@ - - /request.yyyy_mm_dd.log - 2 - true + true GMT true diff --git a/jetty9-compat-base/pom.xml b/jetty9-compat-base/pom.xml index cf85a9a..19706a0 100644 --- a/jetty9-compat-base/pom.xml +++ b/jetty9-compat-base/pom.xml @@ -140,6 +140,9 @@ + + ${project.basedir}/src/main/resources + ${project.build.directory}/jetty-base false diff --git a/jetty9-compat-base/src/main/assembly/assembly.xml b/jetty9-compat-base/src/main/assembly/assembly.xml index e2578fe..88a4d82 100644 --- a/jetty9-compat-base/src/main/assembly/assembly.xml +++ b/jetty9-compat-base/src/main/assembly/assembly.xml @@ -31,6 +31,7 @@ **/META-INF/** + logs/** diff --git a/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/RequestLoggerHandler.java b/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/RequestLoggerHandler.java new file mode 100644 index 0000000..678e0dd --- /dev/null +++ b/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/RequestLoggerHandler.java @@ -0,0 +1,90 @@ +package com.google.apphosting.vmruntime.jetty9; + +import com.google.apphosting.logging.SystemLogger; + +import java.io.IOException; +import java.util.logging.FileHandler; +import java.util.logging.Formatter; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +/** + * The {@link java.util.logging.Handler} is responsible for capturing the + * access logging events from {@link org.eclipse.jetty.server.handler.RequestLogHandler} + * and {@link org.eclipse.jetty.server.Slf4jRequestLog} to a rolling file + * on disk. + */ +public class RequestLoggerHandler extends FileHandler implements SystemLogger { + public static class RequestLogFormatter extends Formatter { + @Override + public String format(LogRecord record) { + // We don't expand the message, or use the ResourceBundle stuff for this formatter. + return record.getMessage(); + } + } + + public static final String LOG_DIRECTORY_PROPERTY = "com.google.apphosting.logs"; + public static final String LOG_PATTERN_CONFIG_PROPERTY = + RequestLoggerHandler.class.getName() + ".pattern"; + private static final String DEFAULT_LOG_DIRECTORY = "/var/log/app_engine"; + private static final String DEFAULT_LOG_PATTERN = "access.%g.log"; + + private static final int LOG_PER_FILE_SIZE = getConfigInt("limit", 10 * 1024 * 1024); + private static final int LOG_MAX_FILES = getConfigInt("count", 3); + private static final boolean LOG_APPEND = getConfigBool("append", true); + + public RequestLoggerHandler() throws IOException, SecurityException { + super(getFilePattern(), LOG_PER_FILE_SIZE, LOG_MAX_FILES, LOG_APPEND); + setFormatter(new RequestLogFormatter()); + } + + private static boolean getConfigBool(String suffix, boolean defValue) { + String val = System.getProperty(RequestLoggerHandler.class.getName() + '.' + suffix); + if (val == null) { + return defValue; + } + return Boolean.parseBoolean(val); + } + + private static int getConfigInt(String suffix, int defValue) { + String val = System.getProperty(RequestLoggerHandler.class.getName() + '.' + suffix); + if (val == null) { + return defValue; + } + return Integer.parseInt(val); + } + + private static String getFilePattern() { + String directory = System.getProperty(LOG_DIRECTORY_PROPERTY, DEFAULT_LOG_DIRECTORY); + + String pattern = System.getProperty(LOG_PATTERN_CONFIG_PROPERTY); + if (pattern != null) { + if (pattern.startsWith("/")) { + return pattern; + } + return directory + "/" + pattern; + } + + return directory + "/" + DEFAULT_LOG_PATTERN; + } + + @Override + public void configure() throws IOException { + // This name is logger name that the Sfl4jRequestLog emits events to + Logger logger = Logger.getLogger("org.eclipse.jetty.server.RequestLog"); + logger.setLevel(Level.INFO); + + // Ensure handler is present + // Look for the expected Handlers + for (Handler handler : logger.getHandlers()) { + if (handler instanceof RequestLoggerHandler) { + // Nothing else to do, return + return; + } + } + + logger.addHandler(new RequestLoggerHandler()); + } +} diff --git a/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java b/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java index a4bac17..8ca3c5c 100644 --- a/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java +++ b/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/VmRuntimeWebAppContext.java @@ -21,6 +21,7 @@ import com.google.appengine.api.memcache.MemcacheSerialization; import com.google.appengine.spi.ServiceFactoryFactory; import com.google.apphosting.api.ApiProxy; +import com.google.apphosting.logging.CoreLogging; import com.google.apphosting.logging.LogContext; import com.google.apphosting.runtime.DatastoreSessionStore; import com.google.apphosting.runtime.DeferredDatastoreSessionStore; @@ -39,7 +40,6 @@ import com.google.apphosting.vmruntime.VmEnvironmentFactory; import com.google.apphosting.vmruntime.VmMetadataCache; import com.google.apphosting.vmruntime.VmRequestUtils; -import com.google.apphosting.vmruntime.VmRuntimeFileLogHandler; import com.google.apphosting.vmruntime.VmRuntimeUtils; import com.google.apphosting.vmruntime.VmTimer; @@ -324,11 +324,12 @@ public void init(String appengineWebXmlFile) throws AppEngineConfigException, IO appEngineWebXml = appEngineWebXmlReader.readAppEngineWebXml(); } VmRuntimeUtils.installSystemProperties(defaultEnvironment, appEngineWebXml); - String logConfig = System.getProperty("java.util.logging.config.file"); + + String logConfig = System.getProperty(CoreLogging.JAVA_UTIL_LOGGING_CONFIG_PROPERTY); if (logConfig != null && logConfig.startsWith("WEB-INF/")) { - System.setProperty("java.util.logging.config.file", URIUtil.addPaths(appDir, logConfig)); + logConfig = URIUtil.addPaths(appDir, logConfig); } - VmRuntimeFileLogHandler.init(); + CoreLogging.init(logConfig); if (appEngineWebXml == null) { // No need to configure the session manager. diff --git a/jetty9-compat-base/src/main/jetty-base/etc/gae.xml b/jetty9-compat-base/src/main/jetty-base/etc/gae.xml index c2265e0..cacb1ae 100644 --- a/jetty9-compat-base/src/main/jetty-base/etc/gae.xml +++ b/jetty9-compat-base/src/main/jetty-base/etc/gae.xml @@ -88,17 +88,14 @@ - - - /request.yyyy_mm_dd.log - 2 - true - true - GMT - true - true - - + + + true + GMT + true + true + + diff --git a/jetty9-compat-base/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger b/jetty9-compat-base/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger new file mode 100644 index 0000000..07df7b2 --- /dev/null +++ b/jetty9-compat-base/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger @@ -0,0 +1 @@ +com.google.apphosting.vmruntime.jetty9.RequestLoggerHandler \ No newline at end of file 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 index 88fae47..82b932f 100644 --- 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 @@ -16,11 +16,11 @@ package com.google.apphosting.vmruntime.jetty9; -import static com.google.apphosting.vmruntime.VmRuntimeFileLogHandler.JAVA_UTIL_LOGGING_CONFIG_PROPERTY; +import static com.google.apphosting.logging.CoreLogging.JAVA_UTIL_LOGGING_CONFIG_PROPERTY; import static com.google.apphosting.vmruntime.jetty9.VmRuntimeTestBase.JETTY_HOME_PATTERN; import com.google.apphosting.jetty9.GoogleRequestCustomizer; -import com.google.apphosting.vmruntime.VmRuntimeFileLogHandler; +import com.google.apphosting.logging.CloudLoggingFileHandler; import org.eclipse.jetty.apache.jsp.JettyJasperInitializer; import org.eclipse.jetty.io.MappedByteBufferPool; @@ -120,9 +120,14 @@ public void doStart() throws Exception { Assert.assertTrue(target.isDirectory()); Assert.assertTrue(jettyBaseFile.isDirectory()); logs = new File(target, "logs"); - logs.delete(); - logs.mkdirs(); - logs.deleteOnExit(); + if (!logs.exists()) { + logs.mkdirs(); + /* Note: due to java.util.logging file locks, you cannot: + * - delete the log directory or + * - delete all of its contents or + * - or perform a deleteOnExit() successfully + */ + } // Set GAE SystemProperties setSystemProperties(logs); @@ -259,8 +264,10 @@ public void run() { * Sets the system properties expected by jetty.xml. */ protected void setSystemProperties(File logs) throws IOException { - String logFilePattern = logs.getAbsolutePath() + "/log.%g"; - System.setProperty(VmRuntimeFileLogHandler.LOG_PATTERN_CONFIG_PROPERTY, logFilePattern); + System.setProperty(CloudLoggingFileHandler.LOG_PATTERN_CONFIG_PROPERTY, + logs.getAbsolutePath() + "/log%u.%g.json"); + System.setProperty(RequestLoggerHandler.LOG_PATTERN_CONFIG_PROPERTY, + logs.getAbsolutePath() + "/request-%u.%g.log"); System.setProperty("jetty.appengineport", String.valueOf(findAvailablePort())); System.setProperty("jetty.appenginehost", "localhost"); System.setProperty("jetty.appengine.forwarded", "true"); 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 index be97a82..5819ead 100644 --- 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 @@ -17,6 +17,7 @@ package com.google.apphosting.vmruntime.jetty9; import static org.hamcrest.Matchers.equalTo; +import static org.hamcrest.Matchers.notNullValue; import static org.junit.Assert.assertThat; import com.google.gson.Gson; @@ -27,19 +28,73 @@ import java.io.BufferedReader; import java.io.File; import java.io.FileInputStream; +import java.io.FileNotFoundException; +import java.io.IOException; import java.io.InputStreamReader; import java.nio.charset.StandardCharsets; +import java.util.regex.Matcher; +import java.util.regex.Pattern; public class LoggingIT extends VmRuntimeTestBase { + /** + * Find the log file that contains the specific content pattern. + *

+ * This exists to get around the fact that the java.util.logging + * layer will generate a new log file each time its reset/initialized + * because it sees the lock from the previous instance before the + * previous instance has a chance to close and remove the lock. + *

+ *

+ * This function will iterate through all of the log files and + * attempt to find the specific pattern you are interested in. + *

+ * + * @param logDir the directory where log files are kept, tracked by + * the {@link JettyRunner} + * @param regex the text (regex) pattern to look for in the log file + * @return the File for the discovered log file + * @throws java.io.FileNotFoundException if unable to find a log + * file with the specific text pattern + * @throws IOException if unable to read a log file and/or pattern + */ + public File findLogFileThatContains(File logDir, String regex) throws IOException { + Pattern logPattern = Pattern.compile("log[0-9]+\\.[0-9]+\\.json"); + Pattern textPattern = Pattern.compile(regex); + Matcher logMatcher; + String line; + + for (File file : logDir.listFiles()) { + logMatcher = logPattern.matcher(file.getName()); + boolean validFile = logMatcher.matches(); + if (validFile) { + // search file + try (FileInputStream in = new FileInputStream(file); + InputStreamReader reader = new InputStreamReader(in, StandardCharsets.UTF_8); + BufferedReader buf = new BufferedReader(reader)) { + Matcher textMatcher; + while ((line = buf.readLine()) != null) { + textMatcher = textPattern.matcher(line); + if (textMatcher.find()) { + return file; + } + } + } + } + } + + throw new FileNotFoundException( + "Unable to find pattern [" + textPattern.pattern() + "] in logs at " + logDir); + } + public void testGet() throws Exception { //runner.dump(); 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)); @@ -47,34 +102,36 @@ public void testGet() throws Exception { String body = get.getResponseBodyAsString(); assertThat(body, equalTo("FINE\nSEVERE\nfalse\n\n")); - File logs = runner.getLogDir(); - File log = new File(logs, "log.0"); + File log = findLogFileThatContains(runner.getLogDir(),query); assertTrue(log.exists()); // Look for the log entry with our query string - try (BufferedReader in = - new BufferedReader( - new InputStreamReader(new FileInputStream(log), StandardCharsets.ISO_8859_1))) { + try (FileInputStream in = new FileInputStream(log); + InputStreamReader reader = new InputStreamReader(in, StandardCharsets.UTF_8); + BufferedReader buf = new BufferedReader(reader)) { String line; - while ((line = in.readLine()) != null) { + while ((line = buf.readLine()) != null) { if (line.contains(query)) { break; } } JsonData data = new Gson().fromJson(line, JsonData.class); + assertThat("Parsed Data", data, notNullValue()); assertThat(data.severity, equalTo("INFO")); - assertThat(data.message, org.hamcrest.Matchers.containsString("LogTest Hello nano=" + query)); + assertThat(data.message, org.hamcrest.Matchers.containsString("LogTest Hello " + query)); - line = in.readLine(); + line = buf.readLine(); data = new Gson().fromJson(line, JsonData.class); + assertThat("Parsed Data", data, notNullValue()); assertThat(data.severity, equalTo("ERROR")); - assertThat( - data.message, org.hamcrest.Matchers.containsString("LoggingServlet doGet: not null")); + assertThat(data.message, + org.hamcrest.Matchers.containsString("LoggingServlet doGet: not null")); - line = in.readLine(); + line = buf.readLine(); data = new Gson().fromJson(line, JsonData.class); + assertThat("Parsed Data", data, notNullValue()); assertThat(data.severity, equalTo("ERROR")); assertThat(data.message, org.hamcrest.Matchers.containsString("LoggingServlet doGet: null")); } @@ -87,6 +144,7 @@ public static class LogTimestamp { public long nanos; } + public LogTimestamp timestamp; public String severity; public String thread; diff --git a/pom.xml b/pom.xml index b43e8c7..df41792 100644 --- a/pom.xml +++ b/pom.xml @@ -95,6 +95,13 @@ 2.3.1 + + org.hamcrest + hamcrest-library + 1.3 + test + + junit junit