// DebugLogger.cpp: Debug Extension code // // Contians DebugLogger, StackLogger, and debug_mem_allocation /******************************************************************* // *** COPYRIGHT NOTICE **** // // Copyright 2003. David Maisonave (david@axter.com) // // This code is free for use under the following conditions: // // You may not claim authorship of this code. // You may not sell or distrubute this code without author's permission. // You can use this code for your applications as you see fit, but this code may not be sold in any form // to others for use in their applications. // This copyright notice may not be removed. // // // No guarantees or warranties are expressed or implied. // This code may contain bugs. *******************************************************************/ // Please let me know of any bugs, bug fixes, or enhancements made to this code. // If you have ideas for this, and/or tips or admonitions, I would be glad to hear them. // ////////////////////////////////////////////////////////////////////// /* Purpose: DebugLogger class: The DebugLogger class is used for logging debug information, which includes Source File Name, Line Number, and if compiler supports __FUNCTION__ macro, function name. This class only contains one object, which is a pointer. By using a pointer to contain complex data, extra header dependencies are removed from the DebugLogger.h header. In addition, the debug level is higher then the session level, the complex data is not created, and the pointer is assigned a NULL. This allows the DebugLogger class to be created and destroyed efficiently when no logging occurs. This means it has very little impact on performance, and can be compiled and used in the release version of the code. StackLogger class: The StackLogger class is used to display the stack while the program is running. It can be used on the debug version and the release version. This class is extremely useful when a debugger can not be used to debug the code. The StackLogger class can also be use as a profiler. ADD_PROFILE_LOGGING_ must be defined to add the profiler functionality to the StackLogger class. debug_mem_allocation class: The debug_mem_allocation class is used to detect memory leaks. It does so by replacing the new and delete operator via macros. It also replaces malloc, realloc, and free functions via macros. The macros are setup to only compile for the DEBUG version of the code, and only if USE_DEBUG_MEM_ALLOCATION is defined. These macros will log into memory all instance in which the new operator and free function is called. When a call is made to delete operator or free function, the pointer is removed from the log. When the program is ready to exit, a call can be made to the following static function: debug_ext::debug_mem_allocation::SendOutCurrentLog(); The above function performs a DebugLogger call for any pointer that was not deleted or free. Usage: DebugLogger class: This class is used via DEBUGLOGGER_ macro, and to use this macro, TWO sets of arguments are used. Example: DEBUGLOGGER_(10)("Did not find file: ", filename); The first argument is the debug level. This argument is separated from the debug log data arguments via parenthesis (). The log data can contain 1, 2, 3, 4, or 5 arguments. DEBUGLOGGER_(3)("Hello "); DEBUGLOGGER_(3)("Hello ", "World "); DEBUGLOGGER_(3)("Hello ", "World ", "Good "); DEBUGLOGGER_(3)("Hello ", "World ", "Good ", "Bye "); DEBUGLOGGER_(3)("Hello ", "World ", "Good ", "Bye ", "Now!"); The information is logged only if the debug level is equal to or less then the session debug level. The session debug level can be set at compile time, or at runtime. To set the debug level at compile time, define DEBUG_LOG_COMPILE_TIME_SETTINGS__LEVEL_ to the desired level. #define DEBUG_LOG_COMPILE_TIME_SETTINGS__LEVEL_ 22 To set session debug level at runtime, make sure the above define is NOT defined, and set environmental variable DEBUG_LOG_LEVEL to desired level. The following are other environmental options: DEBUG_LOG_TO_SCREEN DEBUG_LOG_TO_FILE DEBUG_LOG_TIMESTAMP DEBUG_LOG_UNSTACK DEBUG_LOG_FLUSH DEBUG_LOG_MAX_FILE_SIZE All the above environmental variables have associated defines that will set their values at compile time instead of runtime. StackLogger class: This class is used via STACKLOGGER_ macro, and to use this macro no arguments are needed. The macros should be placed in the first line of a function. Example std::string COutboxClass::SomeFunction() { STACKLOGGER_; return "Hello"; } debug_mem_allocation class: To use this class, the majority of the code should not have to be modified. However compile errors will occur when the delete[] operator is used, and may occur for casting while using new and when calling delete this. Calls to delete[] operator must be replaced with the macro DELETE_ARRAY_AND_NULLIFY. Example: char *pbuffer = new char[33]; strcpy(pbuffer, "foo foo"); DELETE_ARRAY_AND_NULLIFY pbuffer; On some compilers, code that performs a new, and cast at the same time, might need to be modified. Example of original code: CStringData* pData1xx = (CStringData*) new BYTE[99]; Example of workaround method: CStringData* pData1xx = (CStringData*) (new BYTE[99]); On some compilers delete this will fail to compile. Example: delete this; Example workaround: foo* tmp_foo = this; delete tmp_foo; */ #include #ifdef WIN32 #pragma warning(disable : 4786) #endif //WIN32 #include #include #include #include #include #include #define DEBUG_LOG_INCLUDE_FROM_DEBUGLOGGER_CPP_ #include "debuglogger.h" #if defined(WIN32) && !defined(DWORD) #include #define DEBUG_LOG_COMPILE_TIME_SETTINGS_ #endif #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS_ #define DEBUG_LOG_COMPILE_TIME_SETTINGS__LEVEL_ 22 #define DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_SCREEN_ true #define DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_FILE_ false #define DEBUG_LOG_COMPILE_TIME_SETTINGS__TIMESTAMP_ false #define DEBUG_LOG_COMPILE_TIME_SETTINGS__UNSTACK_ true #define DEBUG_LOG_COMPILE_TIME_SETTINGS__FLUSH_ false #define DEBUG_LOG_COMPILE_TIME_SETTINGS__MAX_FILE_SIZE_ 10000 #endif //DEBUG_LOG_COMPILE_TIME_SETTINGS_ namespace debug_ext { const int DebugLogger::m_SessionDebugLevel = DebugLogger::Get_SessionDebugLevel(); int DebugLogger::Get_SessionDebugLevel() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__LEVEL_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__LEVEL_; #else const char* Retrn = getenv("DEBUG_LOG_LEVEL"); if (Retrn) return atoi(Retrn); return 0; #endif } class TICK_COUNT_T { public: enum {SEC_USEC_DIV = 1000}; TICK_COUNT_T():m_sec(0), m_usec(0) { } TICK_COUNT_T(long sec, long usec):m_sec(sec), m_usec(usec) { } const TICK_COUNT_T& operator=(const TICK_COUNT_T& Src) { m_sec = Src.m_sec; m_usec = Src.m_usec; return *this; } const TICK_COUNT_T& operator-=(const TICK_COUNT_T& Src) { m_sec -= Src.m_sec; if (Src.m_usec > m_usec) { m_usec = (SEC_USEC_DIV - Src.m_usec) + m_usec; --m_sec; } else m_usec -= Src.m_usec; return *this; } #ifdef WIN32x TICK_COUNT_T(const DWORD& Src):m_sec(Src/SEC_USEC_DIV), m_usec(Src%SEC_USEC_DIV) { } const TICK_COUNT_T& operator=(const DWORD& Src) { m_sec = Src/SEC_USEC_DIV; m_usec = Src%SEC_USEC_DIV; return *this; } #endif unsigned long GetSec() const { return m_sec; } unsigned long GetUSec() const { return m_usec; } private: unsigned long m_sec; unsigned long m_usec; }; class DebugLogger::DbgMsg_t { public: DbgMsg_t(int LineNo, const char* SourceFileName, const char* FunctionName): m_CodeLineNo(LineNo), m_SourceFileName(((SourceFileName)?SourceFileName:"")) { if (FunctionName && FunctionName[0]) { m_FunctionName = "("; m_FunctionName += FunctionName; m_FunctionName += ")"; } } DbgMsg_t(int LineNo, const std::string& SourceFileName, const std::string& FunctionName) : m_CodeLineNo(LineNo), m_SourceFileName(SourceFileName), m_FunctionName(FunctionName) { } const int m_CodeLineNo; std::string m_DbgMsg; const std::string m_SourceFileName; std::string m_FunctionName; std::string m_StackDbgMsg; std::string m_ReturnValueMsg; #ifdef ADD_PROFILE_LOGGING_ TICK_COUNT_T m_StartTime; #endif }; DebugLogger::DebugLogger(int nNewLevel, int LineNo, const char* SourceFileName, const char* FunctionName) :DbgMsg(((nNewLevel <= m_SessionDebugLevel)? new DbgMsg_t(LineNo, SourceFileName, FunctionName) :NULL)) { } DebugLogger::DebugLogger(const DebugLogger& Src) :DbgMsg(((Src.DbgMsg)? new DbgMsg_t(Src.DbgMsg->m_CodeLineNo, Src.DbgMsg->m_SourceFileName, Src.DbgMsg->m_FunctionName) :NULL)) { } const DebugLogger& DebugLogger::operator=(const DebugLogger& Src) { DbgMsg = (((Src.DbgMsg)? new DbgMsg_t(Src.DbgMsg->m_CodeLineNo, Src.DbgMsg->m_SourceFileName, Src.DbgMsg->m_FunctionName) :NULL)); return *this; } DebugLogger::~DebugLogger(){ if (DbgMsg) delete DbgMsg; /*Make DbgMsg NULL*/ DbgMsg = NULL; } void DebugLogger::AddToDbgMsg(int Number) { if (!DbgMsg) return; char buffer[99]; sprintf(buffer,"(%i) ", Number); DbgMsg->m_DbgMsg += buffer; } void DebugLogger::AddToDbgMsg(const char* Str) { if (!DbgMsg) return; DbgMsg->m_DbgMsg += "("; DbgMsg->m_DbgMsg += ((Str)?Str:"NULL"); DbgMsg->m_DbgMsg += ") "; } void DebugLogger::GenerateStackMsg() { int StkSize; const DebugLogger* StkBegin = StackLogger::GetCurrentStack(StkSize); if (!StkSize) { DbgMsg->m_StackDbgMsg = ""; return; } char buffer[9999]; for(const DebugLogger* i = StkBegin;i < StkBegin+StkSize;++i) { sprintf(buffer,"%s(%i)%s->", i->DbgMsg->m_SourceFileName.c_str(), i->DbgMsg->m_CodeLineNo, i->DbgMsg->m_FunctionName.c_str()); DbgMsg->m_StackDbgMsg += buffer; } DbgMsg->m_StackDbgMsg += "*************************\n"; } bool GetDebugLogOption(const char* Option) { const char* Retrn = getenv(Option); if (Retrn) { std::string UpprValue = Retrn; std::transform(UpprValue.begin(), UpprValue.end(), UpprValue.begin(),toupper); if (UpprValue == "YES" || UpprValue == "TRUE") return true; } return false; } bool GetDebugLogToScreenOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_SCREEN_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_SCREEN_; #else return GetDebugLogOption("DEBUG_LOG_TO_SCREEN"); #endif } bool GetDebugLogToFileOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_FILE_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__TO_FILE_; #else return GetDebugLogOption("DEBUG_LOG_TO_FILE"); #endif } bool GetDebugLogTimeStampOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__TIMESTAMP_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__TIMESTAMP_; #else return GetDebugLogOption("DEBUG_LOG_TIMESTAMP"); #endif } bool GetDebugLogUnstackOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__UNSTACK_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__UNSTACK_; #else return GetDebugLogOption("DEBUG_LOG_UNSTACK"); #endif } bool GetDebugLogFlushOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__FLUSH_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__FLUSH_; #else return GetDebugLogOption("DEBUG_LOG_FLUSH"); #endif } int Get_DebugLogMaxFileSizeOption() { #ifdef DEBUG_LOG_COMPILE_TIME_SETTINGS__MAX_FILE_SIZE_ return DEBUG_LOG_COMPILE_TIME_SETTINGS__MAX_FILE_SIZE_; #else const char* Retrn = getenv("DEBUG_LOG_MAX_FILE_SIZE"); if (Retrn) return atoi(Retrn); return 100000; #endif } namespace { FILE * FileStream = NULL; } void DebugLogger::SendDbgMsg(bool AddEndLineChr) { if (!DbgMsg) return; static const bool DebugLogToScreen = GetDebugLogToScreenOption(); static const bool DebugLogToFile = GetDebugLogToFileOption(); static const bool DebugLogTimeStamp = GetDebugLogTimeStampOption(); if (!DebugLogToScreen && !DebugLogToFile) return; DbgMsg->m_StackDbgMsg = ""; GenerateStackMsg(); time_t aclock; char sztimestamp[32]=""; if (DebugLogTimeStamp) { time(&aclock); /* Get time in seconds */ struct tm *newtime = localtime(&aclock); /* Convert time to struct tm form */ /* Print local time as a string */ strcpy(sztimestamp, asctime(newtime)); // remove CR if it exists if (sztimestamp[strlen(sztimestamp)-1] == '\n') sztimestamp[strlen(sztimestamp)-1] = '\0'; } char EndLineStr[3] = {'\n', ((AddEndLineChr)?'\n':0), 0}; const char PRINT_FORMAT[] = "%s%s(%i): %s: %s%s%s"; const char PRINT_FORMAT_WITH_TIMESTAMP[] = "%s, %d, %s%s(%i): %s: %s%s%s"; if (DebugLogToScreen) { if (DebugLogTimeStamp) printf(PRINT_FORMAT_WITH_TIMESTAMP, sztimestamp, (int)aclock, DbgMsg->m_StackDbgMsg.c_str(), DbgMsg->m_SourceFileName.c_str(), DbgMsg->m_CodeLineNo, DbgMsg->m_FunctionName.c_str(), DbgMsg->m_DbgMsg.c_str(), DbgMsg->m_ReturnValueMsg.c_str(), EndLineStr); else printf(PRINT_FORMAT, DbgMsg->m_StackDbgMsg.c_str(), DbgMsg->m_SourceFileName.c_str(), DbgMsg->m_CodeLineNo, DbgMsg->m_FunctionName.c_str(), DbgMsg->m_DbgMsg.c_str(), DbgMsg->m_ReturnValueMsg.c_str(), EndLineStr); } if (!DebugLogToFile) return; const int QTY_FILE_STRM = 4; static const int MAX_SIZE_OF_DEBUG_FILE = Get_DebugLogMaxFileSizeOption(); static int IterationFileID = 0; static int DebugFileIndex = 0; static int CurrentFileSize = 0; static char FileName[] = "debuglogX"; if (CurrentFileSize > MAX_SIZE_OF_DEBUG_FILE) { fclose(FileStream); FileStream = NULL; } if (!FileStream) { FileName[sizeof(FileName)-2] = '1' + DebugFileIndex; DebugFileIndex = (++DebugFileIndex)&1; FileStream = fopen(FileName, "w"); CurrentFileSize = (FileStream)?fprintf(FileStream,"File ID = %i\n\n", ++IterationFileID):0; } if (FileStream) { if (DebugLogTimeStamp) CurrentFileSize += fprintf(FileStream, PRINT_FORMAT_WITH_TIMESTAMP, sztimestamp, (int)aclock, DbgMsg->m_StackDbgMsg.c_str(), DbgMsg->m_SourceFileName.c_str(), DbgMsg->m_CodeLineNo, DbgMsg->m_FunctionName.c_str(), DbgMsg->m_DbgMsg.c_str(), DbgMsg->m_ReturnValueMsg.c_str(), EndLineStr); else CurrentFileSize += fprintf(FileStream, PRINT_FORMAT, DbgMsg->m_StackDbgMsg.c_str(), DbgMsg->m_SourceFileName.c_str(), DbgMsg->m_CodeLineNo, DbgMsg->m_FunctionName.c_str(), DbgMsg->m_DbgMsg.c_str(), DbgMsg->m_ReturnValueMsg.c_str(), EndLineStr); } } /**************************************************************/ #ifdef ADD_PROFILE_LOGGING_ #ifndef WIN32 //If not WIN32, then use POSIX function #include TICK_COUNT_T TV_TO_WORD(timeval *p_tv = NULL) { timeval Local_tv; if (!p_tv) { p_tv = &Local_tv; gettimeofday(p_tv, NULL); } return ((p_tv->tv_usec/SEC_USEC_DIV)%SEC_USEC_DIV) + ((p_tv->tv_sec%SEC_USEC_DIV0) * SEC_USEC_DIV); } namespace { const TICK_COUNT_T ProgramStartTime = TV_TO_WORD(); } TICK_COUNT_T GetTickCount(VOID) { return TV_TO_WORD() - ProgramStartTime; } #endif //!WIN32 #endif //ADD_PROFILE_LOGGING_ /**************************************************************/ namespace { std::vector CurrentStack; } const DebugLogger* StackLogger::GetCurrentStack(int &StackSize) { StackSize = CurrentStack.size(); return &CurrentStack[0]; } StackLogger::StackLogger(int LineNo, const char* SourceFileName, const char* FunctionName, bool SendDbgMsgInCtor) :DebugLogger(1, LineNo, SourceFileName, FunctionName) { CurrentStack.push_back(*this); static const bool DebugLogFlushOption = GetDebugLogFlushOption(); if (SendDbgMsgInCtor) { if (FunctionName && FunctionName[0]) { AddToDbgMsg("Entered function "); AddToDbgMsg(FunctionName); } #ifdef ADD_PROFILE_LOGGING_ DbgMsg->m_StartTime = GetTickCount(); #endif SendDbgMsg(); if (DebugLogFlushOption) fflush(FileStream); } } StackLogger::~StackLogger() { static const bool DebugLogUnstack = GetDebugLogUnstackOption(); if (DebugLogUnstack) { AddToDbgMsg("!!!*** Exiting Function ***!!!"); SendDbgMsg(true); } #ifdef ADD_PROFILE_LOGGING_ TICK_COUNT_T DurTime = GetTickCount(); DurTime -= DbgMsg->m_StartTime; char buffer[9999]; DbgMsg->m_DbgMsg = ""; sprintf(buffer, "Duration<%4.4i:%4.4i>, %s: [%s(%i)]", (DurTime.GetSec()/TICK_COUNT_T::SEC_USEC_DIV), (DurTime.GetUSec()%TICK_COUNT_T::SEC_USEC_DIV), DbgMsg->m_FunctionName.c_str() , DbgMsg->m_SourceFileName.c_str(), DbgMsg->m_CodeLineNo); AddToDbgMsg(buffer); SendDbgMsg(); #endif CurrentStack.pop_back(); } int StackLogger::AddReturnValue(int RetrnVar, int LineNumber) { if (DbgMsg) { char buffer[99]; sprintf(buffer,": At Code Pos %i, Function Return Value = (%i) : ", LineNumber, RetrnVar); DbgMsg->m_ReturnValueMsg = buffer; } return RetrnVar; } const char* StackLogger::AddReturnValue(const char* RetrnVar, int LineNumber) { if (DbgMsg) { char buffer[199]; sprintf(buffer,": At Code Pos %i, Function Return Value = (\"%.99s\") : ", LineNumber, RetrnVar); DbgMsg->m_ReturnValueMsg = buffer; } return RetrnVar; } class MemAllocLog { public: std::string SrcFileName; int LineNo; std::string FunctionName; friend bool operator<(const MemAllocLog &Src1, const MemAllocLog &Src2) { if (Src1.SrcFileName != Src2.SrcFileName) { return (strcmp(Src1.SrcFileName.c_str(),Src2.SrcFileName.c_str()) < 0); } if (Src1.LineNo != Src2.LineNo) { return (Src1.LineNo < Src2.LineNo); } if (Src1.FunctionName != Src2.FunctionName) { return (strcmp(Src1.FunctionName.c_str(),Src2.FunctionName.c_str()) < 0); } return false; } }; void Logger(void const * const Ptr, debug_mem_allocation::ACTION_SWITCH Sw, const char* FileName, int LineNo, const char* FunctionName) { const char EmptyBuf[] = ""; if (!FunctionName) FunctionName = EmptyBuf; static std::map mem_alloc_log; switch(Sw) { case debug_mem_allocation::AllocateMem: { if (!Ptr) { DebugLogger(1, LineNo, FileName, FunctionName)("Error: Failed to allocate memory for pointer!!!", " Pointer is set to NULL!!!"); } MemAllocLog This_MemAllocLog; This_MemAllocLog.SrcFileName = FileName; This_MemAllocLog.LineNo = LineNo; This_MemAllocLog.FunctionName = FunctionName; int debugsize = mem_alloc_log.size(); mem_alloc_log[Ptr] = This_MemAllocLog; debugsize = mem_alloc_log.size(); } break; case debug_mem_allocation::DeAllocMem: if (!Ptr) { DebugLogger(1, LineNo, FileName, FunctionName)("Error: Attempting to deallocate a NULL pointer!!!"); } mem_alloc_log.erase(Ptr); break; case debug_mem_allocation::GenerateReport: { int debugsize = mem_alloc_log.size(); #if (defined(DEBUG) || defined (_DEBUG)) && defined(USE_DEBUG_MEM_ALLOCATION) for(std::map::const_iterator i = mem_alloc_log.begin(); i != mem_alloc_log.end();++i) { std::string Msg1 = "Memory leak at Source File \"" + i->second.SrcFileName + "\" Line("; std::string Msg2 = ") Func(\"" + i->second.FunctionName + "\")"; DEBUGLOGGER_(5)(Msg1.c_str(), i->second.LineNo, Msg2.c_str()); } printf("Finished displaying memory leak data.....\n"); DEBUGLOGGER_(5)("Finished displaying memory leak data.....***\n"); #endif } break; } } void debug_mem_allocation::Log(void const * const Ptr, ACTION_SWITCH Sw) { Logger(Ptr, Sw, m_FileName, m_LineNo, m_FuncName); } void debug_mem_allocation::SendOutCurrentLog() { Logger(NULL, GenerateReport, NULL, 0, NULL); } void debug_mem_allocation::free_and_log(void *memblock) { Log(memblock, DeAllocMem); free(memblock); } void* debug_mem_allocation::malloc_and_log(int size ) { void *memblock = malloc(size); Log(memblock, AllocateMem); return memblock; } void* debug_mem_allocation::realloc_and_log(void *memblock, int size ) { Log(memblock, DeAllocMem); memblock = realloc(memblock, size); Log(memblock, AllocateMem); return memblock; } }//End of namespace debug_ext