[src] Rework error logging for safety and cleanliness

[kkm000]

Kaldi error logging was giving fits in i-vector training, when the ivector-extractor-sum-accs spawned multiple i-e-acc-stats processes. Training aborted randomly, and all I was getting in logs was a flurry of std::runtime_errors with an empty message from the child processes (they all died together, apparently). At this point I came back to the logging code, and, while it was not exactly clear how I was getting the message, it was easy enough to figure out where it came from, the logging collector destructor. In other cases, I was getting double-logging, which was also kind of understandable: FatalMessageLogger calls HandleMessage then throws, then some magic in the catch clause allowed the destruction to complete, and it's base class MessageLogger invoked logging again.

I feel responsible for messing this code when I introduced the logging-function hook-up, along with some bugs that Karel @vesis84 had to later fix, for which I'm really grateful. I decided to clean-up the code significantly, to avoid throwing in the destructor entirely, as the behavior wrt the base class destructor is undefined, as far as I understand, and in fact proved compiler-dependent.

This is not a small changeset, so let me summarize it part-by-part. If any of these is not clear, each is detailed in a subsection below (some with additional links to M&M in separate gists).

The code has been compiled and tested cleanly with: gcc6, gcc7, gcc8, clang6, clang7, msvc19. A stand-alone test is available in a gist.

Short summary

1. No more throwing destructors. A separate class is tasked with it.
2. The result of logging expression e. g. KALDI_LOG << x is void.
3. A distinct exception of type KaldiFatalError is thrown, not the runtime_error.
4. All uses of the endl manipulator in log << pipes removed from codebase.
5. Minor fixes to stack-tracing, to prevent empty lines on demangling errors.
6. Commentary on KALDI_ASSERT branch prediction removed.

1. Throwing destructors are ugly

Hope this statement is not contentious. Also, the logic there, relying on std::uncaught_exception(), was unsound at best. You do not have to subscribe to Herb Sutter's view that the function is entirely useless as defined (C++20 improves it, FWIW), but I found his arguments quite compelling. So I studied boost::log, gLog and some other logging code to find a better solution.

The idea is to throw the exception from some operator on a special class, not the destructor itself. This has a benefit of a logging expression (e. g., auto useless = KALDI_LOG << x), well, useless. This is similar to what gLog does to make such an expression void. I found their use of operator&() too confusing for Kaldi codebase; operator=() works as good and less confusing to read. Two special small classes expose it: Log() = MessageLogger(....) << 42; just logs the message, and LogAndThrow() = .... also throws. The tatter is [[noreturn]]; this one does not cause a confusion between compilers. It was quite unsurprising that compilers were confused by a [[noreturn]] destructor; I would hardly expect this in their battery of tests.

2. KALDI_LOG << x is void

It makes no sense to use it as a value any more, as logging is done by the operator=() mentioned above. The return value of the operator is void. Logging libraries using the << inserter pipelining pattern commonly do that to prevent a "creative use" of the logging macros.

3. KALDI_ERROR throws KaldiFatalError

This exceptions class is derived from std::runtime_error(), so current catch() handlers are compatible with it, as long as the object is caught by const&, which should normally be the only right way to catch exceptions. This potentially solved the IsKaldiError() problem previously addressed by Karel (see a4fff0d) in case an error source must be distinguished. I believe it's a good thing in general to have a dedicated exception class for Kaldi.

NEED FEEDBACK PLEASE: I do not like these two members of this class:

class KaldiFatalError : public std::runtime_error {
 public:
  //TODO(kkm): Temporary(?) hack. Do we really need it? I think a better
  // approach to avoid double-logging the message is catch the KaldiFatalError
  // in binaries explicitly (and print nothing).
  virtual const char *what() const noexcept override { return ""; }

  const char *KaldiMessage() const { return std::runtime_error::what(); }
};

Here, what() returns an empty string, to avoid double-logging, while there is a member to access a Kaldi-specific error message in case it is requested. This is an abuse of the semantics of the standard what() member. What I would actually find cleaner is the use of one of these patterns in each bin:

