diff --git a/appengine-java-logging/pom.xml b/appengine-java-logging/pom.xml index 136e6d8..d94f0ee 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-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..c2f1e73 --- /dev/null +++ b/appengine-java-logging/src/main/java/com/google/apphosting/logging/CoreLogging.java @@ -0,0 +1,102 @@ +/* + * 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"; + + /** + * 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()) { + 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()) { + appConfig(configFile); + } + } + } + + // 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(); + logManager.readConfiguration(is); + } catch (SecurityException | IOException e) { + System.err.println("Warning: caught exception when reading logging properties: " + 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. + + ServiceLoader serviceLoader = ServiceLoader.load(SystemLogger.class); + for (SystemLogger systemLogger : serviceLoader) { + systemLogger.configure(); + } + } +} 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..a46227b --- /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; + +public class CommonsLoggingExample implements Runnable { + private static final Log LOG = LogFactory.getLog(CommonsLoggingExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + LOG.trace(String.format("A CommonsLogging Trace Event: %d", rand.nextInt())); + LOG.debug(String.format("A CommonsLogging Debug Event: %d", rand.nextInt())); + LOG.info(String.format("A CommonsLogging Info Event: %d", rand.nextInt())); + LOG.warn(String.format("A CommonsLogging Warn Event: %d", rand.nextInt())); + LOG.error(String.format("A CommonsLogging Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} \ No newline at end of file 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..b54d2e2 --- /dev/null +++ b/appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonCaptureHandler.java @@ -0,0 +1,51 @@ +/* + * 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 class JsonCaptureHandler extends Handler { + + private JsonFormatter formatter; + private List events; + + public JsonCaptureHandler() { + super(); + formatter = new JsonFormatter(); + events = new ArrayList<>(); + } + + @Override + public void publish(LogRecord record) { + events.add(formatter.format(record)); + } + + @Override + public void flush() { + } + + @Override + public void close() throws SecurityException { + } + + 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..5c47b70 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,19 +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() { + final Instant now = Instant.now(); + final 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); + 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(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() { + final Instant now = Instant.now(); + final 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() { + final Instant now = Instant.now(); + final 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() { + final Instant now = Instant.now(); + final 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; public String severity; public String thread; 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..9493e17 --- /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; + +public class JulExample implements Runnable { + public static final Logger LOG = Logger.getLogger(JulExample.class.getName()); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + LOG.log(Level.FINEST, "A JUL Finest Event: {0}", rand.nextInt()); + LOG.log(Level.FINER, "A JUL Finer Event: {0}", rand.nextInt()); + LOG.log(Level.FINE, "A JUL Fine Event: {0}", rand.nextInt()); + LOG.log(Level.CONFIG, "A JUL Config Event: {0}", rand.nextInt()); + LOG.log(Level.INFO, "A JUL Info Event: {0}", rand.nextInt()); + LOG.log(Level.WARNING, "A JUL Warning Event: {0}", rand.nextInt()); + LOG.log(Level.SEVERE, String.format("A JUL Severe Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} \ No newline at end of file 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..74c6761 --- /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; + +public class Log4jExample implements Runnable { + private static final Logger LOG = Logger.getLogger(Log4jExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + LOG.trace(String.format("A Log4j Trace Event: %d", rand.nextInt())); + LOG.debug(String.format("A Log4j Debug Event: %d", rand.nextInt())); + LOG.info(String.format("A Log4j Info Event: %d", rand.nextInt())); + LOG.warn(String.format("A Log4j Warn Event: %d", rand.nextInt())); + LOG.error(String.format("A Log4j Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} \ No newline at end of file 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..d2354cf --- /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; + +public class Slf4jExample implements Runnable { + private static final Logger LOG = LoggerFactory.getLogger(Slf4jExample.class); + + @Override + public void run() { + ThreadLocalRandom rand = ThreadLocalRandom.current(); + LOG.trace("A Slf4j Trace Event: {}", rand.nextInt()); + LOG.debug("A Slf4j Debug Event: {}", rand.nextInt()); + LOG.info("A Slf4j Info Event: {}", rand.nextInt()); + LOG.warn("A Slf4j Warn Event: {}", rand.nextInt()); + LOG.error(String.format("A Slf4j Error Event: %d", rand.nextInt()), + new RuntimeException("Generic Error")); + } +} \ No newline at end of file diff --git a/appengine-managed-runtime/pom.xml b/appengine-managed-runtime/pom.xml index 4b022a1..256f925 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/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java b/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java index c46eea5..8176628 100644 --- a/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java +++ b/appengine-managed-runtime/src/main/java/com/google/apphosting/vmruntime/VmRuntimeFileLogHandler.java @@ -17,12 +17,12 @@ package com.google.apphosting.vmruntime; import com.google.apphosting.logging.JsonFormatter; +import com.google.apphosting.logging.SystemLogger; import java.io.IOException; 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; /** @@ -31,8 +31,7 @@ * with the cloud logging agent. * */ -public class VmRuntimeFileLogHandler extends FileHandler { - +public class VmRuntimeFileLogHandler 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 = @@ -41,12 +40,11 @@ public class VmRuntimeFileLogHandler extends FileHandler { 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 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_PER_FILE_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 VmRuntimeFileLogHandler() throws IOException { - super(fileLogPattern(), LOG_MAX_SIZE, LOG_MAX_FILES, true); + public VmRuntimeFileLogHandler() throws IOException { + super(fileLogPattern(), LOG_PER_FILE_SIZE, LOG_MAX_FILES, true); setLevel(Level.FINEST); setFormatter(new JsonFormatter()); } @@ -71,34 +69,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. + // 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 VmRuntimeFileLogHandler()); } } 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..9d08267 --- /dev/null +++ b/appengine-managed-runtime/src/main/resources/META-INF/services/com.google.apphosting.logging.SystemLogger @@ -0,0 +1 @@ +com.google.apphosting.vmruntime.VmRuntimeFileLogHandler \ No newline at end of file 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..e163ac6 --- /dev/null +++ b/jetty9-compat-base/src/main/java/com/google/apphosting/vmruntime/jetty9/RequestLoggerHandler.java @@ -0,0 +1,46 @@ +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.Handler; +import java.util.logging.Level; +import java.util.logging.Logger; + +public class RequestLoggerHandler extends FileHandler implements SystemLogger { + public static final String LOG_DIRECTORY_PROPERTY = "com.google.apphosting.logs"; + 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 = 10 * 1024 * 1024; + private static final int LOG_MAX_FILES = 3; + private static final boolean LOG_APPEND = true; + + public RequestLoggerHandler() throws IOException, SecurityException { + super(getFilePattern(), LOG_PER_FILE_SIZE, LOG_MAX_FILES, LOG_APPEND); + } + + private static String getFilePattern() { + String directory = System.getProperty(LOG_DIRECTORY_PROPERTY, DEFAULT_LOG_DIRECTORY); + 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 912bdc1..1e8e848 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 @@ -22,6 +22,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; @@ -40,11 +41,9 @@ 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; -import org.eclipse.jetty.http.HttpScheme; import org.eclipse.jetty.quickstart.PreconfigureDescriptorProcessor; import org.eclipse.jetty.quickstart.QuickStartDescriptorGenerator; import org.eclipse.jetty.security.ConstraintSecurityHandler; @@ -310,11 +309,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); for (String systemClass : SYSTEM_CLASSES) { addSystemClass(systemClass); 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 7e23932..4f66077 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/pom.xml b/pom.xml index 02ae6a9..0038b67 100644 --- a/pom.xml +++ b/pom.xml @@ -95,6 +95,13 @@ 2.3.1 + + org.hamcrest + hamcrest-library + 1.3 + test + + junit junit