base/kaldi_error : the error messages are no longer printed 2x

[KarelVesely84]

• e.what() contains stackttrace or is empty string
• we should also consider changing binaries to have:
  'std::cerr << e.what();' -> 'fprintf(stderr, e.what().c_str());'
• fprintf is thread-safe, it is better not to mix 'std::cerr' and
  'stderr', and 'stderr' is already used for logging...

[danpovey]

I guess this makes sense. I'll wait for Kirill or others to comment though- I'm in no hurry to commit this, like, today, as it would be a big change.

Regarding substituting std::cerr -> fprintf, I'd rather not do this as it might lead to git merging hassles for others, and it just seems to me that it's more of a theoretical than a practical problem at this point [especially since at exit there will be only 1 thread.]

[KarelVesely84]

There's one more thing which is not logical. If a binary crashes on KALDI_ASSERT, the stacktrace is printed 2x, while both traces are little different. I propose to remove the 'stacktrace' print from the KALDI_ASSERT macro. KALDI_ASSERT generates a call of KALDI_ERR, and KALDI_ERR should be the only place where 'stacktrace' is generated.
@danpovey: Do you agree?
@kkm000: Are you interested in geeting the stacktraces from KALDI_ASSERT and KALDI_ERR in your 'g_log_handler'?

Thanks!

[danpovey]

Oh.

I see now that a failed KALDI_ASSERT does have the same effect as calling
KALDI_ERR. This must have been something that slipped past me when Kirill
refactored the error code. However, this isn't really right. KALDI_ERR
generates an exception that may in some [unusual] circumstances be caught,
e.g. in failure of Cholesky and similar things. However, KALDI_ASSERT is
intended for errors (primarily coding errors) that should never need to be
caught and which should cause the program to die immediately. So
KALDI_ASSERT should call abort(). This will likely require another level
to be added to LogMessage::Severity, e.g. kFatal. The Error, Warning, Info
enum values should be renamed to kError, kWarning, kInfo-- I just checked
the style guide.

It's possible in principle to add another macro KALDI_FATAL, that would
have the same effect as KALDI_ASSERT, i.e. calling abort rather than
raising an exception. However, my feeling is that this will just lead to a
lot of confusion in users, so I'd rather not do it. It's quite rare for us
to attempt to catch the KALDI_ERR exception, and we generally know what
errors are raised inside the function concerned.

It would be good if you can show us an example of how the stack traces are
a little different.

Dan

On Fri, May 6, 2016 at 8:44 AM, Karel Vesely notifications@github.com
wrote:

There's one more thing which is not logical. If a binary crashes on
KALDI_ASSERT, the stacktrace is printed 2x, while both traces are little
different. I propose to remove the 'stacktrace' print from the KALDI_ASSERT
macro. KALDI_ASSERT generates a call of KALDI_ERR, and KALDI_ERR should be
the only place where 'stacktrace' is generated. Do you agree?

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#755 (comment)

[danpovey]

It probably would be better to have the stack traces printed at the point where the error happens, rather than when it's caught.
There are situations where KALDI_ERR gets called multiple times, e.g. in multi-threaded code, and seeing all the stack traces would be helpful to debug.
A possible downside of having the stack traces printed when the error happens (which, at least before Kirill's changes, was not how it worked), is that in cases of Cholesky failure where the error is caught, we'll have more verbose output. But we can always fix that a different way, by modifying that code to work differently.

[danpovey]

OK, I just noticed something. There are quite a few parts of the code that attempt to do something with the error string in the exception. The following are just a small subset:

grep 'e.what()' /.{h,cc} | grep -v '//' | grep -v 'bin/'
feat/wave-reader.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
feat/wave-reader.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
feat/wave-reader.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: KALDI_WARN << "Exception caught writing Table object: " << e.what();
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: KALDI_WARN << "Exception caught writing Table object: " << e.what();
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }
util/kaldi-holder-inl.h: if (!IsKaldiError(e.what())) { std::cerr << e.what(); }

However, most of this code seems intended to print the error if it wasn't already printed, e.g. like

KALDI_WARN << "Exception caught writing table of posteriors";
if (!IsKaldiError(e.what())) { std::cerr << e.what(); }

so if it was e.g. std::bad_alloc it would get printed.

Other instances of this are just redundant, e.g.:
KALDI_WARN << "Exception caught writing Table object: " << e.what();
if (!IsKaldiError(e.what())) { std::cerr << e.what(); }

so it will be printed twice if it wasn't a Kaldi error.

Anyway, I'm just pointing out that if we stop including the string in the exception, that code may need to be changed (and possibly simplified).
Dan

[KarelVesely84]

Hi,
the 'IsKaldiError()' will not work with the current 'master' code anyway, as the messages don't have the 'ERROR' prefix. Okay, if the exceptions need to contain the message, then it makes sense to stop printing the errors inside the 'MessageLogger::~MessageLogger()' and rely on the 'catch' clause in the binary.

