From b9c549c612fbe02c7046100f8d8d07749db3d312 Mon Sep 17 00:00:00 2001 From: Alistair Michael Date: Mon, 2 Dec 2024 16:55:02 +1000 Subject: [PATCH] multiple loggers --- src/main/scala/Main.scala | 18 +- .../InterprocSteensgaardAnalysis.scala | 10 +- .../scala/analysis/IrreducibleLoops.scala | 12 +- src/main/scala/analysis/Lattice.scala | 4 +- src/main/scala/analysis/MemoryModelMap.scala | 36 ++-- .../scala/analysis/MemoryRegionAnalysis.scala | 8 +- src/main/scala/analysis/RegionInjector.scala | 1 - .../scala/analysis/SummaryGenerator.scala | 3 +- src/main/scala/analysis/TaintAnalysis.scala | 1 - src/main/scala/analysis/VSA.scala | 9 +- .../analysis/VariableDependencyAnalysis.scala | 4 +- src/main/scala/ir/eval/Interpreter.scala | 6 +- src/main/scala/ir/transforms/Simp.scala | 26 +-- src/main/scala/translating/IRExpToSMT2.scala | 2 +- .../scala/translating/PrettyPrinter.scala | 32 ++-- src/main/scala/util/Logging.scala | 166 ++++++++++++++---- src/main/scala/util/RunUtils.scala | 154 ++++++++-------- src/test/scala/DifferentialAnalysisTest.scala | 4 +- 18 files changed, 309 insertions(+), 187 deletions(-) diff --git a/src/main/scala/Main.scala b/src/main/scala/Main.scala index 4a6630ce3..0568b594d 100644 --- a/src/main/scala/Main.scala +++ b/src/main/scala/Main.scala @@ -28,8 +28,10 @@ object Main { lambdaStores: Flag, @arg(name = "boogie-procedure-rg", doc = "Switch version of procedure rely/guarantee checks to emit. (function|ifblock)") procedureRG: Option[String], - @arg(name = "verbose", short = 'v', doc = "Show extra debugging logs.") + @arg(name = "verbose", short = 'v', doc = "Show extra debugging logs (the same as -vl log)") verbose: Flag, + @arg(name = "vl", doc = s"Show extra debugging logs for a specific logger (${Logger.allLoggers.map(_.name).mkString(", ")}).") + verboseLog: Seq[String] = Seq(), @arg(name = "analyse", doc = "Run static analysis pass.") analyse: Flag, @arg(name = "interpret", doc = "Run BASIL IL interpreter.") @@ -79,7 +81,19 @@ object Main { Logger.setLevel(LogLevel.INFO) if (conf.verbose.value) { - Logger.setLevel(LogLevel.DEBUG) + Logger.setLevel(LogLevel.DEBUG, true) + } + for (v <- conf.verboseLog) { + Logger.findLoggerByName(v) match { + case None => throw Exception(s"Unknown logger: '${v}': allowed are ${Logger.allLoggers.map(_.name).mkString(", ")}") + case Some(v) => v.setLevel(LogLevel.DEBUG, true) + } + } + + if (conf.analysisResults.isDefined || conf.analysisResultsDot.isDefined) { + DebugDumpIRLogger.setLevel(LogLevel.INFO) + } else { + DebugDumpIRLogger.setLevel(LogLevel.OFF) } val rely = conf.procedureRG match { diff --git a/src/main/scala/analysis/InterprocSteensgaardAnalysis.scala b/src/main/scala/analysis/InterprocSteensgaardAnalysis.scala index 0817628a6..f5e6d416c 100644 --- a/src/main/scala/analysis/InterprocSteensgaardAnalysis.scala +++ b/src/main/scala/analysis/InterprocSteensgaardAnalysis.scala @@ -2,7 +2,7 @@ package analysis import analysis.solvers.{Cons, Term, UnionFindSolver, Var} import ir.* -import util.Logger +import util.SteensLogger import scala.collection.mutable /** Wrapper for variables so we can have Steensgaard-specific equals method indirectly @@ -142,7 +142,7 @@ class InterprocSteensgaardAnalysis( } private def unify(t1: Term[StTerm], t2: Term[StTerm]): Unit = { - //Logger.info(s"univfying constraint $t1 = $t2\n") + //SteensLogger.info(s"univfying constraint $t1 = $t2\n") solver.unify(t1, t2) // note that unification cannot fail, because there is only one kind of term constructor and no constants } @@ -152,8 +152,8 @@ class InterprocSteensgaardAnalysis( def pointsTo(): Map[RegisterWrapperEqualSets, Set[RegisterWrapperEqualSets | MemoryRegion]] = { val solution = solver.solution() val unifications = solver.unifications() - Logger.debug(s"Solution: \n${solution.mkString(",\n")}\n") - Logger.debug(s"Sets: \n${unifications.values.map { s => s"{ ${s.mkString(",")} }"}.mkString(", ")}") + SteensLogger.debug(s"Solution: \n${solution.mkString(",\n")}\n") + SteensLogger.debug(s"Sets: \n${unifications.values.map { s => s"{ ${s.mkString(",")} }"}.mkString(", ")}") val vars = solution.keys.collect { case id: IdentifierVariable => id } val emptyMap = Map[RegisterWrapperEqualSets, Set[RegisterWrapperEqualSets | MemoryRegion]]() @@ -164,7 +164,7 @@ class InterprocSteensgaardAnalysis( }.toSet a + (v.id -> pt) } - Logger.debug(s"\nPoints-to:\n${pointsto.map((k, v) => s"$k -> { ${v.mkString(",")} }").mkString("\n")}\n") + SteensLogger.debug(s"\nPoints-to:\n${pointsto.map((k, v) => s"$k -> { ${v.mkString(",")} }").mkString("\n")}\n") pointsto } } diff --git a/src/main/scala/analysis/IrreducibleLoops.scala b/src/main/scala/analysis/IrreducibleLoops.scala index f3d3bb44e..22c6a94ed 100644 --- a/src/main/scala/analysis/IrreducibleLoops.scala +++ b/src/main/scala/analysis/IrreducibleLoops.scala @@ -2,7 +2,7 @@ package analysis import ir.{CFGPosition, Command, IntraProcIRCursor, Program, Procedure, Block, GoTo, IRWalk} import util.intrusive_list.IntrusiveList -import util.Logger +import util.StaticAnalysisLogger import scala.collection.mutable @@ -325,8 +325,8 @@ class LoopTransform(loops: Set[Loop]) { case _ => } case _ => - Logger.error("Unexpected loop originating node - 1") - Logger.error(origNode) + StaticAnalysisLogger.error("Unexpected loop originating node - 1") + StaticAnalysisLogger.error(origNode) } } @@ -353,11 +353,11 @@ class LoopTransform(loops: Set[Loop]) { case _ => } case _ => - Logger.error("Unexpected loop originating node - 1") - Logger.error(origNode) + StaticAnalysisLogger.error("Unexpected loop originating node - 1") + StaticAnalysisLogger.error(origNode) } } newLoop } -} \ No newline at end of file +} diff --git a/src/main/scala/analysis/Lattice.scala b/src/main/scala/analysis/Lattice.scala index cb499f8c3..1f5d12b73 100644 --- a/src/main/scala/analysis/Lattice.scala +++ b/src/main/scala/analysis/Lattice.scala @@ -2,7 +2,7 @@ package analysis import ir._ import ir.eval.BitVectorEval -import util.Logger +import util.StaticAnalysisLogger /** Basic lattice */ @@ -162,7 +162,7 @@ class ConstantPropagationLattice extends FlatLattice[BitVecLiteral] { case (Top, _) => Top } catch { case e: Exception => - Logger.error(s"Failed on op $op with $a and $b") + StaticAnalysisLogger.error(s"Failed on op $op with $a and $b") throw e } diff --git a/src/main/scala/analysis/MemoryModelMap.scala b/src/main/scala/analysis/MemoryModelMap.scala index 0df82014c..ccd98a2d6 100644 --- a/src/main/scala/analysis/MemoryModelMap.scala +++ b/src/main/scala/analysis/MemoryModelMap.scala @@ -2,7 +2,7 @@ package analysis import analysis.* import ir.* -import util.Logger +import util.MRALogger import scala.collection.immutable.TreeMap import scala.collection.mutable @@ -157,7 +157,7 @@ class MemoryModelMap(val globalOffsets: Map[BigInt, BigInt]) { for (dr <- oldRegions) { val obj = findDataObject(dr.start) if (obj.isEmpty) { - Logger.debug(s"Data region $dr not found in the new data map") + MRALogger.debug(s"Data region $dr not found in the new data map") } else { val isRelocated = relocatedDataRegion(dr.start) if (isRelocated.isDefined) { @@ -284,34 +284,34 @@ class MemoryModelMap(val globalOffsets: Map[BigInt, BigInt]) { case _: HeapRegion => " " case _: DataRegion => " " } - Logger.debug(s"$spacing$range -> $region") + MRALogger.debug(s"$spacing$range -> $region") if content.contains(region) then if content.contains(region) then for value <- content(region) do - Logger.debug(s"$spacing $value") + MRALogger.debug(s"$spacing $value") } - Logger.debug("Stack:") + MRALogger.debug("Stack:") for name <- localStacks.keys do popContext() pushContext(name) - Logger.debug(s" Function: $name") - if stackMap.nonEmpty then Logger.debug(s" Local:") + MRALogger.debug(s" Function: $name") + if stackMap.nonEmpty then MRALogger.debug(s" Local:") // must sort by ranges for ((range, region) <- stackMap) { logRegion(range, region) } - if sharedStackMap.nonEmpty then Logger.debug(s" Shared:") + if sharedStackMap.nonEmpty then MRALogger.debug(s" Shared:") for ((parent, treeMap) <- sharedStackMap) { - Logger.debug(s" Parent: ${parent.name}") + MRALogger.debug(s" Parent: ${parent.name}") for ((range, region) <- treeMap) { logRegion(range, region, true) } } - Logger.debug("Stack Union-Find Roots:") + MRALogger.debug("Stack Union-Find Roots:") for name <- localStacks.keys do popContext() pushContext(name) - Logger.debug(s" Function: $name") + MRALogger.debug(s" Function: $name") var parentCount = 0 // get root regions for ((range, region) <- stackMap) { @@ -320,17 +320,17 @@ class MemoryModelMap(val globalOffsets: Map[BigInt, BigInt]) { logRegion(range, root) parentCount += 1 } - if parentCount == 0 then Logger.debug(" No root regions") else Logger.debug(s" Parents: $parentCount/${stackMap.size}") - Logger.debug("Shared Stacks:") + if parentCount == 0 then MRALogger.debug(" No root regions") else MRALogger.debug(s" Parents: $parentCount/${stackMap.size}") + MRALogger.debug("Shared Stacks:") for (name, sharedStacks) <- sharedStacks do - Logger.debug(s" Function: $name") + MRALogger.debug(s" Function: $name") for region <- sharedStacks do - Logger.debug(s" $region") - Logger.debug("Heap:") + MRALogger.debug(s" $region") + MRALogger.debug("Heap:") for ((range, region) <- heapMap) { logRegion(range, region) } - Logger.debug("Data:") + MRALogger.debug("Data:") for ((range, region) <- dataMap) { logRegion(range, region) } @@ -441,4 +441,4 @@ class UnionFind { } } -} \ No newline at end of file +} diff --git a/src/main/scala/analysis/MemoryRegionAnalysis.scala b/src/main/scala/analysis/MemoryRegionAnalysis.scala index 2cec5dbfa..e498ec3a2 100644 --- a/src/main/scala/analysis/MemoryRegionAnalysis.scala +++ b/src/main/scala/analysis/MemoryRegionAnalysis.scala @@ -3,7 +3,7 @@ package analysis import ir.eval.BitVectorEval.bv2SignedInt import analysis.solvers.SimpleWorklistFixpointSolver import ir.* -import util.Logger +import util.MRALogger import scala.collection.mutable import scala.collection.mutable.ListBuffer @@ -59,8 +59,8 @@ trait MemoryRegionAnalysis(val program: Program, } private def stackDetection(stmt: Statement): Unit = { - Logger.debug("Stack detection") - Logger.debug(spList) + MRALogger.debug("Stack detection") + MRALogger.debug(spList) stmt match { case assign: LocalAssign => if (spList.contains(assign.rhs)) { @@ -174,7 +174,7 @@ trait MemoryRegionAnalysis(val program: Program, Set.empty // we cannot evaluate this to a concrete value, we need VSA for this case _ => - Logger.debug(s"type: ${exp.getClass} $exp\n") + MRALogger.debug(s"type: ${exp.getClass} $exp\n") throw new Exception("Unknown type") } } diff --git a/src/main/scala/analysis/RegionInjector.scala b/src/main/scala/analysis/RegionInjector.scala index 0b178f1b2..b9f674fa0 100644 --- a/src/main/scala/analysis/RegionInjector.scala +++ b/src/main/scala/analysis/RegionInjector.scala @@ -2,7 +2,6 @@ package analysis import ir.eval.BitVectorEval.isNegative import ir.* -import util.Logger import scala.collection.mutable import scala.collection.mutable.ArrayBuffer diff --git a/src/main/scala/analysis/SummaryGenerator.scala b/src/main/scala/analysis/SummaryGenerator.scala index 5cb0b5ab3..7acec3e4c 100644 --- a/src/main/scala/analysis/SummaryGenerator.scala +++ b/src/main/scala/analysis/SummaryGenerator.scala @@ -3,7 +3,6 @@ package analysis import analysis.* import ir.* import boogie.* -import util.Logger import boogie.SpecGlobal /** @@ -180,4 +179,4 @@ class SummaryGenerator( } } } -} \ No newline at end of file +} diff --git a/src/main/scala/analysis/TaintAnalysis.scala b/src/main/scala/analysis/TaintAnalysis.scala index d18e27d48..c4872b0c0 100644 --- a/src/main/scala/analysis/TaintAnalysis.scala +++ b/src/main/scala/analysis/TaintAnalysis.scala @@ -3,7 +3,6 @@ package analysis import analysis.solvers.ForwardIDESolver import ir.* import boogie.* -import util.Logger /** * A value which can propogate taint/be tainted. diff --git a/src/main/scala/analysis/VSA.scala b/src/main/scala/analysis/VSA.scala index 4a9f11a14..5b50b9f7a 100644 --- a/src/main/scala/analysis/VSA.scala +++ b/src/main/scala/analysis/VSA.scala @@ -7,7 +7,8 @@ import scala.collection.mutable.{ArrayBuffer, HashMap, ListBuffer} import java.io.{File, PrintWriter} import scala.collection.mutable import scala.collection.immutable -import util.Logger +import util.VSALogger + /** ValueSets are PowerSet of possible values */ trait Value @@ -68,7 +69,7 @@ trait ValueSetAnalysis(program: Program, case Some(v: Variable) => s + (localAssign.lhs -> s(v)) case None => - Logger.debug(s"Too Complex: ${localAssign.rhs}") // do nothing + VSALogger.debug(s"Too Complex: ${localAssign.rhs}") // do nothing s } } @@ -84,7 +85,7 @@ trait ValueSetAnalysis(program: Program, case Some(v: Variable) => s + (load.lhs -> s(v)) case None => - Logger.debug(s"Too Complex: ${load.index}") // do nothing + VSALogger.debug(s"Too Complex: ${load.index}") // do nothing s } } @@ -105,7 +106,7 @@ trait ValueSetAnalysis(program: Program, case Some(v: Variable) => s ++ regions.map(r => r -> s(v)) case None => - Logger.debug(s"Too Complex: $store.value") // do nothing + VSALogger.debug(s"Too Complex: $store.value") // do nothing s } } diff --git a/src/main/scala/analysis/VariableDependencyAnalysis.scala b/src/main/scala/analysis/VariableDependencyAnalysis.scala index 570d65898..9ae4fa498 100644 --- a/src/main/scala/analysis/VariableDependencyAnalysis.scala +++ b/src/main/scala/analysis/VariableDependencyAnalysis.scala @@ -3,7 +3,7 @@ package analysis import analysis.solvers.ForwardIDESolver import ir.* import boogie.* -import util.Logger +import util.StaticAnalysisLogger import boogie.SpecGlobal import scala.collection.mutable @@ -122,7 +122,7 @@ class VariableDependencyAnalysis( var varDepsSummariesTransposed = Map[Procedure, Map[Taintable, Set[Taintable]]]() scc.flatten.filter(_.blocks.nonEmpty).foreach { procedure => { - Logger.debug("Generating variable dependencies for " + procedure) + StaticAnalysisLogger.debug("Generating variable dependencies for " + procedure) val varDepResults = ProcVariableDependencyAnalysis(program, varDepVariables, globals, constProp, varDepsSummariesTransposed, procedure).analyze() val varDepMap = varDepResults.getOrElse(IRWalk.lastInProc(procedure).getOrElse(procedure), Map()) varDepsSummaries += procedure -> varDepMap diff --git a/src/main/scala/ir/eval/Interpreter.scala b/src/main/scala/ir/eval/Interpreter.scala index e221d2f8a..5b9cfb42d 100644 --- a/src/main/scala/ir/eval/Interpreter.scala +++ b/src/main/scala/ir/eval/Interpreter.scala @@ -6,6 +6,7 @@ import util.functional.* import util.functional.State.* import boogie.Scope import scala.collection.WithFilter +import translating.PrettyPrinter.* import scala.annotation.tailrec import scala.collection.mutable @@ -34,10 +35,7 @@ case class MemoryError(message: String = "") extends InterpreterError /* An erro /* Concrete value type of the interpreter. */ sealed trait BasilValue(val irType: Option[IRType]) case class Scalar(value: Literal) extends BasilValue(Some(value.getType)) { - override def toString = value match { - case b: BitVecLiteral => "0x%x:bv%d".format(b.value, b.size) - case c => c.toString - } + override def toString = pp_expr(value) } /* Abstract callable function address */ diff --git a/src/main/scala/ir/transforms/Simp.scala b/src/main/scala/ir/transforms/Simp.scala index 686f66f39..4225ba8bc 100644 --- a/src/main/scala/ir/transforms/Simp.scala +++ b/src/main/scala/ir/transforms/Simp.scala @@ -1,7 +1,7 @@ package ir.transforms import translating.serialiseIL -import util.Logger +import util.SimplifyLogger import ir.eval.AlgebraicSimplifications import ir.eval.AssumeConditionSimplifications import ir.eval.simplifyExprFixpoint @@ -28,7 +28,7 @@ def difftestLiveVars(p: Procedure, compareResult: Map[CFGPosition, Set[Variable] val c = (compareResult(b) == s) passed = passed && c if (!c) { - Logger.error( + SimplifyLogger.error( s"LiveVars unequal ${b.label}: ${compareResult(b)} == $s (differing ${compareResult(b).diff(s)})" ) } @@ -365,7 +365,7 @@ def copypropTransform(p: Procedure) = { // val dom = ConstCopyProp() // val solver = worklistSolver(dom) - // Logger.info(s"${p.name} ExprComplexity ${ExprComplexity()(p)}") + // SimplifyLogger.info(s"${p.name} ExprComplexity ${ExprComplexity()(p)}") // val result = solver.solveProc(p, true).withDefaultValue(dom.bot) val result = CopyProp.DSACopyProp(p) val solve = t.checkPoint("Solve CopyProp") @@ -381,20 +381,20 @@ def copypropTransform(p: Procedure) = { } val xf = t.checkPoint("transform") - // Logger.info(s" ${p.name} after transform expr complexity ${ExprComplexity()(p)}") + // SimplifyLogger.info(s" ${p.name} after transform expr complexity ${ExprComplexity()(p)}") visit_proc(CleanupAssignments(), p) t.checkPoint("redundant assignments") - // Logger.info(s" ${p.name} after dead var cleanup expr complexity ${ExprComplexity()(p)}") + // SimplifyLogger.info(s" ${p.name} after dead var cleanup expr complexity ${ExprComplexity()(p)}") AlgebraicSimplifications(p) AssumeConditionSimplifications(p) AlgebraicSimplifications(p) - // Logger.info(s" ${p.name} after simp expr complexity ${ExprComplexity()(p)}") + // SimplifyLogger.info(s" ${p.name} after simp expr complexity ${ExprComplexity()(p)}") val sipm = t.checkPoint("algebraic simp") - // Logger.info("[!] Simplify :: RemoveSlices") + // SimplifyLogger.info("[!] Simplify :: RemoveSlices") removeSlices(p) ir.eval.cleanupSimplify(p) AlgebraicSimplifications(p) @@ -470,13 +470,13 @@ def doCopyPropTransform(p: Program) = { applyRPO(p) - Logger.info("[!] Simplify :: Expr/Copy-prop Transform") + SimplifyLogger.info("[!] Simplify :: Expr/Copy-prop Transform") val work = p.procedures .filter(_.blocks.size > 0) .map(p => p -> //Future { - Logger + SimplifyLogger .debug(s"CopyProp Transform ${p.name} (${p.blocks.size} blocks, expr complexity ${ExprComplexity()(p)})") copypropTransform(p) } @@ -488,16 +488,16 @@ def doCopyPropTransform(p: Program) = { job } catch { case e => { - Logger.error("Simplify :: CopyProp " + p.name + ": " + e.toString) + SimplifyLogger.error("Simplify :: CopyProp " + p.name + ": " + e.toString) } } }) - Logger.info("[!] Simplify :: Dead variable elimination") + SimplifyLogger.info("[!] Simplify :: Dead variable elimination") // cleanup visit_prog(CleanupAssignments(), p) - Logger.info("[!] Simplify :: Merge empty blocks") + SimplifyLogger.info("[!] Simplify :: Merge empty blocks") removeEmptyBlocks(p) coalesceBlocks(p) @@ -912,7 +912,7 @@ class Simplify( val bl = s"${block.parent.name}::${block.label}" if (!skipped.contains(bl)) { skipped = skipped + bl - Logger.warn(s"Some skipped substitution at $bl due to resulting expr size > ${threshold} threshold") + SimplifyLogger.warn(s"Some skipped substitution at $bl due to resulting expr size > ${threshold} threshold") } } ChangeDoChildrenPost(result, x => x) diff --git a/src/main/scala/translating/IRExpToSMT2.scala b/src/main/scala/translating/IRExpToSMT2.scala index 107b630fe..6ceadb376 100644 --- a/src/main/scala/translating/IRExpToSMT2.scala +++ b/src/main/scala/translating/IRExpToSMT2.scala @@ -53,7 +53,7 @@ trait BasilIR[Repr[+_]] extends BasilIRExp[Repr] { def vblock(b: Block): Repr[Block] = vblock(b.label, b.statements.toList.map(vstmt), vjump(b.jump)) def vproc(p: Procedure): Repr[Procedure] = vproc( p.name, - p.formalInParam.toList.map(vrvar), + p.formalInParam.toList.map(vlvar), p.formalOutParam.toList.map(vlvar), p.entryBlock.map(vblock), (p.blocks.toSet -- p.entryBlock.toSet -- p.returnBlock.toSet).toList.sortBy( x => -x.rpoOrder).map(vblock), diff --git a/src/main/scala/translating/PrettyPrinter.scala b/src/main/scala/translating/PrettyPrinter.scala index 033fefa68..ac2e6a83d 100644 --- a/src/main/scala/translating/PrettyPrinter.scala +++ b/src/main/scala/translating/PrettyPrinter.scala @@ -3,6 +3,19 @@ import ir.* import scala.collection.mutable +object PrettyPrinter { + def pp_expr(e: Expr) = BasilIRPrettyPrinter()(e) + def pp_stmt(s: Statement) = BasilIRPrettyPrinter()(s) + def pp_cmd(c: Command) = c match { + case j: Jump => pp_jump(j) + case j: Statement => pp_stmt(j) + } + def pp_block(s: Block) = BasilIRPrettyPrinter()(s) + def pp_jump(s: Jump) = BasilIRPrettyPrinter()(s) + def pp_prog(s: Program) = BasilIRPrettyPrinter()(s) + def pp_proc(s: Procedure) = BasilIRPrettyPrinter()(s) +} + case class BST[+T](val v: String) { def ++(s: String) = BST(v ++ s) override def toString = v @@ -37,7 +50,7 @@ class BasilIRPrettyPrinter() extends BasilIR[BST] { } override def vblock(label: String, statements: List[BST[Statement]], terminator: BST[Jump]): BST[Block] = { - BST(s"${blockIndent}block ${label} {\n" + BST(s"${blockIndent}block \"${label}\" {\n" ++ statements.map(statementIndent + _ + ";").mkString("\n") ++ "\n" ++ statementIndent + terminator + ";\n" ++ blockIndent + "}") @@ -86,13 +99,12 @@ class BasilIRPrettyPrinter() extends BasilIR[BST] { BST(s"(${outParams.map((l,r) => l).mkString(", ")}) := call $procname (${inparams.map((l,r) => r).mkString(", ")});") } - override def vindirect(target: BST[Variable]): BST[IndirectCall] = BST(s"indirect_call(${target})") override def vassert(body: BST[Expr]): BST[Assert] = BST(s"assert($body)") override def vassume(body: BST[Expr]): BST[Assume] = BST(s"assume($body)") override def vnop(): BST[NOP] = BST("nop") - override def vgoto(t: List[String]): BST[GoTo] = BST(s"goto(${t.mkString(", ")})") + override def vgoto(t: List[String]): BST[GoTo] = BST(s"goto(${t.map('"' + _ + '"').mkString(", ")})") override def vunreachable(): BST[Unreachable] = BST("unreachable") override def vreturn(outs: List[(BST[Variable], BST[Expr])]) = BST(s"return (${outs.map((l, r) => r).mkString(", ")})") @@ -103,17 +115,15 @@ class BasilIRPrettyPrinter() extends BasilIR[BST] { case _ => ??? } - override def vrvar(e: Variable): BST[Variable] = vlvar(e) + override def vrvar(e: Variable): BST[Variable] = BST(e.name) override def vlvar(e: Variable): BST[Variable] = { - if (seenVars.contains(e)) { - BST(e.name) - } else { - seenVars.add(e) - BST(e.name + s": ${vtype(e.getType)}") + e match { + case l: LocalVar => BST("var " + e.name + s": ${vtype(e.getType)}") + case _ => BST(e.name) } } - override def vextract(ed: Int, start: Int, a: BST[Expr]): BST[Expr] = BST(s"${a}[$ed:$start]") + override def vextract(ed: Int, start: Int, a: BST[Expr]): BST[Expr] = BST(s"extract($ed, $start, ${a})") override def vzeroextend(bits: Int, b: BST[Expr]): BST[Expr] = BST(s"zero_extend($bits, $b)") override def vsignextend(bits: Int, b: BST[Expr]): BST[Expr] = BST(s"sign_extend($bits, $b)") override def vrepeat(reps: Int, b: BST[Expr]) = BST(s"repeat($reps, $b)") @@ -130,8 +140,6 @@ class BasilIRPrettyPrinter() extends BasilIR[BST] { override def vintlit(i: BigInt) = BST("0x%x".format(i)) override def vbvlit(i: BitVecLiteral) = BST("0x%x".format(i.value) + s"bv${i.size}") override def vuninterp_function(name: String, args: Seq[BST[Expr]]): BST[Expr] = BST(s"$name(${args.mkString(", ")})") - - } diff --git a/src/main/scala/util/Logging.scala b/src/main/scala/util/Logging.scala index dcdd148bd..b9f95a4a9 100644 --- a/src/main/scala/util/Logging.scala +++ b/src/main/scala/util/Logging.scala @@ -1,19 +1,86 @@ package util import sourcecode.Line, sourcecode.FileName import scala.io.AnsiColor -import java.io.File as JFile +import collection.mutable.HashSet +import java.io.* enum LogLevel(val id: Int): case DEBUG extends LogLevel(0) case INFO extends LogLevel(1) case WARN extends LogLevel(2) case ERROR extends LogLevel(3) + case OFF extends LogLevel(4) + +class GenericLogger( + val name : String, + val defaultLevel: LogLevel = LogLevel.INFO, + var output: PrintStream = System.out, + var ANSIColour: Boolean = true +) { + + val children: HashSet[GenericLogger] = HashSet() -object Logger: - private var level: LogLevel = LogLevel.INFO import LogLevel.* - def write( + private var level: LogLevel = defaultLevel + + private def setColour(value: Boolean, setChildren: Boolean = false): Unit = { + ANSIColour = value + if (setChildren) { + for (c <- children) { + c.setColour(value, setChildren) + } + } + } + + def disableColour(setChildren: Boolean = false) = setColour(false, setChildren) + def enableColour(setChildren: Boolean = false): Unit = setColour(true, setChildren) + + + def deriveLogger(sname: String, stream: PrintStream): GenericLogger = { + val l = GenericLogger(name + "." + sname, level, stream, ANSIColour) + children.add(l) + l + } + + def deriveLogger(name: String, file: File): GenericLogger = { + deriveLogger(name, PrintStream(file)) + } + + def deriveLogger(name: String): GenericLogger = deriveLogger(name, output) + + def setOutput(stream: PrintStream) = output = stream + + def writeToFile(file: File, content: String) = { + if (level.id < LogLevel.OFF.id) { + val l = deriveLogger(file.getName(), file) + l.print(content) + close() + children.remove(l) + } + } + + def print(s: String) = { + if (level.id < LogLevel.OFF.id) { + output.print(s) + } + } + + def println(s: String) = { + if (level.id < LogLevel.OFF.id) { + output.println(s) + } + } + + def close() = { + output.close() + } + + def flush() = { + output.flush() + } + + private def writeLog( logLevel: LogLevel, arg: Any, line: sourcecode.Line, @@ -21,46 +88,83 @@ object Logger: name: sourcecode.Name ): Unit = { - val colour = logLevel match - case DEBUG => AnsiColor.RESET - case INFO => AnsiColor.GREEN - case WARN => AnsiColor.YELLOW - case ERROR => AnsiColor.RED - - val showPosition = (logLevel, level) match - case (_, DEBUG) => true - case (ERROR, _) => true - case (WARN, _) => true - case (INFO, _) => false - case (DEBUG, _) => false + if (level.id <= logLevel.id) { + val colour = if (!ANSIColour) then "" else logLevel match + case DEBUG => AnsiColor.RESET + case INFO => AnsiColor.GREEN + case WARN => AnsiColor.YELLOW + case ERROR => AnsiColor.RED + case OFF => ??? - val position = if showPosition then s" [${name.value}@${file.value}:${line.value}]" else "" + val showPosition = (logLevel, level) match + case (_, DEBUG) => true + case (ERROR, _) => true + case (WARN, _) => true + case (INFO, _) => false + case (DEBUG, _) => false + case (OFF, _) => ??? - val space = " " - val prefix = s"[$colour$logLevel${AnsiColor.RESET}]$space" - val text = arg.toString().replace("\n", "\n " + (" " * (logLevel.toString).length()) + " " + space ) + val position = if showPosition then s" [${name.value}@${file.value}:${line.value}]" else "" - if (level.id <= logLevel.id) { - System.err.println(s"$prefix $text$position") + val resetColour = if !ANSIColour then "" else AnsiColor.RESET + val space = " " + val prefix = s"[$colour$logLevel${resetColour}]$space" + val text = arg.toString().replace("\n", "\n " + (" " * (logLevel.toString).length()) + " " + space) + output.println(s"$prefix $text$position") } } - def warn(arg: Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { - write(LogLevel.WARN, arg, line, file, name) + def warn(arg: => Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { + writeLog(LogLevel.WARN, arg, line, file, name) } - def error(arg: Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { - write(LogLevel.ERROR, arg, line, file, name) + def error(arg: => Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { + writeLog(LogLevel.ERROR, arg, line, file, name) } - def debug(arg: Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { - write(LogLevel.DEBUG, arg, line, file, name) + def debug(arg: => Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { + writeLog(LogLevel.DEBUG, arg, line, file, name) } - def info(arg: Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { - write(LogLevel.INFO, arg, line, file, name) + def info(arg: => Any)(implicit line: sourcecode.Line, file: sourcecode.FileName, name: sourcecode.Name): Unit = { + writeLog(LogLevel.INFO, arg, line, file, name) } - def setLevel(logLevel: LogLevel): Unit = { + def setLevel(logLevel: LogLevel, setChildren: Boolean = true): Unit = { level = logLevel + if (setChildren) { + for (c <- children) { + c.setLevel(logLevel, setChildren) + } + } } + + def findLoggerByName(s: String) : Option[GenericLogger] = allLoggers.find(_.name == s) + + def allLoggers: Iterable[GenericLogger] = { + (for { + c <- children + cc <- c.allLoggers + } yield (cc)) + ++ Seq(this) + } + +} + +// doesn't work with `mill run` +def isAConsole = System.console() != null + +val Logger = GenericLogger("log", LogLevel.INFO, System.out, isAConsole) +val StaticAnalysisLogger = Logger.deriveLogger("analysis", System.out) +val SimplifyLogger = Logger.deriveLogger("simplify", System.out) +val DebugDumpIRLogger = { + val l = Logger.deriveLogger("debugdumpir") + l.setLevel(LogLevel.OFF) + l +} +val VSALogger = StaticAnalysisLogger.deriveLogger("vsa") +val MRALogger = StaticAnalysisLogger.deriveLogger("mra") +val SteensLogger = StaticAnalysisLogger.deriveLogger("steensgaard") + + + diff --git a/src/main/scala/util/RunUtils.scala b/src/main/scala/util/RunUtils.scala index 18b8c4648..92740803b 100644 --- a/src/main/scala/util/RunUtils.scala +++ b/src/main/scala/util/RunUtils.scala @@ -7,6 +7,7 @@ import com.grammatech.gtirb.proto.Section.Section import spray.json.* import ir.eval import gtirb.* +import translating.PrettyPrinter.* import scala.collection.mutable.ListBuffer import scala.collection.mutable.ArrayBuffer @@ -24,7 +25,7 @@ import org.antlr.v4.runtime.tree.ParseTreeWalker import org.antlr.v4.runtime.BailErrorStrategy import org.antlr.v4.runtime.{CharStreams, CommonTokenStream, Token} import translating.* -import util.Logger +import util.{Logger, DebugDumpIRLogger, SimplifyLogger} import java.util.Base64 import spray.json.DefaultJsonProtocol.* @@ -192,7 +193,7 @@ object IRTransform { /** Initial cleanup before analysis. */ def doCleanup(ctx: IRContext): IRContext = { - Logger.debug("[!] Removing external function calls") + Logger.info("[!] Removing external function calls") // Remove external function references (e.g. @printf) val externalNames = ctx.externalFunctions.map(e => e.name) val externalNamesLibRemoved = mutable.Set[String]() @@ -228,7 +229,7 @@ object IRTransform { Logger.info("[!] Stripping unreachable") val before = ctx.program.procedures.size transforms.stripUnreachableFunctions(ctx.program, config.loading.procedureTrimDepth) - Logger.debug( + Logger.info( s"[!] Removed ${before - ctx.program.procedures.size} functions (${ctx.program.procedures.size} remaining)" ) val dupProcNames = ctx.program.procedures.groupBy(_.name).filter((_, p) => p.size > 1).toList.flatMap(_(1)) @@ -310,30 +311,30 @@ object StaticAnalysis { val globalAddresses = globals.map(s => s.address -> s.name).toMap val globalSizes = globals.map(s => s.name -> s.size).toMap val externalAddresses = externalFunctions.map(e => e.offset -> e.name).toMap - Logger.debug("Globals:") - Logger.debug(globalAddresses) - Logger.debug("Global Offsets: ") - Logger.debug(globalOffsets) - Logger.debug("Global Sizes: ") - Logger.debug(globalSizes) - Logger.debug("External: ") - Logger.debug(externalAddresses) - Logger.debug("Subroutine Addresses:") - Logger.debug(subroutines) - - Logger.info("reducible loops") + StaticAnalysisLogger.debug("Globals:") + StaticAnalysisLogger.debug(globalAddresses) + StaticAnalysisLogger.debug("Global Offsets: ") + StaticAnalysisLogger.debug(globalOffsets) + StaticAnalysisLogger.debug("Global Sizes: ") + StaticAnalysisLogger.debug(globalSizes) + StaticAnalysisLogger.debug("External: ") + StaticAnalysisLogger.debug(externalAddresses) + StaticAnalysisLogger.debug("Subroutine Addresses:") + StaticAnalysisLogger.debug(subroutines) + + StaticAnalysisLogger.info("reducible loops") // reducible loops val detector = LoopDetector(IRProgram) val foundLoops = detector.identify_loops() - foundLoops.foreach(l => Logger.info(s"Loop found: ${l.name}")) + foundLoops.foreach(l => StaticAnalysisLogger.info(s"Loop found: ${l.name}")) val transformer = LoopTransform(foundLoops) val newLoops = transformer.llvm_transform() - newLoops.foreach(l => Logger.info(s"Loop found: ${l.name}")) + newLoops.foreach(l => StaticAnalysisLogger.info(s"Loop found: ${l.name}")) config.analysisDotPath.foreach { s => - writeToFile(dotBlockGraph(IRProgram, IRProgram.map(b => b -> b.toString).toMap), s"${s}_graph-after-reduce-$iteration.dot") - writeToFile(dotBlockGraph(IRProgram, IRProgram.filter(_.isInstanceOf[Block]).map(b => b -> b.toString).toMap), s"${s}_blockgraph-after-reduce-$iteration.dot") + DebugDumpIRLogger.writeToFile(File(s"${s}_graph-after-reduce-$iteration.dot"), dotBlockGraph(IRProgram, IRProgram.map(b => b -> b.toString).toMap)) + DebugDumpIRLogger.writeToFile(File(s"${s}_blockgraph-after-reduce-$iteration.dot"), dotBlockGraph(IRProgram, IRProgram.filter(_.isInstanceOf[Block]).map(b => b -> b.toString).toMap)) } val mergedSubroutines = subroutines ++ externalAddresses @@ -341,24 +342,24 @@ object StaticAnalysis { val domain = computeDomain(IntraProcIRCursor, IRProgram.procedures) val interDomain = computeDomain(InterProcIRCursor, IRProgram.procedures) - Logger.info("[!] Running ANR") + StaticAnalysisLogger.info("[!] Running ANR") val ANRSolver = ANRAnalysisSolver(IRProgram) val ANRResult = ANRSolver.analyze() - Logger.info("[!] Running RNA") + StaticAnalysisLogger.info("[!] Running RNA") val RNASolver = RNAAnalysisSolver(IRProgram) val RNAResult = RNASolver.analyze() - Logger.info("[!] Running Inter-procedural Constant Propagation") + StaticAnalysisLogger.info("[!] Running Inter-procedural Constant Propagation") val interProcConstProp = InterProcConstantPropagation(IRProgram) val interProcConstPropResult: Map[CFGPosition, Map[Variable, FlatElement[BitVecLiteral]]] = interProcConstProp.analyze() config.analysisResultsPath.foreach { s => - writeToFile(printAnalysisResults(IRProgram, interProcConstPropResult), s"${s}OGconstprop$iteration.txt") + DebugDumpIRLogger.writeToFile(File(s"${s}OGconstprop$iteration.txt"), printAnalysisResults(IRProgram, interProcConstPropResult)) } - Logger.info("[!] Variable dependency summaries") + StaticAnalysisLogger.info("[!] Variable dependency summaries") val scc = stronglyConnectedComponents(CallGraph, List(IRProgram.mainProcedure)) val specGlobalAddresses = ctx.specification.globals.map(s => s.address -> s.name).toMap val varDepsSummaries = VariableDependencyAnalysis(IRProgram, ctx.specification.globals, specGlobalAddresses, interProcConstPropResult, scc).analyze() @@ -367,21 +368,21 @@ object StaticAnalysis { val intraProcConstPropResult: Map[CFGPosition, Map[Variable, FlatElement[BitVecLiteral]]] = intraProcConstProp.analyze() config.analysisResultsPath.foreach { s => - writeToFile(printAnalysisResults(IRProgram, intraProcConstPropResult), s"${s}_new_ir_constprop$iteration.txt") + DebugDumpIRLogger.writeToFile(File(s"${s}_new_ir_constprop$iteration.txt"), printAnalysisResults(IRProgram, intraProcConstPropResult)) } config.analysisDotPath.foreach { f => val dumpdomain = computeDomain[CFGPosition, CFGPosition](InterProcIRCursor, IRProgram.procedures) - writeToFile(toDot(dumpdomain.toSet, InterProcIRCursor, Map.empty), s"${f}_new_ir_intercfg$iteration.dot") + DebugDumpIRLogger.writeToFile(File(s"${f}_new_ir_intercfg$iteration.dot"), toDot(dumpdomain.toSet, InterProcIRCursor, Map.empty)) } val reachingDefinitionsAnalysisSolver = InterprocReachingDefinitionsAnalysisSolver(IRProgram) val reachingDefinitionsAnalysisResults = reachingDefinitionsAnalysisSolver.analyze() config.analysisDotPath.foreach { s => - writeToFile( - toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> reachingDefinitionsAnalysisResults(b).toString).toMap, true), - s"${s}_reachingDefinitions$iteration.dot" + DebugDumpIRLogger.writeToFile( + File(s"${s}_reachingDefinitions$iteration.dot"), + toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> reachingDefinitionsAnalysisResults(b).toString).toMap, true) ) } @@ -394,58 +395,58 @@ object StaticAnalysis { Map[CFGPosition, LiftedElement[Map[Variable | MemoryRegion, Set[Value]]]]() } - Logger.info("[!] Running GRA") + StaticAnalysisLogger.info("[!] Running GRA") val graSolver = GlobalRegionAnalysisSolver(IRProgram, domain.toSet, interProcConstPropResult, reachingDefinitionsAnalysisResults, mmm, previousVSAResults) val graResult = graSolver.analyze() - Logger.info("[!] Running MRA") + StaticAnalysisLogger.info("[!] Running MRA") val mraSolver = MemoryRegionAnalysisSolver(IRProgram, domain.toSet, globalAddresses, globalOffsets, mergedSubroutines, interProcConstPropResult, ANRResult, RNAResult, reachingDefinitionsAnalysisResults, graResult, mmm) val mraResult = mraSolver.analyze() config.analysisDotPath.foreach { s => - writeToFile(dotCallGraph(IRProgram), s"${s}_callgraph$iteration.dot") - writeToFile( - dotBlockGraph(IRProgram, IRProgram.filter(_.isInstanceOf[Block]).map(b => b -> b.toString).toMap), - s"${s}_blockgraph$iteration.dot" + DebugDumpIRLogger.writeToFile(File(s"${s}_callgraph$iteration.dot"), dotCallGraph(IRProgram)) + DebugDumpIRLogger.writeToFile( + File(s"${s}_blockgraph$iteration.dot"), + dotBlockGraph(IRProgram, IRProgram.filter(_.isInstanceOf[Block]).map(b => b -> b.toString).toMap) ) - writeToFile( - toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> intraProcConstPropResult(b).toString).toMap), - s"${s}_new_ir_constprop$iteration.dot" + DebugDumpIRLogger.writeToFile( + File(s"${s}_new_ir_constprop$iteration.dot"), + toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> intraProcConstPropResult(b).toString).toMap) ) - writeToFile( - toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> mraResult(b).toString).toMap), - s"${s}_MRA$iteration.dot" + DebugDumpIRLogger.writeToFile( + File(s"${s}_MRA$iteration.dot"), + toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> mraResult(b).toString).toMap) ) - writeToFile( - toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> graResult(b).toString).toMap), - s"${s}_GRA$iteration.dot" + DebugDumpIRLogger.writeToFile( + File(s"${s}_GRA$iteration.dot"), + toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> graResult(b).toString).toMap) ) } - Logger.debug("[!] Running MMM") + StaticAnalysisLogger.info("[!] Running MMM") mmm.convertMemoryRegions(mraSolver.procedureToStackRegions, mraSolver.procedureToHeapRegions, mraResult, mraSolver.procedureToSharedRegions, graSolver.getDataMap, graResult) mmm.logRegions() - Logger.debug("[!] Running Steensgaard") + StaticAnalysisLogger.info("[!] Running Steensgaard") val steensgaardSolver = InterprocSteensgaardAnalysis(interDomain.toSet, mmm, reachingDefinitionsAnalysisResults, previousVSAResults) steensgaardSolver.analyze() val steensgaardResults = steensgaardSolver.pointsTo() - Logger.debug("[!] Running VSA") + StaticAnalysisLogger.info("[!] Running VSA") val vsaSolver = ValueSetAnalysisSolver(IRProgram, mmm, interProcConstPropResult) val vsaResult: Map[CFGPosition, LiftedElement[Map[Variable | MemoryRegion, Set[Value]]]] = vsaSolver.analyze() config.analysisDotPath.foreach { s => - writeToFile( - toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> vsaResult(b).toString).toMap), - s"${s}_VSA$iteration.dot" + DebugDumpIRLogger.writeToFile( + File(s"${s}_VSA$iteration.dot"), + toDot(IRProgram, IRProgram.filter(_.isInstanceOf[Command]).map(b => b -> vsaResult(b).toString).toMap) ) } - Logger.debug("[!] Injecting regions") + StaticAnalysisLogger.info("[!] Injecting regions") val regionInjector = if (config.memoryRegions) { val injector = RegionInjector(IRProgram, mmm) injector.nodeVisitor() @@ -541,7 +542,6 @@ object RunUtils { // writeToFile(dotBlockGraph(ctx.program, ctx.program.filter(_.isInstanceOf[Block]).map(b => b -> b.toString).toMap), s"blockgraph-before-simp.dot") Logger.info("[!] Running Simplify") val timer = PerformanceTimer("Simplify") - val write = true transforms.applyRPO(ctx.program) @@ -549,19 +549,20 @@ object RunUtils { transforms.coalesceBlocks(ctx.program) transforms.removeEmptyBlocks(ctx.program) - if write then writeToFile(dotBlockGraph(ctx.program.mainProcedure), s"blockgraph-before-dsa.dot") + DebugDumpIRLogger.writeToFile(File("blockgraph-before-dsa.dot"), dotBlockGraph(ctx.program.mainProcedure)) Logger.info(s"RPO ${timer.checkPoint("RPO")} ms ") Logger.info("[!] Simplify :: DynamicSingleAssignment") - if write then writeToFile(serialiseIL(ctx.program), s"il-before-dsa.il") + DebugDumpIRLogger.writeToFile(File("il-before-dsa.il"), serialiseIL(ctx.program)) // transforms.DynamicSingleAssignment.applyTransform(ctx.program, liveVars) transforms.OnePassDSA().applyTransform(ctx.program) Logger.info(s"DSA ${timer.checkPoint("DSA ")} ms ") - if write then writeToFile(dotBlockGraph(ctx.program, (ctx.program.collect { - case b : Block => b -> translating.BasilIRPrettyPrinter()(b) - }).toMap), s"blockgraph-after-dsa.dot") + DebugDumpIRLogger.writeToFile(File(s"blockgraph-after-dsa.dot"), + dotBlockGraph(ctx.program, (ctx.program.collect { + case b : Block => b -> pp_block(b) + }).toMap)) if (ir.eval.SimplifyValidation.validate) { // Logger.info("Live vars difftest") @@ -577,18 +578,18 @@ object RunUtils { assert(invariant.cfgCorrect(ctx.program)) assert(invariant.blocksUniqueToEachProcedure(ctx.program)) - if write then writeToFile(serialiseIL(ctx.program), s"il-before-copyprop.il") + DebugDumpIRLogger.writeToFile(File("il-before-copyprop.il"), pp_prog(ctx.program)) // brute force run the analysis twice because it cleans up more stuff //assert(ctx.program.procedures.forall(transforms.rdDSAProperty)) transforms.doCopyPropTransform(ctx.program) - if write then writeToFile(dotBlockGraph(ctx.program.mainProcedure), s"blockgraph-after-simp.dot") + DebugDumpIRLogger.writeToFile(File("blockgraph-after-simp.dot"), dotBlockGraph(ctx.program.mainProcedure)) // assert(ctx.program.procedures.forall(transforms.rdDSAProperty)) assert(invariant.blockUniqueLabels(ctx.program)) Logger.info(s"CopyProp ${timer.checkPoint("CopyProp")} ms ") - if write then writeToFile(serialiseIL(ctx.program), s"il-after-copyprop.il") + DebugDumpIRLogger.writeToFile(File("il-after-copyprop.il"), pp_prog(ctx.program)) // val x = ctx.program.procedures.forall(transforms.rdDSAProperty) @@ -602,12 +603,11 @@ object RunUtils { // run this after cond recovery because sign bit calculations often need high bits // which go away in high level conss - if write then writeToFile(serialiseIL(ctx.program), s"il-after-slices.il") + DebugDumpIRLogger.writeToFile(File("il-after-slices.il"), pp_prog(ctx.program)) // re-apply dsa // transforms.OnePassDSA().applyTransform(ctx.program) - if write then writeToFile(translating.BasilIRPrettyPrinter()(ctx.program), "prettyprinted.il") if (ir.eval.SimplifyValidation.validate) { Logger.info("[!] Simplify :: Writing simplification validation") @@ -620,7 +620,7 @@ object RunUtils { } def loadAndTranslate(conf: BASILConfig): BASILResult = { - Logger.debug("[!] Loading Program") + Logger.info("[!] Loading Program") var q = conf var ctx = IRLoading.load(q.loading) @@ -657,11 +657,11 @@ object RunUtils { assert(invariant.blocksUniqueToEachProcedure(ctx.program)) assert(invariant.correctCalls(ctx.program)) - q.loading.dumpIL.foreach(s => writeToFile(serialiseIL(ctx.program), s"$s-before-analysis.il")) + q.loading.dumpIL.foreach(s => DebugDumpIRLogger.writeToFile(File(s"$s-before-analysis.il"), pp_prog(ctx.program))) val analysis = q.staticAnalysis.map { conf => staticAnalysis(conf, ctx) } - q.loading.dumpIL.foreach(s => writeToFile(serialiseIL(ctx.program), s"$s-after-analysis.il")) + q.loading.dumpIL.foreach(s => DebugDumpIRLogger.writeToFile(File(s"$s-after-analysis.il"), pp_prog(ctx.program))) if (q.runInterpret) { val fs = eval.interpretTrace(ctx) @@ -704,10 +704,10 @@ object RunUtils { var modified: Boolean = true val analysisResult = mutable.ArrayBuffer[StaticAnalysisContext]() while (modified || (analysisResult.size < 2 && config.memoryRegions)) { - Logger.debug("[!] Running Static Analysis") + StaticAnalysisLogger.info("[!] Running Static Analysis") val result = StaticAnalysis.analyse(ctx, config, iteration, analysisResult.lastOption) analysisResult.append(result) - Logger.debug("[!] Replacing Indirect Calls") + StaticAnalysisLogger.info("[!] Replacing Indirect Calls") /* modified = transforms.SteensgaardIndirectCallResolution( @@ -723,14 +723,14 @@ object RunUtils { result.mmmResults ).resolveIndirectCalls() - Logger.debug("[!] Generating Procedure Summaries") + StaticAnalysisLogger.info("[!] Generating Procedure Summaries") if (config.summariseProcedures) { IRTransform.generateProcedureSummaries(ctx, ctx.program, result.intraProcConstProp, result.varDepsSummaries) } if (modified) { iteration += 1 - Logger.debug(s"[!] Analysing again (iter $iteration)") + StaticAnalysisLogger.info(s"[!] Analysing again (iter $iteration)") } } @@ -740,33 +740,33 @@ object RunUtils { transforms.splitThreads(ctx.program, analysisResult.last.steensgaardResults, analysisResult.last.reachingDefs) } - Logger.debug("[!] Running Writes To") + StaticAnalysisLogger.info("[!] Running Writes To") val writesTo = WriteToAnalysis(ctx.program).analyze() val reachingDefs = ReachingDefsAnalysis(ctx.program, writesTo).analyze() config.analysisDotPath.foreach { s => - writeToFile(toDot(ctx.program), s"${s}_ct.dot") + DebugDumpIRLogger.writeToFile(File(s"${s}_ct.dot"), toDot(ctx.program)) } - Logger.debug("[!] Running Symbolic Access Analysis") + StaticAnalysisLogger.info("[!] Running Symbolic Access Analysis") val symResults: Map[CFGPosition, Map[SymbolicAddress, TwoElement]] = SymbolicAddressAnalysis(ctx.program, analysisResult.last.interProcConstProp).analyze() config.analysisDotPath.foreach { s => val labels = symResults.map { (k, v) => k -> v.toString } - writeToFile(toDot(ctx.program, labels), s"${s}_saa.dot") + DebugDumpIRLogger.writeToFile(File(s"${s}_saa.dot"), toDot(ctx.program, labels)) } - Logger.debug("[!] Running DSA Analysis") + StaticAnalysisLogger.info("[!] Running DSA Analysis") val symbolTableEntries: Set[SymbolTableEntry] = ctx.globals ++ ctx.funcEntries val dsa = DataStructureAnalysis(ctx.program, symResults, analysisResult.last.interProcConstProp, symbolTableEntries, ctx.globalOffsets, ctx.externalFunctions, reachingDefs, writesTo, analysisResult.last.paramResults) dsa.analyze() config.analysisDotPath.foreach { s => dsa.topDown(ctx.program.mainProcedure).toDot - writeToFile(dsa.topDown(ctx.program.mainProcedure).toDot, s"${s}_main_dsg.dot") + DebugDumpIRLogger.writeToFile(File(s"${s}_main_dsg.dot"), dsa.topDown(ctx.program.mainProcedure).toDot) } assert(invariant.singleCallBlockEnd(ctx.program)) - Logger.debug(s"[!] Finished indirect call resolution after $iteration iterations") + StaticAnalysisLogger.info(s"[!] Finished indirect call resolution after $iteration iterations") analysisResult.last.copy( symbolicAddresses = symResults, localDSA = dsa.local.toMap, @@ -777,7 +777,7 @@ object RunUtils { } def writeToFile(content: String, fileName: String): Unit = { - Logger.debug(s"Writing $fileName (${content.size} bytes)") + Logger.info(s"Writing $fileName (${content.size} bytes)") val outFile = File(fileName) val pw = PrintWriter(outFile, "UTF-8") pw.write(content) diff --git a/src/test/scala/DifferentialAnalysisTest.scala b/src/test/scala/DifferentialAnalysisTest.scala index 9ca9b382b..c9fc0ef95 100644 --- a/src/test/scala/DifferentialAnalysisTest.scala +++ b/src/test/scala/DifferentialAnalysisTest.scala @@ -19,7 +19,7 @@ import util.RunUtils.loadAndTranslate import scala.collection.mutable -class DifferentialAnalysisTest extends AnyFunSuite { +class DifferentialTest extends AnyFunSuite { Logger.setLevel(LogLevel.WARN) @@ -92,7 +92,7 @@ class DifferentialAnalysisTest extends AnyFunSuite { } -class DifferentialTestAnalysis extends DifferentialTest { +class DifferentialAnalysisTest extends DifferentialTest { def runSystemTests(): Unit = {