diff options
author | siggi@chromium.org <siggi@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2010-11-04 15:50:49 +0000 |
---|---|---|
committer | siggi@chromium.org <siggi@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2010-11-04 15:50:49 +0000 |
commit | 162ac0f02a2a7a6f1909a85a222ab5da3d280d12 (patch) | |
tree | ccc49648b2197f598acaeafa4d4f58c0c0048bdd | |
parent | ce833284bfd1b0a5db62e0f3c25f48af70ae8784 (diff) | |
download | chromium_src-162ac0f02a2a7a6f1909a85a222ab5da3d280d12.zip chromium_src-162ac0f02a2a7a6f1909a85a222ab5da3d280d12.tar.gz chromium_src-162ac0f02a2a7a6f1909a85a222ab5da3d280d12.tar.bz2 |
Integrate ETW with VLOG logging.
This change extends the log severities into the negative for VLOG verbosities.
It also keeps track of file/line information and passes it to any registered log handler.
The log level is naturally controlled by translating ETW log levels to the severities.
BUG=none
TEST=none
Review URL: http://codereview.chromium.org/4164011
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@65062 0039d316-1c4b-4281-b951-d872f2087c98
-rw-r--r-- | base/logging.cc | 32 | ||||
-rw-r--r-- | base/logging.h | 32 | ||||
-rw-r--r-- | base/logging_win.cc | 102 | ||||
-rw-r--r-- | base/logging_win.h | 14 | ||||
-rw-r--r-- | base/vlog.cc | 29 | ||||
-rw-r--r-- | base/vlog.h | 14 | ||||
-rw-r--r-- | base/vlog_unittest.cc | 19 | ||||
-rw-r--r-- | ceee/testing/utils/test_utils.cc | 5 | ||||
-rw-r--r-- | ceee/testing/utils/test_utils.h | 3 | ||||
-rw-r--r-- | chrome/browser/safe_browsing/safe_browsing_database_unittest.cc | 3 | ||||
-rw-r--r-- | chrome/common/logging_chrome.cc | 5 |
11 files changed, 175 insertions, 83 deletions
diff --git a/base/logging.cc b/base/logging.cc index 1ca00fb..2658519 100644 --- a/base/logging.cc +++ b/base/logging.cc @@ -351,7 +351,8 @@ bool BaseInitLoggingImpl(const PathChar* new_log_file, command_line->HasSwitch(switches::kVModule)) { g_vlog_info = new VlogInfo(command_line->GetSwitchValueASCII(switches::kV), - command_line->GetSwitchValueASCII(switches::kVModule)); + command_line->GetSwitchValueASCII(switches::kVModule), + &min_log_level); } LoggingLock::Init(lock_log, new_log_file); @@ -389,11 +390,15 @@ int GetMinLogLevel() { return min_log_level; } +int GetVlogVerbosity() { + return std::max(-1, LOG_INFO - GetMinLogLevel()); +} + int GetVlogLevelHelper(const char* file, size_t N) { DCHECK_GT(N, 0U); return g_vlog_info ? g_vlog_info->GetVlogLevel(base::StringPiece(file, N - 1)) : - VlogInfo::kDefaultVlogLevel; + GetVlogVerbosity(); } void SetLogItems(bool enable_process_id, bool enable_thread_id, @@ -508,30 +513,30 @@ LogMessage::SaveLastError::~SaveLastError() { LogMessage::LogMessage(const char* file, int line, LogSeverity severity, int ctr) - : severity_(severity) { + : severity_(severity), file_(file), line_(line) { Init(file, line); } LogMessage::LogMessage(const char* file, int line, const CheckOpString& result) - : severity_(LOG_FATAL) { + : severity_(LOG_FATAL), file_(file), line_(line) { Init(file, line); stream_ << "Check failed: " << (*result.str_); } LogMessage::LogMessage(const char* file, int line, LogSeverity severity, const CheckOpString& result) - : severity_(severity) { + : severity_(severity), file_(file), line_(line) { Init(file, line); stream_ << "Check failed: " << (*result.str_); } LogMessage::LogMessage(const char* file, int line) - : severity_(LOG_INFO) { + : severity_(LOG_INFO), file_(file), line_(line) { Init(file, line); } LogMessage::LogMessage(const char* file, int line, LogSeverity severity) - : severity_(severity) { + : severity_(severity), file_(file), line_(line) { Init(file, line); } @@ -569,8 +574,12 @@ void LogMessage::Init(const char* file, int line) { } if (log_tickcount) stream_ << TickCount() << ':'; - stream_ << log_severity_names[severity_] << ":" << filename << - "(" << line << ")] "; + if (severity_ >= 0) + stream_ << log_severity_names[severity_]; + else + stream_ << "VERBOSE" << -severity_; + + stream_ << ":" << file << "(" << line << ")] "; message_start_ = stream_.tellp(); } @@ -594,8 +603,11 @@ LogMessage::~LogMessage() { std::string str_newline(stream_.str()); // Give any log message handler first dibs on the message. - if (log_message_handler && log_message_handler(severity_, str_newline)) + if (log_message_handler && log_message_handler(severity_, file_, line_, + message_start_, str_newline)) { + // The handler took care of it, no further processing. return; + } if (logging_destination == LOG_ONLY_TO_SYSTEM_DEBUG_LOG || logging_destination == LOG_TO_BOTH_FILE_AND_SYSTEM_DEBUG_LOG) { diff --git a/base/logging.h b/base/logging.h index 7315ea5..6689eec 100644 --- a/base/logging.h +++ b/base/logging.h @@ -209,13 +209,18 @@ inline bool InitLogging(const PathChar* log_file, // Sets the log level. Anything at or above this level will be written to the // log file/displayed to the user (if applicable). Anything below this level -// will be silently ignored. The log level defaults to 0 (everything is logged) -// if this function is not called. +// will be silently ignored. The log level defaults to 0 (everything is logged +// up to level INFO) if this function is not called. +// Note that log messages for VLOG(x) are logged at level -x, so setting +// the min log level to negative values enables verbose logging. void SetMinLogLevel(int level); // Gets the current log level. int GetMinLogLevel(); +// Gets the VLOG default verbosity level. +int GetVlogVerbosity(); + // Gets the current vlog level for the given file (usually taken from // __FILE__). @@ -257,11 +262,15 @@ void SetLogReportHandler(LogReportHandlerFunction handler); // it's sent to other log destinations (if any). // Returns true to signal that it handled the message and the message // should not be sent to other log destinations. -typedef bool (*LogMessageHandlerFunction)(int severity, const std::string& str); +typedef bool (*LogMessageHandlerFunction)(int severity, + const char* file, int line, size_t message_start, const std::string& str); void SetLogMessageHandler(LogMessageHandlerFunction handler); LogMessageHandlerFunction GetLogMessageHandler(); typedef int LogSeverity; +const LogSeverity LOG_VERBOSE = -1; // This is level 1 verbosity +// Note: the log severities are used to index into the array of names, +// see log_severity_names. const LogSeverity LOG_INFO = 0; const LogSeverity LOG_WARNING = 1; const LogSeverity LOG_ERROR = 2; @@ -354,9 +363,16 @@ const LogSeverity LOG_0 = LOG_ERROR; #define SYSLOG(severity) LOG(severity) #define SYSLOG_IF(severity, condition) LOG_IF(severity, condition) -#define VLOG(verboselevel) LOG_IF(INFO, VLOG_IS_ON(verboselevel)) -#define VLOG_IF(verboselevel, condition) \ - LOG_IF(INFO, VLOG_IS_ON(verboselevel) && (condition)) +// The VLOG macros log with negative verbosities. +#define VLOG_STREAM(verbose_level) \ + logging::LogMessage(__FILE__, __LINE__, -verbose_level).stream() + +#define VLOG(verbose_level) \ + LAZY_STREAM(VLOG_STREAM(verbose_level), VLOG_IS_ON(verbose_level)) + +#define VLOG_IF(verbose_level, condition) \ + LAZY_STREAM(VLOG_STREAM(verbose_level), \ + VLOG_IS_ON(verbose_level) && (condition)) // TODO(akalin): Add more VLOG variants, e.g. VPLOG. @@ -718,6 +734,10 @@ class LogMessage { std::ostringstream stream_; size_t message_start_; // Offset of the start of the message (past prefix // info). + // The file and line information passed in to the constructor. + const char* file_; + const int line_; + #if defined(OS_WIN) // Stores the current value of GetLastError in the constructor and restores // it in the destructor by calling SetLastError. diff --git a/base/logging_win.cc b/base/logging_win.cc index f17cf34..588e4d9 100644 --- a/base/logging_win.cc +++ b/base/logging_win.cc @@ -22,25 +22,31 @@ DEFINE_GUID(kLogEventId, LogEventProvider::LogEventProvider() : old_log_level_(LOG_NONE) { } -bool LogEventProvider::LogMessage(int severity, const std::string& message) { +bool LogEventProvider::LogMessage(logging::LogSeverity severity, + const char* file, int line, size_t message_start, + const std::string& message) { EtwEventLevel level = TRACE_LEVEL_NONE; // Convert the log severity to the most appropriate ETW trace level. - switch (severity) { - case LOG_INFO: - level = TRACE_LEVEL_INFORMATION; - break; - case LOG_WARNING: - level = TRACE_LEVEL_WARNING; - break; - case LOG_ERROR: - case LOG_ERROR_REPORT: - level = TRACE_LEVEL_ERROR; - break; - case LOG_FATAL: - level = TRACE_LEVEL_FATAL; - break; - }; + if (severity >= 0) { + switch (severity) { + case LOG_INFO: + level = TRACE_LEVEL_INFORMATION; + break; + case LOG_WARNING: + level = TRACE_LEVEL_WARNING; + break; + case LOG_ERROR: + case LOG_ERROR_REPORT: + level = TRACE_LEVEL_ERROR; + break; + case LOG_FATAL: + level = TRACE_LEVEL_FATAL; + break; + } + } else { // severity < 0 is VLOG verbosity levels. + level = TRACE_LEVEL_INFORMATION - severity; + } // Bail if we're not logging, not at that level, // or if we're post-atexit handling. @@ -48,27 +54,43 @@ bool LogEventProvider::LogMessage(int severity, const std::string& message) { if (provider == NULL || level > provider->enable_level()) return false; - // And now log the event, with stack trace if one is - // requested per our enable flags. - if (provider->enable_flags() & ENABLE_STACK_TRACE_CAPTURE) { + // And now log the event. + if (provider->enable_flags() & ENABLE_LOG_MESSAGE_ONLY) { + EtwMofEvent<1> event(kLogEventId, LOG_MESSAGE, level); + event.SetField(0, message.length() + 1 - message_start, + message.c_str() + message_start); + + provider->Log(event.get()); + } else { const size_t kMaxBacktraceDepth = 32; void* backtrace[kMaxBacktraceDepth]; - DWORD depth = CaptureStackBackTrace(2, kMaxBacktraceDepth, backtrace, NULL); - EtwMofEvent<3> event(kLogEventId, LOG_MESSAGE_WITH_STACKTRACE, level); + DWORD depth = 0; + // Capture a stack trace if one is requested. + // requested per our enable flags. + if (provider->enable_flags() & ENABLE_STACK_TRACE_CAPTURE) + depth = CaptureStackBackTrace(2, kMaxBacktraceDepth, backtrace, NULL); + + EtwMofEvent<5> event(kLogEventId, LOG_MESSAGE_FULL, level); + if (file == NULL) + file = ""; + + // Add the stack trace. event.SetField(0, sizeof(depth), &depth); event.SetField(1, sizeof(backtrace[0]) * depth, &backtrace); - event.SetField(2, message.length() + 1, message.c_str()); + // The line. + event.SetField(2, sizeof(line), &line); + // The file. + event.SetField(3, strlen(file) + 1, file); + // And finally the message. + event.SetField(4, message.length() + 1 - message_start, + message.c_str() + message_start); provider->Log(event.get()); - } else { - EtwMofEvent<1> event(kLogEventId, LOG_MESSAGE, level); - event.SetField(0, message.length() + 1, message.c_str()); - provider->Log(event.get()); } // Don't increase verbosity in other log destinations. - if (severity >= provider->old_log_level_) + if (severity < provider->old_log_level_) return true; return false; @@ -95,21 +117,17 @@ void LogEventProvider::OnEventsEnabled() { // Convert the new trace level to a logging severity // and enable logging at that level. EtwEventLevel level = enable_level(); - switch (level) { - case TRACE_LEVEL_NONE: - case TRACE_LEVEL_FATAL: - SetMinLogLevel(LOG_FATAL); - break; - case TRACE_LEVEL_ERROR: - SetMinLogLevel(LOG_ERROR); - break; - case TRACE_LEVEL_WARNING: - SetMinLogLevel(LOG_WARNING); - break; - case TRACE_LEVEL_INFORMATION: - case TRACE_LEVEL_VERBOSE: - SetMinLogLevel(LOG_INFO); - break; + if (level == TRACE_LEVEL_NONE || level == TRACE_LEVEL_FATAL) { + SetMinLogLevel(LOG_FATAL); + } else if (level == TRACE_LEVEL_ERROR) { + SetMinLogLevel(LOG_ERROR); + } else if (level == TRACE_LEVEL_WARNING) { + SetMinLogLevel(LOG_WARNING); + } else if (level == TRACE_LEVEL_INFORMATION) { + SetMinLogLevel(LOG_INFO); + } else if (level >= TRACE_LEVEL_VERBOSE) { + // Above INFO, we enable verbose levels with negative severities. + SetMinLogLevel(TRACE_LEVEL_INFORMATION - level); } } diff --git a/base/logging_win.h b/base/logging_win.h index f2e6e5a..74f0da0 100644 --- a/base/logging_win.h +++ b/base/logging_win.h @@ -21,6 +21,10 @@ enum LogEnableMask { // If this bit is set in our provider enable mask, we will include // a stack trace with every log message. ENABLE_STACK_TRACE_CAPTURE = 0x0001, + // If this bit is set in our provider enable mask, the provider will log + // a LOG message with only the textual content of the message, and no + // stack trace. + ENABLE_LOG_MESSAGE_ONLY = 0x0002, }; // The message types our log event provider generates. @@ -31,6 +35,12 @@ enum LogMessageTypes { // A message with a stack trace, followed by the zero-terminated // message text. LOG_MESSAGE_WITH_STACKTRACE = 11, + // A message with: + // a stack trace, + // the line number as a four byte integer, + // the file as a zero terminated UTF8 string, + // the zero-terminated UTF8 message text. + LOG_MESSAGE_FULL = 12, }; // Trace provider class to drive log control and transport @@ -39,7 +49,9 @@ class LogEventProvider : public EtwTraceProvider { public: LogEventProvider(); - static bool LogMessage(int severity, const std::string& message); + static bool LogMessage(logging::LogSeverity severity, const char* file, + int line, size_t message_start, const std::string& str); + static void Initialize(const GUID& provider_name); static void Uninitialize(); diff --git a/base/vlog.cc b/base/vlog.cc index 8c615cb..cda9cea 100644 --- a/base/vlog.cc +++ b/base/vlog.cc @@ -29,14 +29,20 @@ VlogInfo::VmodulePattern::VmodulePattern() match_target(MATCH_MODULE) {} VlogInfo::VlogInfo(const std::string& v_switch, - const std::string& vmodule_switch) - : max_vlog_level_(kDefaultVlogLevel) { + const std::string& vmodule_switch, + int* min_log_level) + : min_log_level_(min_log_level) { + DCHECK(min_log_level != NULL); + typedef std::pair<std::string, std::string> KVPair; - if (!v_switch.empty() && - !base::StringToInt(v_switch, &max_vlog_level_)) { + int vlog_level = 0; + if (base::StringToInt(v_switch, &vlog_level)) { + SetMaxVlogLevel(vlog_level); + } else { LOG(WARNING) << "Parsed v switch \"" - << v_switch << "\" as " << max_vlog_level_; + << v_switch << "\" as " << vlog_level; } + std::vector<KVPair> kv_pairs; if (!base::SplitStringIntoKeyValuePairs( vmodule_switch, '=', ',', &kv_pairs)) { @@ -57,6 +63,15 @@ VlogInfo::VlogInfo(const std::string& v_switch, VlogInfo::~VlogInfo() {} +void VlogInfo::SetMaxVlogLevel(int level) { + // Log severity is the negative verbosity. + *min_log_level_ = -level; +} + +int VlogInfo::GetMaxVlogLevel() const { + return -*min_log_level_; +} + namespace { // Given a path, returns the basename with the extension chopped off @@ -79,7 +94,7 @@ base::StringPiece GetModule(const base::StringPiece& file) { } // namespace -int VlogInfo::GetVlogLevel(const base::StringPiece& file) { +int VlogInfo::GetVlogLevel(const base::StringPiece& file) const { if (!vmodule_levels_.empty()) { base::StringPiece module(GetModule(file)); for (std::vector<VmodulePattern>::const_iterator it = @@ -90,7 +105,7 @@ int VlogInfo::GetVlogLevel(const base::StringPiece& file) { return it->vlog_level; } } - return max_vlog_level_; + return GetMaxVlogLevel(); } bool MatchVlogPattern(const base::StringPiece& string, diff --git a/base/vlog.h b/base/vlog.h index 428b3e1..529afd5 100644 --- a/base/vlog.h +++ b/base/vlog.h @@ -28,21 +28,29 @@ class VlogInfo { // code in source files "my_module.*" and "foo*.*" ("-inl" suffixes // are also disregarded for this matching). // + // |log_severity| points to an int that stores the log level. If a valid + // |v_switch| is provided, it will set the log level, and the default + // vlog severity will be read from there.. + // // Any pattern containing a forward or backward slash will be tested // against the whole pathname and not just the module. E.g., // "*/foo/bar/*=2" would change the logging level for all code in // source files under a "foo/bar" directory. VlogInfo(const std::string& v_switch, - const std::string& vmodule_switch); + const std::string& vmodule_switch, + int* min_log_level); ~VlogInfo(); // Returns the vlog level for a given file (usually taken from // __FILE__). - int GetVlogLevel(const base::StringPiece& file); + int GetVlogLevel(const base::StringPiece& file) const; static const int kDefaultVlogLevel; private: + void SetMaxVlogLevel(int level); + int GetMaxVlogLevel() const; + // VmodulePattern holds all the information for each pattern parsed // from |vmodule_switch|. struct VmodulePattern { @@ -57,8 +65,8 @@ class VlogInfo { MatchTarget match_target; }; - int max_vlog_level_; std::vector<VmodulePattern> vmodule_levels_; + int* min_log_level_; DISALLOW_COPY_AND_ASSIGN(VlogInfo); }; diff --git a/base/vlog_unittest.cc b/base/vlog_unittest.cc index b3ecde6..f583f44 100644 --- a/base/vlog_unittest.cc +++ b/base/vlog_unittest.cc @@ -18,12 +18,13 @@ class VlogTest : public testing::Test { }; TEST_F(VlogTest, NoVmodule) { - EXPECT_EQ(0, VlogInfo("", "").GetVlogLevel("test1")); - EXPECT_EQ(0, VlogInfo("0", "").GetVlogLevel("test2")); - EXPECT_EQ(0, VlogInfo("blah", "").GetVlogLevel("test3")); - EXPECT_EQ(0, VlogInfo("0blah1", "").GetVlogLevel("test4")); - EXPECT_EQ(1, VlogInfo("1", "").GetVlogLevel("test5")); - EXPECT_EQ(5, VlogInfo("5", "").GetVlogLevel("test6")); + int min_log_level = 0; + EXPECT_EQ(0, VlogInfo("", "", &min_log_level).GetVlogLevel("test1")); + EXPECT_EQ(0, VlogInfo("0", "", &min_log_level).GetVlogLevel("test2")); + EXPECT_EQ(0, VlogInfo("blah", "", &min_log_level).GetVlogLevel("test3")); + EXPECT_EQ(0, VlogInfo("0blah1", "", &min_log_level).GetVlogLevel("test4")); + EXPECT_EQ(1, VlogInfo("1", "", &min_log_level).GetVlogLevel("test5")); + EXPECT_EQ(5, VlogInfo("5", "", &min_log_level).GetVlogLevel("test6")); } TEST_F(VlogTest, MatchVlogPattern) { @@ -78,7 +79,8 @@ TEST_F(VlogTest, VmoduleBasic) { const char kVSwitch[] = "-1"; const char kVModuleSwitch[] = "foo=,bar=0,baz=blah,,qux=0blah1,quux=1,corge.ext=5"; - VlogInfo vlog_info(kVSwitch, kVModuleSwitch); + int min_log_level = 0; + VlogInfo vlog_info(kVSwitch, kVModuleSwitch, &min_log_level); EXPECT_EQ(-1, vlog_info.GetVlogLevel("/path/to/grault.cc")); EXPECT_EQ(0, vlog_info.GetVlogLevel("/path/to/foo.cc")); EXPECT_EQ(0, vlog_info.GetVlogLevel("D:\\Path\\To\\bar-inl.mm")); @@ -92,7 +94,8 @@ TEST_F(VlogTest, VmoduleBasic) { TEST_F(VlogTest, VmoduleDirs) { const char kVModuleSwitch[] = "foo/bar.cc=1,baz\\*\\qux.cc=2,*quux/*=3,*/*-inl.h=4"; - VlogInfo vlog_info("", kVModuleSwitch); + int min_log_level = 0; + VlogInfo vlog_info("", kVModuleSwitch, &min_log_level); EXPECT_EQ(0, vlog_info.GetVlogLevel("/foo/bar.cc")); EXPECT_EQ(0, vlog_info.GetVlogLevel("bar.cc")); EXPECT_EQ(1, vlog_info.GetVlogLevel("foo/bar.cc")); diff --git a/ceee/testing/utils/test_utils.cc b/ceee/testing/utils/test_utils.cc index 48e522a..c55588d 100644 --- a/ceee/testing/utils/test_utils.cc +++ b/ceee/testing/utils/test_utils.cc @@ -57,8 +57,9 @@ HRESULT GetConnectionCount(IUnknown* container, return E_UNEXPECTED; } - -bool LogDisabler::DropMessageHandler(int severity, const std::string& str) { +bool LogDisabler::DropMessageHandler(int severity, const char* file, int line, + size_t message_start, const std::string& str) { + // Message is handled, no further processing. return true; } diff --git a/ceee/testing/utils/test_utils.h b/ceee/testing/utils/test_utils.h index 55582be..a51ca63 100644 --- a/ceee/testing/utils/test_utils.h +++ b/ceee/testing/utils/test_utils.h @@ -68,7 +68,8 @@ class LogDisabler { private: logging::LogMessageHandlerFunction old_handler_; - static bool DropMessageHandler(int severity, const std::string& str); + static bool DropMessageHandler(int severity, const char* file, int line, + size_t message_start, const std::string& str); }; // Overrides a path in the PathService singleton, replacing the diff --git a/chrome/browser/safe_browsing/safe_browsing_database_unittest.cc b/chrome/browser/safe_browsing/safe_browsing_database_unittest.cc index 2713814..89cc553 100644 --- a/chrome/browser/safe_browsing/safe_browsing_database_unittest.cc +++ b/chrome/browser/safe_browsing/safe_browsing_database_unittest.cc @@ -51,7 +51,8 @@ class ScopedLogMessageIgnorer { } private: - static bool LogMessageIgnorer(int severity, const std::string& str) { + static bool LogMessageIgnorer(int severity, const char* file, int line, + size_t message_start, const std::string& str) { // Intercept FATAL, strip the stack backtrace, and log it without // the crash part. if (severity == logging::LOG_FATAL) { diff --git a/chrome/common/logging_chrome.cc b/chrome/common/logging_chrome.cc index 48bcc37..196c581 100644 --- a/chrome/common/logging_chrome.cc +++ b/chrome/common/logging_chrome.cc @@ -64,8 +64,9 @@ static bool chrome_logging_redirected_ = false; #if defined(OS_WIN) // {7FE69228-633E-4f06-80C1-527FEA23E3A7} -DEFINE_GUID(kChromeTraceProviderName, - 0x7fe69228, 0x633e, 0x4f06, 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7); +static const GUID kChromeTraceProviderName = { + 0x7fe69228, 0x633e, 0x4f06, + { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } }; #endif // Assertion handler for logging errors that occur when dialogs are |