The difference of the stacktraces is small, i.e. only the last level is different, once context comes from the KALDI_ASSERT and second time from the KALDI_ERR. But there is no real reason to show the stack-trace 2x (I already deleted the log).

Concerning the cases like 'Cholesky' failure, it might be interesting to define some custom exception, say 'CholeskyNumericException' derived from std::runtime_error and pass it to KALDI_ERR macro as an argument.

I can make a toy example to prove that can be done. The final code would look like this:
KALDI_ERR(CholeskyNumericException) << "Message";
Then it would be possible to catch the specific exceptions, while the extra complication is that MessageLogger would become a template.

As it is now, the macro without an argument would simply produce the std::runtime_error :
KALDI_ERR << "Message";

What do you think of it?

[KarelVesely84]

Hi, in the end, the specific exceptions to be passed through KALDI_ERR are not easily doable.
We cannot define such macro that supports this:
KALDI_ERR << "Message";
KALDI_ERR(CholeskyNumericException) << "Message";

The macros cannot be redefined, 2nd with 'Variadic macros' we could do:
KALDI_ERR(<>) << "Message";
KALDI_ERR() << "Message";

But this is not what we really need. We could define KALDI_EXCEPT(...) but this would be similar story to 'KALDI_FATAL', the new extension would confuse people who are used to the old version.

[KarelVesely84]

Okay, Kirill probably needs to get the ASSERT_FAILED message to the Logger handler. So we can define a new severity 'AssertFailed' with ordinal value -3, let the log-print happen and call abort().

For the KALDI_ERR the whole message will go through the e.what(), while it will also be forwarded to the Kirills Logger. Btw, Are there many people using that Logger thing? Is it something like a standard interface?

[danpovey]

Hm, that's not really what I was saying..

The exceptions do not need to contain the message-- I was just pointing out
that we may also need to modify some code that assumes that the exceptions
might contain the message. Most of that code that looks at those
messages tries to avoid printing it anyway, I think, if it is a Kaldi error.

In fact, it is better to have the error message printed in the logger-class
destructor. There are many situations where the error wouldn't be caught--
for instance, in multi-threaded code where the thread doesn't catch the
error.

I think adding a new severity is the right way to ensure that
assert-failures really cause the program to die immediately. The Logger
thing is something Kirill added recently so I doubt many people are using
it.

Regarding the error messages raised from Cholesky, that are caught-- I
don't think we necessarily need to get the Kaldi error-handling code
involved here. If needed we can just call KALDI_WARN and then raise a
specific type of exception manually. But that's for the future, it's a
separate issue-- for now leaving it as KALDI_ERR is OK I think.

Dan

On Mon, May 9, 2016 at 10:39 AM, Karel Vesely notifications@github.com
wrote:

Okay, Kirill probably needs to get the ASSERT_FAILED message to the Logger
handler. So we can define a new severity 'AssertFailed' with ordinal value
-3, let the log-print happen and call abort().

For the KALDI_ERR the whole message will go through the e.what(), while it
will also be forwarded to the Kirills Logger. Btw, Are there many people
using that Logger thing? Is it something like a standard interface?

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#755 (comment)

[KarelVesely84]

Hi, could you please take a look at the updated code?

• some TODO's are to be decided:
  • Can we remove the: 'IsKaldiError()'? (It's very 'dirty' function looking into 'what' message. And it's used only in the table-I/O to suppress printing 'what' messages from KALDI_ERR. IMHO, it may not be a good idea to suppress this.)
  • With Kirill's log-handler, the log is sent and then there's no abort() for errors/asserts (seems like a bad idea, but it is the way it worked previously).

It is simplified and more logically structured.
The core logging code moved from '~MessageLogger' to 'SendToLog'.

I already tested the 'KALDI_ERR', 'KALDI_ASSERT' and 'KALDI_LOG',
the outputs looked nice and were the not different from previous ones.

Cheers, K.

[danpovey]

please don't indent the #ifdefs, I couldn't find any example in the Google C++ style guide of doing this.

[KarelVesely84]

Okay. Well, it is not strictly against the Google style:
https://google.github.io/styleguide/cppguide.html#Preprocessor_Macros

Indents make the macros more readable, but I can put it back as it was if it is an issue...

[danpovey]

It's not specifically forbidden in that text, but I've never seen code like
this elsewhere in Google stuff or in Kaldi-- please put it back.

On Tue, May 10, 2016 at 1:42 PM, Karel Vesely notifications@github.com
wrote:

In src/base/kaldi-error.cc
#755 (comment):

@@ -18,156 +19,122 @@
// limitations under the License.

#ifdef HAVE_EXECINFO_H
-#include <execinfo.h> // To get stack trace in error messages.
-// If this #include fails there is an error in the Makefile, it does not
-// support your platform well. Make sure HAVE_EXECINFO_H is undefined, and the
-// code will compile.
-#ifdef HAVE_CXXABI_H
-#include <cxxabi.h> // For name demangling.
-// Useful to decode the stack trace, but only used if we have execinfo.h
-#endif // HAVE_CXXABI_H

