Improve and uniform logging

src/core/log.cpp

@@ -10,10 +10,10 @@ Logger& Logger::operator=(Logger&&) = default;
 Logger::~Logger() = default;
 
 Logger::Logger() {
-  bool truncate = true;
-  if (char* _ = getenv("OMVLL_DONT_TRUNCATE")) {
+  bool truncate = false;
+  if (getenv("OMVLL_TRUNCATE_LOG"))
     truncate = true;
-  }
+
   sink_ = spdlog::basic_logger_mt("omvll", "omvll.log", truncate);
   //sink_ = spdlog::stdout_color_mt("omvll");
   sink_->set_pattern("%v");

src/core/omvll_config.cpp

@@ -19,6 +19,7 @@ void init_default_config() {
     Cleaning::name().str(),
   };
 
+  config.cleaning = true;
   config.inline_jni_wrappers = true;
   config.shuffle_functions   = true;
 }

src/core/plugin.cpp

@@ -16,14 +16,14 @@
 
 using namespace llvm;
 
-#define REGISTER_PASS(X)     \
-  do {                       \
-    if (pass == X::name()) { \
-      SINFO("[+] {}", pass); \
-      MPM.addPass(X());      \
-      continue;              \
-    }                        \
-  } while(0)
+#define REGISTER_PASS(X)                                                       \
+  do {                                                                         \
+    if (pass == X::name()) {                                                   \
+      SDEBUG("Registering {}", pass);                                          \
+      MPM.addPass(X());                                                        \
+      continue;                                                                \
+    }                                                                          \
+  } while (0)
 
 template <>
 struct yaml::MappingTraits<omvll::yaml_config_t> {

src/include/omvll/omvll_config.hpp

@@ -6,6 +6,7 @@
 namespace omvll {
 struct config_t {
   std::vector<std::string> passes;
+  bool cleaning;
   bool shuffle_functions;
   bool inline_jni_wrappers;
 };

src/passes/anti-hook/AntiHook.cpp

@@ -43,16 +43,13 @@ bool AntiHook::runOnFunction(llvm::Function &F) {
     return false;
   }
 
-  PyConfig& config = PyConfig::instance();
-  if (!config.getUserConfig()->anti_hooking(F.getParent(), &F)) {
-    return false;
-  }
-
   if (F.hasPrologueData()) {
     fatalError("Can't inject a hooking prologue in the function '" + demangle(F.getName().str()) + "' "
                "since there is one.");
   }
 
+  SDEBUG("[{}] Injecting Anti-Frida prologue in {}", name(), F.getName());
+
   std::uniform_int_distribution<size_t> Dist(0, ANTI_FRIDA_PROLOGUES.size() - 1);
   size_t idx = Dist(*RNG_);
   const PrologueInfoTy& P = ANTI_FRIDA_PROLOGUES[idx];
@@ -72,16 +69,23 @@ bool AntiHook::runOnFunction(llvm::Function &F) {
 
 PreservedAnalyses AntiHook::run(Module &M,
                                 ModuleAnalysisManager &FAM) {
+  PyConfig &config = PyConfig::instance();
+  SINFO("[{}] Executing on module {}", name(), M.getName());
   bool Changed = false;
   jitter_ = std::make_unique<Jitter>(M.getTargetTriple());
 
   RNG_ = M.createRNG(name());
 
   for (Function& F : M) {
+    if (!config.getUserConfig()->anti_hooking(F.getParent(), &F))
+      continue;
+
     Changed |= runOnFunction(F);
   }
 
-  SINFO("[{}] Done!", name());
+  if (Changed)
+    SINFO("[{}] Changes applied on module {}", name(), M.getName());
+
   return Changed ? PreservedAnalyses::none() :
                    PreservedAnalyses::all();
 

src/passes/arithmetic/Arithmetic.cpp

@@ -218,6 +218,9 @@ bool Arithmetic::runOnBasicBlock(BasicBlock &BB) {
             continue;
           }
 
+          SINFO("[{}][{}] Replacing {} with {}", name(), F->getName(),
+                I.getName(), Result->getName());
+
           BasicBlock *InstParent = I.getParent();
           BasicBlock::iterator InsertPos = I.getIterator();
 
@@ -240,14 +243,13 @@ bool Arithmetic::runOnBasicBlock(BasicBlock &BB) {
   return Changed;
 }
 
-PreservedAnalyses Arithmetic::run(Module &M,
-                                  ModuleAnalysisManager &FAM) {
+PreservedAnalyses Arithmetic::run(Module &M, ModuleAnalysisManager &FAM) {
+  PyConfig &config = PyConfig::instance();
+  SINFO("[{}] Executing on module {}", name(), M.getName());
+  bool Changed = false;
   RNG_ = M.createRNG(name());
-  SDEBUG("Running {} on {}", name(), M.getName().str());
   IRChangesMonitor ModuleChanges(M, name());
 
-  PyConfig& config = PyConfig::instance();
-
   auto& Fs = M.getFunctionList();
 
   // "Backup" all the functions since the pass adds new functions and thus,
@@ -262,15 +264,17 @@ PreservedAnalyses Arithmetic::run(Module &M,
     if (!opt)
       continue;
 
+    SINFO("[{}] Visiting function {}", name(), F->getName());
     opts_.insert({F, std::move(opt)});
 
-    for (BasicBlock& BB : *F) {
-      bool Changed = runOnBasicBlock(BB);
-      ModuleChanges.notify(Changed);
-    }
+    for (BasicBlock &BB : *F)
+      Changed |= runOnBasicBlock(BB);
   }
 
-  SINFO("[{}] Done!", name());
+  SINFO("[{}] Changes{}applied on module {}", name(), Changed ? " " : " not ",
+        M.getName());
+
+  ModuleChanges.notify(Changed);
   return ModuleChanges.report();
 }
 }

src/passes/break-cfg/BreakControlFlow.cpp

@@ -48,13 +48,7 @@ bool BreakControlFlow::runOnFunction(Function &F) {
     return false;
   }
 
-  PyConfig& config = PyConfig::instance();
-  if (!config.getUserConfig()->break_control_flow(F.getParent(), &F)) {
-    return false;
-  }
-
-
-  SDEBUG("{}", F.getName().str());
+  SINFO("[{}] Visiting function {}", name(), F.getName());
 
   ValueToValueMapTy VMap;
   ClonedCodeInfo info;
@@ -119,6 +113,8 @@ bool BreakControlFlow::runOnFunction(Function &F) {
                "'" + demangle(F.getName().str()) + "'");
   }
 
+  SDEBUG("[{}][{}] Injecting breaking stub", name(), F.getName());
+
   FCopied->setPrologueData(Prologue);
   FCopied->setLinkage(GlobalValue::InternalLinkage);
 
@@ -183,9 +179,10 @@ bool BreakControlFlow::runOnFunction(Function &F) {
 
 PreservedAnalyses BreakControlFlow::run(Module &M,
                                         ModuleAnalysisManager &FAM) {
+  PyConfig &config = PyConfig::instance();
+  SINFO("[{}] Executing on module {}", name(), M.getName());
   RNG_ = M.createRNG(name());
   Jitter_ = std::make_unique<Jitter>(M.getTargetTriple());
-  SINFO("[{}] Run on: {}", name(), M.getName().str());
   bool Changed = false;
   std::vector<Function*> Fs;
   for (Function& F : M) {
@@ -194,11 +191,13 @@ PreservedAnalyses BreakControlFlow::run(Module &M,
     Fs.push_back(&F);
   }
 
-  for (Function* F : Fs) {
-    Changed |= runOnFunction(*F);
-  }
+  for (Function *F : Fs)
+    if (config.getUserConfig()->break_control_flow(&M, F))
+      Changed |= runOnFunction(*F);
+
+  SINFO("[{}] Changes{}applied on module {}", name(), Changed ? " " : " not ",
+        M.getName());
 
-  SINFO("[{}] Done!", name());
   return Changed ? PreservedAnalyses::none() :
                    PreservedAnalyses::all();
 

src/passes/cleaning/Cleaning.cpp

@@ -10,12 +10,16 @@ using namespace llvm;
 namespace omvll {
 
 PreservedAnalyses Cleaning::run(Module &M, ModuleAnalysisManager &FAM) {
+  if (!config.cleaning)
+    return PreservedAnalyses::all();
+
+  SINFO("[{}] Executing on module {}", name(), M.getName());
   bool Changed = false;
   for (Function& F : M) {
     std::string Name  = demangle(F.getName().str());
     StringRef NRef = Name;
     if (NRef.startswith("_JNIEnv::") && config.inline_jni_wrappers) {
-      SINFO("Inlining {}", Name);
+      SDEBUG("[{}] Inlining {}", Name);
       F.addFnAttr(Attribute::AlwaysInline);
       Changed = true;
     }
@@ -26,7 +30,9 @@ PreservedAnalyses Cleaning::run(Module &M, ModuleAnalysisManager &FAM) {
     Changed = true;
   }
 
-  SINFO("[{}] Done!", name());
+  SINFO("[{}] Changes{}applied on module {}", name(), Changed ? " " : " not ",
+        M.getName());
+
   return Changed ? PreservedAnalyses::none() :
                    PreservedAnalyses::all();
 

src/passes/flattening/ControlFlowFlattening.cpp

@@ -125,11 +125,7 @@ bool ControlFlowFlattening::runOnFunction(Function& F, RandomNumberGenerator& RN
     return false;
   }
 
-  PyConfig& config = PyConfig::instance();
-  if (!config.getUserConfig()->flatten_cfg(F.getParent(), &F)) {
-    return false;
-  }
-  SINFO("Running CFG Flat on {}", demangled);
+  SINFO("[{}] Visiting function {}", ControlFlowFlattening::name(), demangled);
 
   SmallVector<BasicBlock*, 20> flattedBB;
   demotePHINode(F);
@@ -214,46 +210,54 @@ bool ControlFlowFlattening::runOnFunction(Function& F, RandomNumberGenerator& RN
 
   const size_t nbBlock = count_if(flattedBB, [] (BasicBlock* BB) {return !BB->isLandingPad();});
   if (nbBlock <= 1) {
-    SWARN("[{}] Is too small (#{}) to be flattened", ControlFlowFlattening::name().str(), flattedBB.size());
+    SWARN("[{}] Is too small (#{}) to be flattened",
+          ControlFlowFlattening::name(), flattedBB.size());
     return false;
   }
 
   if (auto* br = dyn_cast<BranchInst>(EntryBlock->getTerminator())) {
     if (br->isConditional()) {
       Value* cond = br->getCondition();
       if (auto* instCond = dyn_cast<Instruction>(cond)) {
-        BasicBlock* EntrySplited = EntryBlock->splitBasicBlockBefore(instCond, "EntrySplit");
+        BasicBlock *EntrySplit =
+            EntryBlock->splitBasicBlockBefore(instCond, "EntrySplit");
         flattedBB.insert(flattedBB.begin(), EntryBlock);
 
 #ifdef OMVLL_DEBUG
-        for (Instruction& I : *EntrySplited) {
-          SDEBUG("[EntrySplited] {}", ToString(I));
+        for (Instruction &I : *EntrySplit) {
+          SDEBUG("[{}][EntrySplit] {}", ControlFlowFlattening::name(),
+                 ToString(I));
         }
 
         for (Instruction& I : *EntryBlock) {
-          SDEBUG("[EntryBlock  ] {}", ToString(I));
+          SDEBUG("[{}][EntryBlock] {}", ControlFlowFlattening::name(),
+                 ToString(I));
         }
 #endif // OMVLL_DEBUG
 
-        EntryBlock = EntrySplited;
+        EntryBlock = EntrySplit;
       } else {
-        SWARN("The condition is not an instruction");
+        SWARN("[{}] Found condition is not an instruction",
+              ControlFlowFlattening::name());
       }
     }
   }
   else if (auto* swInst = dyn_cast<SwitchInst>(EntryBlock->getTerminator())) {
-    BasicBlock* EntrySplited = EntryBlock->splitBasicBlockBefore(swInst, "EntrySplit");
+    BasicBlock *EntrySplit =
+        EntryBlock->splitBasicBlockBefore(swInst, "EntrySplit");
     flattedBB.insert(flattedBB.begin(), EntryBlock);
-    EntryBlock = EntrySplited;
+    EntryBlock = EntrySplit;
   }
 
   else if (auto* Invoke = dyn_cast<InvokeInst>(EntryBlock->getTerminator())) {
-    BasicBlock* EntrySplited = EntryBlock->splitBasicBlockBefore(Invoke, "EntrySplit");
+    BasicBlock *EntrySplit =
+        EntryBlock->splitBasicBlockBefore(Invoke, "EntrySplit");
     flattedBB.insert(flattedBB.begin(), EntryBlock);
-    EntryBlock = EntrySplited;
+    EntryBlock = EntrySplit;
   }
 
-  SDEBUG("Erasing {}", ToString(*EntryBlock->getTerminator()));
+  SDEBUG("[{}] Erasing {}", ControlFlowFlattening::name(),
+         ToString(*EntryBlock->getTerminator()));
   EntryBlock->getTerminator()->eraseFromParent();
 
   /* Create a state encoding for the BB to flatten */
@@ -322,7 +326,8 @@ bool ControlFlowFlattening::runOnFunction(Function& F, RandomNumberGenerator& RN
   /* Update the basic block with the switch var */
   for (BasicBlock* toFlat : flattedBB) {
     Instruction* terminator = toFlat->getTerminator();
-    SDEBUG("Flattening {} ({})", ToString(*toFlat), ToString(*terminator));
+    SDEBUG("[{}] Flattening {} ({})", ControlFlowFlattening::name(),
+           ToString(*toFlat), ToString(*terminator));
 
     if (isa<ReturnInst>(terminator) || isa<UnreachableInst>(terminator)) {
       /* Typically a ret instruction
@@ -449,10 +454,15 @@ bool ControlFlowFlattening::runOnFunction(Function& F, RandomNumberGenerator& RN
 
 PreservedAnalyses ControlFlowFlattening::run(Module &M,
                                              ModuleAnalysisManager &MAM) {
+  PyConfig &config = PyConfig::instance();
+  SINFO("[{}] Executing on module {}", name(), M.getName());
   std::unique_ptr<RandomNumberGenerator> RNG = M.createRNG(name());
 
   bool Changed = false;
   for (Function& F : M) {
+    if (!config.getUserConfig()->flatten_cfg(&M, &F))
+      continue;
+
     bool fChanged = runOnFunction(F, *RNG);
 
     if (fChanged) {
@@ -462,7 +472,9 @@ PreservedAnalyses ControlFlowFlattening::run(Module &M,
     Changed |= fChanged;
   }
 
-  SINFO("[{}] Done!", name());
+  SINFO("[{}] Changes{}applied on module {}", name(), Changed ? " " : " not ",
+        M.getName());
+
   return Changed ? PreservedAnalyses::none() :
                    PreservedAnalyses::all();
 

src/passes/objcleaner/ObjCleaner.cpp

@@ -23,19 +23,22 @@ inline bool isObjCVar(const GlobalVariable& G) {
 
 PreservedAnalyses ObjCleaner::run(Module &M,
                                   ModuleAnalysisManager &FAM) {
+  SINFO("[{}] Executing on module {}", name(), M.getName());
   bool Changed = false;
 
   for (GlobalVariable& G : M.getGlobalList()) {
     if (!isObjCVar(G)) {
       continue;
     }
-    SINFO("ObjC -> {} {}", G.getName().str(), ToString(*G.getValueType()));
+
     if (!G.hasInitializer()) {
       continue;
     }
 
-    if (auto* CSTy = dyn_cast<ConstantStruct>(G.getInitializer())) {
-        SINFO("Found {}", CSTy->getType()->getName());
+    SDEBUG("[{}] ObjC -> {} {}", name(), G.getName().str(),
+           ToString(*G.getValueType()));
+
+    if (auto *CSTy = dyn_cast<ConstantStruct>(G.getInitializer())) {
       if (CSTy->getType()->getName().contains("_objc_method")) {
       }
     }
@@ -53,7 +56,8 @@ PreservedAnalyses ObjCleaner::run(Module &M,
     if (data == nullptr || !data->isCString()) {
       continue;
     }
-    SINFO("     ObjC Var: {}: {}", G.getName(), data->getAsCString().str());
+    SDEBUG("[{}] ObjC Var: {}: {}", name(), G.getName(),
+           data->getAsCString().str());
     //std::string value = data->getAsCString().str();
     //SINFO("String: {}", value);
     //Regex R("SampleClass");
@@ -65,8 +69,10 @@ PreservedAnalyses ObjCleaner::run(Module &M,
   //for (Function& F : M) {
   //  Changed |= runOnFunction(F);
   //}
-  SDEBUG("{}", ToString(M));
-  SINFO("[{}] Done!", name());
+
+  SINFO("[{}] Changes{}applied on module {}", name(), Changed ? " " : " not ",
+        M.getName());
+
   return Changed ? PreservedAnalyses::none() :
                    PreservedAnalyses::all();