diff options
author | <shinichiro.hamaji@gmail.com> | 2009-01-15 10:34:35 +0000 |
---|---|---|
committer | <shinichiro.hamaji@gmail.com> | 2009-01-15 10:34:35 +0000 |
commit | e31a91b6502b3d15ecd7c2d1b518fafbc7234572 (patch) | |
tree | ae0e0e0995653622e0d753bbffa664fa7a506200 | |
parent | eecffc5aa5501b69e9d493ebe8b4e19699d62fb2 (diff) | |
download | glog-e31a91b6502b3d15ecd7c2d1b518fafbc7234572.tar.gz glog-e31a91b6502b3d15ecd7c2d1b518fafbc7234572.tar.bz2 glog-e31a91b6502b3d15ecd7c2d1b518fafbc7234572.zip |
* Add LOG_TO_STRING.
* Add LOG_AT_LEVEL.
* Add DVLOG.
* Add LOG_TO_SINK_ONLY.
* Log microseconds.
* Add --log_backtrace_at option.
* Introduce CrashReason class.
* Fix some bugs.
git-svn-id: https://google-glog.googlecode.com/svn/trunk@29 eb4d4688-79bd-11dd-afb4-1d65580434c0
-rw-r--r-- | src/glog/logging.h.in | 237 | ||||
-rw-r--r-- | src/glog/raw_logging.h.in | 90 | ||||
-rw-r--r-- | src/googletest.h | 5 | ||||
-rw-r--r-- | src/logging.cc | 426 | ||||
-rw-r--r-- | src/logging_unittest.cc | 202 | ||||
-rw-r--r-- | src/logging_unittest.err | 582 | ||||
-rw-r--r-- | src/raw_logging.cc | 72 | ||||
-rw-r--r-- | src/utilities.cc | 68 | ||||
-rw-r--r-- | src/utilities.h | 32 |
9 files changed, 1174 insertions, 540 deletions
diff --git a/src/glog/logging.h.in b/src/glog/logging.h.in index 0949432..8f6389e 100644 --- a/src/glog/logging.h.in +++ b/src/glog/logging.h.in @@ -229,6 +229,35 @@ typedef unsigned __int64 uint64; // --v=# set the verbose level // --logtostderr log all the messages to stderr instead of to logfiles +// LOG LINE PREFIX FORMAT +// +// Log lines have this form: +// +// Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg... +// +// where the fields are defined as follows: +// +// L A single character, representing the log level +// (eg 'I' for INFO) +// mm The month (zero padded; ie May is '05') +// dd The day (zero padded) +// hh:mm:ss.uuuuuu Time in hours, minutes and fractional seconds +// threadid The space-padded thread ID as returned by GetTID() +// (this matches the PID on Linux) +// file The file name +// line The line number +// msg The user-supplied message +// +// Example: +// +// I1103 11:57:31.739339 24395 google.cc:2341] Command line: ./some_prog +// I1103 11:57:31.739403 24395 google.cc:2342] Process id 24395 +// +// NOTE: although the microseconds are useful for comparing events on +// a single machine, clocks on different machines may not be well +// synchronized. Hence, use caution when comparing the low bits of +// timestamps from different machines. + #ifndef DECLARE_VARIABLE #define MUST_UNDEF_GFLAGS_DECLARE_MACROS #define DECLARE_VARIABLE(type, name, tn) \ @@ -257,9 +286,23 @@ typedef unsigned __int64 uint64; // Set whether log messages go to stderr instead of logfiles DECLARE_bool(logtostderr); -// Set how important a log message should be to avoid buffering +// Set whether log messages go to stderr in addition to logfiles. +DECLARE_bool(alsologtostderr); + +// Log messages at a level >= this flag are automatically sent to +// stderr in addition to log files. +DECLARE_int32(stderrthreshold); + +// Set whether the log prefix should be prepended to each line of output. +DECLARE_bool(log_prefix); + +// Log messages at a level <= this flag are buffered. +// Log messages at a higher level are flushed immediately. DECLARE_int32(logbuflevel); +// Sets the maximum number of seconds which logs may be buffered for. +DECLARE_int32(logbufsecs); + // Log suppression level: messages logged at a lower level than this // are suppressed. DECLARE_int32(minloglevel); @@ -268,10 +311,17 @@ DECLARE_int32(minloglevel); // default logging directory. DECLARE_string(log_dir); +// Sets the path of the directory into which to put additional links +// to the log files. +DECLARE_string(log_link); + DECLARE_int32(v); // in vlog_is_on.cc -DECLARE_int32(stderrthreshold); -DECLARE_bool(alsologtostderr); +// Sets the maximum log file size (in MB). +DECLARE_int32(max_log_size); + +// Sets whether to avoid logging to the disk if the disk is full. +DECLARE_bool(stop_logging_if_full_disk); #ifdef MUST_UNDEF_GFLAGS_DECLARE_MACROS #undef MUST_UNDEF_GFLAGS_DECLARE_MACROS @@ -288,36 +338,53 @@ DECLARE_bool(alsologtostderr); // LOG(INFO) and its ilk are used all over our code, it's // better to have compact code for these operations. -#if 0 >= GOOGLE_STRIP_LOG -#define COMPACT_GOOGLE_LOG_INFO @ac_google_namespace@::LogMessage(__FILE__, __LINE__) +#if GOOGLE_STRIP_LOG == 0 +#define COMPACT_GOOGLE_LOG_INFO @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__) +#define LOG_TO_STRING_INFO(message) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::INFO, message) #else #define COMPACT_GOOGLE_LOG_INFO @ac_google_namespace@::NullStream() +#define LOG_TO_STRING_INFO(message) @ac_google_namespace@::NullStream() #endif -#if 1 >= GOOGLE_STRIP_LOG -#define COMPACT_GOOGLE_LOG_WARNING @ac_google_namespace@::LogMessage(__FILE__, __LINE__, @ac_google_namespace@::WARNING) +#if GOOGLE_STRIP_LOG <= 1 +#define COMPACT_GOOGLE_LOG_WARNING @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::WARNING) +#define LOG_TO_STRING_WARNING(message) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::WARNING, message) #else #define COMPACT_GOOGLE_LOG_WARNING @ac_google_namespace@::NullStream() +#define LOG_TO_STRING_WARNING(message) @ac_google_namespace@::NullStream() #endif -#if 2 >= GOOGLE_STRIP_LOG -#define COMPACT_GOOGLE_LOG_ERROR @ac_google_namespace@::LogMessage(__FILE__, __LINE__, @ac_google_namespace@::ERROR) +#if GOOGLE_STRIP_LOG <= 2 +#define COMPACT_GOOGLE_LOG_ERROR @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::ERROR) +#define LOG_TO_STRING_ERROR(message) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::ERROR, message) #else #define COMPACT_GOOGLE_LOG_ERROR @ac_google_namespace@::NullStream() +#define LOG_TO_STRING_ERROR(message) @ac_google_namespace@::NullStream() #endif -#if 3 >= GOOGLE_STRIP_LOG -#define COMPACT_GOOGLE_LOG_FATAL @ac_google_namespace@::LogMessageFatal(__FILE__, __LINE__) +#if GOOGLE_STRIP_LOG <= 3 +#define COMPACT_GOOGLE_LOG_FATAL @ac_google_namespace@::LogMessageFatal( \ + __FILE__, __LINE__) +#define LOG_TO_STRING_FATAL(message) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::FATAL, message) #else #define COMPACT_GOOGLE_LOG_FATAL @ac_google_namespace@::NullStreamFatal() +#define LOG_TO_STRING_FATAL(message) @ac_google_namespace@::NullStreamFatal() #endif // For DFATAL, we want to use LogMessage (as opposed to // LogMessageFatal), to be consistent with the original behavior. #ifdef NDEBUG #define COMPACT_GOOGLE_LOG_DFATAL COMPACT_GOOGLE_LOG_ERROR -#elif 3 >= GOOGLE_STRIP_LOG -#define COMPACT_GOOGLE_LOG_DFATAL @ac_google_namespace@::LogMessage(__FILE__, __LINE__, @ac_google_namespace@::FATAL) +#elif GOOGLE_STRIP_LOG <= 3 +#define COMPACT_GOOGLE_LOG_DFATAL LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::FATAL) #else #define COMPACT_GOOGLE_LOG_DFATAL @ac_google_namespace@::NullStreamFatal() #endif @@ -395,7 +462,7 @@ GOOGLE_GLOG_DLL_DECL void InstallFailureFunction(void (*fail_func)()); class LogSink; // defined below // If a non-NULL sink pointer is given, we push this message to that sink. -// We then do normal LOG(severity) logging as well. +// For LOG_TO_SINK we then do normal LOG(severity) logging as well. // This is useful for capturing messages and passing/storing them // somewhere more specific than the global log of the process. // Argument types: @@ -403,8 +470,28 @@ class LogSink; // defined below // LogSeverity severity; // The cast is to disambiguate NULL arguments. #define LOG_TO_SINK(sink, severity) \ - @ac_google_namespace@::LogMessage(__FILE__, __LINE__, @ac_google_namespace@::severity, \ - static_cast<@ac_google_namespace@::LogSink*>(sink)).stream() + @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, \ + @ac_google_namespace@::severity, \ + static_cast<@ac_google_namespace@::LogSink*>(sink), true).stream() +#define LOG_TO_SINK_BUT_NOT_TO_LOGFILE(sink, severity) \ + @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, \ + @ac_google_namespace@::severity, \ + static_cast<@ac_google_namespace@::LogSink*>(sink), false).stream() + +// If a non-NULL string pointer is given, we write this message to that string. +// We then do normal LOG(severity) logging as well. +// This is useful for capturing messages and storing them somewhere more +// specific than the global log of the process. +// Argument types: +// string* message; +// LogSeverity severity; +// The cast is to disambiguate NULL arguments. +// NOTE: LOG(severity) expands to LogMessage().stream() for the specified +// severity. +#define LOG_TO_STRING(severity, message) \ + LOG_TO_STRING_##severity(static_cast<string*>(message)).stream() // If a non-NULL pointer is given, we push the message onto the end // of a vector of strings; otherwise, we report it with LOG(severity). @@ -415,8 +502,7 @@ class LogSink; // defined below // vector<string> *outvec; // The cast is to disambiguate NULL arguments. #define LOG_STRING(severity, outvec) \ - @ac_google_namespace@::LogMessage(__FILE__, __LINE__, @ac_google_namespace@::severity, \ - static_cast<std::vector<std::string>*>(outvec)).stream() + LOG_TO_STRING_##severity(static_cast<vector<string>*>(outvec)).stream() #define LOG_IF(severity, condition) \ !(condition) ? (void) 0 : @ac_google_namespace@::LogMessageVoidify() & LOG(severity) @@ -541,9 +627,13 @@ DEFINE_CHECK_OP_IMPL(_GT, > ) // in the macro. typedef std::string _Check_string; #define CHECK_OP_LOG(name, op, val1, val2, log) \ - while (@ac_google_namespace@::_Check_string* _result = \ - @ac_google_namespace@::Check##name##Impl((val1), (val2), #val1 " " #op " " #val2)) \ - log(__FILE__, __LINE__, @ac_google_namespace@::CheckOpString(_result)).stream() + while (@ac_google_namespace@::_Check_string* _result = \ + @ac_google_namespace@::Check##name##Impl( \ + @ac_google_namespace@::GetReferenceableValue(val1), \ + @ac_google_namespace@::GetReferenceableValue(val2), \ + #val1 " " #op " " #val2)) \ + log(__FILE__, __LINE__, \ + @ac_google_namespace@::CheckOpString(_result)).stream() #else // In optimized mode, use CheckOpString to hint to compiler that // the while condition is unlikely. @@ -555,8 +645,13 @@ typedef std::string _Check_string; log(__FILE__, __LINE__, _result).stream() #endif // STATIC_ANALYSIS, !NDEBUG +#if GOOGLE_STRIP_LOG <= 3 #define CHECK_OP(name, op, val1, val2) \ CHECK_OP_LOG(name, op, val1, val2, @ac_google_namespace@::LogMessageFatal) +#else +#define CHECK_OP(name, op, val1, val2) \ + CHECK_OP_LOG(name, op, val1, val2, @ac_google_namespace@::NullStreamFatal) +#endif // STRIP_LOG <= 3 // Equality/Inequality checks - compare two values, and log a FATAL message // including the two values when the result is not as expected. The values @@ -715,7 +810,19 @@ PLOG_IF(FATAL, GOOGLE_PREDICT_BRANCH_NOT_TAKEN((invocation) == -1)) \ __FILE__, __LINE__, @ac_google_namespace@::severity, LOG_OCCURRENCES, \ &what_to_do).stream() -#define LOG_EVERY_N(severity, n) \ +namespace glog_internal_namespace_ { +template <bool> +struct CompileAssert { +}; +} // namespace glog_internal_namespace_ + +#define GOOGLE_GLOG_COMPILE_ASSERT(expr, msg) \ + typedef @ac_google_namespace@::glog_internal_namespace_::CompileAssert<(bool(expr))> msg[bool(expr) ? 1 : -1] + +#define LOG_EVERY_N(severity, n) \ + GOOGLE_GLOG_COMPILE_ASSERT(@ac_google_namespace@::severity < \ + @ac_google_namespace@::NUM_SEVERITIES, \ + INVALID_REQUESTED_LOG_SEVERITY); \ SOME_KIND_OF_LOG_EVERY_N(severity, (n), @ac_google_namespace@::LogMessage::SendToLog) #define SYSLOG_EVERY_N(severity, n) \ @@ -739,6 +846,7 @@ enum PRIVATE_Counter {COUNTER}; #ifndef NDEBUG #define DLOG(severity) LOG(severity) +#define DVLOG(verboselevel) VLOG(verboselevel) #define DLOG_IF(severity, condition) LOG_IF(severity, condition) #define DLOG_EVERY_N(severity, n) LOG_EVERY_N(severity, n) #define DLOG_IF_EVERY_N(severity, condition, n) \ @@ -763,6 +871,10 @@ enum PRIVATE_Counter {COUNTER}; #define DLOG(severity) \ true ? (void) 0 : @ac_google_namespace@::LogMessageVoidify() & LOG(severity) +#define DVLOG(verboselevel) \ + (true || !VLOG_IS_ON(verboselevel)) ?\ + (void) 0 : @ac_google_namespace@::LogMessageVoidify() & LOG(INFO) + #define DLOG_IF(severity, condition) \ (true || !(condition)) ? (void) 0 : @ac_google_namespace@::LogMessageVoidify() & LOG(severity) @@ -908,9 +1020,11 @@ public: // saves 17 bytes per call site. LogMessage(const char* file, int line, LogSeverity severity); - // Constructor to also log this message to a specified sink (if not NULL). - // Implied are: ctr = 0, send_method = &LogMessage::SendToSinkAndLog. - LogMessage(const char* file, int line, LogSeverity severity, LogSink* sink); + // Constructor to log this message to a specified sink (if not NULL). + // Implied are: ctr = 0, send_method = &LogMessage::SendToSinkAndLog if + // also_send_to_log is true, send_method = &LogMessage::SendToSink otherwise. + LogMessage(const char* file, int line, LogSeverity severity, LogSink* sink, + bool also_send_to_log); // Constructor where we also give a vector<string> pointer // for storing the messages (if the pointer is not NULL). @@ -918,6 +1032,12 @@ public: LogMessage(const char* file, int line, LogSeverity severity, std::vector<std::string>* outvec); + // Constructor where we also give a string pointer for storing the + // message (if the pointer is not NULL). Implied are: ctr = 0, + // send_method = &LogMessage::WriteToStringAndLog. + LogMessage(const char* file, int line, LogSeverity severity, + std::string* message); + // A special constructor used for check failures LogMessage(const char* file, int line, const CheckOpString& result); @@ -940,7 +1060,7 @@ public: // Call abort() or similar to perform LOG(FATAL) crash. static void Fail() @ac_cv___attribute___noreturn@; - std::ostream& stream() { return data_->stream_; } + std::ostream& stream() { return *(data_->stream_); } int preserved_errno() const { return data_->preserved_errno_; } @@ -948,58 +1068,57 @@ public: static int64 num_messages(int severity); private: - // Fully internal SendMethod cases: void SendToSinkAndLog(); // Send to sink if provided and dispatch to the logs - void SaveOrSendToLog(); // Save to stringvec if provided, else to logs + void SendToSink(); // Send to sink if provided, do nothing otherwise. - struct LogMessageData; + // Write to string if provided and dispatch to the logs. + void WriteToStringAndLog(); + + void SaveOrSendToLog(); // Save to stringvec if provided, else to logs void Init(const char* file, int line, LogSeverity severity, void (LogMessage::*send_method)()); - LogMessageData* GetMessageData(int preserved_errno, LogSeverity, int ctr); - // Counts of messages sent at each priority: static int64 num_messages_[NUM_SEVERITIES]; // under log_mutex // We keep the data in a separate struct so that each instance of // LogMessage uses less stack space. struct GOOGLE_GLOG_DLL_DECL LogMessageData { - // ORDER DEPENDENCY: preserved_errno_ comes before buf_ comes before - // message_text_ comes before stream_ + LogMessageData() {}; + int preserved_errno_; // preserved errno char* buf_; char* message_text_; // Complete message text (points to selected buffer) - LogStream stream_; - const char severity_; // What level is this LogMessage logged at? + LogStream* stream_alloc_; + LogStream* stream_; + char severity_; // What level is this LogMessage logged at? int line_; // line number where logging call is. void (LogMessage::*send_method_)(); // Call this in destructor to send union { // At most one of these is used: union to keep the size low. - LogSink* sink_; // NULL or sink to send message to - std::vector<std::string>* outvec_; // NULL or vector to push message onto + LogSink* sink_; // NULL or sink to send message to + std::vector<std::string>* outvec_; // NULL or vector to push message onto + std::string* message_; // NULL or string to write message into }; - time_t timestamp_; // Time of creation of LogMessage - struct ::tm tm_time_; // Time of creation of LogMessage - size_t num_prefix_chars_; // How many chars of "prefix" for this message? - size_t num_chars_to_log_; // How many chars of msg to send to log? - size_t num_chars_to_syslog_; // How many chars of msg to send to syslog? - - const char* basename_; // basename of the file which called LOG. - const char* fullname_; // full name (including directory) - // of the file which called LOG. - - bool has_been_flushed_; // False if data has not yet been flushed. + time_t timestamp_; // Time of creation of LogMessage + struct ::tm tm_time_; // Time of creation of LogMessage + size_t num_prefix_chars_; // # of chars of prefix in this message + size_t num_chars_to_log_; // # of chars of msg to send to log + size_t num_chars_to_syslog_; // # of chars of msg to send to syslog + const char* basename_; // basename of file that called LOG + const char* fullname_; // fullname of file that called LOG + bool has_been_flushed_; // false => data has not been flushed + bool first_fatal_; // true => this was first fatal msg - LogMessageData(int preserved_errno, LogSeverity severity, int ctr); ~LogMessageData(); - private: LogMessageData(const LogMessageData&); void operator=(const LogMessageData&); }; - static LogMessageData fatal_message_data_; + static LogMessageData fatal_msg_data_exclusive_; + static LogMessageData fatal_msg_data_shared_; LogMessageData* allocated_; LogMessageData* data_; @@ -1022,10 +1141,16 @@ class GOOGLE_GLOG_DLL_DECL LogMessageFatal : public LogMessage { // A non-macro interface to the log facility; (useful // when the logging level is not a compile-time constant). -inline void LogAtLevel(int const log_level, std::string const &msg) { - LogMessage(__FILE__, __LINE__, log_level).stream() << msg; +inline void LogAtLevel(int const severity, std::string const &msg) { + LogMessage(__FILE__, __LINE__, severity).stream() << msg; } +// A macro alternative of LogAtLevel. New code may want to use this +// version since there are two advantages: 1. this version outputs the +// file name and the line number where this macro is put like other +// LOG macros, 2. this macro can be used as C++ stream. +#define LOG_AT_LEVEL(severity) LogMessage(__FILE__, __LINE__, severity).stream() + // A small helper for CHECK_NOTNULL(). template <typename T> T* CheckNotNull(const char *file, int line, const char *names, T* t) { @@ -1284,6 +1409,9 @@ class GOOGLE_GLOG_DLL_DECL NullStream : public LogMessage::LogStream { // NullStream& is implicitly converted to LogStream&, in which case // the overloaded NullStream::operator<< will not be invoked. NullStream() : LogMessage::LogStream(message_buffer_, 1, 0) { } + NullStream(const char* /*file*/, int /*line*/, + const CheckOpString& /*result*/) : + LogMessage::LogStream(message_buffer_, 1, 0) { } NullStream &stream() { return *this; } private: // A very short buffer for messages (which we discard anyway). This @@ -1305,6 +1433,9 @@ inline NullStream& operator<<(NullStream &str, const T &value) { return str; } // trace), like LogMessageFatal. class GOOGLE_GLOG_DLL_DECL NullStreamFatal : public NullStream { public: + NullStreamFatal() { } + NullStreamFatal(const char* file, int line, const CheckOpString& result) : + NullStream(file, line, result) { } @ac_cv___attribute___noreturn@ ~NullStreamFatal() { _exit(1); } }; diff --git a/src/glog/raw_logging.h.in b/src/glog/raw_logging.h.in index c7d92d9..c785c36 100644 --- a/src/glog/raw_logging.h.in +++ b/src/glog/raw_logging.h.in @@ -1,12 +1,12 @@ // Copyright 2006 Google Inc. All Rights Reserved. // Author: Maxim Lifantsev // -// Logging routines that do not allocate any memory and acquire any -// locks, and can therefore be used by low-level memory allocation -// and synchronization code. +// Thread-safe logging routines that do not allocate any memory or +// acquire any locks, and can therefore be used by low-level memory +// allocation and synchronization code. -#ifndef BASE_RAW_LOGGING_H__ -#define BASE_RAW_LOGGING_H__ +#ifndef BASE_RAW_LOGGING_H_ +#define BASE_RAW_LOGGING_H_ @ac_google_start_namespace@ @@ -38,26 +38,79 @@ // I0821 211317 file.cc:142] RAW: status is 20 #define RAW_LOG(severity, ...) \ do { \ - @ac_google_namespace@::RawLog__(@ac_google_namespace@::severity, __FILE__, __LINE__, __VA_ARGS__); \ + switch (@ac_google_namespace@::severity) { \ + case 0: \ + RAW_LOG_INFO(__VA_ARGS__); \ + break; \ + case 1: \ + RAW_LOG_WARNING(__VA_ARGS__); \ + break; \ + case 2: \ + RAW_LOG_ERROR(__VA_ARGS__); \ + break; \ + case 3: \ + RAW_LOG_FATAL(__VA_ARGS__); \ + break; \ + default: \ + break; \ + } \ } while (0) +// The following STRIP_LOG testing is performed in the header file so that it's +// possible to completely compile out the logging code and the log messages. +#if STRIP_LOG == 0 #define RAW_VLOG(verboselevel, ...) \ do { \ if (VLOG_IS_ON(verboselevel)) { \ - @ac_google_namespace@::RawLog__(@ac_google_namespace@::INFO, __FILE__, __LINE__, __VA_ARGS__); \ + RAW_LOG_INFO(__VA_ARGS__); \ } \ } while (0) +#else +#define RAW_VLOG(verboselevel, ...) RawLogStub__(0, __VA_ARGS__) +#endif // STRIP_LOG == 0 + +#if STRIP_LOG == 0 +#define RAW_LOG_INFO(...) @ac_google_namespace@::RawLog__(@ac_google_namespace@::INFO, \ + __FILE__, __LINE__, __VA_ARGS__) +#else +#define RAW_LOG_INFO(...) @ac_google_namespace@::RawLogStub__(0, __VA_ARGS__) +#endif // STRIP_LOG == 0 + +#if STRIP_LOG <= 1 +#define RAW_LOG_WARNING(...) @ac_google_namespace@::RawLog__(@ac_google_namespace@::WARNING, \ + __FILE__, __LINE__, __VA_ARGS__) +#else +#define RAW_LOG_WARNING(...) @ac_google_namespace@::RawLogStub__(0, __VA_ARGS__) +#endif // STRIP_LOG <= 1 + +#if STRIP_LOG <= 2 +#define RAW_LOG_ERROR(...) @ac_google_namespace@::RawLog__(@ac_google_namespace@::ERROR, \ + __FILE__, __LINE__, __VA_ARGS__) +#else +#define RAW_LOG_ERROR(...) @ac_google_namespace@::RawLogStub__(0, __VA_ARGS__) +#endif // STRIP_LOG <= 2 + +#if STRIP_LOG <= 3 +#define RAW_LOG_FATAL(...) @ac_google_namespace@::RawLog__(@ac_google_namespace@::FATAL, \ + __FILE__, __LINE__, __VA_ARGS__) +#else +#define RAW_LOG_FATAL(...) \ + do { \ + @ac_google_namespace@::RawLogStub__(0, __VA_ARGS__); \ + exit(1); \ + } while (0) +#endif // STRIP_LOG <= 3 // Similar to CHECK(condition) << message, // but for low-level modules: we use only RAW_LOG that does not allocate memory. // We do not want to provide args list here to encourage this usage: // if (!cond) RAW_LOG(FATAL, "foo ...", hard_to_compute_args); // so that the args are not computed when not needed. -#define RAW_CHECK(condition, message) \ - do { \ - if (!(condition)) { \ - RAW_LOG(FATAL, "Check %s failed: %s", #condition, message); \ - } \ +#define RAW_CHECK(condition, message) \ + do { \ + if (!(condition)) { \ + RAW_LOG(FATAL, "Check %s failed: %s", #condition, message); \ + } \ } while (0) // Debug versions of RAW_LOG and RAW_CHECK @@ -68,8 +121,8 @@ #else // NDEBUG -#define RAW_DLOG(severity, ...) \ - while (false) \ +#define RAW_DLOG(severity, ...) \ + while (false) \ RAW_LOG(severity, __VA_ARGS__) #define RAW_DCHECK(condition, message) \ while (false) \ @@ -77,6 +130,11 @@ #endif // NDEBUG +// Stub log function used to work around for unused variable warnings when +// building with STRIP_LOG > 0. +static inline void RawLogStub__(int ignored, ...) { +} + // Helper function to implement RAW_LOG and RAW_VLOG // Logs format... at "severity" level, reporting it // as called from file:line. @@ -91,8 +149,8 @@ GOOGLE_GLOG_DLL_DECL void RawLog__(LogSeverity severity, // this module does not have to directly call localtime_r(), // which could allocate memory. extern "C" struct ::tm; -GOOGLE_GLOG_DLL_DECL void RawLog__SetLastTime(const struct ::tm& t); +GOOGLE_GLOG_DLL_DECL void RawLog__SetLastTime(const struct ::tm& t, int usecs); @ac_google_end_namespace@ -#endif // BASE_RAW_LOGGING_H__ +#endif // BASE_RAW_LOGGING_H_ diff --git a/src/googletest.h b/src/googletest.h index 8b669f2..4a4475b 100644 --- a/src/googletest.h +++ b/src/googletest.h @@ -58,7 +58,7 @@ DEFINE_string(test_srcdir, TEST_SRC_DIR, #ifdef NDEBUG DEFINE_int32(benchmark_iters, 100000000, "Number of iterations per benchmark"); #else -DEFINE_int32(benchmark_iters, 1000000, "Number of iterations per benchmark"); +DEFINE_int32(benchmark_iters, 100000, "Number of iterations per benchmark"); #endif #ifdef HAVE_LIB_GTEST @@ -153,7 +153,7 @@ static int RUN_ALL_TESTS() { _END_GOOGLE_NAMESPACE_ -#endif +#endif // ! HAVE_LIB_GTEST _START_GOOGLE_NAMESPACE_ @@ -366,7 +366,6 @@ static string MungeLine(const string& line) { } if (!before.empty()) before += " "; iss >> time; - CHECK_EQ(6, time.size()); iss >> thread_lineinfo; CHECK(!thread_lineinfo.empty()); if (thread_lineinfo[thread_lineinfo.size() - 1] != ']') { diff --git a/src/logging.cc b/src/logging.cc index 2f34c4c..04580e5 100644 --- a/src/logging.cc +++ b/src/logging.cc @@ -33,10 +33,15 @@ #include "glog/raw_logging.h" #include "base/googleinit.h" +#ifdef HAVE_STACKTRACE +# include "stacktrace.h" +#endif + using std::string; using std::vector; using std::ostrstream; using std::setw; +using std::setfill; using std::hex; using std::dec; using std::min; @@ -44,10 +49,32 @@ using std::ostream; using std::ostringstream; using std::strstream; -DEFINE_bool(logtostderr, false, +// There is no thread annotation support. +#define EXCLUSIVE_LOCKS_REQUIRED(mu) + +static bool BoolFromEnv(const char *varname, bool defval) { + const char* const valstr = getenv(varname); + if (!valstr) { + return defval; + } + return memchr("tTyY1\0", valstr[0], 6) != NULL; +} + +DEFINE_bool(logtostderr, BoolFromEnv("GOOGLE_LOGTOSTDERR", false), "log messages go to stderr instead of logfiles"); -DEFINE_bool(alsologtostderr, false, +DEFINE_bool(alsologtostderr, BoolFromEnv("GOOGLE_ALSOLOGTOSTDERR", false), "log messages go to stderr in addition to logfiles"); +#ifdef OS_LINUX +DEFINE_bool(drop_log_memory, true, "Drop in-memory buffers of log contents. " + "Logs can grow very quickly and they are rarely read before they " + "need to be evicted from memory. Instead, drop them from memory " + "as soon as they are flushed to disk."); +_START_GOOGLE_NAMESPACE_ +namespace logging { +static const int64 kPageSize = getpagesize(); +} +_END_GOOGLE_NAMESPACE_ +#endif // By default, errors (including fatal errors) get logged to stderr as // well as the file. @@ -100,11 +127,15 @@ DEFINE_string(log_link, "", "Put additional links to the log " "files in this directory"); DEFINE_int32(max_log_size, 1800, - "approx. maximum log file size (in MB)"); + "approx. maximum log file size (in MB). A value of 0 will " + "be silently overridden to 1."); DEFINE_bool(stop_logging_if_full_disk, false, "Stop attempting to log to disk if the disk is full."); +DEFINE_string(log_backtrace_at, "", + "Emit a backtrace when logging at file:linenum."); + // TODO(hamaji): consider windows #define PATH_SEPARATOR '/' @@ -132,6 +163,11 @@ static void GetHostName(string* hostname) { _START_GOOGLE_NAMESPACE_ +// Safely get max_log_size, overriding to 1 if it somehow gets defined as 0 +static int32 MaxLogSize() { + return (FLAGS_max_log_size > 0 ? FLAGS_max_log_size : 1); +} + // A mutex that allows only one thread to log at a time, to keep things from // getting jumbled. Some other very uncommon logging operations (like // changing the destination file for log messages of a given severity) also @@ -149,6 +185,9 @@ const char*const LogSeverityNames[NUM_SEVERITIES] = { "INFO", "WARNING", "ERROR", "FATAL" }; +// Has the user called SetExitOnDFatal(true)? +static bool exit_on_dfatal = true; + const char* GetLogSeverityName(LogSeverity severity) { return LogSeverityNames[severity]; } @@ -307,8 +346,8 @@ class LogDestination { // Errors do not get logged to email by default. LogSeverity LogDestination::email_logging_severity_ = 99999; -string LogDestination::addresses_ = ""; -string LogDestination::hostname_ = ""; +string LogDestination::addresses_; +string LogDestination::hostname_; vector<LogSink*>* LogDestination::sinks_ = NULL; Mutex LogDestination::sink_mutex_; @@ -521,8 +560,10 @@ inline void LogDestination::WaitForSinks(LogMessage::LogMessageData* data) { (*sinks_)[i]->WaitTillSent(); } } - if (data->send_method_ == &LogMessage::SendToSinkAndLog && - data->sink_ != NULL) { + const bool send_to_sink = + (data->send_method_ == &LogMessage::SendToSink) || + (data->send_method_ == &LogMessage::SendToSinkAndLog); + if (send_to_sink && data->sink_ != NULL) { data->sink_->WaitTillSent(); } } @@ -675,8 +716,8 @@ void LogFileObject::Write(bool force_flush, return; } - if (static_cast<int>(file_length_ >> 20) >= FLAGS_max_log_size) { - fclose(file_); + if (static_cast<int>(file_length_ >> 20) >= MaxLogSize()) { + if (file_ != NULL) fclose(file_); file_ = NULL; file_length_ = bytes_since_flush_ = 0; rollover_attempt_ = kRolloverAttemptFrequency-1; @@ -778,6 +819,8 @@ void LogFileObject::Write(bool force_flush, << setw(2) << tm_time.tm_sec << '\n' << "Running on machine: " << LogDestination::hostname() << '\n' + << "Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu " + << "threadid file:line] msg" << '\n' << '\0'; int header_len = strlen(file_header_string); fwrite(file_header_string, 1, header_len, file_); @@ -814,153 +857,168 @@ void LogFileObject::Write(bool force_flush, (bytes_since_flush_ >= 1000000) || (CycleClock_Now() >= next_flush_time_) ) { FlushUnlocked(); +#ifdef OS_LINUX + if (FLAGS_drop_log_memory) { + if (file_length_ >= logging::kPageSize) { + // don't evict the most recent page + uint32 len = file_length_ & ~(logging::kPageSize - 1); + posix_fadvise(fileno(file_), 0, len, POSIX_FADV_DONTNEED); + } + } +#endif } } } // namespace -// -// LogMessage's constructor starts each message with a string like: -// I1018 160715 logging.cc:1153] -// (1st letter of severity level, GMT month, date, & time; -// thread id (if not 0x400); basename of file and line of the logging command) -// We ignore thread id 0x400 because it seems to be the default for single- -// threaded programs. - // An arbitrary limit on the length of a single log message. This // is so that streaming can be done more efficiently. const size_t LogMessage::kMaxLogMessageLen = 30000; -// Need to reserve some space for FATAL messages because -// we usually do LOG(FATAL) when we ran out of heap memory. -// However, since LogMessage() also calls new[], in this case, -// it will recusively call LOG(FATAL), which then call new[] ... etc. -// Eventually, the program will run out of stack memory and no message -// will get logged. Note that we will not be protecting this buffer -// with a lock because the chances are very small that there will -// be a contention during LOG(FATAL) which can only happen at most -// once per program. -static char fatal_message_buffer[LogMessage::kMaxLogMessageLen+1]; - -// Similarly we reserve space for a LogMessageData struct to be used -// for FATAL messages. -LogMessage::LogMessageData LogMessage::fatal_message_data_(0, FATAL, 0); - -LogMessage::LogMessageData::LogMessageData(int preserved_errno, - LogSeverity severity, - int ctr) : - // ORDER DEPENDENCY: buf_ comes before message_text_ comes before stream_ - preserved_errno_(preserved_errno), - // Use static buffer for LOG(FATAL) - buf_((severity != FATAL) ? new char[kMaxLogMessageLen+1] : NULL), - message_text_((severity != FATAL) ? buf_ : fatal_message_buffer), - stream_(message_text_, kMaxLogMessageLen, ctr), - severity_(severity) { -} +// Static log data space to avoid alloc failures in a LOG(FATAL) +// +// Since multiple threads may call LOG(FATAL), and we want to preserve +// the data from the first call, we allocate two sets of space. One +// for exclusive use by the first thread, and one for shared use by +// all other threads. +static Mutex fatal_msg_lock; +static CrashReason crash_reason; +static bool fatal_msg_exclusive = true; +static char fatal_msg_buf_exclusive[LogMessage::kMaxLogMessageLen+1]; +static char fatal_msg_buf_shared[LogMessage::kMaxLogMessageLen+1]; +static LogMessage::LogStream fatal_msg_stream_exclusive( + fatal_msg_buf_exclusive, LogMessage::kMaxLogMessageLen, 0); +static LogMessage::LogStream fatal_msg_stream_shared( + fatal_msg_buf_shared, LogMessage::kMaxLogMessageLen, 0); +LogMessage::LogMessageData LogMessage::fatal_msg_data_exclusive_; +LogMessage::LogMessageData LogMessage::fatal_msg_data_shared_; LogMessage::LogMessageData::~LogMessageData() { delete[] buf_; -} - -LogMessage::LogMessageData* LogMessage::GetMessageData(int preserved_errno, - LogSeverity severity, - int ctr) { - if (severity != FATAL) { - return allocated_; - } else { - fatal_message_data_.preserved_errno_ = preserved_errno; - fatal_message_data_.stream_.set_ctr(ctr); - return &fatal_message_data_; - } + delete stream_alloc_; } LogMessage::LogMessage(const char* file, int line, LogSeverity severity, - int ctr, void (LogMessage::*send_method)()) : - allocated_((severity != FATAL) ? - new LogMessageData(errno, severity, ctr) : NULL), - data_(GetMessageData(errno, severity, ctr)) { + int ctr, void (LogMessage::*send_method)()) { Init(file, line, severity, send_method); + data_->stream_->set_ctr(ctr); } -LogMessage::LogMessage(const char* file, int line, const CheckOpString& result) - : allocated_(NULL), - data_(GetMessageData(errno, FATAL, 0)) { +LogMessage::LogMessage(const char* file, int line, + const CheckOpString& result) { Init(file, line, FATAL, &LogMessage::SendToLog); stream() << "Check failed: " << (*result.str_) << " "; } -LogMessage::LogMessage(const char* file, int line) : - allocated_(new LogMessageData(errno, INFO, 0)), - data_(GetMessageData(errno, INFO, 0)) { +LogMessage::LogMessage(const char* file, int line) { Init(file, line, INFO, &LogMessage::SendToLog); } -LogMessage::LogMessage(const char* file, int line, LogSeverity severity) : - allocated_((severity != FATAL) ? - new LogMessageData(errno, severity, 0) : NULL), - data_(GetMessageData(errno, severity, 0)) { +LogMessage::LogMessage(const char* file, int line, LogSeverity severity) { Init(file, line, severity, &LogMessage::SendToLog); } LogMessage::LogMessage(const char* file, int line, LogSeverity severity, - LogSink* sink) : - allocated_((severity != FATAL) ? - new LogMessageData(errno, severity, 0) : NULL), - data_(GetMessageData(errno, severity, 0)) { - Init(file, line, severity, &LogMessage::SendToSinkAndLog); + LogSink* sink, bool also_send_to_log) { + Init(file, line, severity, also_send_to_log ? &LogMessage::SendToSinkAndLog : + &LogMessage::SendToSink); data_->sink_ = sink; // override Init()'s setting to NULL } LogMessage::LogMessage(const char* file, int line, LogSeverity severity, - vector<string> *outvec) : - allocated_((severity != FATAL) ? - new LogMessageData(errno, severity, 0) : NULL), - data_(GetMessageData(errno, severity, 0)) { + vector<string> *outvec) { Init(file, line, severity, &LogMessage::SaveOrSendToLog); data_->outvec_ = outvec; // override Init()'s setting to NULL } -void LogMessage::Init(const char* file, int line, LogSeverity severity, +LogMessage::LogMessage(const char* file, int line, LogSeverity severity, + string *message) { + Init(file, line, severity, &LogMessage::WriteToStringAndLog); + data_->message_ = message; // override Init()'s setting to NULL +} + +void LogMessage::Init(const char* file, + int line, + LogSeverity severity, void (LogMessage::*send_method)()) { + allocated_ = NULL; + if (severity != FATAL || !exit_on_dfatal) { + allocated_ = new LogMessageData(); + data_ = allocated_; + data_->buf_ = new char[kMaxLogMessageLen+1]; + data_->message_text_ = data_->buf_; + data_->stream_alloc_ = + new LogStream(data_->message_text_, kMaxLogMessageLen, 0); + data_->stream_ = data_->stream_alloc_; + data_->first_fatal_ = false; + } else { + MutexLock l(&fatal_msg_lock); + if (fatal_msg_exclusive) { + fatal_msg_exclusive = false; + data_ = &fatal_msg_data_exclusive_; + data_->message_text_ = fatal_msg_buf_exclusive; + data_->stream_ = &fatal_msg_stream_exclusive; + data_->first_fatal_ = true; + } else { + data_ = &fatal_msg_data_shared_; + data_->message_text_ = fatal_msg_buf_shared; + data_->stream_ = &fatal_msg_stream_shared; + data_->first_fatal_ = false; + } + data_->stream_alloc_ = NULL; + } + + stream().fill('0'); + data_->preserved_errno_ = errno; + data_->severity_ = severity; data_->line_ = line; data_->send_method_ = send_method; - - data_->outvec_ = NULL; data_->sink_ = NULL; - data_->timestamp_ = time(NULL); + data_->outvec_ = NULL; + WallTime now = WallTime_Now(); + data_->timestamp_ = static_cast<time_t>(now); localtime_r(&data_->timestamp_, &data_->tm_time_); - RawLog__SetLastTime(data_->tm_time_); + int usecs = static_cast<int>((now - data_->timestamp_) * 1000000); + RawLog__SetLastTime(data_->tm_time_, usecs); + + data_->num_chars_to_log_ = 0; + data_->num_chars_to_syslog_ = 0; data_->basename_ = const_basename(file); data_->fullname_ = file; - data_->stream_.fill('0'); + data_->has_been_flushed_ = false; - // In some cases, we use logging like a print mechanism and - // the prefixes get in the way + // If specified, prepend a prefix to each line. For example: + // I1018 160715 f5d4fbb0 logging.cc:1153] + // (log level, GMT month, date, time, thread_id, file basename, line) + // We exclude the thread_id for the default thread. if (FLAGS_log_prefix && (line != kNoLogPrefix)) { - if ( is_default_thread() ) { - stream() << LogSeverityNames[severity][0] - << setw(2) << 1+data_->tm_time_.tm_mon - << setw(2) << data_->tm_time_.tm_mday - << ' ' - << setw(2) << data_->tm_time_.tm_hour - << setw(2) << data_->tm_time_.tm_min - << setw(2) << data_->tm_time_.tm_sec - << ' ' << data_->basename_ << ':' << data_->line_ << "] "; - } else { - stream() << LogSeverityNames[severity][0] - << setw(2) << 1+data_->tm_time_.tm_mon - << setw(2) << data_->tm_time_.tm_mday - << ' ' - << setw(2) << data_->tm_time_.tm_hour - << setw(2) << data_->tm_time_.tm_min - << setw(2) << data_->tm_time_.tm_sec - << ' ' << setw(8) << std::hex << pthread_self() << std::dec - << ' ' << data_->basename_ << ':' << data_->line_ << "] "; + stream() << LogSeverityNames[severity][0] + << setw(2) << 1+data_->tm_time_.tm_mon + << setw(2) << data_->tm_time_.tm_mday + << ' ' + << setw(2) << data_->tm_time_.tm_hour << ':' + << setw(2) << data_->tm_time_.tm_min << ':' + << setw(2) << data_->tm_time_.tm_sec << "." + << setw(6) << usecs + << ' ' + << setfill(' ') << setw(5) + << static_cast<unsigned int>(GetTID()) << setfill('0') + << ' ' + << data_->basename_ << ':' << data_->line_ << "] "; + } + data_->num_prefix_chars_ = data_->stream_->pcount(); + + if (!FLAGS_log_backtrace_at.empty()) { + char fileline[128]; + snprintf(fileline, sizeof(fileline), "%s:%d", data_->basename_, line); +#ifdef HAVE_STACKTRACE + if (!strcmp(FLAGS_log_backtrace_at.c_str(), fileline)) { + string stacktrace; + DumpStackTraceToString(&stacktrace); + stream() << " (stacktrace:\n" << stacktrace << ") "; } +#endif } - - data_->num_prefix_chars_ = data_->stream_.pcount(); - data_->has_been_flushed_ = false; } LogMessage::~LogMessage() { @@ -974,13 +1032,13 @@ void LogMessage::Flush() { if (data_->has_been_flushed_ || data_->severity_ < FLAGS_minloglevel) return; - data_->num_chars_to_log_ = data_->stream_.pcount(); + data_->num_chars_to_log_ = data_->stream_->pcount(); data_->num_chars_to_syslog_ = data_->num_chars_to_log_ - data_->num_prefix_chars_; // Do we need to add a \n to the end of this message? bool append_newline = - (data_->message_text_[data_->num_chars_to_log_-1] != '\n'); + (data_->message_text_[data_->num_chars_to_log_-1] != '\n'); char original_final_char = '\0'; // If we do need to add a \n, we'll do it by violating the memory of the @@ -1022,13 +1080,9 @@ void LogMessage::Flush() { data_->has_been_flushed_ = true; } -// Copy of FATAL log message so that we can print it out again after -// all the stack traces. -// We cannot simply use fatal_message_buffer, because two or more FATAL log -// messages may happen in a row. This is a real possibility given that -// FATAL log messages are often associated with corrupted process state. -// In this case, we still want to reprint the first FATAL log message, so -// we need to save away the first message in a separate buffer. +// Copy of first FATAL log message so that we can print it out again +// after all the stack traces. To preserve legacy behavior, we don't +// use fatal_msg_buf_exclusive. static time_t fatal_time; static char fatal_message[256]; @@ -1044,7 +1098,7 @@ void ReprintFatalMessage() { } // L >= log_mutex (callers must hold the log_mutex). -void LogMessage::SendToLog() { +void LogMessage::SendToLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { static bool already_warned_before_initgoogle = false; log_mutex.AssertHeld(); @@ -1097,13 +1151,28 @@ void LogMessage::SendToLog() { // If we log a FATAL message, flush all the log destinations, then toss // a signal for others to catch. We leave the logs in a state that // someone else can use them (as long as they flush afterwards) - if (data_->severity_ == FATAL) { - // save away the fatal message so we can print it again later - const int copy = min<int>(data_->num_chars_to_log_, - sizeof(fatal_message)-1); - memcpy(fatal_message, data_->message_text_, copy); - fatal_message[copy] = '\0'; - fatal_time = data_->timestamp_; + if (data_->severity_ == FATAL && exit_on_dfatal) { + if (data_->first_fatal_) { + crash_reason.filename = fatal_msg_data_exclusive_.fullname_; + crash_reason.line_number = fatal_msg_data_exclusive_.line_; + crash_reason.message = fatal_msg_buf_exclusive + + fatal_msg_data_exclusive_.num_prefix_chars_; +#ifdef HAVE_STACKTRACE + crash_reason.depth = GetStackTrace(crash_reason.stack, + ARRAYSIZE(crash_reason.stack), + 3); +#else + crash_reason.depth = 0; +#endif + SetCrashReason(&crash_reason); + + // Store shortened fatal message for other logs and GWQ status + const int copy = min<int>(data_->num_chars_to_log_, + sizeof(fatal_message)-1); + memcpy(fatal_message, data_->message_text_, copy); + fatal_message[copy] = '\0'; + fatal_time = data_->timestamp_; + } if (!FLAGS_logtostderr) { for (int i = 0; i < NUM_SEVERITIES; ++i) { @@ -1111,7 +1180,7 @@ void LogMessage::SendToLog() { LogDestination::log_destinations_[i]->logger_->Write(true, 0, "", 0); } } - + // release the lock that our caller (directly or indirectly) // LogMessage::~LogMessage() grabbed so that signal handlers // can use the logging facility. Alternately, we could add @@ -1120,6 +1189,8 @@ void LogMessage::SendToLog() { log_mutex.Unlock(); LogDestination::WaitForSinks(data_); + const char* message = "*** Check failure stack trace: ***\n"; + write(STDERR_FILENO, message, strlen(message)); Fail(); } } @@ -1150,7 +1221,7 @@ void LogMessage::Fail() { } // L >= log_mutex (callers must hold the log_mutex). -void LogMessage::SendToSinkAndLog() { +void LogMessage::SendToSink() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { if (data_->sink_ != NULL) { RAW_DCHECK(data_->num_chars_to_log_ > 0 && data_->message_text_[data_->num_chars_to_log_-1] == '\n', ""); @@ -1160,11 +1231,16 @@ void LogMessage::SendToSinkAndLog() { (data_->num_chars_to_log_ - data_->num_prefix_chars_ - 1)); } +} + +// L >= log_mutex (callers must hold the log_mutex). +void LogMessage::SendToSinkAndLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { + SendToSink(); SendToLog(); } // L >= log_mutex (callers must hold the log_mutex). -void LogMessage::SaveOrSendToLog() { +void LogMessage::SaveOrSendToLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { if (data_->outvec_ != NULL) { RAW_DCHECK(data_->num_chars_to_log_ > 0 && data_->message_text_[data_->num_chars_to_log_-1] == '\n', ""); @@ -1177,6 +1253,18 @@ void LogMessage::SaveOrSendToLog() { } } +void LogMessage::WriteToStringAndLog() EXCLUSIVE_LOCKS_REQUIRED(log_mutex) { + if (data_->message_ != NULL) { + RAW_DCHECK(data_->num_chars_to_log_ > 0 && + data_->message_text_[data_->num_chars_to_log_-1] == '\n', ""); + // Omit prefix of message and trailing newline when writing to message_. + const char *start = data_->message_text_ + data_->num_prefix_chars_; + int len = data_->num_chars_to_log_ - data_->num_prefix_chars_ - 1; + data_->message_->assign(start, len); + } + SendToLog(); +} + // L >= log_mutex (callers must hold the log_mutex). void LogMessage::SendToSyslogAndLog() { #ifdef HAVE_SYSLOG_H @@ -1267,26 +1355,24 @@ string LogSink::ToString(LogSeverity severity, const char* file, int line, ostringstream stream(string(message, message_len)); stream.fill('0'); - if ( is_default_thread() ) { - stream << LogSeverityNames[severity][0] - << setw(2) << 1+tm_time->tm_mon - << setw(2) << tm_time->tm_mday - << ' ' - << setw(2) << tm_time->tm_hour - << setw(2) << tm_time->tm_min - << setw(2) << tm_time->tm_sec - << ' ' << file << ':' << line << "] "; - } else { - stream << LogSeverityNames[severity][0] - << setw(2) << 1+tm_time->tm_mon - << setw(2) << tm_time->tm_mday - << ' ' - << setw(2) << tm_time->tm_hour - << setw(2) << tm_time->tm_min - << setw(2) << tm_time->tm_sec - << ' ' << setw(8) << std::hex << pthread_self() << std::dec - << ' ' << file << ':' << line << "] "; - } + // FIXME(jrvb): Updating this to use the correct value for usecs + // requires changing the signature for both this method and + // LogSink::send(). This change needs to be done in a separate CL + // so subclasses of LogSink can be updated at the same time. + int usecs = 0; + + stream << LogSeverityNames[severity][0] + << setw(2) << 1+tm_time->tm_mon + << setw(2) << tm_time->tm_mday + << ' ' + << setw(2) << tm_time->tm_hour << ':' + << setw(2) << tm_time->tm_min << ':' + << setw(2) << tm_time->tm_sec << '.' + << setw(6) << usecs + << ' ' + << setfill(' ') << setw(5) << GetTID() << setfill('0') + << ' ' + << file << ':' << line << "] "; stream << string(message, message_len); return stream.str(); @@ -1316,6 +1402,32 @@ void LogToStderr() { LogDestination::LogToStderr(); } +namespace base { +namespace internal { + +bool GetExitOnDFatal() { + MutexLock l(&log_mutex); + return exit_on_dfatal; +} + +// Determines whether we exit the program for a LOG(DFATAL) message in +// debug mode. It does this by skipping the call to Fail/FailQuietly. +// This is intended for testing only. +// +// This can have some effects on LOG(FATAL) as well. Failure messages +// are always allocated (rather than sharing a buffer), the crash +// reason is not recorded, the "gwq" status message is not updated, +// and the stack trace is not recorded. The LOG(FATAL) *will* still +// exit the program. Since this function is used only in testing, +// these differences are acceptable. +void SetExitOnDFatal(bool value) { + MutexLock l(&log_mutex); + exit_on_dfatal = value; +} + +} // namespace internal +} // namespace base + // use_logging controls whether the logging functions LOG/VLOG are used // to log errors. It should be set to false when the caller holds the // log_mutex. @@ -1330,8 +1442,8 @@ static bool SendEmailInternal(const char*dest, const char *subject, subject, body, dest); } - string cmd(FLAGS_logmailer); - cmd = cmd + " -s\"" + string(subject) + "\" " + string(dest); + string cmd = + FLAGS_logmailer + " -s\"" + subject + "\" " + dest; FILE* pipe = popen(cmd.c_str(), "w"); if (pipe != NULL) { // Add the body if we have one @@ -1489,10 +1601,10 @@ void TruncateLogFile(const char *path, int64 limit, int64 keep) { } return; } - + if (fstat(fd, &statbuf) == -1) { - PLOG(ERROR) << "Unable to fstat()"; - goto out_close_fd; + PLOG(ERROR) << "Unable to fstat()"; + goto out_close_fd; } // See if the path refers to a regular file bigger than the @@ -1503,9 +1615,9 @@ void TruncateLogFile(const char *path, int64 limit, int64 keep) { // This log file is too large - we need to truncate it LOG(INFO) << "Truncating " << path << " to " << keep << " bytes"; - + // Copy the last "keep" bytes of the file to the beginning of the file - read_offset = statbuf.st_size - keep; + read_offset = statbuf.st_size - keep; write_offset = 0; int bytesin, bytesout; while ((bytesin = pread(fd, copybuf, sizeof(copybuf), read_offset)) > 0) { @@ -1520,7 +1632,7 @@ void TruncateLogFile(const char *path, int64 limit, int64 keep) { write_offset += bytesout; } if (bytesin == -1) PLOG(ERROR) << "Unable to read from " << path; - + // Truncate the remainder of the file. If someone else writes to the // end of the file after our last read() above, we lose their latest // data. Too bad ... @@ -1537,7 +1649,7 @@ void TruncateLogFile(const char *path, int64 limit, int64 keep) { void TruncateStdoutStderr() { #ifdef HAVE_UNISTD_H - int64 limit = FLAGS_max_log_size << 20; + int64 limit = MaxLogSize() << 20; int64 keep = 1 << 20; TruncateLogFile("/proc/self/fd/1", limit, keep); TruncateLogFile("/proc/self/fd/2", limit, keep); diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index 2687a72..14c9789 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -28,15 +28,42 @@ #include "glog/raw_logging.h" #include "googletest.h" +DECLARE_string(log_backtrace_at); // logging.cc + +#ifdef HAVE_LIB_GMOCK +#include <gmock/gmock.h> +#include "mock-log.h" +// Introduce several symbols from gmock. +using testing::_; +using testing::AnyNumber; +using testing::HasSubstr; +using testing::AllOf; +using testing::StrNe; +using testing::StrictMock; +using testing::InitGoogleMock; +using GOOGLE_NAMESPACE::glog_testing::ScopedMockLog; +#endif + using namespace std; using namespace GOOGLE_NAMESPACE; +// Some non-advertised functions that we want to test or use. +_START_GOOGLE_NAMESPACE_ +namespace base { +namespace internal { +bool GetExitOnDFatal(); +void SetExitOnDFatal(bool value); +} // namespace internal +} // namespace base +_END_GOOGLE_NAMESPACE_ + static void TestLogging(bool check_counts); static void TestRawLogging(); static void LogWithLevels(int v, int severity, bool err, bool alsoerr); static void TestLoggingLevels(); static void TestLogString(); static void TestLogSink(); +static void TestLogToString(); static void TestLogSinkWaitTillSent(); static void TestCHECK(); static void TestDCHECK(); @@ -98,6 +125,20 @@ BENCHMARK(BM_Check2); static void CheckFailure(int a, int b, const char* file, int line, const char* msg) { } +static void BM_logspeed(int n) { + while (n-- > 0) { + LOG(INFO) << "test message"; + } +} +BENCHMARK(BM_logspeed); + +static void BM_vlog(int n) { + while (n-- > 0) { + VLOG(1) << "test message"; + } +} +BENCHMARK(BM_vlog); + int main(int argc, char **argv) { // Test some basics before InitGoogleLogging: CaptureTestStderr(); @@ -106,13 +147,16 @@ int main(int argc, char **argv) { LogWithLevels(0, 0, 0, 0); // simulate "before global c-tors" const string early_stderr = GetCapturedTestStderr(); - FLAGS_logtostderr = true; - InitGoogleLogging(argv[0]); RunSpecifiedBenchmarks(); + FLAGS_logtostderr = true; + InitGoogleTest(&argc, argv); +#ifdef HAVE_LIB_GTEST + InitGoogleMock(&argc, argv); +#endif // so that death tests run before we use threads CHECK_EQ(RUN_ALL_TESTS(), 0); @@ -127,6 +171,7 @@ int main(int argc, char **argv) { TestLoggingLevels(); TestLogString(); TestLogSink(); + TestLogToString(); TestLogSinkWaitTillSent(); TestCHECK(); TestDCHECK(); @@ -145,7 +190,7 @@ int main(int argc, char **argv) { TestErrno(); TestTruncate(); - LOG(INFO) << "PASS"; + fprintf(stdout, "PASS\n"); return 0; } @@ -368,6 +413,22 @@ void TestLogString() { } } +void TestLogToString() { + string error; + string* no_error = NULL; + + LOG_TO_STRING(INFO, &error) << "LOG_TO_STRING: " << "collected info"; + LOG(INFO) << "Captured by LOG_TO_STRING: " << error; + LOG_TO_STRING(WARNING, &error) << "LOG_TO_STRING: " << "collected warning"; + LOG(INFO) << "Captured by LOG_TO_STRING: " << error; + LOG_TO_STRING(ERROR, &error) << "LOG_TO_STRING: " << "collected error"; + LOG(INFO) << "Captured by LOG_TO_STRING: " << error; + + LOG_TO_STRING(INFO, no_error) << "LOG_TO_STRING: " << "reported info"; + LOG_TO_STRING(WARNING, no_error) << "LOG_TO_STRING: " << "reported warning"; + LOG_TO_STRING(ERROR, NULL) << "LOG_TO_STRING: " << "reported error"; +} + class TestLogSinkImpl : public LogSink { public: vector<string> errors; @@ -392,6 +453,20 @@ void TestLogSink() { LOG_TO_SINK(no_sink, WARNING) << "LOG_TO_SINK: " << "reported warning"; LOG_TO_SINK(NULL, ERROR) << "LOG_TO_SINK: " << "reported error"; + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, INFO) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected info"; + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, WARNING) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected warning"; + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(&sink, ERROR) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "collected error"; + + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(no_sink, INFO) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed info"; + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(no_sink, WARNING) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed warning"; + LOG_TO_SINK_BUT_NOT_TO_LOGFILE(NULL, ERROR) + << "LOG_TO_SINK_BUT_NOT_TO_LOGFILE: " << "thrashed error"; + LOG(INFO) << "Captured by LOG_TO_SINK:"; for (size_t i = 0; i < sink.errors.size(); ++i) { LogMessage("foo", LogMessage::kNoLogPrefix, INFO).stream() @@ -948,6 +1023,127 @@ void MyCheck(bool a, bool b) { CHECK_EQ(a, b); } +#ifdef HAVE_LIB_GMOCK + +TEST(DVLog, Basic) { + ScopedMockLog log; + +#if NDEBUG + // We are expecting that nothing is logged. + EXPECT_CALL(log, Log(_, _, _)).Times(0); +#else + EXPECT_CALL(log, Log(INFO, __FILE__, "debug log")); +#endif + + FLAGS_v = 1; + DVLOG(1) << "debug log"; +} + +TEST(DVLog, V0) { + ScopedMockLog log; + + // We are expecting that nothing is logged. + EXPECT_CALL(log, Log(_, _, _)).Times(0); + + FLAGS_v = 0; + DVLOG(1) << "debug log"; +} + +TEST(LogAtLevel, Basic) { + ScopedMockLog log; + + // The function version outputs "logging.h" as a file name. + EXPECT_CALL(log, Log(WARNING, StrNe(__FILE__), "function version")); + EXPECT_CALL(log, Log(INFO, __FILE__, "macro version")); + + int severity = WARNING; + LogAtLevel(severity, "function version"); + + severity = INFO; + // We can use the macro version as a C++ stream. + LOG_AT_LEVEL(severity) << "macro" << ' ' << "version"; +} + +TEST(TestExitOnDFatal, ToBeOrNotToBe) { + // Check the default setting... + EXPECT_TRUE(base::internal::GetExitOnDFatal()); + + // Turn off... + base::internal::SetExitOnDFatal(false); + EXPECT_FALSE(base::internal::GetExitOnDFatal()); + + // We don't die. + { + ScopedMockLog log; + //EXPECT_CALL(log, Log(_, _, _)).Times(AnyNumber()); + // LOG(DFATAL) has severity FATAL if debugging, but is + // downgraded to ERROR if not debugging. + const LogSeverity severity = +#ifdef NDEBUG + ERROR; +#else + FATAL; +#endif + EXPECT_CALL(log, Log(severity, __FILE__, "This should not be fatal")); + LOG(DFATAL) << "This should not be fatal"; + } + + // Turn back on... + base::internal::SetExitOnDFatal(true); + EXPECT_TRUE(base::internal::GetExitOnDFatal()); + + // Death comes on little cats' feet. + EXPECT_DEBUG_DEATH({ + LOG(DFATAL) << "This should be fatal in debug mode"; + }, "This should be fatal in debug mode"); +} + +#ifdef HAVE_STACKTRACE + +static void BacktraceAtHelper() { + LOG(INFO) << "Not me"; + +// The vertical spacing of the next 3 lines is significant. + LOG(INFO) << "Backtrace me"; +} +static int kBacktraceAtLine = __LINE__ - 2; // The line of the LOG(INFO) above + +TEST(LogBacktraceAt, DoesNotBacktraceWhenDisabled) { + StrictMock<ScopedMockLog> log; + + FLAGS_log_backtrace_at = ""; + + EXPECT_CALL(log, Log(_, _, "Backtrace me")); + EXPECT_CALL(log, Log(_, _, "Not me")); + + BacktraceAtHelper(); +} + +TEST(LogBacktraceAt, DoesBacktraceAtRightLineWhenEnabled) { + StrictMock<ScopedMockLog> log; + + char where[100]; + snprintf(where, 100, "%s:%d", const_basename(__FILE__), kBacktraceAtLine); + FLAGS_log_backtrace_at = where; + + // The LOG at the specified line should include a stacktrace which includes + // the name of the containing function, followed by the log message. + // We use HasSubstr()s instead of ContainsRegex() for environments + // which don't have regexp. + EXPECT_CALL(log, Log(_, _, AllOf(HasSubstr("stacktrace:"), + HasSubstr("BacktraceAtHelper"), + HasSubstr("main"), + HasSubstr("Backtrace me")))); + // Other LOGs should not include a backtrace. + EXPECT_CALL(log, Log(_, _, "Not me")); + + BacktraceAtHelper(); +} + +#endif // HAVE_STACKTRACE + +#endif // HAVE_LIB_GMOCK + struct UserDefinedClass { bool operator==(const UserDefinedClass& rhs) const { return true; } }; diff --git a/src/logging_unittest.err b/src/logging_unittest.err index 7bf7066..4f80bf5 100644 --- a/src/logging_unittest.err +++ b/src/logging_unittest.err @@ -1,293 +1,305 @@ -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=2 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=2 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error WARNING: Logging before InitGoogleLogging() is written to STDERR -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=0 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] foo bar 10 3.4 -EDATE TIME__ logging_unittest.cc:LINE] Plog every 2, iteration 1: __SUCCESS__ [0] -EDATE TIME__ logging_unittest.cc:LINE] Log every 3, iteration 1 -EDATE TIME__ logging_unittest.cc:LINE] Log every 4, iteration 1 -WDATE TIME__ logging_unittest.cc:LINE] Log if every 5, iteration 1 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 1 -EDATE TIME__ logging_unittest.cc:LINE] Log if less than 3 every 2, iteration 1 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 2 -EDATE TIME__ logging_unittest.cc:LINE] Plog every 2, iteration 3: __ENOENT__ [2] -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 3 -EDATE TIME__ logging_unittest.cc:LINE] Log if less than 3 every 2, iteration 3 -EDATE TIME__ logging_unittest.cc:LINE] Log every 3, iteration 4 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 4 -EDATE TIME__ logging_unittest.cc:LINE] Plog every 2, iteration 5: __EINTR__ [4] -EDATE TIME__ logging_unittest.cc:LINE] Log every 4, iteration 5 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 5 -WDATE TIME__ logging_unittest.cc:LINE] Log if every 5, iteration 6 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 6 -EDATE TIME__ logging_unittest.cc:LINE] Plog every 2, iteration 7: __ENXIO__ [6] -EDATE TIME__ logging_unittest.cc:LINE] Log every 3, iteration 7 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 7 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 8 -EDATE TIME__ logging_unittest.cc:LINE] Plog every 2, iteration 9: __ENOEXEC__ [8] -EDATE TIME__ logging_unittest.cc:LINE] Log every 4, iteration 9 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 9 -EDATE TIME__ logging_unittest.cc:LINE] Log every 3, iteration 10 -IDATE TIME__ logging_unittest.cc:LINE] Log if every 1, iteration 10 -WDATE TIME__ logging_unittest.cc:LINE] log_if this -IDATE TIME__ logging_unittest.cc:LINE] array -IDATE TIME__ logging_unittest.cc:LINE] const array -EDATE TIME__ logging_unittest.cc:LINE] foo 1000 0000001000 3e8 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=0 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] foo bar 10 3.4 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Plog every 2, iteration 1: __SUCCESS__ [0] +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 3, iteration 1 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 4, iteration 1 +WDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 5, iteration 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 1 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log if less than 3 every 2, iteration 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 2 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Plog every 2, iteration 3: __ENOENT__ [2] +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 3 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log if less than 3 every 2, iteration 3 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 3, iteration 4 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 4 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Plog every 2, iteration 5: __EINTR__ [4] +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 4, iteration 5 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 5 +WDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 5, iteration 6 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 6 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Plog every 2, iteration 7: __ENXIO__ [6] +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 3, iteration 7 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 7 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 8 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Plog every 2, iteration 9: __ENOEXEC__ [8] +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 4, iteration 9 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 9 +EDATE TIME__ THREADID logging_unittest.cc:LINE] Log every 3, iteration 10 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Log if every 1, iteration 10 +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if this +IDATE TIME__ THREADID logging_unittest.cc:LINE] array +IDATE TIME__ THREADID logging_unittest.cc:LINE] const array +EDATE TIME__ THREADID logging_unittest.cc:LINE] foo 1000 0000001000 3e8 no prefix -IDATE TIME__ logging_unittest.cc:LINE] RAW: foo bar 10 3.400000 -WDATE TIME__ logging_unittest.cc:LINE] RAW: array -IDATE TIME__ logging_unittest.cc:LINE] RAW: const array -IDATE TIME__ logging_unittest.cc:LINE] RAW: ptr 0x12345678 -IDATE TIME__ logging_unittest.cc:LINE] RAW: ptr __NULLP__ -EDATE TIME__ logging_unittest.cc:LINE] RAW: foo 1000 0000001000 3e8 -IDATE TIME__ logging_unittest.cc:LINE] RAW: foo 1000 -IDATE TIME__ logging_unittest.cc:LINE] RAW: foo 1000 -WDATE TIME__ logging_unittest.cc:LINE] RAW: RAW_LOG ERROR: The Message was too long! -IDATE TIME__ logging_unittest.cc:LINE] RAW: RAW_LOG ERROR: The Message was too long! -IDATE TIME__ logging_unittest.cc:LINE] RAW: log -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 on -IDATE TIME__ logging_unittest.cc:LINE] RAW: log -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 1 on -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 2 on -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=0 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=0 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] vlog 1 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 1 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=-1 stderrthreshold=0 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=1 logtostderr=0 alsologtostderr=0 -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=2 logtostderr=0 alsologtostderr=0 -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -EDATE TIME__ logging_unittest.cc:LINE] log error -EDATE TIME__ logging_unittest.cc:LINE] log_if error -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=0 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=1 alsologtostderr=0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=0 alsologtostderr=1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=1 logtostderr=0 alsologtostderr=0 -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=3 logtostderr=0 alsologtostderr=1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] RAW: vlog 1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: log info -WDATE TIME__ logging_unittest.cc:LINE] RAW: log warning -EDATE TIME__ logging_unittest.cc:LINE] RAW: log error -IDATE TIME__ logging_unittest.cc:LINE] vlog -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog 0 -IDATE TIME__ logging_unittest.cc:LINE] vlog 1 -IDATE TIME__ logging_unittest.cc:LINE] log info -WDATE TIME__ logging_unittest.cc:LINE] log warning -EDATE TIME__ logging_unittest.cc:LINE] log error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if -1 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 1 -IDATE TIME__ logging_unittest.cc:LINE] log_if info -WDATE TIME__ logging_unittest.cc:LINE] log_if warning -EDATE TIME__ logging_unittest.cc:LINE] log_if error -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error expr -IDATE TIME__ logging_unittest.cc:LINE] log_if info every 1 expr -EDATE TIME__ logging_unittest.cc:LINE] log_if error every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] vlog_if 0 every 1 expr -IDATE TIME__ logging_unittest.cc:LINE] LOG_STRING: reported info -WDATE TIME__ logging_unittest.cc:LINE] LOG_STRING: reported warning -EDATE TIME__ logging_unittest.cc:LINE] LOG_STRING: reported error -IDATE TIME__ logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected info -IDATE TIME__ logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected warning -IDATE TIME__ logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected error -IDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected info -WDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected warning -EDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected error -IDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: reported info -WDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: reported warning -EDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: reported error -IDATE TIME__ logging_unittest.cc:LINE] Captured by LOG_TO_SINK: -IDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected info -WDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected warning -EDATE TIME__ logging_unittest.cc:LINE] LOG_TO_SINK: collected error -IDATE TIME__ logging_unittest.cc:LINE] Message 1 -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffering -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffered -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waiting +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo bar 10 3.400000 +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: array +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: const array +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: ptr 0x12345678 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: ptr __NULLP__ +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo 1000 0000001000 3e8 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo 1000 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: foo 1000 +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: RAW_LOG ERROR: The Message was too long! +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: RAW_LOG ERROR: The Message was too long! +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 on +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 1 on +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 2 on +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=0 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=0 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=-1 stderrthreshold=0 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=1 logtostderr=0 alsologtostderr=0 +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=2 logtostderr=0 alsologtostderr=0 +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=0 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=1 alsologtostderr=0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=0 stderrthreshold=3 logtostderr=0 alsologtostderr=1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=1 logtostderr=0 alsologtostderr=0 +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Test: v=1 stderrthreshold=3 logtostderr=0 alsologtostderr=1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: vlog 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if -1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info +WDATE TIME__ THREADID logging_unittest.cc:LINE] log_if warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] log_if info every 1 expr +EDATE TIME__ THREADID logging_unittest.cc:LINE] log_if error every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] vlog_if 0 every 1 expr +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_STRING: reported info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_STRING: reported warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_STRING: reported error +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected info +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected warning +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_STRING: LOG_STRING: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: reported info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: reported warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: reported error +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_TO_SINK: +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK_BUT_NOT_TO_LOGFILE: collected info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK_BUT_NOT_TO_LOGFILE: collected warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_SINK_BUT_NOT_TO_LOGFILE: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: collected info +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_TO_STRING: LOG_TO_STRING: collected info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: collected warning +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_TO_STRING: LOG_TO_STRING: collected warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] Captured by LOG_TO_STRING: LOG_TO_STRING: collected error +IDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: reported info +WDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: reported warning +EDATE TIME__ THREADID logging_unittest.cc:LINE] LOG_TO_STRING: reported error +IDATE TIME__ THREADID logging_unittest.cc:LINE] Message 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffering +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffered +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waiting IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Sink got a messages -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waited -IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: IDATE TIME__ logging_unittest.cc:LINE] Message 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waited +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: IDATE TIME__ THREADID logging_unittest.cc:LINE] Message 1 IDATE TIME__ THREADID logging_unittest.cc:LINE] Have 0 left -EDATE TIME__ logging_unittest.cc:LINE] Message 2 -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffering -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffered -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waiting +EDATE TIME__ THREADID logging_unittest.cc:LINE] Message 2 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffering +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffered +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waiting IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Sink got a messages -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waited -IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: EDATE TIME__ logging_unittest.cc:LINE] Message 2 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waited +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: EDATE TIME__ THREADID logging_unittest.cc:LINE] Message 2 IDATE TIME__ THREADID logging_unittest.cc:LINE] Have 0 left -WDATE TIME__ logging_unittest.cc:LINE] Message 3 -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffering -IDATE TIME__ logging_unittest.cc:LINE] RAW: Buffered -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waiting +WDATE TIME__ THREADID logging_unittest.cc:LINE] Message 3 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffering +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Buffered +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waiting IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Sink got a messages -IDATE TIME__ logging_unittest.cc:LINE] RAW: Waited -IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: WDATE TIME__ logging_unittest.cc:LINE] Message 3 +IDATE TIME__ THREADID logging_unittest.cc:LINE] RAW: Waited +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink is sending out a message: WDATE TIME__ THREADID logging_unittest.cc:LINE] Message 3 IDATE TIME__ THREADID logging_unittest.cc:LINE] Have 0 left -IDATE TIME__ logging_unittest.cc:LINE] Sink capture: IDATE TIME__ logging_unittest.cc:LINE] Message 1 -IDATE TIME__ logging_unittest.cc:LINE] Sink capture: EDATE TIME__ logging_unittest.cc:LINE] Message 2 -IDATE TIME__ logging_unittest.cc:LINE] Sink capture: WDATE TIME__ logging_unittest.cc:LINE] Message 3 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink capture: IDATE TIME__ THREADID logging_unittest.cc:LINE] Message 1 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink capture: EDATE TIME__ THREADID logging_unittest.cc:LINE] Message 2 +IDATE TIME__ THREADID logging_unittest.cc:LINE] Sink capture: WDATE TIME__ THREADID logging_unittest.cc:LINE] Message 3 diff --git a/src/raw_logging.cc b/src/raw_logging.cc index 70aa807..7678bee 100644 --- a/src/raw_logging.cc +++ b/src/raw_logging.cc @@ -7,10 +7,20 @@ #include <stdarg.h> #include <stdio.h> +#include <errno.h> +#ifdef HAVE_UNISTD_H +# include <unistd.h> // for close() and write() +#endif +#include <fcntl.h> // for open() #include <time.h> #include "config.h" #include "glog/logging.h" // To pick up flag settings etc. #include "glog/raw_logging.h" +#include "base/commandlineflags.h" + +#ifdef HAVE_STACKTRACE +# include "stacktrace.h" +#endif #if defined(HAVE_SYSCALL_H) #include <syscall.h> // for syscall() @@ -21,15 +31,24 @@ # include <unistd.h> #endif +#if defined(HAVE_SYSCALL_H) || defined(HAVE_SYS_SYSCALL_H) +# define safe_write(fd, s, len) syscall(SYS_write, fd, s, len) +#else + // Not so safe, but what can you do? +# define safe_write(fd, s, len) write(fd, s, len) +#endif + _START_GOOGLE_NAMESPACE_ // Data for RawLog__ below. We simply pick up the latest // time data created by a normal log message to avoid calling // localtime_r which can allocate memory. static struct ::tm last_tm_time_for_raw_log; +static int last_usecs_for_raw_log; -void RawLog__SetLastTime(const struct ::tm& t) { +void RawLog__SetLastTime(const struct ::tm& t, int usecs) { memcpy(&last_tm_time_for_raw_log, &t, sizeof(last_tm_time_for_raw_log)); + last_usecs_for_raw_log = usecs; } // CAVEAT: vsnprintf called from *DoRawLog below has some (exotic) code paths @@ -61,6 +80,11 @@ inline static bool VADoRawLog(char** buf, int* size, return true; } +static const int kLogBufSize = 3000; +static bool crashed = false; +static CrashReason crash_reason; +static char crash_buf[kLogBufSize + 1] = { 0 }; // Will end in '\0' + void RawLog__(LogSeverity severity, const char* file, int line, const char* format, ...) { if (!(FLAGS_logtostderr || severity >= FLAGS_stderrthreshold || @@ -69,21 +93,22 @@ void RawLog__(LogSeverity severity, const char* file, int line, } // can't call localtime_r here: it can allocate struct ::tm& t = last_tm_time_for_raw_log; - char buffer[3000]; // 3000 bytes should be enough for everyone... :-) + char buffer[kLogBufSize]; char* buf = buffer; int size = sizeof(buffer); - if (is_default_thread()) { - DoRawLog(&buf, &size, "%c%02d%02d %02d%02d%02d %s:%d] RAW: ", - LogSeverityNames[severity][0], - 1 + t.tm_mon, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, - const_basename(const_cast<char *>(file)), line); - } else { - DoRawLog(&buf, &size, "%c%02d%02d %02d%02d%02d %08x %s:%d] RAW: ", - LogSeverityNames[severity][0], - 1 + t.tm_mon, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, - int(pthread_self()), - const_basename(const_cast<char *>(file)), line); - } + + // NOTE: this format should match the specification in base/logging.h + DoRawLog(&buf, &size, "%c%02d%02d %02d:%02d:%02d.%06d %5u %s:%d] RAW: ", + LogSeverityNames[severity][0], + 1 + t.tm_mon, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, + last_usecs_for_raw_log, + static_cast<unsigned int>(GetTID()), + const_basename(const_cast<char *>(file)), line); + + // Record the position and size of the buffer after the prefix + const char* msg_start = buf; + const int msg_size = size; + va_list ap; va_start(ap, format); bool no_chop = VADoRawLog(&buf, &size, format, ap); @@ -97,12 +122,23 @@ void RawLog__(LogSeverity severity, const char* file, int line, // avoiding FILE buffering (to avoid invoking malloc()), and bypassing // libc (to side-step any libc interception). // We write just once to avoid races with other invocations of RawLog__. -#if defined(HAVE_SYSCALL_H) || defined(HAVE_SYS_SYSCALL_H) - syscall(SYS_write, STDERR_FILENO, buffer, strlen(buffer)); + safe_write(STDERR_FILENO, buffer, strlen(buffer)); + if (severity == FATAL) { + if (!sync_val_compare_and_swap(&crashed, false, true)) { + crash_reason.filename = file; + crash_reason.line_number = line; + memcpy(crash_buf, msg_start, msg_size); // Don't include prefix + crash_reason.message = crash_buf; +#ifdef HAVE_STACKTRACE + crash_reason.depth = + GetStackTrace(crash_reason.stack, ARRAYSIZE(crash_reason.stack), 1); #else - write(STDERR_FILENO, buffer, strlen(buffer)); + crash_reason.depth = 0; #endif - if (severity == FATAL) LogMessage::Fail(); + SetCrashReason(&crash_reason); + } + LogMessage::Fail(); // abort() + } } _END_GOOGLE_NAMESPACE_ diff --git a/src/utilities.cc b/src/utilities.cc index 711d743..6477065 100644 --- a/src/utilities.cc +++ b/src/utilities.cc @@ -8,6 +8,11 @@ # include <sys/time.h> #endif #include <time.h> +#if defined(HAVE_SYSCALL_H) +#include <syscall.h> // for syscall() +#elif defined(HAVE_SYS_SYSCALL_H) +#include <sys/syscall.h> // for syscall() +#endif #include "base/googleinit.h" #include "stacktrace.h" @@ -41,6 +46,10 @@ static void DebugWriteToStderr(const char* data, void *unused) { write(STDERR_FILENO, data, strlen(data)); } +void DebugWriteToString(const char* data, void *arg) { + reinterpret_cast<string*>(arg)->append(data); +} + // Print a program counter and its symbol name. static void DumpPCAndSymbol(DebugWriter *writerfn, void *arg, void *pc, const char * const prefix) { @@ -146,7 +155,6 @@ int64 CycleClock_Now() { return (static_cast<int64>(now.wSecond) * 1000000 + static_cast<int64>(now.wMilliseconds) * 1000); #else - // TODO(hamaji): temporary impementation - it might be too slow. struct timeval tv; gettimeofday(&tv, NULL); return static_cast<int64>(tv.tv_sec) * 1000000 + tv.tv_usec; @@ -157,11 +165,53 @@ int64 UsecToCycles(int64 usec) { return usec; } +WallTime WallTime_Now() { + // Now, cycle clock is retuning microseconds since the epoch. + return CycleClock_Now() * 0.000001; +} + static int32 g_main_thread_pid = getpid(); int32 GetMainThreadPid() { return g_main_thread_pid; } +pid_t GetTID() { + // On Linux and FreeBSD, we try to use gettid(). +#if defined OS_LINUX || defined OS_FREEBSD || defined OS_MACOSX +#ifndef __NR_gettid +#ifdef OS_MACOSX +#define __NR_gettid SYS_gettid +#elif ! defined __i386__ +#error "Must define __NR_gettid for non-x86 platforms" +#else +#define __NR_gettid 224 +#endif +#endif + static bool lacks_gettid = false; + if (!lacks_gettid) { + pid_t tid = syscall(__NR_gettid); + if (tid != -1) { + return tid; + } + // Technically, this variable has to be volatile, but there is a small + // performance penalty in accessing volatile variables and there should + // not be any serious adverse effect if a thread does not immediately see + // the value change to "true". + lacks_gettid = true; + } +#endif // OS_LINUX || OS_FREEBSD + + // If gettid() could not be used, we use one of the following. +#if defined OS_LINUX + return getpid(); // Linux: getpid returns thread ID when gettid is absent +#elif defined OS_WINDOWS || defined OS_CYGWIN + return GetCurrentThreadId(); +#else + // If none of the techniques above worked, we use pthread_self(). + return (pid_t)pthread_self(); +#endif +} + const char* const_basename(const char* filepath) { const char* base = strrchr(filepath, '/'); #ifdef OS_WINDOWS // Look for either path separator in Windows @@ -186,6 +236,22 @@ static void MyUserNameInitializer() { } REGISTER_MODULE_INITIALIZER(utilities, MyUserNameInitializer()); +#ifdef HAVE_STACKTRACE +void DumpStackTraceToString(string* stacktrace) { + DumpStackTrace(1, DebugWriteToString, stacktrace); +} +#endif + +// We use an atomic operation to prevent problems with calling CrashReason +// from inside the Mutex implementation (potentially through RAW_CHECK). +static const CrashReason* g_reason = 0; + +void SetCrashReason(const CrashReason* r) { + sync_val_compare_and_swap(&g_reason, + reinterpret_cast<const CrashReason*>(0), + r); +} + } // namespace glog_internal_namespace_ void InitGoogleLogging(const char* argv0) { diff --git a/src/utilities.h b/src/utilities.h index 700a6a9..dc8c208 100644 --- a/src/utilities.h +++ b/src/utilities.h @@ -40,7 +40,7 @@ #include <string> -#ifdef OS_WINDOWS +#if defined(OS_WINDOWS) && !defined(__CYGWIN__) # include "port.h" #endif @@ -74,7 +74,7 @@ # define STACKTRACE_H "stacktrace_x86-inl.h" # elif defined(__x86_64__) && __GNUC__ >= 2 # define STACKTRACE_H "stacktrace_x86_64-inl.h" -# elif ((__ppc__) || defined(__PPC__)) && __GNUC__ >= 2 +# elif (defined(__ppc__) || defined(__PPC__)) && __GNUC__ >= 2 # define STACKTRACE_H "stacktrace_powerpc-inl.h" # endif #endif @@ -95,8 +95,10 @@ # define HAVE_SYMBOLIZE #endif -// There is a better way, but this is good enough in this file. -#define ARRAYSIZE(a) (sizeof(a) / sizeof(*(a))) +#ifndef ARRAYSIZE +// There is a better way, but this is good enough for our purpose. +# define ARRAYSIZE(a) (sizeof(a) / sizeof(*(a))) +#endif _START_GOOGLE_NAMESPACE_ @@ -119,8 +121,13 @@ int64 CycleClock_Now(); int64 UsecToCycles(int64 usec); +typedef double WallTime; +WallTime WallTime_Now(); + int32 GetMainThreadPid(); +pid_t GetTID(); + const std::string& MyUserName(); // Get the part of filepath after the last path separator. @@ -155,6 +162,23 @@ inline T sync_val_compare_and_swap(T* ptr, T oldval, T newval) { #endif } +void DumpStackTraceToString(std::string* stacktrace); + +struct CrashReason { + CrashReason() : filename(0), line_number(0), message(0), depth(0) {} + + const char* filename; + int line_number; + const char* message; + + // We'll also store a bit of context at the time of crash as it may not be + // available later on. + void* stack[32]; + int depth; +}; + +void SetCrashReason(const CrashReason* r); + } // namespace glog_internal_namespace_ _END_GOOGLE_NAMESPACE_ |