int main(int argc, char *argv[]) {
 try {
   /* ... */
 } catch(const KaldiFatalError&) {
   return -1;  // Error has been logged already.
 }
}

which just exists with a failure exit code because the error has been already logged, or

int main(int argc, char *argv[]) {
  try {
  /* ... */
  } catch(const KaldiFatalError&) {
    return -1;  // Error has been logged already.
  } catch(const std::exception &e) {
    std::cerr << "FATAL: " << e.what() << "\n";
    return -1;
  }
}

to stderr other stdc++ exceptions in case of a library error. Personally, I'd prefer the former, as it would puke a coredump on an unhandled exception, while the latter would lose stack trace of the error, and is quite uninformative (what's the point of e.g. "FATAL: )

So what is the best approach, in your opinion?

1. Leave bins alone, keep the hack.
2. Update them all to the former pattern (one catch clause).
3. Update them all to the latter pattern (two catch clauses).

4. Most uses of std::endl in Kaldi codebase are incorrect

The manipulator does not equal a '\n'; it is a '\n' followed by flush()!

While an overload of operator << on the MessageLogger would have allowed it, I decided to bite the bullet and remove it (or replace with a '\n' if not at EOL) everywhere it is used with logging macros. This allowed me to get rid of the code that removed trailing linefeeds in the logger as well.

But generally speaking, I see many incorrect uses of this manipulator in the codebase. Here's a very relevant note from comments in the glibc ostream header:

This manipulator is often mistakenly used when a simple newline is > desired, leading to poor buffering performance. See > https://gcc.gnu.org/onlinedocs/libstdc++/manual/streambufs.html#io.streambuf.buffering > for more on this subject.

I sanitized its use everywhere in those files that I had to edit only. The only exception is a baffling loop starting at onlinebin/online-audio-client.cc:175, which seems to output one empty line to stdout per each line of header read from the server, except for lines starting with "PARTIAL:", for which the rest of such a line is printed and flushed explicitly (twice, as it currently is); I do not understand how it is used, so I left the flushing version intact.

There are places where endl is used when actual files are being written; I changed two instances in the same onlinebin/online-audio-client.cc where the file was being flushed to disk on every write. There is more cases like this; they should probably be taken care of eventually.

It is also important that std::cerr is set to auto-flush after every insertion << by default; per N3337 §27.4.2, 5:

After the object cerr is initialized, cerr.flags() & unitbuf is nonzero [...]

5. Stack trace could contain empty strings on demangling failure

It actually did without -rdynamic with gcc (but not clang). I massaged the code a bit to print the original reported string from the stack trace in such a case.

6. Commentary on KALDI_ASSERT branch prediction was dubious

I have been long surprised by the statement that compilers prefer the if-true branch rather than the else branch. It always bothered me, as modern compilers are rather dealing with very thoroughly cooked internal representation when the code reaches the optimizer. Doing this rework, I decided to spend some time to check if that is still the case these days.

TL;DR: absolutely not, with no exceptions, for all the 4 ways to write ASSERT-like statement I wrote, and all compilers I tested: gcc, clang, icc, msvc, multiple version each where available. Full exposure is available in this gist, if you are interested in details of the test.

In the end, I removed the comment, as it has become rather misleading.

It is also notable that [[noreturn]] seems a strong optimization hint, suggesting the compiler that the code calling that function should be put on the conditional jump branch. All compilers/versions tested do that with -O2, and most but not all with -O1. Again, specific details are at the link above. It was a fascinating exercise, really.

[danpovey]

if this is going to be permanent, better to just explain the purpose,

[kkm000]

Sure thing, I want to remove the TODO and finalize the interface before this merge. We need to decide how this will be used. My complete question is under the "NEED FEEDBACK PLEASE" heading in the description. Very briefly, I do not like the current approach, which is: log the error then throw runtime_error(""). My understanding this empty string is to avoid double-printing of the already logged message, because all bins do cerr << e.what();. The two member functions of the KaldiFatalError exist solely to continue to support this hack: what() always returns "", but the additional member KaldiMessage() is available (just in case) to get the error message.

What I would like to do is change the catch clause in all binaries to catch (const KaldiFatalError&) { return -1; }, essentially. In this case, the what() hack becomes unnecessary, and the KaldiMessage() accessor won't be needed (so no non-inherited members in the class KaldiFatalError). It's a non-zero amount of work, naturally, and I wanted to run it by you first. And what should be the form of the catch-clause wrt catching non-Kaldi std:: exceptions, see the full question for the two possibilities.

[kkm000]

Or maybe I am not understanding the reason for the empty what() message at all?

[btiplitz]

I make use of catching exceptions with a custom logger and thus don't assume the message has gone to the output. Does this effect your thoughts on your "NEED FEEDBACK PLEASE" design ?

[kkm000]

I also do, although I know I should not; Kaldi has never been designed for that. At some points it leaks memory, for one.

I am not changing any existing behavior. The custom logger (or the default one, no matter) is called before throwing, and has always been. And if it's called with kError, you know it's going to throw. It it's called with kAssertFailed, Kaldi will abort, but you can throw your own exception at this point and bypass the abort. Whether to log or not, your choice in the logging function. Of course, having caught the exception, you should assume that all the state has been corrupted, memory leaked and gremlins are out to get you.

[danpovey]

Thanks for this. It seems reasonable to me; and thanks for testing on multiple compilers.
I'm thinking, if no-one objects, to just merge it and we'll deal with any problems from weird compilers (if any), as they come up.

[danpovey]

I think you are right about the reason for the empty what() message. I think it was added in a previous refactoring. I don't like the idea of catching the kaldi-fatal thing separately for all binaries, it would be a lot of work and too much boilerplate; I think it would be easiest just to make what() be "" or something short and standard like the class name, in this case.

…

On Sat, Mar 2, 2019 at 8:16 PM kkm (aka Kirill Katsnelson) < ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In src/base/kaldi-error.h <#3064 (comment)>: > @@ -78,81 +80,100 @@ struct LogMessageEnvelope { int32 line; }; -// Class MessageLogger is invoked from the KALDI_ASSERT, KALDI_ERR, KALDI_WARN and -// KALDI_LOG macros. It formats the message, then either prints it to stderr or -// passes to the log custom handler if provided, then, in case of the error, -// throws an std::runtime_exception, in case of failed KALDI_ASSERT calls abort(). +/// Kaldi runtime error exception. Thrown from any use of KALDI_ERR. +class KaldiFatalError : public std::runtime_error { + public: + explicit KaldiFatalError(const std::string &message) + : std::runtime_error(message) { } + explicit KaldiFatalError(const char *message) + : std::runtime_error(message) { } + + //TODO(kkm): Temporary(?) hack. Do we really need it? I think a better Or maybe I am not understanding the reason for the empty what() message at all? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#3064 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADJVuxJ1xBudZ9RDeRBUK6TPgrTexPRfks5vSyJkgaJpZM4baUoM> .

[kkm000]

it would be easiest just to make what() be "" or something short and standard like the class name, in this case.

SGTM! Yes, most std::exception derivates just return their class name (e. g., "std::bad_alloc"), will do same, and leave KaldiMessage() for those library uses where it might be helpful.

[kkm000]

Done, the exception class documented. Also also added doxygen comments for public logging interfaces too, and un-doxygened the MessageLogger class, as it is technically an implementation detail.

I also added a second commit, replacing a few throw runtime_exception with KALDI_ERR, as that was intended (except in fsext/, naturally), and changed the thrown exception class name in all comments where runtime_exception was said to be thrown.

[danpovey]

Thanks. What kind of testing have you done, that the output looks similar to the current output?

…

On Sun, Mar 3, 2019 at 5:15 AM kkm (aka Kirill Katsnelson) < ***@***.***> wrote: Done, the exception class documented. Also also added doxygen comments for public logging interfaces too, and un-doxygened the MessageLogger class, as it is technically an implementation detail. I also added a second commit, replacing a few throw runtime_exception with KALDI_ERR, as that was intended (except in fsext/, naturally), and changed the thrown exception class name in all comments where runtime_exception was said to be thrown. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#3064 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADJVu_tK1n4z6o4qlqc9NGQXRzxwvsY6ks5vS6DDgaJpZM4baUoM> .

