Small call stack logger for C ++


To write this topic, I was prompted by the topic “ What code tricks do you know? ”, And I wanted to share this logger there, but the author asked “without fanaticism”, and wanted to see such tricks that took no more than five to ten seconds to understand, therefore I decided to put this matter in a separate topic, because in a quick way you can’t take a look.

We will consider a small, but sometimes quite useful class, plus a small trick with macros that allow you to conduct an initial analysis of the call stack directly in stdout, in the process of running the program. Of course, the wedge did not converge on stdout, and you can redirect at least to a file, at least somewhere else - I just demonstrate a general principle.

Immediately agree:
  1. macro abuse is evil
  2. there is nothing new and supernatural in this article, it will be clear even to a beginner (it is designed for them)
  3. this technique is not applicable (or not applicable at all) in a multithreaded environment
  4. implementation does not pretend to be perfect, complete, and even more unique
  5. this technique in no way replaces, but only complements the debugger

But if when writing a program you wrote more than once something like printf ("Entering Foo () \ n"); to monitor the entrance to a particular function, then you came just to the address.

So, we will try to refine this very printf ("Entering Foo () \ n") and squeeze the maximum out of it. The first thing that comes to mind is to replace the manual typing of the function name with the predefined macro __FUNCTION__, which contains a string (i.e. const shar *) with the name of the framing function:

printf("Entering %s()\n", __FUNCTION__);


And in order not to clutter up the code visually and not create distracting factors when reading, we hide this thing under the macro:

#define LOG_TRACE printf("Entering %s()\n", __FUNCTION__);


Now, if we have some kind of noodle-like code, then carefully placing the LOG_TRACE macros at the beginning of each function, we get something like this:
#include <stdio.h>

#define LOG_TRACE printf("Entering %s()\n", __FUNCTION__);

void abc() {
	LOG_TRACE
}

void foo() {
	LOG_TRACE
	abc();
}

void bar() {
	LOG_TRACE
	foo();
	abc();
}

int main(int argc, char* argv[]) {
	bar();
	return 0;
}

When executed, the console will display
Entering bar()
Entering foo()
Entering abc()
Entering abc()


Already something. But not enough. However, if we recall that in addition to the __FUNCTION__ macro, we have no less remarkable macros __FILE__ and __LINE__, then in addition to the function name, we can also display the file name and line number:
#define LOG_TRACE printf("Entering %s() (%s:%d)\n", __FUNCTION__, __FILE__, __LINE__);

Entering bar() (main.cpp:23)
Entering foo() (main.cpp:18)
Entering abc() (main.cpp:14)
Entering abc() (main.cpp:14)


Already better - you can immediately see where to look.

We will not pull the cat by the tail and make it so that not only the input, but also the exit from the function is logged. At this stage, we part with a cozy little bishop and move on to its plus-sized offspring.

What happens when we exit a function (and any other scope)? The stack is cleared of what was put in it in the body of the function (scope). Technically, it’s not exactly cleaning, but just moving the top of the stack pointer, but let's call it that, because we are interested in nothing more than the destruction of objects created on the stack when leaving the scope, and therefore their destructors are called.
So if we now replace the logger function with an object of similar behavior, we can monitor not only the entrance to the function, but also the exit from it.

Let's start the TraceLogger class, which in the constructor will report the entrance to the function, and happily report the exit in the destructor.

TraceLogger.h:
class TraceLogger {
public:
	TraceLogger(const char* fileName, const char* funcName, int lineNumber);
	~TraceLogger();
	
private:
	const char* _fileName;
	const char* _funcName;
};

#define LOG_TRACE TraceLogger traceLogger(__FILE__, __FUNCTION__, __LINE__);


Now the macro hides the creation of an object on the stack with the file name, function name and line number in the constructor passed to it. We will remember the file names and functions - they will be useful in the destructor. In this case, you can not create copies of strings, but restrict yourself to pointers to them, because the lifetime of the object is limited by the body of the function, and it is during this period of time that the lines remain in which the __FILE__ and __FUNCTION__ macros are deployed during preprocessing.

The implementation of the methods looks like this:
TraceLogger.cpp:
TraceLogger::TraceLogger(const char* fileName, const char* funcName, int lineNumber) {
	_fileName = fileName;
	_funcName = funcName;
	std::cout << "Entering " << _funcName << "() - (" << _fileName << ":" << lineNumber << ")" << std::endl;
}

TraceLogger::~TraceLogger() {
	std::cout << "Leaving  " << _funcName << "() - (" << _fileName << ")" << std::endl;
}


And the conclusion, accordingly, is this:

Entering bar() - (main.cpp:19)
Entering foo() - (main.cpp:14)
Entering abc() - (main.cpp:10)
Leaving  abc() - (main.cpp)
Leaving  foo() - (main.cpp)
Entering abc() - (main.cpp:10)
Leaving  abc() - (main.cpp)
Leaving  bar() - (main.cpp)


Looking at this, the phrase “I wish I could indent this!” Revolves in my tongue, right? No problem! We will create a static member of the class in which we will store the indent line (stupidly several spaces) and we will display it at the beginning of the log line. When creating a new instance (what happens when you enter the next function), we will increase the indentation, and when it is destroyed (what happens when you exit the function), we will decrease it.

TraceLogger.h:
class TraceLogger {
	...
private:
	...
	static std::string Indent;
};


TraceLogger.cpp:
std::string TraceLogger::Indent;

TraceLogger::TraceLogger(const char* fileName, const char* funcName, int lineNumber) {
	_fileName = fileName;
	_funcName = funcName;
	std::cout << Indent << "Entering " << _funcName << "() - (" << _fileName << ":" << lineNumber << ")" << std::endl;
	Indent.append("  ");
}

TraceLogger::~TraceLogger() {
	Indent.resize(Indent.length() - 2);
	std::cout << Indent << "Leaving  " << _funcName << "() - (" << _fileName << ")" << std::endl;
}


And now our conclusion looks like this:

Entering bar() - (main.cpp:19)
  Entering foo() - (main.cpp:14)
    Entering abc() - (main.cpp:10)
    Leaving  abc() - (main.cpp)
  Leaving  foo() - (main.cpp)
  Entering abc() - (main.cpp:10)
  Leaving  abc() - (main.cpp)
Leaving  bar() - (main.cpp)


Hooray! Now, at any time during the execution of the program, you can clearly see what function we are currently in and how we actually got there. Well, if something fell, then you can immediately see exactly where (even before uncovering gdb and feeding him a crust).

What else can be done? Of course, disable all this mess in the release version:
TraceLogger.h:
...
#ifdef DEBUG
#define LOG_TRACE TraceLogger logger(__FILE__, __FUNCTION__, __LINE__);
#else
#define LOG_TRACE
#endif


And now in the release version all our LOG_TRACE are corny empty. And to preserve the purity of the binary, you can even bite the entire class altogether, hiding both the declaration and the implementation behind #ifdef DEBUG - I will leave this for you to finalize yourself. Like timestamps at the beginning of a line, they are also very useful.

That's all. I hope someone will find it useful.

Happy coding!