• #include <execinfo.h> // To get stack trace in error messages.
• // If this #include fails there is an error in the Makefile, it does not
• // support your platform well. Make sure HAVE_EXECINFO_H is undefined,
• // and the code will compile.
• #ifdef HAVE_CXXABI_H
• #include <cxxabi.h> // For name demangling.

Okay. Well, it is not strictly against the Google style:
https://google.github.io/styleguide/cppguide.html#Preprocessor_Macros

Indents make the macros more readable, but I can put it back as it was if
it is an issue...

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
https://github.com/kaldi-asr/kaldi/pull/755/files/24bef8dcb4c501a59324debcafd9dcd426bfde23#r62717661

[KarelVesely84]

Integrated the comments from Dan.

[danpovey]

It looks good to me now.
But let's leave this up there for a few days at least, maybe a week or so. I don't think it's good to rush into such far-reaching changes; also we can get comments from Kirill, and leave more time for you to notice problems as you use it in your own work.
I think there were a couple of minor TODOs on your separate PR about fixing cpplint errors.

[KarelVesely84]

Hi, it might be a good time to merge this...

[danpovey]

Would you mind changing the enum variables to start with a k, like kError, kWarning, etc.? I know this was Kirill's code... the Google style guide now mandates this style for enums (or all upper-case).

[KarelVesely84]

Sure, the 'k' is added to the enum. I'll also send an email to Kirill @kkm000 , so he knows the API is little different now.

[kkm000]

Thanks for paging me in. I am totally fine with adding another enum value.

I am not using stack traces in the messages, but I think it might make sense to keep them if available.

Getting rid of IsKaldiError is a good idea.

With Kirill's log-handler, the log is sent and then there's no abort() for errors/asserts (seems like a bad idea, but it is the way it worked previously).

I did not intend it to work this way. If it does, it's a bug I introduced. Errors and assets should be fatal, Kaldi is just coded this way.

[kkm000]

Karel, I had

static void SendToLog(const LogMessageEnvelope &envelope, ... {
   // Send to a logging handler if provided.
  if (g_log_handler != NULL) {
    g_log_handler(envelope, message);
    return;
  }

  // Otherwise, use Kaldi default logging.
...
}

and then

MessageLogger::~MessageLogger() ... {
  SendToLog(envelope_, str.c_str());
  if (envelope_.severity > LogMessageEnvelope::Error)
    return;
  // On error, throw an exception with the message, plus traceback info if available.
  if (!std::uncaught_exception()) {  
 . . .

The new code changed that, so that aborting does not happen if custom error logger is installed. Is this really intended? It can be argued that this behavior has its merit, but we must decide on one or the other. To me, it is way too unsafe to allow the handler to return and continue after KALDI_ERROR -- most code assumes errors/asserts are not continuable. Also, it will break the table handlers that rely on std::runtime_exception being thrown on error. I would rather keep always aborting even with a custom log handler.

[KarelVesely84]

Hi, I see, from the code it was not clearly obvious that the 'return' in the 'SendToLog' was followed by throwing the exception in the ~MessageLogger. Okay, let's do the aborting on asserts and errors when custom log handler is used... Thanks for the info! K.

[kkm000]

I am wondering if there is much point now in having MessageLogger::HandleMessage as a separate function. An argument against it is that it's another extra line in the stack trace.

[danpovey]

Hm. We might be able to just take one element off the stack trace.

Regarding the behavior of errors and asserts, it needs to be precisely as
follows:

• Assert needs to abort.
• Error needs to throw an exception.

Quite a lot of code assumes that error throws an exception, there are cases
both in mathematical stuff (Cholesky) and I/O (table reading) where
exceptions thrown by ERROR are caught.

Dan

On Tue, May 17, 2016 at 2:42 PM, Kirill Katsnelson <notifications@github.com

wrote:

I am wondering if there is much point now in having
MessageLogger::HandleMessage as a separate function. An argument against
it is that it's another extra line in the stack trace.

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#755 (comment)

[kkm000]

• Assert needs to abort.
• Error needs to throw an exception.

That's what I read in the latest Karel's code.

[KarelVesely84]

I was thinking of the MessageLogger::HandleMessage too, the positive is that the name of the method is more self-explaining than was the destructor. Yes it 'occupies' one line in the print, but we can always increase the number of lines which get printed if it becomes a problem. As it is now, the code very clear, transparent and easy to read, which was my priority when thinking about it...

[danpovey]

OK- it looks good to me now. Karel, are you running any experiments right now?
With such a big change I'd be happier waiting a few days with you running the code, just in case problems come to light.

[KarelVesely84]

Hi, I tried to cause an error, a failed assert and to run the 'rm' recipe up to sgmm2. All looks normal... Should I try something more?

[danpovey]

OK that sounds enough. I'll merge now.

On Wed, May 18, 2016 at 11:33 AM, Karel Vesely notifications@github.com
wrote:

Hi, I tried to cause an error, a failed assert and to run the 'rm' recipe
up to sgmm2. All looks normal... Should I try something more?

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#755 (comment)