📜 ⬆️ ⬇️

We log context of exceptions

On the eve of the Day of the programmer and in the footsteps of the Day of the tester, I want to talk about how to simplify the lives of both of them in their common cause - software development and debugging.
Namely, I’ll talk about how to make C ++ exceptions more informative, and error logging more compact.

After a year and a half of working with Java, I’m used to exceptions that contain StackTrace like
 Exception in thread "main" java.lang.IllegalStateException: A book has a null property
         at com.example.myproject.Author.getBookIds (Author.java:38)
         at com.example.myproject.Bootstrap.main (Bootstrap.java:14)
 Caused by: java.lang.NullPointerException
         at com.example.myproject.Book.getId (Book.java:22)
         at com.example.myproject.Author.getBookIds (Author.java:35)
         ... 1 more

Switching to C ++, I was struck after a while by the uninformativeness of exceptions in terms of identifying the causes of the error and further debugging. It was necessary to log the passage of all the important points of the program, so that according to the logs it was clear exactly where something went wrong and led to the exception.
Next, I present a simplified evolution of logging through which I went through myself.
The source program, which we will debug and improve
void foo(int a) { if (a == 0) { throw runtime_error("foo throw because zero argument"); } } void bar(int a) { foo(a - 10); } int main() { try { for (int i = 0; i < 100; i++) { bar(i); } } catch (const exception &e) { cerr << "Caught exception: " << e.what() << endl; } return 0; } 


In this form, without knowing anything about the call path foo and the function bar, it is very difficult to understand what to do with the received exception.
Caught exception: throw away

Add a little logs
 void bar(int a) { cerr << "Calling foo(" << a - 10 << ")" << endl; foo(a - 10); } int main() { try { for (int i = 0; i < 100; i++) { cerr << "Calling bar(" << i << ")" << endl; bar(i); } } catch (const exception &e) { cerr << "Caught exception: " << e.what() << endl; } return 0; } 


Result of performance:
Calling bar (0)
Calling foo (-10)
Calling bar (1)
Calling foo (-9)
Calling bar (2)
Calling foo (-8)
Calling bar (3)
Calling foo (-7)
Calling bar (4)
Calling foo (-6)
Calling bar (5)
Calling foo (-5)
Calling bar (6)
Calling foo (-4)
Calling bar (7)
Calling foo (-3)
Calling bar (8)
Calling foo (-2)
Calling bar (9)
Calling foo (-1)
Calling bar (10)
Calling foo (0)
Caught exception: throw away

Now it is clear what happened, but the log turned out to be too cluttered. But let's imagine a nightmare into which it will turn into, if the program has to process all the files in the directory, each file has 5 lines of log and an exception occurred after 1000 files. Total - 5000 lines of the log about how everything is fine, and 10 lines of the error log.
During the reading of this log, the curses of fellow developers and testers, who read my log instead of a holiday and write a bug report, will drive my karma to minus infinity.
That means you have to log only the “erroneous” branches of execution.
It is obvious that at the time of the function call it is unknown it will end normally or throw an exception. This means that the recording in the log will have to be postponed until exiting the function and analyzing the program execution progress.
Like so
 void bar(int a) { try { foo(a - 10); } catch (const exception &e) { string msg = string("calling foo(") + to_string(a - 10) + ") failed"; throw runtime_error(string(e.what()) + "\n" + msg); } } int main() { try { int i; try { for (i = 0; i < 100; i++) { bar(i); } } catch (const exception &e) { string msg = string("calling bar(") + to_string(i) + ") failed"; throw runtime_error(string(e.what()) + "\n" + msg); } } catch (const exception &e) { cerr << "Caught exception: " << e.what() << endl; } return 0; } 

Caught exception: throw away
calling foo (0) failed
calling bar (10) failed

Now testers can easily write a bug report and attach a beautiful, informative and clean log to it. But the program has become ugly and has lost all the beauty of exceptions - the ability to spread the working code and error handling. In fact, we returned almost to checking the return codes of the function and the cruel times of pure C. And I want a beautiful solution that allows you to use to create a clean log and not to disfigure the program. Those. Someone must analyze and secure what is happening for us when leaving the function. Here we come to the aid of the approach already described on Habré, namely, the recording of logs when calling the destructor.

So the requirements for the logging class:
  1. Set message for log
  2. Message output, only in case of exception.

This is where the bool uncaught_exception () function comes in, which says whether there is an unhandled exception.
ExceptionContext class
 class ExceptionContext { public: ExceptionContext(const std::string &msg); ~ExceptionContext(); private: std::string message; }; ExceptionContext::ExceptionContext(const std::string &msg): message(msg) {} ExceptionContext::~ExceptionContext() { if (std::uncaught_exception()) { std::cerr << message << std::endl; } } 


Usage example
 void bar(int a) { ExceptionContext e(string("calling foo(") + to_string(a - 10) + ")"); foo(a - 10); } int main() { try { for (int i = 0; i < 100; i++) { ExceptionContext e(string("calling bar(") + to_string(i) + ")"); bar(i); } } catch (const exception &e) { cerr << "Caught exception: " << e.what() << endl;http://habrahabr.ru/topic/edit/266729/# } return 0; } 

calling foo (0)
calling bar (10)
Caught exception: throw away

It can be seen that this option combines the compactness of the log (we log only the fallen branch of execution) with the compactness of the program (the main code and exception handling are spaced out, logging is inserted into the main code in one line). Now both the developers and testers have stopped cursing me.
In fact, the main goal has already been achieved, but one can take the path of many further improvements, including those described at the end of the post already mentioned.
I will consider only two points:
  1. Interaction with other loggers
  2. Thread safety

Printing the log directly to cerr can be inconvenient because it is impossible to get the accumulated context with such difficulty to duplicate it somewhere else (yes, at least to the developer’s mail, since we have significantly reduced its volume!). Again, if there are other logging tools or multi-threaded execution, there may be unpleasant special effects like mixed log lines. Therefore, now the ExceptionContext class will be stored inside the logs, and issued outside on demand, in the manner printStackTrace from Java.

Thread safe option (using C ++ 11)
 class ExceptionContext { public: ExceptionContext(const std::string &msg); ~ExceptionContext(); static void Print(); //!    cerr   . private: std::string message; static thread_local std::string global_context; //!      . }; ExceptionContext::ExceptionContext(const std::string &msg): message(msg) {} ExceptionContext::~ExceptionContext() { if (std::uncaught_exception()) { global_context += message + std::string("\n"); } } void ExceptionContext::Print() { std::cerr << global_context << std::endl; global_context.clear(); } thread_local std::string ExceptionContext::global_context = std::string(""); 

')
And the catch block in the main program now looks like this:
  catch (const exception &e) { cerr << "Caught exception: " << e.what() << endl; ExceptionContext::Print(); } 


From C ++ 11, the thread_local modifier is used here, which guarantees that in each execution thread the global_context object will have its own, despite the fact that it is a static member of the class and must be the same for all instances.

Have a good weekend, clean code, readable logs and other successes in work!

Source: https://habr.com/ru/post/266729/


All Articles