Created
March 2, 2019 09:38
-
-
Save kkm000/e40db103e1c591ff59255d6f59da14a5 to your computer and use it in GitHub Desktop.
Standalone verification of Kaldi logging code rework
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
/* logs-shoots-and-leaves.cc. | |
One-liner test in bash: | |
set -x; for cxx in g++-6 g++-7 g++-8 clang++-6.0 clang++-7; do \ | |
for std in 11 14 17; do \ | |
for endl in 0 1; do \ | |
$cxx -std=c++${std} -g -fdiagnostics-color \ | |
-Wall -Wextra -Wpedantic -rdynamic \ | |
-DTEST_ENDL=$endl -DHAVE_CXXABI_H -DHAVE_EXECINFO_H \ | |
logs-shoots-and-leaves.cc -o test && \ | |
./test; \ | |
done; done; done; set +x | |
*/ | |
#include <cstdio> | |
#include <cstring> | |
#include <sstream> | |
#include <stdexcept> | |
#include <string> | |
#include <vector> | |
// Not in kaldi-error.{cc.h}: | |
#include <iostream> | |
#include <typeinfo> | |
typedef int32_t int32; | |
#define KALDI_VERSION "1.2.3.4" | |
//--- | |
#ifdef _MSC_VER | |
#define __func__ __FUNCTION__ | |
#endif | |
#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 | |
#endif // HAVE_EXECINFO_H | |
namespace kaldi { | |
/// \addtogroup error_group | |
/// @{ | |
/***** VERBOSITY LEVEL *****/ | |
/// This is set by util/parse-options.{h, cc} if you set --verbose=? option. | |
extern int32 g_kaldi_verbose_level; | |
/// This is set by util/parse-options.{h, cc} (from argv[0]) and used (if set) | |
/// in error reporting code to display the name of the program (this is because | |
/// in our scripts, we often mix together the stderr of many programs). It is | |
/// the base-name of the program (no directory). | |
extern std::string g_program_name; | |
inline int32 GetVerboseLevel() { return g_kaldi_verbose_level; } | |
/// This should be rarely used; command-line programs set the verbosity level | |
/// automatically from ParseOptions. | |
inline void SetVerboseLevel(int32 i) { g_kaldi_verbose_level = i; } | |
/***** KALDI LOGGING *****/ | |
/// Log message severity and source location info. | |
struct LogMessageEnvelope { | |
enum Severity { | |
kAssertFailed = -3, | |
kError = -2, | |
kWarning = -1, | |
kInfo = 0, | |
}; | |
// An 'enum Severity' value, or a positive number indicating verbosity level. | |
int severity; | |
const char *func; | |
const char *file; | |
int32 line; | |
}; | |
/// 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 | |
// 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(); } | |
}; | |
// 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 custom logging handler if provided, then, in case of the | |
// error, throws a KaldiErrorException, or in case of failed KALDI_ASSERT | |
// calls std::terminate(). | |
// | |
// Note: we do not use std::cerr because it allows output from threads to | |
// interleave. fprintf(), on the other hand, outputs its formatted string | |
// atomically. | |
class MessageLogger { | |
public: | |
/// The constructor stores the message's "envelope", a set of data which | |
/// identifies the location in source which is sending the message to log. | |
/// The pointers to strings are stored internally, and not owned or copied, | |
/// so that their storage must outlive this object. | |
MessageLogger(LogMessageEnvelope::Severity severity, | |
const char *func, | |
const char *file, | |
int32 line); | |
/// The stream insertion operator, used in e.g. 'KALDI_LOG << "Message"'. | |
template <typename T> | |
MessageLogger &operator<<(const T &val) { | |
ss_ << val; | |
return *this; | |
} | |
#if TEST_ENDL | |
/// The stream insertion operator for manipulators, e.g. 'KALDI_LOG << endl'. | |
/// #### I DO NOT LIKE IT! Remove all uses of the endl() instead. | |
MessageLogger& operator<<(std::ostream &(*val)(std::ostream &)) { | |
ss_ << val; | |
return *this; | |
} | |
#endif | |
/// When assigned a MessageLogger, log its contents. | |
struct Log final { | |
void operator=(const MessageLogger& logger) { | |
logger.LogMessage(); | |
} | |
}; | |
/// When assigned a MessageLogger, log its contents and then throw | |
/// a KaldiFatalError. | |
struct LogAndThrow final { | |
[[ noreturn ]] void operator=(const MessageLogger& logger) { | |
logger.LogMessage(); | |
throw KaldiFatalError(logger.GetMessage()); | |
} | |
}; | |
private: | |
std::string GetMessage() const; | |
void LogMessage() const; | |
LogMessageEnvelope envelope_; | |
std::ostringstream ss_; | |
}; | |
// Logging macros. | |
#define KALDI_ERR \ | |
::kaldi::MessageLogger::LogAndThrow() = \ | |
::kaldi::MessageLogger(::kaldi::LogMessageEnvelope::kError, \ | |
__func__, __FILE__, __LINE__) | |
#define KALDI_WARN \ | |
::kaldi::MessageLogger::Log() = \ | |
::kaldi::MessageLogger(::kaldi::LogMessageEnvelope::kWarning, \ | |
__func__, __FILE__, __LINE__) | |
#define KALDI_LOG \ | |
::kaldi::MessageLogger::Log() = \ | |
::kaldi::MessageLogger(::kaldi::LogMessageEnvelope::kInfo, \ | |
__func__, __FILE__, __LINE__) | |
#define KALDI_VLOG(v) \ | |
if ((v) <= ::kaldi::g_kaldi_verbose_level) \ | |
::kaldi::MessageLogger::Log() = \ | |
::kaldi::MessageLogger((::kaldi::LogMessageEnvelope::Severity)(v), \ | |
__func__, __FILE__, __LINE__) | |
/***** KALDI ASSERTS *****/ | |
[[ noreturn ]] void KaldiAssertFailure_(const char *func, const char *file, | |
int32 line, const char *cond_str); | |
// Note on KALDI_ASSERT and KALDI_PARANOID_ASSERT. | |
// The original (simple) version of the code was this | |
// | |
// #define KALDI_ASSERT(cond) if (!(cond)) | |
// kaldi::KaldiAssertFailure_(__func__, __FILE__, __LINE__, #cond); | |
// | |
// That worked well, but we were concerned that it could potentially cause a | |
// performance issue due to failed branch prediction (best practice is to have | |
// the if branch be the commonly taken one). | |
// | |
// Therefore, we decided to move the call into the else{} branch. A single block | |
// {} around if/else does not work, because it causes syntax error (unmatched | |
// else block) in the following code: | |
// | |
// if (condition) | |
// KALDI_ASSERT(condition2); | |
// else | |
// SomethingElse(); | |
// | |
// do {} while(0) -- note there is no semicolon at the end! -- works nicely, | |
// and compilers will be able to optimize the loop away (as the condition is | |
// always false). | |
// | |
// Also see KALDI_COMPILE_TIME_ASSERT, defined in base/kaldi-utils.h, and | |
// KALDI_ASSERT_IS_INTEGER_TYPE and KALDI_ASSERT_IS_FLOATING_TYPE, also defined | |
// there. | |
#ifndef NDEBUG | |
#define KALDI_ASSERT(cond) do { if (cond) (void)0; else \ | |
::kaldi::KaldiAssertFailure_(__func__, __FILE__, __LINE__, #cond); } while(0) | |
#else | |
#define KALDI_ASSERT(cond) (void)0 | |
#endif | |
// Some more expensive asserts only checked if this defined | |
#ifdef KALDI_PARANOID | |
#define KALDI_PARANOID_ASSERT(cond) do { if (cond) (void)0; else \ | |
::kaldi::KaldiAssertFailure_(__func__, __FILE__, __LINE__, #cond); } while(0) | |
#else | |
#define KALDI_PARANOID_ASSERT(cond) (void)0 | |
#endif | |
/***** THIRD-PARTY LOG-HANDLER *****/ | |
/// Type of third-party logging function. | |
typedef void (*LogHandler)(const LogMessageEnvelope &envelope, | |
const char *message); | |
/// Set logging handler. If called with a non-NULL function pointer, the | |
/// function pointed by it is called to send messages to a caller-provided log. | |
/// If called with a NULL pointer, restores default Kaldi error logging to | |
/// stderr. SetLogHandler is obviously not thread safe; the log handler must be. | |
LogHandler SetLogHandler(LogHandler); | |
/// @} end "addtogroup error_group" | |
/***** GLOBAL VARIABLES FOR LOGGING *****/ | |
int32 g_kaldi_verbose_level = 0; | |
std::string g_program_name; | |
static LogHandler g_log_handler = NULL; | |
/***** HELPER FUNCTIONS *****/ | |
// Trim filename to at most 1 trailing directory long. Given a filename like | |
// "/a/b/c/d/e/f.cc", return "e/f.cc". Support both '/' and '\' as the path | |
// separator. | |
static const char *GetShortFileName(const char *path) { | |
if (path == nullptr) | |
return ""; | |
const char *prev = path, *last = path; | |
while ((path = std::strpbrk(path, "\\/")) != nullptr) { | |
++path; | |
prev = last; | |
last = path; | |
} | |
return prev; | |
} | |
/***** STACKTRACE *****/ | |
#ifdef HAVE_EXECINFO_H | |
static std::string Demangle(std::string trace_name) { | |
#ifdef HAVE_CXXABI_H | |
// At input the string looks like: | |
// ./kaldi-error-test(_ZN5kaldi13UnitTestErrorEv+0xb) [0x804965d] | |
// We want to extract the name e.g. '_ZN5kaldi13UnitTestErrorEv" | |
// and demangle it. | |
// Try to locate '(' and '+', take the string in between. | |
size_t begin(trace_name.find("(")), | |
end(trace_name.rfind("+")); | |
if (begin != std::string::npos && end != std::string::npos && begin < end) { | |
trace_name = trace_name.substr(begin + 1, end - (begin + 1)); | |
} | |
// Try to demangle function name. | |
int status; | |
char *demangled_name = abi::__cxa_demangle(trace_name.c_str(), 0, 0, &status); | |
if (status == 0) { | |
trace_name = demangled_name; | |
free(demangled_name); | |
} | |
#endif // HAVE_CXXABI_H | |
return trace_name; | |
} | |
#endif // HAVE_EXECINFO_H | |
static std::string KaldiGetStackTrace() { | |
std::string ans; | |
#ifdef HAVE_EXECINFO_H | |
const size_t KALDI_MAX_TRACE_SIZE = 50; | |
const size_t KALDI_MAX_TRACE_PRINT = 20; // Must be even. | |
// Buffer for the trace. | |
void *trace[KALDI_MAX_TRACE_SIZE]; | |
// Get the trace. | |
size_t size = backtrace(trace, KALDI_MAX_TRACE_SIZE); | |
// Get the trace symbols. | |
char **trace_symbol = backtrace_symbols(trace, size); | |
if (trace_symbol == NULL) | |
return ans; | |
// Compose a human-readable backtrace string. | |
ans += "[ Stack-Trace: ]\n"; | |
if (size <= KALDI_MAX_TRACE_PRINT) { | |
for (size_t i = 0; i < size; i++) { | |
ans += Demangle(trace_symbol[i]) + "\n"; | |
} | |
} else { // Print out first+last (e.g.) 5. | |
for (size_t i = 0; i < KALDI_MAX_TRACE_PRINT/2; i++) { | |
ans += Demangle(trace_symbol[i]) + "\n"; | |
} | |
ans += ".\n.\n.\n"; | |
for (size_t i = size - KALDI_MAX_TRACE_PRINT/2; i < size; i++) { | |
ans += Demangle(trace_symbol[i]) + "\n"; | |
} | |
if (size == KALDI_MAX_TRACE_SIZE) | |
ans += ".\n.\n.\n"; // Stack was too long, probably a bug. | |
} | |
// We must free the array of pointers allocated by backtrace_symbols(), | |
// but not the strings themselves. | |
free(trace_symbol); | |
#endif // HAVE_EXECINFO_H | |
return ans; | |
} | |
/***** KALDI LOGGING *****/ | |
MessageLogger::MessageLogger(LogMessageEnvelope::Severity severity, | |
const char *func, const char *file, int32 line) { | |
// Obviously, we assume the strings survive the destruction of this object. | |
envelope_.severity = severity; | |
envelope_.func = func; | |
envelope_.file = GetShortFileName(file); // Points inside 'file'. | |
envelope_.line = line; | |
} | |
std::string MessageLogger::GetMessage() const { | |
std::string str = ss_.str(); | |
// Remove any number of trailing linefeeds. | |
// #### UGH!!! | |
while (!str.empty() && (str[str.length() - 1] == '\n')) | |
str.resize(str.length() - 1); | |
return str; | |
} | |
void MessageLogger::LogMessage() const { | |
std::string message = GetMessage(); | |
// Send to a logging handler if provided. | |
if (g_log_handler != NULL) { | |
g_log_handler(envelope_, message.c_str()); | |
return; | |
} | |
// Otherwise, use the default Kaldi logging. | |
// Build the log-message header. | |
std::stringstream header; | |
if (envelope_.severity > LogMessageEnvelope::kInfo) { | |
header << "VLOG[" << envelope_.severity << "] ("; | |
} else { | |
switch (envelope_.severity) { | |
case LogMessageEnvelope::kInfo : | |
header << "LOG ("; | |
break; | |
case LogMessageEnvelope::kWarning : | |
header << "WARNING ("; | |
break; | |
case LogMessageEnvelope::kAssertFailed : | |
header << "ASSERTION_FAILED ("; | |
break; | |
case LogMessageEnvelope::kError : | |
default: // If not the ERROR, it still an error! | |
header << "ERROR ("; | |
break; | |
} | |
} | |
// Fill other info from the envelope. | |
header << g_program_name.c_str() << "[" KALDI_VERSION "]" << ':' | |
<< envelope_.func << "():" << envelope_.file << ':' | |
<< envelope_.line << ")"; | |
// Add stack trace for errors and assertion failures, if available. | |
if (envelope_.severity < LogMessageEnvelope::kWarning) { | |
std::string stack_trace = KaldiGetStackTrace(); | |
if (!stack_trace.empty()) { | |
message.append("\n\n"); | |
message.append(stack_trace); | |
} | |
} | |
// Print the complete message to stderr. | |
fprintf(stderr, "%s %s\n", header.str().c_str(), message.c_str()); | |
} | |
/***** KALDI ASSERTS *****/ | |
void KaldiAssertFailure_(const char *func, const char *file, | |
int32 line, const char *cond_str) { | |
MessageLogger::Log() = | |
MessageLogger (LogMessageEnvelope::kAssertFailed, func, file, line) | |
<< "Assertion '" << cond_str << "' failed"; | |
fflush(NULL); | |
std::abort(); | |
} | |
/***** THIRD-PARTY LOG-HANDLER *****/ | |
LogHandler SetLogHandler(LogHandler handler) { | |
LogHandler old_handler = g_log_handler; | |
g_log_handler = handler; | |
return old_handler; | |
} | |
} // namespace kaldi | |
// A custom inserter. | |
struct Nnet { | |
}; | |
class NnetComputation { | |
public: | |
void Print(std::ostream& os, const Nnet&) const { | |
os << "[NnetComputation]"; | |
} | |
}; | |
struct NnetComputationPrintInserter { | |
const NnetComputation &computation; | |
const Nnet &nnet; | |
void Print(std::ostream &os) const { computation.Print(os, nnet); } | |
friend std::ostream &operator<<(std::ostream &os, | |
NnetComputationPrintInserter xhis) { | |
xhis.Print(os); | |
return os; | |
} | |
}; | |
double foo(const std::string& s) { | |
int i = 42; | |
double pi = 3.1415926; | |
Nnet nnet; | |
NnetComputation nnet_comp; | |
KALDI_WARN << "Number=" << i | |
<< ", float=" << pi | |
<< ", hex=0x" << std::hex << i | |
<< ", boolean='" << std::boolalpha << (i == 42) << '\'' | |
<< ", strings '" << s << "' and '" << s.c_str() << "'. " | |
#if TEST_ENDL | |
<< std::endl | |
#endif | |
<< "Custom inserter: " << NnetComputationPrintInserter{nnet_comp, nnet} | |
#if TEST_ENDL | |
<< std::endl << std::endl | |
#endif | |
; | |
KALDI_ERR << "Number=" << i | |
<< ", float=" << pi | |
<< ", hex=0x" << std::hex << i | |
<< ", boolean='" << std::boolalpha << (i == 42) << '\'' | |
<< ", strings '" << s << "' and '" << s.c_str() << "'. " | |
#if TEST_ENDL | |
<< std::endl | |
#endif | |
<< "Custom inserter: " << NnetComputationPrintInserter{nnet_comp, nnet} | |
#if TEST_ENDL | |
<< std::endl << std::endl | |
#endif | |
; | |
// No return, no compliant. | |
} | |
int main () { | |
try { | |
foo("jabberwhacky"); | |
printf("*** foo() unexpectedly returned\n"); | |
} catch (const kaldi::KaldiFatalError& e) { | |
printf("Calling foo(), caught KaldiFatalError, what()=\"%s\", message=\"%s\"\n", | |
e.what(), e.KaldiMessage()); | |
} catch (const std::exception& e) { | |
printf("*** This is unexpected. " | |
"Calling foo(), caught '%s', what()=\"%s\"\n", | |
typeid(e).name(), e.what()); | |
} | |
int i = 42; | |
try { | |
KALDI_ASSERT(i > 42); | |
printf("*** KALDI_ASSERT() unexpectedly returned!\n"); | |
} catch (const std::exception &e) { | |
printf("*** KALDI_ASSERT() should have aborted! " | |
"Caught '%s', what()=\"%s\"\n", | |
typeid(e).name(), e.what()); | |
} | |
return 0; | |
} |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Test output, all clean and as expected: