GP-3615 - Added a test harness method to make it easier to change log output from a test. The test harness will reset any changes made at the end of the test.

This commit is contained in:
dragonmacher 2023-07-19 12:47:47 -04:00
parent f8ec071906
commit bd0c491263
9 changed files with 170 additions and 105 deletions

View file

@ -27,14 +27,13 @@ import java.util.concurrent.atomic.AtomicReference;
import javax.swing.*;
import javax.swing.table.TableModel;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.*;
import docking.widgets.filter.FilterOptions;
import docking.widgets.table.threaded.ThreadedTableModelStub;
import ghidra.docking.settings.Settings;
import ghidra.framework.LoggingInitialization;
import ghidra.framework.plugintool.ServiceProvider;
import ghidra.test.AbstractGhidraHeadedIntegrationTest;
import ghidra.util.datastruct.Accumulator;
@ -55,16 +54,11 @@ public class SelectionManagerTest extends AbstractGhidraHeadedIntegrationTest {
private Logger logger;
public SelectionManagerTest() {
super();
}
@Before
public void setUp() throws Exception {
LoggingInitialization.initializeLoggingSystem();
logger = LogManager.getLogger(SelectionManager.class);
Configurator.setLevel(logger.getName(), Level.DEBUG);
// setLogLevel(SelectionManager.class, Level.DEBUG);
logger.trace("\n\nsetUp(): " + testName.getMethodName());

View file

@ -20,8 +20,7 @@ import static org.junit.Assert.*;
import java.io.*;
import java.nio.file.Path;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.Level;
import org.junit.Test;
import docking.test.AbstractDockingTest;
@ -38,7 +37,6 @@ import utilities.util.FileUtilities;
public class GhidraScriptMgrPlugin2Test extends AbstractGhidraScriptMgrPluginTest {
public GhidraScriptMgrPlugin2Test() {
super();
}
@Test
@ -150,8 +148,7 @@ public class GhidraScriptMgrPlugin2Test extends AbstractGhidraScriptMgrPluginTes
assertTrue("Unable to delete class files from the user scripts directory", isEmpty);
// remove all class files from the user script bin dir
File userScriptsBinDir =
getBinDirFromScriptFile(new ResourceFile(newScriptFile)).toFile();
File userScriptsBinDir = getBinDirFromScriptFile(new ResourceFile(newScriptFile)).toFile();
File[] userScriptBinDirFiles;
if (userScriptsBinDir.exists()) {
userScriptBinDirFiles = userScriptsBinDir.listFiles(classFileFilter);
@ -195,8 +192,7 @@ public class GhidraScriptMgrPlugin2Test extends AbstractGhidraScriptMgrPluginTes
waitForScriptCompletion(scriptID, 20000);
// verify that the generated class file is placed in the default scripting home/bin
File userScriptsBinDir =
getBinDirFromScriptFile(systemScriptFile).toFile();
File userScriptsBinDir = getBinDirFromScriptFile(systemScriptFile).toFile();
String className = scriptName.replace(".java", ".class");
File expectedClassFile = new File(userScriptsBinDir, className);
@ -251,8 +247,7 @@ public class GhidraScriptMgrPlugin2Test extends AbstractGhidraScriptMgrPluginTes
public void testRenameWithTreeFilter() throws Exception {
// debug
Logger logger = LogManager.getLogger(SelectionManager.class);
Configurator.setLevel(logger.getName(), Level.TRACE);
setLogLevel(SelectionManager.class, Level.TRACE);
pressNewButton();

View file

@ -21,8 +21,7 @@ import static org.junit.Assert.*;
import java.util.*;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.Level;
import org.junit.After;
import org.junit.Before;
@ -119,11 +118,8 @@ public abstract class AbstractFunctionSignatureMarkupTest
controller = vtTestEnv.getVTController();
vtTestEnv.showTool();
Logger functionLogger = LogManager.getLogger(FunctionDB.class);
Configurator.setLevel(functionLogger.getName(), Level.TRACE);
Logger variableLogger = LogManager.getLogger(VariableSymbolDB.class);
Configurator.setLevel(variableLogger.getName(), Level.TRACE);
setLogLevel(FunctionDB.class, Level.TRACE);
setLogLevel(VariableSymbolDB.class, Level.TRACE);
}
private void disableAutoAnalysis(Program program) {

View file

@ -41,8 +41,7 @@ import javax.swing.table.JTableHeader;
import org.apache.commons.io.FileUtils;
import org.apache.commons.lang3.ArrayUtils;
import org.apache.commons.lang3.StringUtils;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.Level;
import org.junit.*;
import docking.*;
@ -52,7 +51,8 @@ import docking.widgets.DropDownSelectionTextField;
import docking.widgets.SpyDropDownWindowVisibilityListener;
import docking.widgets.table.*;
import generic.concurrent.ConcurrentQ;
import ghidra.framework.*;
import ghidra.framework.OperatingSystem;
import ghidra.framework.Platform;
import ghidra.framework.preferences.Preferences;
import ghidra.util.Msg;
import ghidra.util.filechooser.ExtensionFileFilter;
@ -1556,9 +1556,7 @@ public class GhidraFileChooserTest extends AbstractDockingTest {
//
// Enable tracing to catch odd test failure
LoggingInitialization.initializeLoggingSystem();
Logger logger = LogManager.getLogger(GhidraFileChooser.class);
Configurator.setLevel(logger.getName(), Level.TRACE);
setLogLevel(GhidraFileChooser.class, Level.TRACE);
final JComponent component = chooser.getComponent();
Dimension originalSize = component.getSize();
@ -1591,9 +1589,7 @@ public class GhidraFileChooserTest extends AbstractDockingTest {
//
// Enable tracing to catch odd test failure
LoggingInitialization.initializeLoggingSystem();
Logger logger = LogManager.getLogger(GhidraFileChooser.class);
Configurator.setLevel(logger.getName(), Level.TRACE);
setLogLevel(GhidraFileChooser.class, Level.TRACE);
JComponent component = chooser.getComponent();
EmptyBorderToggleButton detailsButton =
@ -2045,8 +2041,7 @@ public class GhidraFileChooserTest extends AbstractDockingTest {
// debug code
if (expected != actual) {
waitForCondition(() -> expected == actual,
"Wrong list index selected ");
waitForCondition(() -> expected == actual, "Wrong list index selected ");
}
}
@ -2119,8 +2114,8 @@ public class GhidraFileChooserTest extends AbstractDockingTest {
}
private void setTableMode() {
AbstractButton button = (AbstractButton) findComponentByName(chooser.getComponent(),
"DETAILS_BUTTON");
AbstractButton button =
(AbstractButton) findComponentByName(chooser.getComponent(), "DETAILS_BUTTON");
boolean isSelected = runSwing(() -> button.isSelected());
if (!isSelected) {
// toggle from the table 'details mode'
@ -2129,8 +2124,8 @@ public class GhidraFileChooserTest extends AbstractDockingTest {
}
private void setListMode() {
AbstractButton button = (AbstractButton) findComponentByName(chooser.getComponent(),
"DETAILS_BUTTON");
AbstractButton button =
(AbstractButton) findComponentByName(chooser.getComponent(), "DETAILS_BUTTON");
boolean isSelected = runSwing(() -> button.isSelected());
if (isSelected) {
// toggle from the table 'details mode'

View file

@ -15,6 +15,8 @@
*/
package generic.test;
import static org.junit.Assert.*;
import java.awt.*;
import java.awt.image.BufferedImage;
import java.io.*;
@ -27,6 +29,12 @@ import java.util.regex.Pattern;
import javax.swing.SwingUtilities;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.*;
import org.junit.After;
import org.junit.Rule;
import org.junit.rules.*;
import org.junit.runner.Description;
@ -36,8 +44,7 @@ import generic.test.rule.Repeated;
import generic.test.rule.RepeatedTestRule;
import generic.util.WindowUtilities;
import ghidra.GhidraTestApplicationLayout;
import ghidra.framework.Application;
import ghidra.framework.ApplicationConfiguration;
import ghidra.framework.*;
import ghidra.util.Msg;
import ghidra.util.SystemUtilities;
import ghidra.util.exception.AssertException;
@ -67,6 +74,8 @@ public abstract class AbstractGenericTest extends AbstractGTest {
private volatile boolean hasFailed;
private boolean logSettingsChanged;
public TestWatcher watchman = new TestWatcher() {
@Override
@ -114,6 +123,13 @@ public abstract class AbstractGenericTest extends AbstractGTest {
@Rule
public TestRule repeatedRule = new RepeatedTestRule();
@After
public void resetLogging() {
if (logSettingsChanged) {
LoggingInitialization.reinitialize();
}
}
private void debugBatch(String message) {
if (BATCH_MODE) {
Msg.debug(AbstractGenericTest.class, message);
@ -232,6 +248,71 @@ public abstract class AbstractGenericTest extends AbstractGTest {
// perform diagnostic stuff here when a test has failed
}
/**
* A convenience method for {@link #setLogLevel(String, Level)}.
*
* @param loggerClazz the logger class
* @param newLevel the new level
*/
protected void setLogLevel(Class<?> loggerClazz, Level newLevel) {
setLogLevel(loggerClazz.getName(), newLevel);
}
/**
* A convenience method to change the log level of the given logger name. The logger name is
* typically the class name that contains specialized logging. You may also pass a package
* name to get logging for all classes in that package.
* See {@link Configurator#setLevel(String, Level)}
* <P>
* The console appender's log level will be changed if needed to ensure that messages for the
* given log level are displayed.
* <P>
* The log system will be reset to the default settings when the test is finished.
*
* @param loggerName the logger name
* @param newLevel the new log level to use
*/
protected void setLogLevel(String loggerName, Level newLevel) {
logSettingsChanged = true;
Configurator.setLevel(loggerName, newLevel);
LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false);
Configuration configuration = loggerContext.getConfiguration();
LoggerConfig rootLoggerConfiguration = configuration.getLoggers().get("");
AppenderRef consoleAppender = getConsoleAppender(configuration, rootLoggerConfiguration);
Level currentLevel = consoleAppender.getLevel();
if (currentLevel.compareTo(newLevel) > 0) {
// the requested level is lower than the current level, so the messages will be shown
return;
}
// Note: we have to tell the console appender to change its level as well. Otherwise, users
// may not see their messages in the console. It is set to DEBUG by default.
String consoleAppenderName = "console";
rootLoggerConfiguration.removeAppender(consoleAppenderName);
Appender appender = configuration.getAppender(consoleAppenderName);
rootLoggerConfiguration.addAppender(appender, newLevel, null);
loggerContext.updateLoggers();
}
private AppenderRef getConsoleAppender(Configuration configuration,
LoggerConfig rootLoggerConfigiguration) {
String consoleAppenderName = "console";
List<AppenderRef> appenders = rootLoggerConfigiguration.getAppenderRefs();
for (AppenderRef ref : appenders) {
String refName = ref.getRef();
if (refName.equals(consoleAppenderName)) {
return ref;
}
}
fail("Unable to find the logging console appender");
return null;
}
/**
* Returns the window parent of c. If c is a window, then c is returned.
*

View file

@ -171,9 +171,8 @@ public class LoggingInitialization {
// determine the log file name. Once that's set, the log configuration must be 'kicked' to
// pick up the change.
System.setProperty("logFilename", file.getAbsolutePath());
if (INITIALIZED) {
((LoggerContext) LogManager.getContext(false)).reconfigure();
}
reinitialize();
}
/**
@ -209,6 +208,16 @@ public class LoggingInitialization {
// 'kicked' to pick up the change.
System.setProperty("scriptLogFilename", file.getAbsolutePath());
reinitialize();
}
/**
* Signals to reload the log settings from the log configuration files in use. This is useful
* for tests that wish to temporarily change log settings, restoring them when done.
* <p>
* This method will do nothing if {@link #initializeLoggingSystem()} has not been called.
*/
public synchronized static void reinitialize() {
if (INITIALIZED) {
((LoggerContext) LogManager.getContext(false)).reconfigure();
}

View file

@ -28,7 +28,6 @@ import org.junit.*;
import generic.test.AbstractGTest;
import generic.test.AbstractGuiTest;
import ghidra.framework.LoggingInitialization;
import ghidra.util.Msg;
import ghidra.util.SystemUtilities;
import ghidra.util.datastruct.WeakDataStructureFactory;
@ -57,20 +56,14 @@ public class VisualGraphJobRunnerTest extends AbstractGuiTest {
System.setProperty(SystemUtilities.HEADLESS_PROPERTY, "false");
LoggingInitialization.initializeLoggingSystem();
logger = LogManager.getLogger(GraphJobRunner.class);
// enable tracing for debugging (note: this still requires the active log4j file
// to have the 'console' appender set to 'TRACE'
// Configurator.setLevel(logger.getName(), org.apache.logging.log4j.Level.TRACE);
//
// Logger myLogger = LogManager.getLogger(VisualGraphJobRunnerTest.class);
// Configurator.setLevel(myLogger.getName(), org.apache.logging.log4j.Level.TRACE);
// use this to see the tracing output
// setLogLevel("ghidra.graph.job", Level.TRACE);
}
@After
public void tearDown() {
for (JobExecutionThread t : jobThreads) {
t.killThread();
}
@ -78,6 +71,7 @@ public class VisualGraphJobRunnerTest extends AbstractGuiTest {
@Test
public void testRunJob() {
BasicJob basicJob = new BasicJob();
schedule(basicJob);
waitForJobToStart(basicJob);
@ -461,7 +455,17 @@ public class VisualGraphJobRunnerTest extends AbstractGuiTest {
}
}
logger.trace("\n\n\t@Test - done waiting\n\n");
// The job may already be finished while the thread is busy cleaning up. We need to wait
// for the thread to be finished as well.
waitForJobThreads();
logger.trace("\n\n\t@Test - done waiting - is busy?: " + jobRunner.isBusy() + "\n\n");
}
private void waitForJobThreads() {
for (JobExecutionThread t : jobThreads) {
waitFor(() -> t.isFinished);
}
}
private void assertFinishedAndShortcut(AbstractTestGraphJob... jobs) {
@ -796,7 +800,6 @@ public class VisualGraphJobRunnerTest extends AbstractGuiTest {
private class NonShortcuttableJob extends TimeBasedJob {
NonShortcuttableJob() {
super();
}
NonShortcuttableJob(long runtime) {

View file

@ -23,8 +23,7 @@ import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.config.Configurator;
import org.apache.logging.log4j.Level;
import org.junit.*;
import generic.concurrent.GThreadPool;
@ -46,7 +45,6 @@ public class GTaskTest extends AbstractGenericTest {
};
public GTaskTest() {
super();
}
@Before
@ -420,8 +418,7 @@ public class GTaskTest extends AbstractGenericTest {
public void testExceptionInTaskListenerTaskCompleted() {
// disable printing of exception below
Logger logger = LogManager.getLogger(GTaskManager.class);
Configurator.setLevel(logger.getName(), Level.OFF);
setLogLevel(GTaskManager.class, Level.OFF);
gTaskManager.addTaskListener(new GTaskListenerAdapter() {
@Override
@ -434,16 +431,13 @@ public class GTaskTest extends AbstractGenericTest {
// this is testing that the exception does cause the taskManager to timeout still busy
waitForTaskManager();
Configurator.setLevel(logger.getName(), Level.DEBUG);
}
@Test
public void testExceptionInTaskListenerTaskStarted() {
// disable printing of exception below
Logger logger = LogManager.getLogger(GTaskManager.class);
Configurator.setLevel(logger.getName(), Level.OFF);
setLogLevel(GTaskManager.class, Level.OFF);
gTaskManager.addTaskListener(new GTaskListenerAdapter() {
@Override
@ -456,8 +450,6 @@ public class GTaskTest extends AbstractGenericTest {
// this is testing that the exception does cause the taskManager to timeout still busy
waitForTaskManager();
Configurator.setLevel(logger.getName(), Level.DEBUG);
}
private void cancelCurrentTask() {

View file

@ -19,7 +19,8 @@ package ghidra.pcodeCPort.slgh_compile.regression;
import static org.junit.Assert.*;
import java.io.*;
import java.util.*;
import java.util.Iterator;
import java.util.List;
import java.util.regex.Pattern;
import org.antlr.runtime.RecognitionException;
@ -66,7 +67,6 @@ public class SleighCompileRegressionTest extends AbstractGenericTest {
StringBuffer summary = new StringBuffer();
LoggingInitialization.initializeLoggingSystem();
List<ResourceFile> inputs = getSlaspecFiles();
Iterator<ResourceFile> ii = inputs.iterator();