* Add LOG_TO_STRING.
author <shinichiro.hamaji@gmail.com> <>
Thu, 15 Jan 2009 10:34:35 +0000 (10:34 +0000)
committer <shinichiro.hamaji@gmail.com> <>
Thu, 15 Jan 2009 10:34:35 +0000 (10:34 +0000)
* 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

src/glog/logging.h.in
src/glog/raw_logging.h.in
src/googletest.h
src/logging.cc
src/logging_unittest.cc
src/logging_unittest.err
src/raw_logging.cc
src/utilities.cc
src/utilities.h

index 0949432..8f6389e 100644 (file)
@@ -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); }
 };
 
index c7d92d9..c785c36 100644 (file)
@@ -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@
 
 //   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
 
 #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) \
 
 #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_
index 8b669f2..4a4475b 100644 (file)
@@ -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] != ']') {
index 2f34c4c..04580e5 100644 (file)
 #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);
index 2687a72..14c9789 100644 (file)
 #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; }
 };
index 7bf7066..4f80bf5 100644 (file)
-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
index 70aa807..7678bee 100644 (file)
@@ -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()
 # 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_
index 711d743..6477065 100644 (file)
@@ -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) {
index 700a6a9..dc8c208 100644 (file)
@@ -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
 # 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_