[btiplitz]

within the c++ construct, is it better to rethrow a fatal exception vs a direct call to abort?

the abort breaks programs I have that catch errors and continue on the next task

[kkm000]

This function only handles KALDI_ASSERT. It's reasonable to die at this point, because the macro says "it's impossible that the condition is false." You can throw around this abort in your logging function.

[btiplitz]

ok, I see that. Thanks

[btiplitz]

Should this be an inline function ?

[kkm000]

I am not following. Why?

[btiplitz]

never mind. Not that important. I was thinking of performance, but it should not get called that much

[kkm000]

Ah, got it! Compilers take care of this these days. Look how the register keyword has gone from the language.

[btiplitz]

Since you cleaned up the destructor output, it would seem to make sense to make this a static function as to not re-construct the class on every log message

[kkm000]

I'm sorry, I am a little bit dense today. The thing is constructed on the stack, and takes whopping 16 bytes of it. Why should I store a 16-byte buffer in TLS? Or am I totally missing your idea?

[btiplitz]

it's not a bunch of memory. But it seems like a waste to construct the class and destruct it. Wasted cpu time

[kkm000]

Ah, I thought you are talking about the envelope, and you are talking about the whole MessageLoger thing. The class just contains an ostrstream. The logger itself lives on the stack, together with the stream (which in turn just encapsulates an std::string in the end). The stream allocates memory, of course. But we still need to log to something, so this is unavoidable.

It could have been more efficient if we did not pull the string from this logger to append to another stream. But compared to other computational stuff which is going on, it hardly worth an optimization. Verbose logging is for debugging, and normal logging is pretty insignificant.

[kkm000]

  if (GetVerboseLevel() >= 3) {
00007FF614FFA88D  xor         ebx,ebx  
00007FF614FFA88F  lea         r12,[string "kaldi::nnet3::Optimize" (07FF61524E4A0h)]  
00007FF614FFA896  lea         r13,[string "ext\\kaldi\\@"... (07FF61524E6A0h)]  
00007FF614FFA89D  cmp         dword ptr [kaldi::g_kaldi_verbose_level (07FF61531D448h)],3  
00007FF614FFA8A4  jl          kaldi::nnet3::Optimize+0E2h (07FF614FFA932h)  
    CheckComputation(nnet, *computation, true);
00007FF614FFA8AA  mov         r8b,1  
00007FF614FFA8AD  mov         rdx,r9  
00007FF614FFA8B0  mov         rcx,r15  
00007FF614FFA8B3  call        kaldi::nnet3::CheckComputation (07FF614F88DA0h)  
    KALDI_LOG << "Before optimization, max memory use (bytes) = "
00007FF614FFA8B8  lea         rcx,[rbp-50h]  
00007FF614FFA8BC  call        std::basic_ostringstream<char,std::char_traits<char>,std::allocator<char> >::basic_ostringstream<char,std::char_traits<char>,std::allocator<char> > (07FF614E29680h)  
00007FF614FFA8C1  mov         dword ptr [rbp-70h],ebx  
00007FF614FFA8C4  mov         qword ptr [rbp-68h],r12  
00007FF614FFA8C8  lea         edx,[rbx+2Fh]  
00007FF614FFA8CB  mov         rcx,r13 

So this is all it boils down to. An ostringstream constructor call.

[btiplitz]

I get many compilation warnings saying not to throw in a destructor, so updating the code to solve this seems like a good idea

[kkm000]

@danpovey

What kind of testing have you done, that the output looks similar to the current output?

Besides compiling and running the code snippet in the bash loop, I checked the output of kaldi-error-test and, rather surprisingly, nnetbin/cuda-gpu-available, because it's output is formatted in an interesting way.

[kkm000]

@danpovey, do you want me to ping somebody else to ask to review this (Karel, Yenda)? Or just need more time? I just want to make sure this does not fall of everyone's radar. I nearly forgot about this my own MR... : ) To me, it should be good to go, I checked it very thoroughly, as I do with all base stuff.

I have a few little fixes that are based on top of this.