From 79725f2d9cbc5fb4e4cc195388bc16087a295ac6 Mon Sep 17 00:00:00 2001 From: kshakir Date: Thu, 18 Nov 2010 20:22:01 +0000 Subject: [PATCH] Excluding the QFunction log files from the set of files to delete on completion. When a QGraph is empty displaying a warning instead of crashing with an JGraph internal assertion error. Cleaned up code using the Log4J root logger and explicitly talking to a logger for Sting. When integration tests are run detecting that the logger has already been setup so that messages aren't logged twice. Updated from Ivy 2.2.0-rc1 to 2.2.0. git-svn-id: file:///humgen/gsa-scr1/gsa-engineering/svn_contents/trunk@4707 348d0f76-0448-11de-a6fe-93d51630548a --- build.xml | 7 ++- .../sting/commandline/CommandLineProgram.java | 37 +++++------- .../sting/commandline/CommandLineUtils.java | 39 ++++++++++++ .../gatk/GATKExtensionsGenerator.java | 2 +- .../sting/utils/help/HelpFormatter.java | 2 +- .../org/broadinstitute/sting/BaseTest.java | 60 ++++++++----------- .../sting/queue/engine/QGraph.scala | 5 +- .../queue/function/InProcessFunction.scala | 2 +- .../sting/queue/function/QFunction.scala | 11 +++- .../scattergather/CloneFunction.scala | 2 +- .../sting/queue/util/Logging.scala | 28 ++++++++- 11 files changed, 127 insertions(+), 68 deletions(-) diff --git a/build.xml b/build.xml index 3d3d92140..98d5d5526 100644 --- a/build.xml +++ b/build.xml @@ -85,7 +85,7 @@ - + @@ -93,8 +93,6 @@ - - @@ -114,6 +112,9 @@ + + + diff --git a/java/src/org/broadinstitute/sting/commandline/CommandLineProgram.java b/java/src/org/broadinstitute/sting/commandline/CommandLineProgram.java index 47a4db9ef..7714ebe28 100644 --- a/java/src/org/broadinstitute/sting/commandline/CommandLineProgram.java +++ b/java/src/org/broadinstitute/sting/commandline/CommandLineProgram.java @@ -39,9 +39,6 @@ public abstract class CommandLineProgram { /** The command-line program and the arguments it returned. */ protected ParsingEngine parser = null; - /** our log, which we want to capture anything from org.broadinstitute.sting */ - private static Logger logger = Logger.getRootLogger(); - /** the default log level */ @Argument(fullName = "logging_level", shortName = "l", @@ -79,13 +76,16 @@ public abstract class CommandLineProgram { private static String patternString = "%-5p %d{HH:mm:ss,SSS} %C{1} - %m %n"; private static String debugPatternString = "%n[level] %p%n[date]\t\t %d{dd MMM yyyy HH:mm:ss,SSS} %n[class]\t\t %C %n[location]\t %l %n[line number]\t %L %n[message]\t %m %n"; - /** - * The very first thing that any Sting application does is forces the JVM locale into US English, so that we don't have - * to think about number formatting issues. - */ - { + static { + /** + * The very first thing that any Sting application does is forces the JVM locale into US English, so that we don't have + * to think about number formatting issues. + */ forceJVMLocaleToUSEnglish(); - } + // setup a basic log configuration + CommandLineUtils.configureConsoleLogging(); + } + /** * Allows a given application to return a brief description of itself. @@ -139,14 +139,10 @@ public abstract class CommandLineProgram { * when all the argument processing is done * * @return the return code to exit the program with + * @throws Exception when an exception occurs */ protected abstract int execute() throws Exception; - static { - // setup a basic log configuration - BasicConfigurator.configure(); - } - public static int result = -1; /** @@ -155,6 +151,7 @@ public abstract class CommandLineProgram { * * @param clp the command line program to execute * @param args the command line arguments passed in + * @throws Exception when an exception occurs */ @SuppressWarnings("unchecked") public static void start(CommandLineProgram clp, String[] args) throws Exception { @@ -163,12 +160,10 @@ public abstract class CommandLineProgram { // setup our log layout PatternLayout layout = new PatternLayout(); + Logger logger = CommandLineUtils.getStingLogger(); + // now set the layout of all the loggers to our layout - Enumeration en = logger.getAllAppenders(); - for (; en.hasMoreElements();) { - Appender app = en.nextElement(); - app.setLayout(layout); - } + CommandLineUtils.setLayout(logger, layout); // Initialize the logger using the defaults. clp.setupLoggerLevel(layout); @@ -269,10 +264,8 @@ public abstract class CommandLineProgram { private void setupLoggerLevel(PatternLayout layout) { // if we're in debug mode, set the mode up if (debugMode) { - //logger.info("Setting debug"); layout.setConversionPattern(debugPatternString); } else { - //logger.info("not Setting debug"); layout.setConversionPattern(patternString); } @@ -295,7 +288,7 @@ public abstract class CommandLineProgram { throw new ArgumentException("Unable to match: " + logging_level + " to a logging level, make sure it's a valid level (INFO, DEBUG, ERROR, FATAL, OFF)"); } - logger.setLevel(par); + CommandLineUtils.getStingLogger().setLevel(par); } /** diff --git a/java/src/org/broadinstitute/sting/commandline/CommandLineUtils.java b/java/src/org/broadinstitute/sting/commandline/CommandLineUtils.java index 57e83a38c..6eb772dde 100644 --- a/java/src/org/broadinstitute/sting/commandline/CommandLineUtils.java +++ b/java/src/org/broadinstitute/sting/commandline/CommandLineUtils.java @@ -25,6 +25,7 @@ package org.broadinstitute.sting.commandline; +import org.apache.log4j.*; import org.broadinstitute.sting.utils.exceptions.ReviewedStingException; import java.util.*; @@ -142,4 +143,42 @@ public class CommandLineUtils { private static boolean isObjectPointer(String s) { return s != null && s.matches(pointerRegexp); } + + /** + * Returns the root logger for all Sting code. + * @return the root logger for all Sting code. + */ + public static Logger getStingLogger() { + return Logger.getLogger("org.broadinstitute.sting"); + } + + /** + * Enables console logging. + */ + @SuppressWarnings("unchecked") + public static void configureConsoleLogging() { + // Check to see if a console logger has already been enabled. + for (Logger logger = getStingLogger(); logger != null; logger = (Logger)logger.getParent()) { + Enumeration e = (Enumeration) logger.getAllAppenders(); + for (Appender appender: Collections.list(e)) { + if (appender instanceof ConsoleAppender) + return; + } + } + // Extracted from BasicConfigurator.configure(), but only applied to the Sting logger. + getStingLogger().addAppender(new ConsoleAppender( + new PatternLayout(PatternLayout.TTCC_CONVERSION_PATTERN))); + } + + /** + * Sets the layout of the logger. + * @param logger The logger. + * @param layout The layout. + */ + @SuppressWarnings("unchecked") + public static void setLayout(Logger logger, PatternLayout layout) { + Enumeration e = (Enumeration) logger.getAllAppenders(); + for (Appender appender: Collections.list(e)) + appender.setLayout(layout); + } } diff --git a/java/src/org/broadinstitute/sting/queue/extensions/gatk/GATKExtensionsGenerator.java b/java/src/org/broadinstitute/sting/queue/extensions/gatk/GATKExtensionsGenerator.java index fb626b859..039cf955f 100644 --- a/java/src/org/broadinstitute/sting/queue/extensions/gatk/GATKExtensionsGenerator.java +++ b/java/src/org/broadinstitute/sting/queue/extensions/gatk/GATKExtensionsGenerator.java @@ -55,7 +55,7 @@ import java.util.Map.Entry; * ArgumentCollections are flattened into a single module. */ public class GATKExtensionsGenerator extends CommandLineProgram { - private static final Logger logger = Logger.getRootLogger(); + private static final Logger logger = Logger.getLogger(GATKExtensionsGenerator.class); public static final String GATK_EXTENSIONS_PACKAGE_NAME = "org.broadinstitute.sting.queue.extensions.gatk"; private static final String COMMANDLINE_PACKAGE_NAME = GATK_EXTENSIONS_PACKAGE_NAME; private static final String FILTER_PACKAGE_NAME = GATK_EXTENSIONS_PACKAGE_NAME; diff --git a/java/src/org/broadinstitute/sting/utils/help/HelpFormatter.java b/java/src/org/broadinstitute/sting/utils/help/HelpFormatter.java index 799139832..493f26e76 100755 --- a/java/src/org/broadinstitute/sting/utils/help/HelpFormatter.java +++ b/java/src/org/broadinstitute/sting/utils/help/HelpFormatter.java @@ -47,7 +47,7 @@ import java.text.SimpleDateFormat; public class HelpFormatter { /** our log, which we want to capture anything from org.broadinstitute.sting */ - private static Logger logger = Logger.getRootLogger(); + private static Logger logger = Logger.getLogger(HelpFormatter.class); public static final int FIELD_SEPARATION_WIDTH = 3; diff --git a/java/test/org/broadinstitute/sting/BaseTest.java b/java/test/org/broadinstitute/sting/BaseTest.java index 44e5d0680..99e132f60 100755 --- a/java/test/org/broadinstitute/sting/BaseTest.java +++ b/java/test/org/broadinstitute/sting/BaseTest.java @@ -2,14 +2,13 @@ package org.broadinstitute.sting; import org.apache.log4j.*; import org.apache.log4j.spi.LoggingEvent; +import org.broadinstitute.sting.commandline.CommandLineUtils; import org.broadinstitute.sting.utils.exceptions.ReviewedStingException; -import org.testng.annotations.BeforeClass; import java.io.*; import java.math.BigInteger; import java.security.MessageDigest; import java.security.NoSuchAlgorithmException; -import java.util.Enumeration; /** * @@ -38,48 +37,41 @@ import java.util.Enumeration; * This is the base test class for all of our test cases. All test cases should extend from this * class; it sets up the logger, and resolves the location of directories that we rely on. */ +@SuppressWarnings("unchecked") public abstract class BaseTest { /** our log, which we want to capture anything from org.broadinstitute.sting */ - public static Logger logger = Logger.getRootLogger(); + public static final Logger logger = CommandLineUtils.getStingLogger(); - public static String hg18Reference = "/seq/references/Homo_sapiens_assembly18/v0/Homo_sapiens_assembly18.fasta"; - public static String hg19Reference = "/seq/references/Homo_sapiens_assembly19/v0/Homo_sapiens_assembly19.fasta"; - public static String b36KGReference = "/humgen/1kg/reference/human_b36_both.fasta"; - public static String b37KGReference = "/humgen/1kg/reference/human_g1k_v37.fasta"; - public static String GATKDataLocation = "/humgen/gsa-hpprojects/GATK/data/"; - public static String validationDataLocation = GATKDataLocation + "Validation_Data/"; - public static String evaluationDataLocation = GATKDataLocation + "Evaluation_Data/"; - public static String comparisonDataLocation = GATKDataLocation + "Comparisons/"; + public static final String hg18Reference = "/seq/references/Homo_sapiens_assembly18/v0/Homo_sapiens_assembly18.fasta"; + public static final String hg19Reference = "/seq/references/Homo_sapiens_assembly19/v0/Homo_sapiens_assembly19.fasta"; + public static final String b36KGReference = "/humgen/1kg/reference/human_b36_both.fasta"; + public static final String b37KGReference = "/humgen/1kg/reference/human_g1k_v37.fasta"; + public static final String GATKDataLocation = "/humgen/gsa-hpprojects/GATK/data/"; + public static final String validationDataLocation = GATKDataLocation + "Validation_Data/"; + public static final String evaluationDataLocation = GATKDataLocation + "Evaluation_Data/"; + public static final String comparisonDataLocation = GATKDataLocation + "Comparisons/"; - public String testDir = "testdata/"; - protected static boolean alreadySetup = false; - + public final String testDir = "testdata/"; /** before the class starts up */ - public BaseTest() { - if (!alreadySetup) { + static { + // setup a basic log configuration + CommandLineUtils.configureConsoleLogging(); - alreadySetup = true; - // setup a basic log configuration - BasicConfigurator.configure(); + // setup our log layout + PatternLayout layout = new PatternLayout(); + layout.setConversionPattern("TEST %C{1}.%M - %d{HH:mm:ss,SSS} - %m%n"); - // setup our log layout - PatternLayout layout = new PatternLayout(); - layout.setConversionPattern("TEST %C{1}.%M - %d{HH:mm:ss,SSS} - %m%n"); + // now set the layout of all the loggers to our layout + CommandLineUtils.setLayout(logger, layout); - // now set the layout of all the loggers to our layout - Enumeration en = logger.getAllAppenders(); - for (; en.hasMoreElements();) { - Appender app = en.nextElement(); - app.setLayout(layout); - } - logger.setLevel(Level.WARN); + // Set the Root logger to only output warnings. + logger.setLevel(Level.WARN); - // find our file sources - if (!fileExist(hg18Reference) || !fileExist(hg19Reference) || !fileExist(b36KGReference)) { - logger.fatal("We can't locate the reference directories. Aborting!"); - throw new RuntimeException("BaseTest setup failed: unable to locate the reference directories"); - } + // find our file sources + if (!fileExist(hg18Reference) || !fileExist(hg19Reference) || !fileExist(b36KGReference)) { + logger.fatal("We can't locate the reference directories. Aborting!"); + throw new RuntimeException("BaseTest setup failed: unable to locate the reference directories"); } } diff --git a/scala/src/org/broadinstitute/sting/queue/engine/QGraph.scala b/scala/src/org/broadinstitute/sting/queue/engine/QGraph.scala index c5b814e26..1b6306d37 100755 --- a/scala/src/org/broadinstitute/sting/queue/engine/QGraph.scala +++ b/scala/src/org/broadinstitute/sting/queue/engine/QGraph.scala @@ -45,11 +45,14 @@ class QGraph extends Logging { * Checks the functions for missing values and the graph for cyclic dependencies and then runs the functions in the graph. */ def run = { + IOUtils.checkTempDir(settings.qSettings.tempDirectory) val numMissingValues = fillGraph val isReady = numMissingValues == 0 - if (settings.getStatus) { + if (this.jobGraph.edgeSet.isEmpty) { + logger.warn("Nothing to run! Were any Functions added?"); + } else if (settings.getStatus) { logger.info("Checking pipeline status.") logStatus() } else if (this.dryRun) { diff --git a/scala/src/org/broadinstitute/sting/queue/function/InProcessFunction.scala b/scala/src/org/broadinstitute/sting/queue/function/InProcessFunction.scala index 078699e70..00207fea0 100644 --- a/scala/src/org/broadinstitute/sting/queue/function/InProcessFunction.scala +++ b/scala/src/org/broadinstitute/sting/queue/function/InProcessFunction.scala @@ -5,5 +5,5 @@ package org.broadinstitute.sting.queue.function */ trait InProcessFunction extends QFunction { def run() - def description = (List(this.getClass.getSimpleName) ++ this.outputs.filter(file => useStatusOutput(file)).map(_.getAbsolutePath)).mkString(" ") + def description = (List(this.getClass.getSimpleName) ++ this.outputs.filterNot(file => isLogFile(file)).map(_.getAbsolutePath)).mkString(" ") } diff --git a/scala/src/org/broadinstitute/sting/queue/function/QFunction.scala b/scala/src/org/broadinstitute/sting/queue/function/QFunction.scala index fa3e919cb..ab9e6ac12 100644 --- a/scala/src/org/broadinstitute/sting/queue/function/QFunction.scala +++ b/scala/src/org/broadinstitute/sting/queue/function/QFunction.scala @@ -85,8 +85,13 @@ trait QFunction extends Logging { * Returns true if the file should be used for status output. * @return true if the file should be used for status output. */ - def useStatusOutput(file: File) = - file != jobOutputFile && file != jobErrorFile + def useStatusOutput(file: File) = !isLogFile(file) + + /** + * Returns true if the file is a log file for this function. + */ + protected def isLogFile(file: File) = + file == jobOutputFile || file == jobErrorFile /** * Returns the output files for this function. @@ -165,7 +170,7 @@ trait QFunction extends Logging { * Deletes the output files and all the status files for this function. */ def deleteOutputs() = { - outputs.foreach(file => IOUtils.tryDelete(file)) + outputs.filterNot(file => isLogFile(file)).foreach(file => IOUtils.tryDelete(file)) doneOutputs.foreach(file => IOUtils.tryDelete(file)) failOutputs.foreach(file => IOUtils.tryDelete(file)) } diff --git a/scala/src/org/broadinstitute/sting/queue/function/scattergather/CloneFunction.scala b/scala/src/org/broadinstitute/sting/queue/function/scattergather/CloneFunction.scala index b7451f69e..f0bb1598b 100644 --- a/scala/src/org/broadinstitute/sting/queue/function/scattergather/CloneFunction.scala +++ b/scala/src/org/broadinstitute/sting/queue/function/scattergather/CloneFunction.scala @@ -43,7 +43,7 @@ class CloneFunction extends CommandLineFunction { override def description = withScatterPart(() => originalFunction.description) override protected def functionFieldClass = originalFunction.getClass override def useStatusOutput(file: File) = - file != jobOutputFile && file != jobErrorFile && originalFunction.useStatusOutput(file) + !isLogFile(file) && originalFunction.useStatusOutput(file) def commandLine = withScatterPart(() => originalFunction.commandLine) diff --git a/scala/src/org/broadinstitute/sting/queue/util/Logging.scala b/scala/src/org/broadinstitute/sting/queue/util/Logging.scala index 5a9fed204..3361c1023 100755 --- a/scala/src/org/broadinstitute/sting/queue/util/Logging.scala +++ b/scala/src/org/broadinstitute/sting/queue/util/Logging.scala @@ -1,11 +1,37 @@ package org.broadinstitute.sting.queue.util import org.apache.log4j._ +import java.lang.{Throwable, String} +import org.apache.log4j.spi.{ThrowableInformation, LocationInfo, LoggingEvent, LoggerFactory} +import java.util.Hashtable /** * A mixin to add logging to a class */ trait Logging { private val className = this.getClass.getName - protected lazy val logger = Logger.getLogger(className) + protected lazy val logger = Logger.getLogger(className, Logging.factory) +} + +object Logging { + private object factory extends LoggerFactory { + /** + * Do not log the scala generated class name after "$". + * All these shenanigans can be avoided if we use the format + * string c{1} (the name passed to Logger.getLogger) + * versus C{1} (the class name of the calling method) + */ + def makeNewLoggerInstance(name: String) = new Logger(name) { + override def forcedLog(fqcn: String, level: Priority, message: AnyRef, t: Throwable) = { + // Strip off the "$" from the class name. + val info = new LocationInfo(new Throwable, fqcn) { override def getClassName = super.getClassName.takeWhile(_ != '$') } + // If the following aren't retrieved here, LoggingEvent will NOT lazy load them. + val throwable = if (t == null) null else new ThrowableInformation(t) + val ndc = NDC.get + val mdc = MDC.getContext().asInstanceOf[Hashtable[_,_]]; + callAppenders(new LoggingEvent(fqcn, this, System.currentTimeMillis, + level.asInstanceOf[Level], message, null, throwable, ndc, info, mdc)) + } + } + } }