Skip to content

Commit

Permalink
Issue GoogleCloudPlatform#231 - Improved testing of new CoreLogging
Browse files Browse the repository at this point in the history
  • Loading branch information
@joakime
joakime committed Jun 27, 2016
1 parent 5398963 commit 1c6132f
Show file tree
Hide file tree
Showing 4 changed files with 102 additions and 21 deletions.
22 changes: 20 additions & 2 deletions appengine-java-logging/src/main/java/com/google/apphosting/logging/CoreLogging.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -44,15 +45,22 @@ 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
String julConfigFile = System.getProperty(JAVA_UTIL_LOGGING_CONFIG_PROPERTY);
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");
}
}

Expand All @@ -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);
Expand All @@ -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
Expand All @@ -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);
}
}
12 changes: 8 additions & 4 deletions appengine-java-logging/src/test/java/com/google/apphosting/logging/JsonFormatterTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"));
Expand Down Expand Up @@ -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"));
Expand Down Expand Up @@ -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"));
Expand Down Expand Up @@ -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"));
Expand Down
59 changes: 57 additions & 2 deletions jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/JettyRunner.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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 {

Expand Down Expand Up @@ -254,11 +261,59 @@ public void run() {
}
}

/**
* Find the log file that contains the specific content pattern.
* <p>
* 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.
* </p>
* <p>
* This function will iterate through all of the log files and
* attempt to find the specific pattern you are interested in.
* </p>
*
* @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");
Expand Down
30 changes: 17 additions & 13 deletions jetty9-compat-base/src/test/java/com/google/apphosting/vmruntime/jetty9/LoggingIT.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -38,43 +39,45 @@ 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));

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"));
}
Expand All @@ -87,6 +90,7 @@ public static class LogTimestamp {
public long nanos;
}


public LogTimestamp timestamp;
public String severity;
public String thread;
Expand Down

0 comments on commit 1c6132f

Please sign in to comment.