Add parameter to set the logging level for TestLogger (#2873)

labkey-tchad · web-flow · commit d1a75f2c3147 · 2026-02-10T15:10:31.000-08:00
- Add parameter (`webtest.log.level`) to set the logging level for TestLogger
- Remove circular static initialization dependency between `TestLogger` and `TestProperties`
- Adjust `WebDriverWrapper.waitForPageToLoad` to work better on Chrome
diff --git a/src/org/labkey/test/TestProperties.java b/src/org/labkey/test/TestProperties.java
@@ -17,11 +17,12 @@
 
 import org.apache.commons.lang3.StringUtils;
 import org.apache.commons.lang3.SystemUtils;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.labkey.serverapi.reader.Readers;
 import org.labkey.test.util.CachingSupplier;
 import org.labkey.test.util.CspLogUtil;
 import org.labkey.test.util.TestDataGenerator;
-import org.labkey.test.util.TestLogger;
 import org.labkey.test.util.Version;
 import org.openqa.selenium.Dimension;
 
@@ -42,41 +43,41 @@
 import java.util.Objects;
 import java.util.Optional;
 import java.util.Properties;
-import java.util.Random;
 import java.util.stream.Collectors;
 import java.util.stream.Stream;
 
 public abstract class TestProperties
 {
+    private static final Logger LOG = LogManager.getLogger(TestProperties.class);
+
     static
     {
         final File propFile = new File(TestFileUtils.getTestRoot(), "test.properties");
         final File propFileTemplate = new File(TestFileUtils.getTestRoot(), "test.properties.template");
         if (!propFile.exists())
         {
-            TestLogger.log(String.format("'%s' does not exist. Creating default from '%s'", propFile.getName(), propFileTemplate.getName()));
+            LOG.info("'{}' does not exist. Creating default from '{}'", propFile.getName(), propFileTemplate.getName());
             try (Stream<String> propStream = Files.lines(propFileTemplate.toPath()))
             {
                 final Iterator<String> iterator = propStream.filter(line -> !line.startsWith("#!!")).iterator();
                 Files.write(propFile.toPath(), (Iterable<String>) () -> iterator, StandardOpenOption.CREATE_NEW);
             }
             catch (IOException e)
             {
-                TestLogger.error(e.getMessage());
+                LOG.error(e.getMessage(), e);
             }
         }
         try (Reader propReader = Readers.getReader(propFile))
         {
-            TestLogger.log("Loading properties from " + propFile.getName());
+            LOG.info("Loading properties from {}", propFile.getName());
             Properties properties = new Properties();
             properties.load(propReader);
             properties.putAll(System.getProperties());
             System.setProperties(properties);
         }
         catch (IOException ioe)
         {
-            TestLogger.error("Failed to load " + propFile.getName() + " file. Running with hard-coded defaults");
-            ioe.printStackTrace(System.err);
+            LOG.error("Failed to load {} file. Running with hard-coded defaults", propFile.getName(), ioe);
         }
 
         final List<String> gradleProperties = List.of("labkeyVersion");
@@ -85,7 +86,7 @@ public abstract class TestProperties
         {
             try (Reader propReader = Readers.getReader(serverPropFile))
             {
-                TestLogger.log("Loading properties from " + serverPropFile.getName());
+                LOG.info("Loading properties from {}", serverPropFile.getName());
                 Properties properties = new Properties();
                 properties.load(propReader);
                 for (String key : gradleProperties)
@@ -98,8 +99,7 @@ public abstract class TestProperties
             }
             catch (IOException ioe)
             {
-                TestLogger.error("Failed to load " + serverPropFile.getName() + " file.");
-                ioe.printStackTrace(System.err);
+                LOG.error("Failed to load {} file.", serverPropFile.getName(), ioe);
             }
         }
 
@@ -298,9 +298,9 @@ public static boolean isTroubleshootingStacktracesEnabled()
         return getBooleanProperty("webtest.troubleshooting.stacktraces", false);
     }
 
-    public static boolean isDebugLoggingEnabled()
+    public static String getTestLogLevel()
     {
-        return getBooleanProperty("webtest.logging.debug", false);
+        return System.getProperty("webtest.log.level");
     }
 
     public static boolean isPrimaryUserAppAdmin()
@@ -432,7 +432,7 @@ public static File getDumpDir()
                         "Tried system properties failure.output.dir and java.io.tmpdir");
             }
 
