adding logs to JUnit stuff. Helpful for disambiguating which of several testcases with same method names runs, but primarily aimed at diagnosing a remoteweb test timeout... surely not all of the clients really go AWOL all at once??
Review by: zundel
git-svn-id: https://google-web-toolkit.googlecode.com/svn/trunk@2922 8db76d5a-ed1c-0410-87a9-c151d255dfc7
diff --git a/common.ant.xml b/common.ant.xml
index 4070dfd..43833b2 100755
--- a/common.ant.xml
+++ b/common.ant.xml
@@ -160,7 +160,7 @@
<junit dir="@{test.out}" fork="yes" printsummary="yes" failureproperty="junit.failure" >
<jvmarg line="${junit.platform.args}" />
<jvmarg line="-Xmx512m" />
- <sysproperty key="gwt.args" value="${junit.notheadless.arg} @{test.args}" />
+ <sysproperty key="gwt.args" value="-logLevel TRACE ${junit.notheadless.arg} @{test.args}" />
<sysproperty key="java.awt.headless" value="${junit.headless}" />
<sysproperty key="gwt.devjar" value="${gwt.dev.staging.jar}" />
<classpath>
diff --git a/dev/core/src/com/google/gwt/dev/shell/GWTShellServlet.java b/dev/core/src/com/google/gwt/dev/shell/GWTShellServlet.java
index 399bec6..ae17f2c 100644
--- a/dev/core/src/com/google/gwt/dev/shell/GWTShellServlet.java
+++ b/dev/core/src/com/google/gwt/dev/shell/GWTShellServlet.java
@@ -59,6 +59,11 @@
*/
public class GWTShellServlet extends HttpServlet {
+ /**
+ * Silence the serialVersionUID warning.
+ */
+ private static final long serialVersionUID = 1L;
+
private static class RequestParts {
public final String moduleName;
@@ -143,6 +148,11 @@
protected void processFileRequest(HttpServletRequest request,
HttpServletResponse response) throws IOException {
+ TreeLogger logger = getLogger();
+
+ logger.log(TreeLogger.TRACE, "Servlet request for " +
+ request.getPathInfo() + " from " + request.getRemoteHost());
+
String pathInfo = request.getPathInfo();
if (pathInfo.length() == 0 || pathInfo.equals("/")) {
response.setContentType("text/html");
@@ -153,8 +163,6 @@
return;
}
- TreeLogger logger = getLogger();
-
// Parse the request assuming it is module/resource.
//
RequestParts parts;
@@ -203,7 +211,8 @@
StringBuffer url = request.getRequestURL();
// Branch the logger in case we decide to log more below.
- logger = logger.branch(TreeLogger.TRACE, "Request " + id + ": " + url,
+ logger = logger.branch(TreeLogger.TRACE, "Request " + id + ": " + url +
+ " from " + request.getRemoteHost(),
null);
}
@@ -275,6 +284,7 @@
// Load/get the servlet if we found one.
if (servletClassName != null) {
+ logger.log(TreeLogger.TRACE, "Delegating to " + servletClassName + " for " + moduleDef);
HttpServlet delegatee = tryGetOrLoadServlet(logger, moduleDef,
servletClassName);
if (delegatee == null) {
@@ -607,10 +617,12 @@
}
/**
- * We don't actually log this on purpose since the client does anyway.
+ * We don't actually log this (except at TRACE) on purpose since the client
+ * does anyway.
*/
private ModuleDef getModuleDef(TreeLogger logger, String moduleName)
throws UnableToCompleteException {
+ logger.log(TreeLogger.TRACE, "Servlet getModuleDef(logger, \"" + moduleName + "\"");
synchronized (loadedModulesByName) {
ModuleDef moduleDef = loadedModulesByName.get(moduleName);
if (moduleDef == null) {
diff --git a/user/src/com/google/gwt/junit/JUnitMessageQueue.java b/user/src/com/google/gwt/junit/JUnitMessageQueue.java
index 7466b3c..5f4ecb8 100644
--- a/user/src/com/google/gwt/junit/JUnitMessageQueue.java
+++ b/user/src/com/google/gwt/junit/JUnitMessageQueue.java
@@ -15,6 +15,9 @@
*/
package com.google.gwt.junit;
+import com.google.gwt.core.ext.TreeLogger;
+import com.google.gwt.core.ext.TreeLogger.Type;
+import com.google.gwt.dev.util.log.PrintWriterTreeLogger;
import com.google.gwt.junit.client.TimeoutException;
import com.google.gwt.junit.client.impl.JUnitResult;
import com.google.gwt.junit.client.impl.JUnitHost.TestInfo;
@@ -70,6 +73,7 @@
*/
private TestInfo currentTest;
+ private TreeLogger logger;
/**
* The number of TestCase clients executing in parallel.
*/
@@ -80,8 +84,16 @@
*
* @param numClients The number of parallel clients being served by this
* queue.
+ * @param loglevel The loglevel to use. There is a circular dependency in
+ * startup; we need the message queue to make the GWTShell, but its
+ * logger depends on having mainWnd which requires the GWTShell be
+ * started. So, initially, we log to a PrintWriterTreeLogger, and
+ * use setLogger after the bootstrap.
*/
- JUnitMessageQueue(int numClients) {
+ JUnitMessageQueue(int numClients, Type loglevel) {
+ PrintWriterTreeLogger consolelog = new PrintWriterTreeLogger();
+ consolelog.setMaxDetail(loglevel);
+ logger = consolelog;
synchronized (clientStatusesLock) {
this.numClients = numClients;
}
@@ -130,6 +142,9 @@
// Record that this client has retrieved the current test.
clientStatus.hasRequestedCurrentTest = true;
+ logger.log(TreeLogger.TRACE,
+ "Client " + clientId + " has next test info for " +
+ currentTest.getTestClass() + "." + currentTest.getTestMethod());
return currentTest;
}
}
@@ -145,8 +160,14 @@
synchronized (clientStatusesLock) {
if (testInfo != null && !testInfo.equals(currentTest)) {
// A client is reporting results for the wrong test.
+ logger.log(TreeLogger.WARN,
+ "Wrong (stale?) test report from " + clientId + ": reporting on " +
+ testInfo.getTestClass() + "." + testInfo.getTestMethod() +
+ " (current test is " + testInfo.getTestClass() + "." +
+ testInfo.getTestMethod() + ")");
return;
}
+ logger.log(TreeLogger.TRACE, "Client " + clientId + "reported results.");
assert (results != null);
ClientStatus clientStatus = clientStatuses.get(clientId);
clientStatus.currentTestResults = results;
@@ -154,6 +175,10 @@
}
}
+ public void setLogger(TreeLogger newlog) {
+ logger = newlog;
+ }
+
/**
* Returns any new clients that have contacted the server since the last call.
* The same client will never be returned from this method twice.
diff --git a/user/src/com/google/gwt/junit/JUnitShell.java b/user/src/com/google/gwt/junit/JUnitShell.java
index 22bafdc..fa8d0a3 100644
--- a/user/src/com/google/gwt/junit/JUnitShell.java
+++ b/user/src/com/google/gwt/junit/JUnitShell.java
@@ -171,7 +171,7 @@
}
unitTestShell.messageQueue = new JUnitMessageQueue(
- unitTestShell.numClients);
+ unitTestShell.numClients, unitTestShell.getLogLevel());
if (!unitTestShell.startUp()) {
throw new JUnitFatalLaunchException("Shell failed to start");
@@ -436,6 +436,16 @@
} else {
super.initializeLogger();
}
+ TreeLogger log = getTopLogger();
+ if (log.isLoggable(TreeLogger.ALL)) {
+ log.log(TreeLogger.INFO, "Logging ALL messages.");
+ } else if (log.isLoggable(TreeLogger.SPAM)) {
+ log.log(TreeLogger.INFO, "Logging SPAM messages.");
+ } else if (log.isLoggable(TreeLogger.TRACE)) {
+ log.log(TreeLogger.INFO, "Logging TRACE messages.");
+ } else if (log.isLoggable(TreeLogger.INFO)) {
+ log.log(TreeLogger.INFO, "Logging INFO messages.");
+ }
}
/**
@@ -524,12 +534,14 @@
throw new UnableToCompleteException();
}
+ TreeLogger log = getTopLogger();
if (!sameTest) {
/*
* Synthesize a synthetic module that derives from the user-specified
* module but also includes JUnit support.
*/
- currentModule = ModuleDefLoader.createSyntheticModule(getTopLogger(),
+ log.log(TreeLogger.TRACE, "Switching to module " + syntheticModuleName);
+ currentModule = ModuleDefLoader.createSyntheticModule(log,
syntheticModuleName, new String[] {
moduleName, strategy.getModuleInherit()}, true);
// Replace any user entry points with our test runner.
@@ -540,9 +552,15 @@
"junit.moduleName");
moduleNameProp.addKnownValue(moduleName);
moduleNameProp.setActiveValue(moduleName);
+ long startCompile = System.currentTimeMillis();
runStyle.maybeCompileModule(syntheticModuleName);
+ double compileTime = (System.currentTimeMillis() - startCompile) / 1000.0D;
+ log.log(TreeLogger.INFO, "Switched to module " + syntheticModuleName +
+ " (compiled in " + compileTime + "sec)");
}
+ log.log(TreeLogger.TRACE, "Queueing test " + testCase.getClass().getName() + "."
+ + testCase.getName());
messageQueue.setNextTest(new TestInfo(currentModule.getName(),
testCase.getClass().getName(), testCase.getName()));
@@ -570,6 +588,7 @@
}
assert (messageQueue.hasResult());
+ log.log(TreeLogger.TRACE, "Completed test, fetching results...");
Map<String, JUnitResult> results = messageQueue.getResults();
boolean parallelTesting = numClients > 1;
@@ -577,6 +596,7 @@
for (Entry<String, JUnitResult> entry : results.entrySet()) {
String clientId = entry.getKey();
JUnitResult result = entry.getValue();
+ log.log(TreeLogger.TRACE, "Got result from " + clientId + ": " + result);
assert (result != null);
Throwable exception = result.getException();
// In the case that we're running multiple clients at once, we need to
diff --git a/user/src/com/google/gwt/junit/RunStyleRemoteWeb.java b/user/src/com/google/gwt/junit/RunStyleRemoteWeb.java
index 6aa714a..c565486 100644
--- a/user/src/com/google/gwt/junit/RunStyleRemoteWeb.java
+++ b/user/src/com/google/gwt/junit/RunStyleRemoteWeb.java
@@ -250,11 +250,16 @@
@Override
public boolean wasInterrupted() {
synchronized (wasInterruptedLock) {
+ if (wasInterrupted) {
+ getLogger().log(TreeLogger.INFO, "A remote test was interrupted.");
+ }
return wasInterrupted;
}
}
private synchronized boolean doKeepAlives() {
+ getLogger().log(TreeLogger.TRACE, "Sending keepalives to browsermanagerservers (time="
+ + System.currentTimeMillis());
for (RemoteBrowser remoteBrowser : remoteBrowsers) {
if (remoteBrowser.getToken() > 0) {
long callStart = System.currentTimeMillis();
@@ -267,7 +272,7 @@
if (cause instanceof SocketTimeoutException) {
long elapsed = System.currentTimeMillis() - callStart;
throw new TimeoutException("Timeout: " + elapsed
- + "ms keeping alive remote browser at: " + rmiUrl,
+ + "ms keeping alive remote browser at: " + rmiUrl,
e.getCause());
} else if (e instanceof IllegalStateException) {
getLogger().log(TreeLogger.INFO,
@@ -286,6 +291,10 @@
}
synchronized (wasInterruptedLock) {
+ if (wasInterrupted) {
+ getLogger().log(TreeLogger.INFO,
+ "Remote test was interrupted during keepalives to browsermanagerserver.");
+ }
return !wasInterrupted;
}
}
