From 1c6132f87dbf9c8c3ba04f6a34ad4338296e7fd9 Mon Sep 17 00:00:00 2001 From: Joakim Erdfelt Date: Mon, 27 Jun 2016 14:52:22 -0700 Subject: [PATCH] Issue #231 - Improved testing of new CoreLogging --- .../apphosting/logging/CoreLogging.java | 22 ++++++- .../apphosting/logging/JsonFormatterTest.java | 12 ++-- .../vmruntime/jetty9/JettyRunner.java | 59 ++++++++++++++++++- .../vmruntime/jetty9/LoggingIT.java | 30 ++++++---- 4 files changed, 102 insertions(+), 21 deletions(-) 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 index c2f1e73..118b9dd 100644 --- 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 @@ -27,6 +27,7 @@ */ 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. @@ -44,6 +45,7 @@ public class CoreLogging { public static void init(File appConfigFile) throws IOException { // Use App (User) Configuration specified as a file parameter if (appConfigFile != null && appConfigFile.exists()) { + debug("Loading User Config (from file): %s", appConfigFile); appConfig(appConfigFile); } else { // Use App (User) Configuration specified as a System property @@ -51,8 +53,14 @@ public static void init(File appConfigFile) throws IOException { if (julConfigFile != null) { File configFile = new File(julConfigFile); if (configFile.exists()) { + debug("Loading User Config (from property): %s", appConfigFile); appConfig(configFile); + } else { + warning("Logging Config System Property (%s) points to invalid file: %s", + JAVA_UTIL_LOGGING_CONFIG_PROPERTY, appConfigFile.getAbsolutePath()); } + } else { + debug("No User Config"); } } @@ -68,7 +76,7 @@ public static void init(File appConfigFile) throws IOException { */ public static void init(String appConfigFilename) throws IOException { File appConfigFile = null; - if (appConfigFilename == null) { + if (appConfigFilename != null) { appConfigFile = new File(appConfigFilename); } init(appConfigFile); @@ -77,7 +85,7 @@ public static void init(String appConfigFilename) throws IOException { private static void appConfig(File configFile) { try (FileInputStream is = new FileInputStream(configFile)) { LogManager logManager = LogManager.getLogManager(); - logManager.reset(); + logManager.reset(); // close & remove existing handlers, reset existing logger levels logManager.readConfiguration(is); } catch (SecurityException | IOException e) { System.err.println("Warning: caught exception when reading logging properties: " + configFile @@ -99,4 +107,14 @@ private static void systemConfig() throws IOException { systemLogger.configure(); } } + + private static void debug(String format, Object... args) { + if (DEBUG) { + System.err.printf("[CoreLogging:DEBUG] " + format + "%n", args); + } + } + + private static void warning(String format, Object... args) { + System.err.printf("[CoreLogging:WARNING] " + format + "%n", args); + } } 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 5c47b70..7586ca8 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 @@ -133,7 +133,8 @@ public void testCommonsLogging() { 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])); + 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")); @@ -167,7 +168,8 @@ public void testJavaUtilLogging() { 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])); + 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")); @@ -200,7 +202,8 @@ public void testLog4jLogging() { 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])); + 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")); @@ -233,7 +236,8 @@ public void testSlf4jLogging() { 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])); + 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")); 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 3f8541c..3f76029 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,7 +16,7 @@ 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; @@ -40,12 +40,19 @@ import org.eclipse.jetty.util.thread.QueuedThreadPool; import org.junit.Assert; +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.net.ServerSocket; +import java.nio.charset.StandardCharsets; import java.util.Collections; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; +import java.util.regex.Matcher; +import java.util.regex.Pattern; class JettyRunner extends AbstractLifeCycle implements Runnable { @@ -254,11 +261,59 @@ public void run() { } } + /** + * 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 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(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 : getLogDir().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 " + getLogDir()); + } + /** * Sets the system properties expected by jetty.xml. */ protected void setSystemProperties(File logs) throws IOException { - String logFilePattern = logs.getAbsolutePath() + "/log.%g"; + String logFilePattern = logs.getAbsolutePath() + "/log%u.%g.json"; System.setProperty(VmRuntimeFileLogHandler.LOG_PATTERN_CONFIG_PROPERTY, logFilePattern); System.setProperty("jetty.appengineport", String.valueOf(findAvailablePort())); System.setProperty("jetty.appenginehost", "localhost"); 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..3a8e584 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; @@ -38,8 +39,8 @@ public void testGet() throws Exception { HttpClient httpClient = new HttpClient(); httpClient.getHttpConnectionManager().getParams().setConnectionTimeout(30000); - String query = Long.toHexString(System.nanoTime()); - GetMethod get = new GetMethod(createUrl("/testLogging?nano=" + query).toString()); + String query = "nano=" + Long.toHexString(System.nanoTime()); + GetMethod get = new GetMethod(createUrl("/testLogging?" + query).toString()); int httpCode = httpClient.executeMethod(get); assertThat(httpCode, equalTo(200)); @@ -47,34 +48,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 = runner.findLogFileThatContains(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 +90,7 @@ public static class LogTimestamp { public long nanos; } + public LogTimestamp timestamp; public String severity; public String thread;