Merge pull request #148 from trailofbits/trace_logging

Trace logging

bin/deepstate/common.py

@@ -14,8 +14,10 @@
 
 import logging
 logging.basicConfig()
+logging.addLevelName(15, "TRACE")
 
 import argparse
+import functools
 import md5
 import os
 import struct
@@ -32,19 +34,20 @@ class TestInfo(object):
 
 
 LOG_LEVEL_DEBUG = 0
-LOG_LEVEL_INFO = 1
-LOG_LEVEL_WARNING = 2
-LOG_LEVEL_ERROR = 3
-LOG_LEVEL_EXTERNAL = 4
-LOG_LEVEL_FATAL = 5
+LOG_LEVEL_TRACE = 1
+LOG_LEVEL_INFO = 2
+LOG_LEVEL_WARNING = 3
+LOG_LEVEL_ERROR = 4
+LOG_LEVEL_EXTERNAL = 5
+LOG_LEVEL_FATAL = 6
 
 
 LOGGER = logging.getLogger("deepstate")
 LOGGER.setLevel(logging.DEBUG)
 
-
 LOG_LEVEL_TO_LOGGER = {
   LOG_LEVEL_DEBUG: LOGGER.debug,
+  LOG_LEVEL_TRACE: functools.partial(LOGGER.log, 15), 
   LOG_LEVEL_INFO: LOGGER.info,
   LOG_LEVEL_WARNING: LOGGER.warning,
   LOG_LEVEL_ERROR: LOGGER.error,

examples/Fixture.cpp

@@ -20,12 +20,12 @@ class MyTest : public deepstate::Test {
  public:
 
   void SetUp(void) {
-    LOG(INFO)
+    LOG(TRACE)
         << "Setting up!";
   }
 
   void TearDown(void) {
-    LOG(INFO)
+    LOG(TRACE)
         << "Tearing down!";
   }
 

examples/StreamingAndFormatting.cpp

@@ -18,19 +18,20 @@
 
 TEST(Streaming, BasicLevels) {
   LOG(DEBUG) << "This is a debug message";
-  LOG(INFO) << "This is an info message";
+  LOG(TRACE) << "This is a trace message";
+  LOG(INFO) << "This is an info message";  
   LOG(WARNING) << "This is a warning message";
   LOG(ERROR) << "This is a error message";
-  LOG(INFO) << "This is a info message again";
+  LOG(TRACE) << "This is a trace message again";
   ASSERT(true) << "This should not be printed.";
 }
 
 TEST(Streaming, BasicTypes) {
-  LOG(INFO) << 'a';
-  LOG(INFO) << 1;
-  LOG(INFO) << 1.0;
-  LOG(INFO) << "string";
-  LOG(INFO) << nullptr;
+  LOG(TRACE) << 'a';
+  LOG(TRACE) << 1;
+  LOG(TRACE) << 1.0;
+  LOG(TRACE) << "string";
+  LOG(TRACE) << nullptr;
 }
 
 TEST(Formatting, OverridePrintf) {

src/include/deepstate/DeepState.hpp

@@ -521,6 +521,9 @@ struct Comparer {
 #define LOG_DEBUG(cond) \
     ::deepstate::Stream(DeepState_LogDebug, (cond), __FILE__, __LINE__)
 
+#define LOG_TRACE(cond) \
+    ::deepstate::Stream(DeepState_LogTrace, (cond), __FILE__, __LINE__)
+
 #define LOG_INFO(cond) \
     ::deepstate::Stream(DeepState_LogInfo, (cond), __FILE__, __LINE__)
 

src/include/deepstate/Log.h

@@ -34,12 +34,13 @@ struct DeepState_VarArgs {
 
 enum DeepState_LogLevel {
   DeepState_LogDebug = 0,
-  DeepState_LogInfo = 1,
-  DeepState_LogWarning = 2,
+  DeepState_LogTrace = 1,  
+  DeepState_LogInfo = 2,  
+  DeepState_LogWarning = 3,
   DeepState_LogWarn = DeepState_LogWarning,
-  DeepState_LogError = 3,
-  DeepState_LogExternal = 4,
-  DeepState_LogFatal = 5,
+  DeepState_LogError = 4,
+  DeepState_LogExternal = 5,
+  DeepState_LogFatal = 6,
   DeepState_LogCritical = DeepState_LogFatal,
 };
 

src/lib/Log.c

@@ -47,6 +47,8 @@ static const char *DeepState_LogLevelStr(enum DeepState_LogLevel level) {
   switch (level) {
     case DeepState_LogDebug:
       return "DEBUG";
+    case DeepState_LogTrace:
+      return "TRACE";      
     case DeepState_LogInfo:
       return "INFO";
     case DeepState_LogWarning:
@@ -136,7 +138,7 @@ void DeepState_LogFormat(enum DeepState_LogLevel level,
 /* Override libc! */
 DEEPSTATE_NOINLINE
 int puts(const char *str) {
-  DeepState_Log(DeepState_LogInfo, str);
+  DeepState_Log(DeepState_LogTrace, str);
   return 0;
 }
 
@@ -144,7 +146,7 @@ DEEPSTATE_NOINLINE
 int printf(const char *format, ...) {
   va_list args;
   va_start(args, format);
-  DeepState_LogVFormat(DeepState_LogInfo, format, args);
+  DeepState_LogVFormat(DeepState_LogTrace, format, args);
   va_end(args);
   return 0;
 }
@@ -153,20 +155,20 @@ DEEPSTATE_NOINLINE
 int __printf_chk(int flag, const char *format, ...) {
   va_list args;
   va_start(args, format);
-  DeepState_LogVFormat(DeepState_LogInfo, format, args);
+  DeepState_LogVFormat(DeepState_LogTrace, format, args);
   va_end(args);
   return 0;
 }
 
 DEEPSTATE_NOINLINE
 int vprintf(const char *format, va_list args) {
-  DeepState_LogVFormat(DeepState_LogInfo, format, args);
+  DeepState_LogVFormat(DeepState_LogTrace, format, args);
   return 0;
 }
 
 DEEPSTATE_NOINLINE
 int __vprintf_chk(int flag, const char *format, va_list args) {
-  DeepState_LogVFormat(DeepState_LogInfo, format, args);
+  DeepState_LogVFormat(DeepState_LogTrace, format, args);
   return 0;
 }
 
@@ -175,7 +177,7 @@ int vfprintf(FILE *file, const char *format, va_list args) {
   if (stderr == file) {
     DeepState_LogVFormat(DeepState_LogDebug, format, args);
   } else if (stdout == file) {
-    DeepState_LogVFormat(DeepState_LogInfo, format, args);
+    DeepState_LogVFormat(DeepState_LogTrace, format, args);
   } else {
     DeepState_LogVFormat(DeepState_LogExternal, format, args);
   }

tests/test_streamingandformatting.py

@@ -11,10 +11,11 @@ class StreamingAndFormattingTest(deepstate_base.DeepStateTestCase):
 
     self.assertTrue("Failed: Streaming_BasicLevels" in output)
     self.assertTrue("This is a debug message" in output)
+    self.assertTrue("This is a trace message" in output)    
     self.assertTrue("This is an info message" in output)
     self.assertTrue("This is a warning message" in output)
     self.assertTrue("This is a error message" in output)
-    self.assertTrue("This is a info message again" in output)
+    self.assertTrue("This is a trace message again" in output)
     self.assertTrue(": 97" in output)
     self.assertTrue(": 1" in output)
     self.assertTrue(": 1.000000" in output)