-            TestLogger.log("Using " + dumpDir + " to store test output");
+            LOG.info("Using {} to store test output", dumpDir);
         }
         return dumpDir;
     }
@@ -475,7 +475,7 @@ public static int getIntegerProperty(String key, int def)
             }
             catch (NumberFormatException e)
             {
-                TestLogger.warn("Invalid value for property %s: '%s'".formatted(key, prop), e);
+                LOG.warn("Invalid value for property {}: '{}'", key, prop, e);
             }
         }
         return def;
@@ -499,7 +499,7 @@ public static double getDoubleProperty(String key, double def)
             }
             catch (NumberFormatException e)
             {
-                TestLogger.warn("Invalid value for property %s: '%s'".formatted(key, prop), e);
+                LOG.warn("Invalid value for property {}: '{}'", key, prop, e);
             }
         }
         return def;
diff --git a/src/org/labkey/test/WebDriverWrapper.java b/src/org/labkey/test/WebDriverWrapper.java
@@ -355,6 +355,7 @@ protected Pair<WebDriver, DriverService> createNewWebDriver(@NotNull Pair<WebDri
                     profile.setPreference("extensions.update.enabled", false);
                     profile.setPreference("dom.max_script_run_time", 0);
                     profile.setPreference("dom.max_chrome_script_run_time", 0);
+                    //profile.setPreference("dom.reporting.enabled", true); // Enable support for CSP report-to
 
                     // Prevent crawler from hanging on '_print=1' pages
                     profile.setPreference("print.always_print_silent", true);
@@ -1997,19 +1998,18 @@ private void waitForPageToLoad(WebElement toBeStale, Timer timer)
     {
         try
         {
-            toBeStale.isEnabled();
             new WebDriverWait(getDriver(), timer.timeRemaining())
                     .withMessage("waiting for browser to navigate")
                     .until(ExpectedConditions.stalenessOf(toBeStale));
         }
-        catch (StaleElementReferenceException | NoSuchElementException | NullPointerException ignore)
-        {
-            // `ExpectedConditions.stalenessOf(toBeStale)` sometimes chokes when coming from a blank page (about:blank)
-        }
         catch (TimeoutException ex)
         {
             throw new TestTimeoutException(ex); // Triggers thread dump.
         }
+        catch (WebDriverException | NullPointerException ignore)
+        {
+            // `ExpectedConditions.stalenessOf(toBeStale)` sometimes chokes when coming from a blank page (about:blank)
+        }
 
         // WebDriver usually does this automatically, but not always.
         new WebDriverWait(getDriver(), timer.timeRemaining())
diff --git a/src/org/labkey/test/aspects/MethodLoggingAspect.java b/src/org/labkey/test/aspects/MethodLoggingAspect.java
@@ -72,7 +72,7 @@ public void beforeLoggedMethod(JoinPoint joinPoint, LogMethod logMethod)
 
         String argsString = getArgsString(loggedParameters);
 
-        if (logMethod.quiet())
+        if (logMethod.quiet() && !TestLogger.log().isDebugEnabled())
         {
             TestLogger.suppressLogging(true);
             quietMethods.add(method);
@@ -108,7 +108,7 @@ private void logMethodEnd(JoinPoint joinPoint, LogMethod logMethod, String logPr
 
         String argString = " done";
 
-        if (logMethod.quiet())
+        if (logMethod.quiet() && !TestLogger.log().isDebugEnabled())
         {
             quietMethods.pop();
             argString = quietMethodsArgStrings.pop();
diff --git a/src/org/labkey/test/util/TestLogger.java b/src/org/labkey/test/util/TestLogger.java
@@ -16,19 +16,29 @@
 package org.labkey.test.util;
 
 import org.apache.commons.lang3.StringUtils;
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.apache.logging.log4j.ThreadContext;
+import org.apache.logging.log4j.core.config.Configurator;
 import org.jetbrains.annotations.Contract;
 import org.jetbrains.annotations.NotNull;
 
 import java.util.concurrent.TimeUnit;
 
+import static org.labkey.test.TestProperties.getTestLogLevel;
+
 public class TestLogger
 {
     private static final Logger LOG = LogManager.getLogger(TestLogger.class);
     private static final Logger NO_OP = LogManager.getLogger("NoOpLogger");
 
+    static
+    {
+        if (getTestLogLevel() != null)
+            Configurator.setLevel(LOG, Level.toLevel(getTestLogLevel()));
+    }
+
     private static final int indentStep = 2;
     private static final int MAX_INDENT = 20;
 
diff --git a/test.properties.template b/test.properties.template
@@ -64,6 +64,10 @@ test.credentials.file=
 webtest.timeout.multiplier=1.0
 ## Runs just the cleanup steps of the specified tests/suites
 cleanOnly=false
+## Set logging level for Selenium tests (default: INFO)
+#webtest.log.level=DEBUG
+## Set whether DeferredErrorCollector should fail immediately when errors are encountered (default: false)
+#webtest.checker.fatal=true
 
 
 #==============================================================================
@@ -131,7 +135,7 @@ labkey.contextpath=
 #==============================================================================
 # Server configuration properties
 #
-# These define certain Tomcat startup properties. Mostly only used by TeamCity
+# These inform tests of certain LabKey startup properties. Mostly only used by TeamCity
 #==============================================================================
 disableAssertions=false
 devMode=true

Original file line number	Diff line number	Diff line change
`@@ -17,11 +17,12 @@`
`17`	`17`
`18`	`18`	`import org.apache.commons.lang3.StringUtils;`
`19`	`19`	`import org.apache.commons.lang3.SystemUtils;`
	`20`	`+import org.apache.logging.log4j.LogManager;`
	`21`	`+import org.apache.logging.log4j.Logger;`
`20`	`22`	`import org.labkey.serverapi.reader.Readers;`
`21`	`23`	`import org.labkey.test.util.CachingSupplier;`
`22`	`24`	`import org.labkey.test.util.CspLogUtil;`
`23`	`25`	`import org.labkey.test.util.TestDataGenerator;`
`24`		`-import org.labkey.test.util.TestLogger;`
`25`	`26`	`import org.labkey.test.util.Version;`
`26`	`27`	`import org.openqa.selenium.Dimension;`
`27`	`28`
`@@ -42,41 +43,41 @@`
`42`	`43`	`import java.util.Objects;`
`43`	`44`	`import java.util.Optional;`
`44`	`45`	`import java.util.Properties;`
`45`		`-import java.util.Random;`
`46`	`46`	`import java.util.stream.Collectors;`
`47`	`47`	`import java.util.stream.Stream;`
`48`	`48`
`49`	`49`	`public abstract class TestProperties`
`50`	`50`	`{`
	`51`	`+ private static final Logger LOG = LogManager.getLogger(TestProperties.class);`
	`52`	`+`
`51`	`53`	`static`
`52`	`54`	`{`
`53`	`55`	`final File propFile = new File(TestFileUtils.getTestRoot(), "test.properties");`
`54`	`56`	`final File propFileTemplate = new File(TestFileUtils.getTestRoot(), "test.properties.template");`
`55`	`57`	`if (!propFile.exists())`
`56`	`58`	`{`
`57`		`- TestLogger.log(String.format("'%s' does not exist. Creating default from '%s'", propFile.getName(), propFileTemplate.getName()));`
	`59`	`+ LOG.info("'{}' does not exist. Creating default from '{}'", propFile.getName(), propFileTemplate.getName());`
`58`	`60`	`try (Stream<String> propStream = Files.lines(propFileTemplate.toPath()))`
`59`	`61`	`{`
`60`	`62`	`final Iterator<String> iterator = propStream.filter(line -> !line.startsWith("#!!")).iterator();`
`61`	`63`	`Files.write(propFile.toPath(), (Iterable<String>) () -> iterator, StandardOpenOption.CREATE_NEW);`
`62`	`64`	`}`
`63`	`65`	`catch (IOException e)`
`64`	`66`	`{`
`65`		`- TestLogger.error(e.getMessage());`
	`67`	`+ LOG.error(e.getMessage(), e);`
`66`	`68`	`}`
`67`	`69`	`}`
`68`	`70`	`try (Reader propReader = Readers.getReader(propFile))`
`69`	`71`	`{`
`70`		`- TestLogger.log("Loading properties from " + propFile.getName());`
	`72`	`+ LOG.info("Loading properties from {}", propFile.getName());`
`71`	`73`	`Properties properties = new Properties();`
`72`	`74`	`properties.load(propReader);`
`73`	`75`	`properties.putAll(System.getProperties());`
`74`	`76`	`System.setProperties(properties);`
`75`	`77`	`}`
`76`	`78`	`catch (IOException ioe)`
`77`	`79`	`{`
`78`		`- TestLogger.error("Failed to load " + propFile.getName() + " file. Running with hard-coded defaults");`
`79`		`- ioe.printStackTrace(System.err);`
	`80`	`+ LOG.error("Failed to load {} file. Running with hard-coded defaults", propFile.getName(), ioe);`
`80`	`81`	`}`
`81`	`82`
`82`	`83`	`final List<String> gradleProperties = List.of("labkeyVersion");`
`@@ -85,7 +86,7 @@ public abstract class TestProperties`
`85`	`86`	`{`
`86`	`87`	`try (Reader propReader = Readers.getReader(serverPropFile))`
`87`	`88`	`{`
`88`		`- TestLogger.log("Loading properties from " + serverPropFile.getName());`
	`89`	`+ LOG.info("Loading properties from {}", serverPropFile.getName());`
`89`	`90`	`Properties properties = new Properties();`
`90`	`91`	`properties.load(propReader);`
`91`	`92`	`for (String key : gradleProperties)`
`@@ -98,8 +99,7 @@ public abstract class TestProperties`
`98`	`99`	`}`
`99`	`100`	`catch (IOException ioe)`
`100`	`101`	`{`
`101`		`- TestLogger.error("Failed to load " + serverPropFile.getName() + " file.");`
`102`		`- ioe.printStackTrace(System.err);`
	`102`	`+ LOG.error("Failed to load {} file.", serverPropFile.getName(), ioe);`
`103`	`103`	`}`
`104`	`104`	`}`
`105`	`105`
`@@ -298,9 +298,9 @@ public static boolean isTroubleshootingStacktracesEnabled()`
`298`	`298`	`return getBooleanProperty("webtest.troubleshooting.stacktraces", false);`
`299`	`299`	`}`
`300`	`300`
`301`		`- public static boolean isDebugLoggingEnabled()`
	`301`	`+ public static String getTestLogLevel()`
`302`	`302`	`{`
`303`		`- return getBooleanProperty("webtest.logging.debug", false);`
	`303`	`+ return System.getProperty("webtest.log.level");`
`304`	`304`	`}`
`305`	`305`
`306`	`306`	`public static boolean isPrimaryUserAppAdmin()`
`@@ -432,7 +432,7 @@ public static File getDumpDir()`
`432`	`432`	`"Tried system properties failure.output.dir and java.io.tmpdir");`
`433`	`433`	`}`
`434`	`434`
`435`		`- TestLogger.log("Using " + dumpDir + " to store test output");`
	`435`	`+ LOG.info("Using {} to store test output", dumpDir);`
`436`	`436`	`}`
`437`	`437`	`return dumpDir;`
`438`	`438`	`}`
`@@ -475,7 +475,7 @@ public static int getIntegerProperty(String key, int def)`
`475`	`475`	`}`
`476`	`476`	`catch (NumberFormatException e)`
`477`	`477`	`{`
`478`		`- TestLogger.warn("Invalid value for property %s: '%s'".formatted(key, prop), e);`
	`478`	`+ LOG.warn("Invalid value for property {}: '{}'", key, prop, e);`
`479`	`479`	`}`
`480`	`480`	`}`
`481`	`481`	`return def;`
`@@ -499,7 +499,7 @@ public static double getDoubleProperty(String key, double def)`
`499`	`499`	`}`
`500`	`500`	`catch (NumberFormatException e)`
`501`	`501`	`{`
`502`		`- TestLogger.warn("Invalid value for property %s: '%s'".formatted(key, prop), e);`
	`502`	`+ LOG.warn("Invalid value for property {}: '{}'", key, prop, e);`
`503`	`503`	`}`
`504`	`504`	`}`
`505`	`505`	`return def;`
Original file line number	Diff line number	Diff line change
`@@ -355,6 +355,7 @@ protected Pair<WebDriver, DriverService> createNewWebDriver(@NotNull Pair<WebDri`
`355`	`355`	`profile.setPreference("extensions.update.enabled", false);`
`356`	`356`	`profile.setPreference("dom.max_script_run_time", 0);`
`357`	`357`	`profile.setPreference("dom.max_chrome_script_run_time", 0);`
	`358`	`+ //profile.setPreference("dom.reporting.enabled", true); // Enable support for CSP report-to`
`358`	`359`
`359`	`360`	`// Prevent crawler from hanging on '_print=1' pages`
`360`	`361`	`profile.setPreference("print.always_print_silent", true);`
`@@ -1997,19 +1998,18 @@ private void waitForPageToLoad(WebElement toBeStale, Timer timer)`
`1997`	`1998`	`{`
`1998`	`1999`	`try`
`1999`	`2000`	`{`
`2000`		`- toBeStale.isEnabled();`
`2001`	`2001`	`new WebDriverWait(getDriver(), timer.timeRemaining())`
`2002`	`2002`	`.withMessage("waiting for browser to navigate")`
`2003`	`2003`	`.until(ExpectedConditions.stalenessOf(toBeStale));`
`2004`	`2004`	`}`
`2005`		`- catch (StaleElementReferenceException \| NoSuchElementException \| NullPointerException ignore)`
`2006`		`- {`
`2007`		- // `ExpectedConditions.stalenessOf(toBeStale)` sometimes chokes when coming from a blank page (about:blank)
`2008`		`- }`
`2009`	`2005`	`catch (TimeoutException ex)`
`2010`	`2006`	`{`
`2011`	`2007`	`throw new TestTimeoutException(ex); // Triggers thread dump.`
`2012`	`2008`	`}`
	`2009`	`+ catch (WebDriverException \| NullPointerException ignore)`
	`2010`	`+ {`
	`2011`	+ // `ExpectedConditions.stalenessOf(toBeStale)` sometimes chokes when coming from a blank page (about:blank)
	`2012`	`+ }`
`2013`	`2013`
`2014`	`2014`	`// WebDriver usually does this automatically, but not always.`
`2015`	`2015`	`new WebDriverWait(getDriver(), timer.timeRemaining())`
Original file line number	Diff line number	Diff line change
`@@ -72,7 +72,7 @@ public void beforeLoggedMethod(JoinPoint joinPoint, LogMethod logMethod)`
`72`	`72`
`73`	`73`	`String argsString = getArgsString(loggedParameters);`
`74`	`74`
`75`		`- if (logMethod.quiet())`
	`75`	`+ if (logMethod.quiet() && !TestLogger.log().isDebugEnabled())`
`76`	`76`	`{`
`77`	`77`	`TestLogger.suppressLogging(true);`
`78`	`78`	`quietMethods.add(method);`
`@@ -108,7 +108,7 @@ private void logMethodEnd(JoinPoint joinPoint, LogMethod logMethod, String logPr`
`108`	`108`
`109`	`109`	`String argString = " done";`
`110`	`110`
`111`		`- if (logMethod.quiet())`
	`111`	`+ if (logMethod.quiet() && !TestLogger.log().isDebugEnabled())`
`112`	`112`	`{`
`113`	`113`	`quietMethods.pop();`
`114`	`114`	`argString = quietMethodsArgStrings.pop();`