| OLD | NEW |
|---|
| (Empty) |
| 1 // Copyright 2003-2009 Google Inc. | |
| 2 // | |
| 3 // Licensed under the Apache License, Version 2.0 (the "License"); | |
| 4 // you may not use this file except in compliance with the License. | |
| 5 // You may obtain a copy of the License at | |
| 6 // | |
| 7 // http://www.apache.org/licenses/LICENSE-2.0 | |
| 8 // | |
| 9 // Unless required by applicable law or agreed to in writing, software | |
| 10 // distributed under the License is distributed on an "AS IS" BASIS, | |
| 11 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. | |
| 12 // See the License for the specific language governing permissions and | |
| 13 // limitations under the License. | |
| 14 // ======================================================================== | |
| 15 // | |
| 16 // Tracing and logging system. | |
| 17 // | |
| 18 // The log output goes to "All Users/Application Data/Google/Update/Log/". | |
| 19 // The log configuration file is under | |
| 20 // "%Program Files%/C:\Program Files\Google\Common\Update". | |
| 21 // By default, the logging is on in debug modes and off in opt mode although in | |
| 22 // opt mode only the OPT_LOG statements write to the log. | |
| 23 // | |
| 24 // The log is open to all the users to write to. There is a known vulnerability | |
| 25 // where a DOS can be created by holding on to the logging mutex. | |
| 26 // | |
| 27 // In this module use of ASSERT & REPORT is banned. This is to prevent any | |
| 28 // possible recursion issues between logging (logging.h) and | |
| 29 // asserting/reporting (debug.h). Both are basement-level systems that need to | |
| 30 // work when almost nothing else works and interdependencies are best avoided. | |
| 31 // One unavoidable interdependency is that debugASSERT will send messages to | |
| 32 // the logger via Logger::OutputMessage - which then broadcasts it to each | |
| 33 // LogWriter's OutputMessage. So these methods should be as simple as | |
| 34 // possible. (Also, unlike asserting/reporting - this module will not avoid | |
| 35 // use of the heap, however the code executed from Logger::OutputMessage | |
| 36 // doesn't use the heap (for all the LogWriters in this file).) | |
| 37 // | |
| 38 // TODO(omaha): implement the minidump handling in terms of breakpad. | |
| 39 // Log initialization if full of lazy init. Consider doing | |
| 40 // eager init of log and its registered log writers when the | |
| 41 // log is created and initialized. | |
| 42 // Reimplement in terms of smart handles and locks. | |
| 43 // Reimplement without dependency on any other compilation unit | |
| 44 // that can call assert, verify, or the log itself. | |
| 45 // Redo the history logging feature | |
| 46 | |
| 47 #include "omaha/base/logging.h" | |
| 48 | |
| 49 #include <excpt.h> // Microsoft specific: structured exceptions. | |
| 50 #include <shlobj.h> | |
| 51 #include <shlwapi.h> | |
| 52 #include <string.h> | |
| 53 #include <atlpath.h> | |
| 54 #include <atlsecurity.h> | |
| 55 #include "base/basictypes.h" | |
| 56 #include "omaha/base/app_util.h" | |
| 57 #include "omaha/base/const_debug.h" | |
| 58 #include "omaha/base/constants.h" | |
| 59 #include "omaha/base/debug.h" | |
| 60 #include "omaha/base/etw_log_writer.h" | |
| 61 #include "omaha/base/file.h" | |
| 62 #include "omaha/base/path.h" | |
| 63 #include "omaha/base/string.h" | |
| 64 #include "omaha/base/time.h" | |
| 65 #include "omaha/base/utils.h" | |
| 66 | |
| 67 namespace omaha { | |
| 68 | |
| 69 // enforce ban on ASSERT/REPORT | |
| 70 #undef ASSERT | |
| 71 #undef REPORT | |
| 72 | |
| 73 #ifdef LOGGING | |
| 74 | |
| 75 #define kNumLockRetries (20) | |
| 76 #define kLockRetryDelayMs (50) | |
| 77 | |
| 78 // Circular buffer to log history. | |
| 79 static wchar_t history_buffer[kMaxHistoryBufferSize]; | |
| 80 | |
| 81 // Index into the history buffer to begin writing at. | |
| 82 static int history_buffer_next_idx = 0; | |
| 83 | |
| 84 // Indicates whether the history buffer has ever reached its full capacity. | |
| 85 // Once this boolean is true, if never becomes false. | |
| 86 static bool history_buffer_full = false; | |
| 87 | |
| 88 // | |
| 89 // Table of category names to categories. | |
| 90 // | |
| 91 #define LC_ENTRY(lc_value) (L#lc_value), (lc_value) | |
| 92 struct { | |
| 93 wchar_t* category_name; | |
| 94 LogCategory category; | |
| 95 } static LogCategoryNames[] = { | |
| 96 LC_ENTRY(LC_UTIL), | |
| 97 LC_ENTRY(LC_SETUP), | |
| 98 LC_ENTRY(LC_SHELL), | |
| 99 LC_ENTRY(LC_CORE), | |
| 100 LC_ENTRY(LC_JS), | |
| 101 LC_ENTRY(LC_PLUGIN), | |
| 102 LC_ENTRY(LC_SERVICE), | |
| 103 LC_ENTRY(LC_OPT), | |
| 104 LC_ENTRY(LC_NET), | |
| 105 LC_ENTRY(LC_REPORT), | |
| 106 }; | |
| 107 | |
| 108 COMPILE_ASSERT(arraysize(LogCategoryNames) == LC_MAX_CAT - 1, | |
| 109 LogCategoryNames_missing_category); | |
| 110 | |
| 111 static CString StripBackslashes(const CString& name) { | |
| 112 int n = String_FindChar(name, L'\\'); | |
| 113 if (n == -1) { | |
| 114 return name; | |
| 115 } else { | |
| 116 CString result; | |
| 117 for (int i = 0; i < name.GetLength(); ++i) { | |
| 118 if (name[i] != L'\\') { | |
| 119 result += name[i]; | |
| 120 } | |
| 121 } | |
| 122 return result; | |
| 123 } | |
| 124 } | |
| 125 | |
| 126 static CString GetProcName() { | |
| 127 CString proc_name(app_util::GetAppNameWithoutExtension()); | |
| 128 CString module_name(app_util::GetCurrentModuleNameWithoutExtension()); | |
| 129 CString result(proc_name); | |
| 130 if (module_name.CompareNoCase(proc_name) != 0) { | |
| 131 result += L":"; | |
| 132 result += module_name; | |
| 133 } | |
| 134 return result; | |
| 135 } | |
| 136 | |
| 137 // Formats a line prefix with the current time min:sec:milisec if wanted, | |
| 138 // otherwise just the process:module. | |
| 139 static void FormatLinePrefix(bool show_time, | |
| 140 const wchar_t* proc_name, | |
| 141 CString& result) { | |
| 142 if (show_time) { | |
| 143 SYSTEMTIME system_time = {0}; | |
| 144 GetLocalTime(&system_time); | |
| 145 result.Format(L"[%02d/%02d/%02d %02d:%02d:%02d.%03d]", | |
| 146 system_time.wMonth, system_time.wDay, system_time.wYear % 100, | |
| 147 system_time.wHour, system_time.wMinute, system_time.wSecond, | |
| 148 system_time.wMilliseconds); | |
| 149 } | |
| 150 result.AppendFormat(L"[%s][%u:%u]", | |
| 151 proc_name, | |
| 152 ::GetCurrentProcessId(), | |
| 153 ::GetCurrentThreadId()); | |
| 154 } | |
| 155 | |
| 156 static bool g_logging_valid = false; | |
| 157 static Logging g_logging; | |
| 158 | |
| 159 // Singleton factory for the Logging object. | |
| 160 Logging* GetLogging() { | |
| 161 return g_logging_valid ? &g_logging : NULL; | |
| 162 } | |
| 163 | |
| 164 // Force the logging system to be initialized during elaboration of static | |
| 165 // constructors, while the program is still single-threaded. This global | |
| 166 // static object will cause the static logger inside of GetLogging() to be | |
| 167 // constructed. However, it might not be the first call to GetLogging() - | |
| 168 // another static object in another object file might get constructed first, | |
| 169 // and in its constructor call a logging API. Just as long as it is done when | |
| 170 // the system is single threaded. (Reason: because the Logger object has a | |
| 171 // LLock object which has a Win32 critical section which needs to be | |
| 172 // initialized - only once!) | |
| 173 | |
| 174 | |
| 175 Logging::Logging() | |
| 176 : logging_initialized_(false), | |
| 177 logging_enabled_(true), | |
| 178 force_show_time_(false), | |
| 179 show_time_(true), | |
| 180 log_to_file_(true), | |
| 181 log_to_debug_out_(true), | |
| 182 append_to_file_(true), | |
| 183 logging_shutdown_(false), | |
| 184 num_writers_(0), | |
| 185 file_log_writer_(NULL), | |
| 186 debug_out_writer_(NULL), | |
| 187 etw_log_writer_(NULL), | |
| 188 is_initializing_(false), | |
| 189 log_file_name_(kDefaultLogFileName), | |
| 190 config_file_path_(GetConfigurationFilePath()) { | |
| 191 g_last_category_check_time = 0; | |
| 192 for (int i = 0; i < max_writers; ++i) { | |
| 193 writers_[i] = NULL; | |
| 194 } | |
| 195 proc_name_ = GetProcName(); | |
| 196 g_logging_valid = true; | |
| 197 | |
| 198 // Read initial settings from the config file. | |
| 199 ReadLoggingSettings(); | |
| 200 } | |
| 201 | |
| 202 // TODO(omaha): why aren't we using a mutexscope and what if an the code | |
| 203 // throws? Will the lock be unlocked? | |
| 204 Logging::~Logging() { | |
| 205 // Acquire the lock outside the try/except block so we'll always release it | |
| 206 lock_.Lock(); | |
| 207 | |
| 208 __try { | |
| 209 // prevent further access to the system | |
| 210 // necessary because the static destructors happen | |
| 211 // in a non-deterministic order | |
| 212 logging_shutdown_ = true; | |
| 213 | |
| 214 // Delete all registered LogWriters | |
| 215 for (int i = 0; i < num_writers_; ++i) { | |
| 216 if (writers_[i]) { | |
| 217 delete writers_[i]; | |
| 218 } | |
| 219 } | |
| 220 | |
| 221 logging_initialized_ = false; | |
| 222 } __except(SehNoMinidump(GetExceptionCode(), | |
| 223 GetExceptionInformation(), | |
| 224 __FILE__, | |
| 225 __LINE__, | |
| 226 true)) { | |
| 227 OutputDebugStringA("Unexpected exception in: " __FUNCTION__ "\r\n"); | |
| 228 logging_initialized_ = false; | |
| 229 } | |
| 230 | |
| 231 g_logging_valid = false; | |
| 232 lock_.Unlock(); | |
| 233 } | |
| 234 | |
| 235 void Logging::UpdateCatAndLevel(const wchar_t* cat_name, LogCategory cat) { | |
| 236 if (cat_name == NULL) { | |
| 237 return; | |
| 238 } | |
| 239 if (cat >= LC_MAX_CAT) { | |
| 240 return; | |
| 241 } | |
| 242 int log_level = kDefaultLogLevel; | |
| 243 CString config_file = GetCurrentConfigurationFilePath(); | |
| 244 if (!config_file.IsEmpty()) { | |
| 245 log_level = GetPrivateProfileInt(kConfigSectionLoggingLevel, | |
| 246 cat_name, | |
| 247 kDefaultLogLevel, | |
| 248 config_file); | |
| 249 } | |
| 250 category_list_[cat].enabled = (log_level != 0); | |
| 251 category_list_[cat].log_level = static_cast<LogLevel>(log_level); | |
| 252 } | |
| 253 | |
| 254 void Logging::ReadLoggingSettings() { | |
| 255 CString config_file = GetCurrentConfigurationFilePath(); | |
| 256 if (!config_file.IsEmpty()) { | |
| 257 logging_enabled_ = ::GetPrivateProfileInt( | |
| 258 kConfigSectionLoggingSettings, | |
| 259 kConfigAttrEnableLogging, | |
| 260 kDefaultLoggingEnabled, | |
| 261 config_file) == 0 ? false : true; | |
| 262 | |
| 263 show_time_ = ::GetPrivateProfileInt( | |
| 264 kConfigSectionLoggingSettings, | |
| 265 kConfigAttrShowTime, | |
| 266 kDefaultShowTime, | |
| 267 config_file) == 0 ? false : true; | |
| 268 | |
| 269 log_to_file_ = ::GetPrivateProfileInt( | |
| 270 kConfigSectionLoggingSettings, | |
| 271 kConfigAttrLogToFile, | |
| 272 kDefaultLogToFile, | |
| 273 config_file) == 0 ? false : true; | |
| 274 | |
| 275 log_to_debug_out_ = ::GetPrivateProfileInt( | |
| 276 kConfigSectionLoggingSettings, | |
| 277 kConfigAttrLogToOutputDebug, | |
| 278 kDefaultLogToOutputDebug, | |
| 279 config_file) == 0 ? false : true; | |
| 280 | |
| 281 append_to_file_ = ::GetPrivateProfileInt( | |
| 282 kConfigSectionLoggingSettings, | |
| 283 kConfigAttrAppendToFile, | |
| 284 kDefaultAppendToFile, | |
| 285 config_file) == 0 ? false : true; | |
| 286 | |
| 287 ::GetPrivateProfileString(kConfigSectionLoggingSettings, | |
| 288 kConfigAttrLogFilePath, | |
| 289 kDefaultLogFileName, | |
| 290 CStrBuf(log_file_name_, MAX_PATH), | |
| 291 MAX_PATH, | |
| 292 config_file); | |
| 293 } else { | |
| 294 logging_enabled_ = kDefaultLoggingEnabled; | |
| 295 show_time_ = kDefaultShowTime; | |
| 296 log_to_file_ = kDefaultLogToFile; | |
| 297 log_to_debug_out_ = kDefaultLogToOutputDebug; | |
| 298 append_to_file_ = kDefaultAppendToFile; | |
| 299 log_file_name_ = kDefaultLogFileName; | |
| 300 } | |
| 301 | |
| 302 if (force_show_time_) { | |
| 303 show_time_ = true; | |
| 304 } | |
| 305 | |
| 306 // The "default" category is always enabled. | |
| 307 category_list_[LC_LOGGING].enabled = true; | |
| 308 category_list_[LC_LOGGING].log_level = LEVEL_ALL; | |
| 309 | |
| 310 // Read each category from the ini file. | |
| 311 for (size_t i = 0; i < arraysize(LogCategoryNames); ++i) { | |
| 312 UpdateCatAndLevel(LogCategoryNames[i].category_name, | |
| 313 LogCategoryNames[i].category); | |
| 314 } | |
| 315 | |
| 316 g_last_category_check_time = GetCurrent100NSTime(); | |
| 317 } | |
| 318 | |
| 319 CString Logging::GetDefaultLogDirectory() const { | |
| 320 CString path; | |
| 321 CStrBuf buf(path, MAX_PATH); | |
| 322 HRESULT hr = ::SHGetFolderPath(NULL, | |
| 323 CSIDL_COMMON_APPDATA, | |
| 324 NULL, | |
| 325 SHGFP_TYPE_CURRENT, | |
| 326 buf); | |
| 327 if (FAILED(hr)) { | |
| 328 return L""; | |
| 329 } | |
| 330 if (!::PathAppend(buf, OMAHA_REL_LOG_DIR)) { | |
| 331 return L""; | |
| 332 } | |
| 333 return path; | |
| 334 } | |
| 335 | |
| 336 CString Logging::GetLogFilePath() const { | |
| 337 if (log_file_name_.IsEmpty()) { | |
| 338 return CString(); | |
| 339 } | |
| 340 | |
| 341 if (!ATLPath::IsRelative(log_file_name_)) { | |
| 342 return log_file_name_; | |
| 343 } | |
| 344 | |
| 345 CString path = GetDefaultLogDirectory(); | |
| 346 if (path.IsEmpty()) { | |
| 347 return CString(); | |
| 348 } | |
| 349 | |
| 350 if (!::PathAppend(CStrBuf(path, MAX_PATH), log_file_name_)) { | |
| 351 return CString(); | |
| 352 } | |
| 353 | |
| 354 return path; | |
| 355 } | |
| 356 | |
| 357 void Logging::ConfigureETWLogWriter() { | |
| 358 // Always create the ETW log writer, as its log level is controlled | |
| 359 // at runtime through Event Tracing for Windows. | |
| 360 if (etw_log_writer_ == NULL) { | |
| 361 etw_log_writer_ = EtwLogWriter::Create(); | |
| 362 if (debug_out_writer_ == NULL) { | |
| 363 OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: ERROR - " | |
| 364 L"Cannot create ETW log writer", | |
| 365 proc_name_)); | |
| 366 } | |
| 367 } | |
| 368 | |
| 369 if (etw_log_writer_ != NULL) { | |
| 370 InternalRegisterWriter(etw_log_writer_); | |
| 371 } | |
| 372 } | |
| 373 | |
| 374 void Logging::ConfigureFileLogWriter() { | |
| 375 if (!log_to_file_) { | |
| 376 return; | |
| 377 } | |
| 378 | |
| 379 // Create the logging file. | |
| 380 if (file_log_writer_ == NULL) { | |
| 381 CString path = GetLogFilePath(); | |
| 382 if (path.IsEmpty()) { | |
| 383 return; | |
| 384 } | |
| 385 | |
| 386 // Extract the final target directory which will not be what | |
| 387 // GetDefaultLogDirectory() returns if log_file_name_ is an absolute path. | |
| 388 CString log_file_dir = GetDirectoryFromPath(path); | |
| 389 if (!File::Exists(log_file_dir)) { | |
| 390 if (FAILED(CreateDir(log_file_dir, NULL))) { | |
| 391 return; | |
| 392 } | |
| 393 } | |
| 394 file_log_writer_ = FileLogWriter::Create(path, append_to_file_); | |
| 395 if (file_log_writer_ == NULL) { | |
| 396 OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: ERROR - " | |
| 397 L"Cannot create log writer to %s", | |
| 398 proc_name_, path)); | |
| 399 } | |
| 400 } | |
| 401 | |
| 402 if (file_log_writer_ != NULL) { | |
| 403 InternalRegisterWriter(file_log_writer_); | |
| 404 } | |
| 405 } | |
| 406 | |
| 407 void Logging::ConfigureDebugOutLogWriter() { | |
| 408 if (!log_to_debug_out_) { | |
| 409 return; | |
| 410 } | |
| 411 | |
| 412 if (debug_out_writer_ == NULL) { | |
| 413 debug_out_writer_ = OutputDebugStringLogWriter::Create(); | |
| 414 if (debug_out_writer_ == NULL) { | |
| 415 OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: ERROR - " | |
| 416 L"Cannot create OutputDebugString log writer", | |
| 417 proc_name_)); | |
| 418 } | |
| 419 } | |
| 420 | |
| 421 if (debug_out_writer_ != NULL) { | |
| 422 InternalRegisterWriter(debug_out_writer_); | |
| 423 } | |
| 424 } | |
| 425 | |
| 426 // Configures/unconfigures the log writers for the current settings. | |
| 427 bool Logging::ConfigureLogging() { | |
| 428 ConfigureETWLogWriter(); | |
| 429 ConfigureFileLogWriter(); | |
| 430 ConfigureDebugOutLogWriter(); | |
| 431 | |
| 432 return num_writers_ > 0; | |
| 433 } | |
| 434 | |
| 435 void Logging::UnconfigureLogging() { | |
| 436 if (etw_log_writer_ != NULL) { | |
| 437 InternalUnregisterWriter(etw_log_writer_); | |
| 438 } | |
| 439 if (file_log_writer_ != NULL) { | |
| 440 InternalUnregisterWriter(file_log_writer_); | |
| 441 } | |
| 442 if (debug_out_writer_ != NULL) { | |
| 443 InternalUnregisterWriter(debug_out_writer_); | |
| 444 } | |
| 445 } | |
| 446 | |
| 447 bool Logging::InternalInitialize() { | |
| 448 __try { | |
| 449 if (logging_shutdown_ == true) { | |
| 450 OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: ERROR - " | |
| 451 L"Calling the logging system after " | |
| 452 L"it has been shut down \n", | |
| 453 GetProcName())); | |
| 454 return false; | |
| 455 } | |
| 456 | |
| 457 if (logging_initialized_ == true) { | |
| 458 return true; | |
| 459 } | |
| 460 // If something called by this method is attempting to do logging, | |
| 461 // just ignore it. The cost/benefit ratio is too high to do otherwise. | |
| 462 if (is_initializing_) { | |
| 463 return false; | |
| 464 } | |
| 465 is_initializing_ = true; | |
| 466 | |
| 467 // Read the initial settings from the config file. | |
| 468 ReadLoggingSettings(); | |
| 469 | |
| 470 // Initialize logging system if enabled at start. | |
| 471 if (logging_enabled_) { | |
| 472 logging_initialized_ = ConfigureLogging(); | |
| 473 } | |
| 474 } __except(SehNoMinidump(GetExceptionCode(), | |
| 475 GetExceptionInformation(), | |
| 476 __FILE__, | |
| 477 __LINE__, | |
| 478 true)) { | |
| 479 OutputDebugStringA("Unexpected exception in: " __FUNCTION__ "\r\n"); | |
| 480 logging_initialized_ = false; | |
| 481 return false; | |
| 482 } | |
| 483 | |
| 484 is_initializing_ = false; | |
| 485 return true; | |
| 486 } | |
| 487 | |
| 488 bool Logging::InitializeLogging() { | |
| 489 // Double-checked locking idiom is broken, especially on multicore machines. | |
| 490 // TODO(omaha): understand how this works and fix it. | |
| 491 if (logging_shutdown_ == true) { | |
| 492 OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: ERROR - Calling the logging " | |
| 493 L"system after it has been shut down \n", | |
| 494 GetProcName())); | |
| 495 return false; | |
| 496 } | |
| 497 | |
| 498 if (logging_initialized_ == true) { | |
| 499 return true; | |
| 500 } | |
| 501 | |
| 502 // Acquire the lock outside the try/except block so we'll always release it. | |
| 503 __mutexScope(lock_); | |
| 504 return InternalInitialize(); | |
| 505 } | |
| 506 | |
| 507 // Enables/disables the logging mechanism. Allows turning logging on/off | |
| 508 // in mid-run. | |
| 509 // TODO(omaha): same comment as for the destructor. | |
| 510 void Logging::EnableLogging() { | |
| 511 if (!InitializeLogging()) { | |
| 512 return; | |
| 513 } | |
| 514 | |
| 515 // Acquire the lock outside the try/except block so we'll always release it. | |
| 516 lock_.Lock(); | |
| 517 | |
| 518 __try { | |
| 519 if (!logging_enabled_) { | |
| 520 ConfigureLogging(); | |
| 521 logging_enabled_ = true; | |
| 522 } | |
| 523 } __except(SehNoMinidump(GetExceptionCode(), | |
| 524 GetExceptionInformation(), | |
| 525 __FILE__, | |
| 526 __LINE__, | |
| 527 true)) { | |
| 528 OutputDebugStringA("Unexpected exception in: " __FUNCTION__ "\r\n"); | |
| 529 logging_enabled_ = false; | |
| 530 } | |
| 531 | |
| 532 lock_.Unlock(); | |
| 533 } | |
| 534 | |
| 535 void Logging::DisableLogging() { | |
| 536 if (!InitializeLogging()) { | |
| 537 return; | |
| 538 } | |
| 539 | |
| 540 // Acquire the lock outside the try/except block so we'll always release it. | |
| 541 lock_.Lock(); | |
| 542 | |
| 543 __try { | |
| 544 if (logging_enabled_) { | |
| 545 logging_enabled_ = false; | |
| 546 UnconfigureLogging(); | |
| 547 } | |
| 548 } __except(SehNoMinidump(GetExceptionCode(), | |
| 549 GetExceptionInformation(), | |
| 550 __FILE__, | |
| 551 __LINE__, | |
| 552 true)) { | |
| 553 OutputDebugStringA("Unexpected exception in: " __FUNCTION__ "\r\n"); | |
| 554 logging_enabled_ = false; | |
| 555 } | |
| 556 | |
| 557 lock_.Unlock(); | |
| 558 } | |
| 559 | |
| 560 // Checks if logging is enabled - and updates logging settings from the | |
| 561 // configuration file every kLogSettingsCheckInterval seconds. | |
| 562 bool Logging::IsLoggingEnabled() { | |
| 563 if (!InitializeLogging()) { | |
| 564 return false; | |
| 565 } | |
| 566 | |
| 567 // Dynamic update - including reading a new value of logging_enabled_. | |
| 568 bool prev_logging_enabled = logging_enabled_; | |
| 569 if (GetCurrent100NSTime() > | |
| 570 g_last_category_check_time + kLogSettingsCheckInterval) { | |
| 571 ReadLoggingSettings(); | |
| 572 } | |
| 573 | |
| 574 // If enabled state has changed either enable or disable logging. | |
| 575 if (prev_logging_enabled != logging_enabled_) { | |
| 576 if (logging_enabled_) { | |
| 577 EnableLogging(); | |
| 578 } else { | |
| 579 DisableLogging(); | |
| 580 } | |
| 581 } | |
| 582 | |
| 583 return logging_enabled_; | |
| 584 } | |
| 585 | |
| 586 bool Logging::IsLoggingAlreadyEnabled() const { | |
| 587 return logging_enabled_; | |
| 588 } | |
| 589 | |
| 590 void Logging::ForceShowTimestamp(bool force_show_time) { | |
| 591 force_show_time_ = show_time_ = force_show_time; | |
| 592 } | |
| 593 | |
| 594 // Get category level | |
| 595 LogLevel Logging::GetCatLevel(LogCategory category) const { | |
| 596 if (!IsLoggingAlreadyEnabled()) { | |
| 597 return kDefaultLogLevel; | |
| 598 } | |
| 599 | |
| 600 if (category >= LC_MAX_CAT) { | |
| 601 return kDefaultLogLevel; | |
| 602 } | |
| 603 | |
| 604 return category_list_[category].log_level; | |
| 605 } | |
| 606 | |
| 607 // Check if logging is enabled for a given category and level | |
| 608 DWORD Logging::IsCatLevelEnabled(LogCategory category, LogLevel level) { | |
| 609 if (!IsLoggingEnabled()) { | |
| 610 return 0; | |
| 611 } | |
| 612 | |
| 613 if (category >= LC_MAX_CAT) { | |
| 614 return 0; | |
| 615 } | |
| 616 | |
| 617 // If the config value is to log: then log to all writers. | |
| 618 if (category_list_[category].enabled && | |
| 619 level <= category_list_[category].log_level) { | |
| 620 return static_cast<DWORD>(all_writers_mask); | |
| 621 } | |
| 622 | |
| 623 // Check each of the registered loggers to see if they want to override the | |
| 624 // negative config value. | |
| 625 DWORD mask = 0; | |
| 626 for (int i = num_writers_ - 1; i >= 0; --i) { | |
| 627 mask <<= 1; | |
| 628 if (writers_[i] && writers_[i]->IsCatLevelEnabled(category, level)) { | |
| 629 mask |= 1; | |
| 630 } | |
| 631 } | |
| 632 | |
| 633 return mask; | |
| 634 } | |
| 635 | |
| 636 // TODO(omaha): For now this is hard coded and there is no way to override | |
| 637 // writing other log categories into the history. Add a store_in_history | |
| 638 // boolean into the CategoryInfo struct that allows reading from the config | |
| 639 // file. This will enable other log categories to get buffered in the history. | |
| 640 bool Logging::IsCategoryEnabledForBuffering(LogCategory cat) { | |
| 641 return cat == LC_REPORT; | |
| 642 } | |
| 643 | |
| 644 void Logging::LogMessage(LogCategory cat, LogLevel level, | |
| 645 const wchar_t* fmt, ...) { | |
| 646 va_list args; | |
| 647 va_start(args, fmt); | |
| 648 LogMessageVA(cat, level, fmt, args); | |
| 649 va_end(args); | |
| 650 } | |
| 651 | |
| 652 void Logging::LogMessageVA(LogCategory cat, LogLevel level, | |
| 653 const wchar_t* fmt, va_list args) { | |
| 654 LogMessageMaskedVA(static_cast<DWORD>(all_writers_mask), | |
| 655 cat, | |
| 656 level, | |
| 657 fmt, | |
| 658 args); | |
| 659 } | |
| 660 | |
| 661 void Logging::InternalLogMessageMaskedVA(DWORD writer_mask, | |
| 662 LogCategory cat, | |
| 663 LogLevel level, | |
| 664 CString* log_buffer, | |
| 665 CString* prefix, | |
| 666 const wchar_t* fmt, | |
| 667 va_list args) { | |
| 668 __try { | |
| 669 // Initial buffer size in characters. | |
| 670 // It will adjust dynamically if the message is bigger. | |
| 671 DWORD buffer_size = 512; | |
| 672 | |
| 673 // Count of chars / bytes written. | |
| 674 int num_chars = 0; | |
| 675 bool result = false; | |
| 676 | |
| 677 // Write the message in the buffer. | |
| 678 // Dynamically adjust the size to hold the entire message. | |
| 679 | |
| 680 while ((num_chars = _vsnwprintf_s( | |
| 681 log_buffer->GetBufferSetLength(buffer_size), | |
| 682 buffer_size, | |
| 683 _TRUNCATE, | |
| 684 fmt, | |
| 685 args)) == -1) { | |
| 686 // Truncate if the message is too big. | |
| 687 if (buffer_size >= kMaxLogMessageSize) { | |
| 688 num_chars = buffer_size; | |
| 689 break; | |
| 690 } | |
| 691 | |
| 692 // Get a buffer that is big enough. | |
| 693 buffer_size *= 2; | |
| 694 } | |
| 695 | |
| 696 log_buffer->ReleaseBuffer(num_chars); | |
| 697 | |
| 698 FormatLinePrefix(show_time_, proc_name_, *prefix); | |
| 699 | |
| 700 // Log the message. | |
| 701 OutputInfo info(cat, level, *prefix, *log_buffer); | |
| 702 OutputMessage(writer_mask, &info); | |
| 703 } __except(SehSendMinidump(GetExceptionCode(), | |
| 704 GetExceptionInformation(), | |
| 705 kMinsTo100ns)) { | |
| 706 OutputDebugStringA("Unexpected exception in: " __FUNCTION__ "\r\n"); | |
| 707 OutputDebugString(fmt); | |
| 708 OutputDebugString(L"\n\r"); | |
| 709 } | |
| 710 } | |
| 711 | |
| 712 void Logging::LogMessageMaskedVA(DWORD writer_mask, | |
| 713 LogCategory cat, | |
| 714 LogLevel level, | |
| 715 const wchar_t* fmt, | |
| 716 va_list args) { | |
| 717 if (!fmt) { | |
| 718 return; | |
| 719 } | |
| 720 | |
| 721 if (writer_mask == 0 && level > kMaxLevelToStoreInLogHistory) { | |
| 722 return; | |
| 723 } | |
| 724 | |
| 725 CString log_buffer; // The buffer for formatted log messages. | |
| 726 CString prefix; | |
| 727 | |
| 728 int i = 0; | |
| 729 while (++i <= kNumLockRetries) { | |
| 730 if (lock_.Lock(0)) { | |
| 731 InternalLogMessageMaskedVA(writer_mask, cat, level, &log_buffer, | |
| 732 &prefix, fmt, args); | |
| 733 lock_.Unlock(); | |
| 734 break; | |
| 735 } | |
| 736 | |
| 737 Sleep(kLockRetryDelayMs); | |
| 738 } | |
| 739 | |
| 740 if (i > kNumLockRetries) { | |
| 741 OutputDebugStringA("LOG_SYSTEM: Couldn't acquire lock - "); | |
| 742 OutputDebugString(fmt); | |
| 743 OutputDebugString(L"\n\r"); | |
| 744 } | |
| 745 } | |
| 746 | |
| 747 void Logging::OutputMessage(DWORD writer_mask, LogCategory cat, LogLevel level, | |
| 748 const wchar_t* msg1, const wchar_t* msg2) { | |
| 749 OutputInfo info(cat, level, msg1, msg2); | |
| 750 OutputMessage(writer_mask, &info); | |
| 751 } | |
| 752 | |
| 753 // Store log message in in-memory history buffer. | |
| 754 void Logging::StoreInHistory(const OutputInfo* output_info) { | |
| 755 AppendToHistory(output_info->msg1); | |
| 756 AppendToHistory(output_info->msg2); | |
| 757 AppendToHistory(L"\r\n"); | |
| 758 } | |
| 759 | |
| 760 // Append string to in-memory history buffer. | |
| 761 // history_buffer_next_idx points to the next index to write at, | |
| 762 // thus it should always be in (0 - kHistoryBufferEndIdx). | |
| 763 void Logging::AppendToHistory(const wchar_t* msg) { | |
| 764 int msg_len = wcslen(msg); | |
| 765 if (msg_len == 0) { | |
| 766 return; | |
| 767 } | |
| 768 | |
| 769 if (msg_len >= kMaxHistoryBufferSize) { | |
| 770 // Write the first kMaxHistoryBufferSize chars. | |
| 771 memcpy(history_buffer, msg, kMaxHistoryBufferSize * sizeof(TCHAR)); | |
| 772 history_buffer_next_idx = 0; | |
| 773 history_buffer_full = true; | |
| 774 return; | |
| 775 } | |
| 776 | |
| 777 // Determine if the message fits into the portion of the buffer after | |
| 778 // history_buffer_next_idx. | |
| 779 if (msg_len + history_buffer_next_idx < kMaxHistoryBufferSize) { | |
| 780 memcpy(history_buffer + history_buffer_next_idx, msg, | |
| 781 msg_len * sizeof(TCHAR)); | |
| 782 history_buffer_next_idx += msg_len; | |
| 783 return; | |
| 784 } | |
| 785 | |
| 786 // Have to split the input message into the part that fits in | |
| 787 // history_buffer_next_idx to kMaxHistoryBufferSize and the remaining message. | |
| 788 int msg_first_part_len = kMaxHistoryBufferSize - history_buffer_next_idx; | |
| 789 int msg_second_part_len = msg_len - msg_first_part_len; | |
| 790 memcpy(history_buffer + history_buffer_next_idx, | |
| 791 msg, | |
| 792 msg_first_part_len * sizeof(TCHAR)); | |
| 793 | |
| 794 history_buffer_full = true; | |
| 795 history_buffer_next_idx = msg_second_part_len; | |
| 796 if (msg_second_part_len) { | |
| 797 memcpy(history_buffer, | |
| 798 msg + msg_first_part_len, | |
| 799 msg_second_part_len * sizeof(TCHAR)); | |
| 800 } | |
| 801 } | |
| 802 | |
| 803 // Retrieve in-memory history buffer. | |
| 804 CString Logging::GetHistory() { | |
| 805 CString history; | |
| 806 | |
| 807 if (history_buffer_full) { | |
| 808 history.Append(history_buffer + history_buffer_next_idx, | |
| 809 kMaxHistoryBufferSize - history_buffer_next_idx); | |
| 810 } | |
| 811 history.Append(history_buffer, history_buffer_next_idx); | |
| 812 | |
| 813 // Reset the history buffer to the original state. | |
| 814 history_buffer_next_idx = 0; | |
| 815 history_buffer_full = false; | |
| 816 memset(history_buffer, 0, kMaxHistoryBufferSize * sizeof(TCHAR)); | |
| 817 | |
| 818 return history; | |
| 819 } | |
| 820 | |
| 821 void Logging::OutputMessage(DWORD writer_mask, | |
| 822 const OutputInfo* output_info) { | |
| 823 if (output_info->level <= kMaxLevelToStoreInLogHistory && | |
| 824 IsCategoryEnabledForBuffering(output_info->category)) { | |
| 825 StoreInHistory(output_info); | |
| 826 } | |
| 827 | |
| 828 for (int i = 0; i < num_writers_; ++i) { | |
| 829 if (writer_mask & 1) { | |
| 830 __try { | |
| 831 if (logging_enabled_ || writers_[i]->WantsToLogRegardless()) { | |
| 832 writers_[i]->OutputMessage(output_info); | |
| 833 } | |
| 834 } | |
| 835 __except(SehNoMinidump(GetExceptionCode(), | |
| 836 GetExceptionInformation(), | |
| 837 __FILE__, | |
| 838 __LINE__, | |
| 839 true)) { | |
| 840 // Just eat errors that happen from within the LogWriters. This is | |
| 841 // important so that if such an error happens when OutputMessage is | |
| 842 // called from debugASSERT we don't go recursively into more | |
| 843 // error handling ... | |
| 844 } | |
| 845 } | |
| 846 writer_mask >>= 1; | |
| 847 } | |
| 848 } | |
| 849 | |
| 850 bool Logging::InternalRegisterWriter(LogWriter* log_writer) { | |
| 851 if (num_writers_ >= max_writers) { | |
| 852 return false; | |
| 853 } | |
| 854 writers_[num_writers_++] = log_writer; | |
| 855 return true; | |
| 856 } | |
| 857 | |
| 858 bool Logging::RegisterWriter(LogWriter* log_writer) { | |
| 859 if (!InternalRegisterWriter(log_writer)) { | |
| 860 return false; | |
| 861 } | |
| 862 if (log_writer->WantsToLogRegardless()) { | |
| 863 EnableLogging(); | |
| 864 } | |
| 865 return true; | |
| 866 } | |
| 867 | |
| 868 bool Logging::InternalUnregisterWriter(LogWriter* log_writer) { | |
| 869 bool result = false; | |
| 870 for (int i = 0; i < num_writers_; ++i) { | |
| 871 if (writers_[i] == log_writer) { | |
| 872 // Replace this entry with last entry in array, then truncate. | |
| 873 writers_[i] = writers_[--num_writers_]; | |
| 874 result = true; | |
| 875 break; | |
| 876 } | |
| 877 } | |
| 878 return result; | |
| 879 } | |
| 880 | |
| 881 bool Logging::UnregisterWriter(LogWriter* log_writer) { | |
| 882 if (!InternalUnregisterWriter(log_writer)) { | |
| 883 return false; | |
| 884 } | |
| 885 if (num_writers_ == 0) { | |
| 886 DisableLogging(); | |
| 887 } | |
| 888 return true; | |
| 889 } | |
| 890 | |
| 891 // The primary configuration file under %PROGRAMFILES%\Google\Update is | |
| 892 // removed on uninstall. This is midly inconvenient during development | |
| 893 // therefore a fallback location for the configuration file is desired. | |
| 894 CString Logging::GetCurrentConfigurationFilePath() const { | |
| 895 if (!config_file_path_.IsEmpty() && | |
| 896 File::Exists(config_file_path_)) { | |
| 897 return config_file_path_; | |
| 898 } else { | |
| 899 return L""; | |
| 900 } | |
| 901 } | |
| 902 | |
| 903 CString Logging::GetConfigurationFilePath() const { | |
| 904 CString file_path; | |
| 905 CString system_drive = GetEnvironmentVariableAsString(_T("SystemDrive")); | |
| 906 if (!system_drive.IsEmpty()) { | |
| 907 file_path = system_drive; | |
| 908 file_path += L"\\"; | |
| 909 } | |
| 910 return file_path + kLogConfigFileName; | |
| 911 } | |
| 912 | |
| 913 LogWriter::LogWriter() { | |
| 914 } | |
| 915 | |
| 916 LogWriter::~LogWriter() { | |
| 917 } | |
| 918 | |
| 919 void LogWriter::Cleanup() {} | |
| 920 | |
| 921 bool LogWriter::WantsToLogRegardless() const { return false; } | |
| 922 | |
| 923 bool LogWriter::IsCatLevelEnabled(LogCategory, LogLevel) const { | |
| 924 return false; | |
| 925 } | |
| 926 | |
| 927 void LogWriter::OutputMessage(const OutputInfo*) { } | |
| 928 | |
| 929 bool LogWriter::Register() { | |
| 930 Logging* logger = GetLogging(); | |
| 931 if (logger) { | |
| 932 return logger->RegisterWriter(this); | |
| 933 } else { | |
| 934 return false; | |
| 935 } | |
| 936 } | |
| 937 | |
| 938 bool LogWriter::Unregister() { | |
| 939 Logging* logger = GetLogging(); | |
| 940 if (logger) { | |
| 941 return logger->RegisterWriter(this); | |
| 942 } else { | |
| 943 return false; | |
| 944 } | |
| 945 } | |
| 946 | |
| 947 // FileLogWriter | |
| 948 | |
| 949 FileLogWriter* FileLogWriter::Create(const wchar_t* file_name, bool append) { | |
| 950 return new FileLogWriter(file_name, append); | |
| 951 } | |
| 952 | |
| 953 FileLogWriter::FileLogWriter(const wchar_t* file_name, bool append) | |
| 954 : initialized_(false), | |
| 955 valid_(false), | |
| 956 file_name_(file_name), | |
| 957 log_file_mutex_(NULL), | |
| 958 log_file_(NULL), | |
| 959 append_(append), | |
| 960 max_file_size_(kDefaultMaxLogFileSize), | |
| 961 log_file_wide_(kDefaultLogFileWide) { | |
| 962 Logging* logger = GetLogging(); | |
| 963 if (logger) { | |
| 964 CString config_file_path = logger->GetCurrentConfigurationFilePath(); | |
| 965 if (!config_file_path.IsEmpty()) { | |
| 966 max_file_size_ = ::GetPrivateProfileInt( | |
| 967 kConfigSectionLoggingSettings, | |
| 968 kConfigAttrMaxLogFileSize, | |
| 969 kDefaultMaxLogFileSize, | |
| 970 config_file_path); | |
| 971 log_file_wide_ = ::GetPrivateProfileInt( | |
| 972 kConfigSectionLoggingSettings, | |
| 973 kConfigAttrLogFileWide, | |
| 974 kDefaultLogFileWide, | |
| 975 config_file_path) == 0 ? false : true; | |
| 976 } else { | |
| 977 max_file_size_ = kDefaultMaxLogFileSize; | |
| 978 log_file_wide_ = kDefaultLogFileWide; | |
| 979 } | |
| 980 proc_name_ = logger->proc_name(); | |
| 981 } | |
| 982 } | |
| 983 | |
| 984 FileLogWriter::~FileLogWriter() { | |
| 985 // TODO(omaha): Figure out a way to pass the proc_name - and possibly | |
| 986 // the show_time var - into here. | |
| 987 Logging* logger = GetLogging(); | |
| 988 if (logger && logger->IsLoggingAlreadyEnabled()) { | |
| 989 // OutputInfo info(LEVEL_WARNING, NULL, kEndOfLogMessage); | |
| 990 // OutputMessage(&info); | |
| 991 } | |
| 992 Cleanup(); | |
| 993 } | |
| 994 | |
| 995 void FileLogWriter::Initialize() { | |
| 996 if (initialized_) { | |
| 997 return; | |
| 998 } | |
| 999 | |
| 1000 initialized_ = true; | |
| 1001 | |
| 1002 bool already_created = CreateLoggingMutex(); | |
| 1003 if (!log_file_mutex_) { | |
| 1004 return; | |
| 1005 } | |
| 1006 | |
| 1007 if (already_created) { | |
| 1008 append_ = true; | |
| 1009 } | |
| 1010 | |
| 1011 if (!GetMutex()) { | |
| 1012 ::OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: " | |
| 1013 L"Could not acquire logging mutex %s\n", | |
| 1014 proc_name_, | |
| 1015 log_file_mutex_name_)); | |
| 1016 return; | |
| 1017 } | |
| 1018 | |
| 1019 CreateLoggingFile(); | |
| 1020 if (!log_file_) { | |
| 1021 ::OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: " | |
| 1022 L"Could not create logging file %s\n", | |
| 1023 proc_name_, | |
| 1024 file_name_)); | |
| 1025 valid_ = false; | |
| 1026 } | |
| 1027 | |
| 1028 valid_ = true; | |
| 1029 ReleaseMutex(); | |
| 1030 } | |
| 1031 | |
| 1032 void FileLogWriter::Cleanup() { | |
| 1033 if (log_file_) { | |
| 1034 ::CloseHandle(log_file_); | |
| 1035 } | |
| 1036 if (log_file_mutex_) { | |
| 1037 ::ReleaseMutex(log_file_mutex_); | |
| 1038 ::CloseHandle(log_file_mutex_); | |
| 1039 } | |
| 1040 } | |
| 1041 | |
| 1042 bool FileLogWriter::CreateLoggingMutex() { | |
| 1043 log_file_mutex_name_ = StripBackslashes(kLoggingMutexName L"_" + file_name_); | |
| 1044 // TODO(omaha): I don't see where this class is used, but I guess the | |
| 1045 // caller is always in the same context. We should use the default security | |
| 1046 // here. If the caller can be in different contexts (System Service, Usermode | |
| 1047 // applications, etc), then we should revisit this code to give access only | |
| 1048 // to those who really need it. What if a malicious piece a code decide | |
| 1049 // to get the mutex and lock it? If it happens, everytime you try to log | |
| 1050 // something, the thread would hang for 500ms and then fail to log the | |
| 1051 // message. | |
| 1052 CSecurityDesc sd; | |
| 1053 GetEveryoneDaclSecurityDescriptor(&sd, GENERIC_ALL, GENERIC_ALL); | |
| 1054 CSecurityAttributes sa(sd); | |
| 1055 log_file_mutex_ = CreateMutexWithSyncAccess(log_file_mutex_name_, &sa); | |
| 1056 if (log_file_mutex_) { | |
| 1057 return ERROR_ALREADY_EXISTS == ::GetLastError(); | |
| 1058 } | |
| 1059 return false; | |
| 1060 } | |
| 1061 | |
| 1062 bool FileLogWriter::CreateLoggingFile() { | |
| 1063 uint32 file_size(0); | |
| 1064 File::GetFileSizeUnopen(file_name_, &file_size); | |
| 1065 if (file_size > max_file_size_) { | |
| 1066 ArchiveLoggingFile(); | |
| 1067 } | |
| 1068 log_file_ = ::CreateFile(file_name_, | |
| 1069 GENERIC_WRITE, | |
| 1070 FILE_SHARE_WRITE | FILE_SHARE_READ, | |
| 1071 NULL, | |
| 1072 append_ ? OPEN_ALWAYS : CREATE_ALWAYS, | |
| 1073 FILE_ATTRIBUTE_NORMAL, | |
| 1074 NULL); | |
| 1075 if (log_file_ == INVALID_HANDLE_VALUE) { | |
| 1076 // The code in this file is written with the assumption that log_file_ is | |
| 1077 // NULL on creation errors. The easy fix is to set it to NULL here. The | |
| 1078 // long term fix should be implementing it in terms of a smart handle. | |
| 1079 log_file_ = NULL; | |
| 1080 return false; | |
| 1081 } | |
| 1082 | |
| 1083 // Allow users to read, write, and delete the log file. | |
| 1084 ACCESS_MASK mask = GENERIC_READ | GENERIC_WRITE | DELETE; | |
| 1085 CDacl dacl; | |
| 1086 if (dacl.AddAllowedAce(ATL::Sids::Users(), mask)) { | |
| 1087 AtlSetDacl(file_name_, SE_FILE_OBJECT, dacl); | |
| 1088 } | |
| 1089 | |
| 1090 // Insert a BOM in the newly created file. | |
| 1091 if (GetLastError() != ERROR_ALREADY_EXISTS && log_file_wide_) { | |
| 1092 DWORD num = 0; | |
| 1093 ::WriteFile(log_file_, &kUnicodeBom, sizeof(kUnicodeBom), &num, NULL); | |
| 1094 } | |
| 1095 return true; | |
| 1096 } | |
| 1097 | |
| 1098 bool FileLogWriter::TruncateLoggingFile() { | |
| 1099 DWORD share_mode = FILE_SHARE_WRITE; | |
| 1100 HANDLE log_file = ::CreateFile(file_name_, | |
| 1101 GENERIC_WRITE, | |
| 1102 FILE_SHARE_WRITE | FILE_SHARE_READ, | |
| 1103 NULL, | |
| 1104 TRUNCATE_EXISTING, | |
| 1105 FILE_ATTRIBUTE_NORMAL, | |
| 1106 NULL); | |
| 1107 if (log_file_ == INVALID_HANDLE_VALUE) { | |
| 1108 return false; | |
| 1109 } | |
| 1110 | |
| 1111 // Insert a BOM in the newly created file. | |
| 1112 if (log_file_wide_) { | |
| 1113 DWORD num = 0; | |
| 1114 ::WriteFile(log_file, &kUnicodeBom, sizeof(kUnicodeBom), &num, NULL); | |
| 1115 } | |
| 1116 ::CloseHandle(log_file); | |
| 1117 return true; | |
| 1118 } | |
| 1119 | |
| 1120 bool FileLogWriter::ArchiveLoggingFile() { | |
| 1121 ::OutputDebugString(L"LOG_SYSTEM: trying to move log file to backup\n"); | |
| 1122 CString backup_file_name = file_name_ + L".bak"; | |
| 1123 HRESULT hr = File::Move(file_name_, backup_file_name, true); | |
| 1124 if (FAILED(hr)) { | |
| 1125 ::OutputDebugString(L"LOG_SYSTEM: failed to move log file to backup\n"); | |
| 1126 | |
| 1127 // Trying to move the log file when loggers have it open returns | |
| 1128 // ERROR_SHARING_VIOLATION. Each call to MoveFileAfterReboot inserts the | |
| 1129 // file into PendingFileRenames list. Moving files at reboot requires the | |
| 1130 // user to be either the LocalSystem account or in the Administrators | |
| 1131 // group. | |
| 1132 if (!IsArchivePending()) { | |
| 1133 File::MoveAfterReboot(file_name_, backup_file_name); | |
| 1134 } | |
| 1135 return false; | |
| 1136 } | |
| 1137 return true; | |
| 1138 } | |
| 1139 | |
| 1140 bool FileLogWriter::IsArchivePending() { | |
| 1141 // We look at the PendingFileRenameOperations to see if our log file is | |
| 1142 // pending a rename. The list is a REG_MULTI_SZ, which is a sequence of | |
| 1143 // null-terminated strings, terminated by an empty string "\0". | |
| 1144 // The strings have the structure: | |
| 1145 // \??\file1\0!\??\file2\0\file3\0\0...\0\0. where file1 is to be renamed to | |
| 1146 // file2 and file3 is to be deleted. | |
| 1147 // It is valid for the PFR list to include an empty string in the middle | |
| 1148 // of the sequence. | |
| 1149 const wchar_t sub_key_name[] = L"SYSTEM\\CurrentControlSet\\Control\\" | |
| 1150 L"Session Manager"; | |
| 1151 HKEY key = NULL; | |
| 1152 int res = ::RegOpenKeyEx(HKEY_LOCAL_MACHINE, | |
| 1153 sub_key_name, | |
| 1154 0, | |
| 1155 KEY_READ, | |
| 1156 &key); | |
| 1157 if (res != ERROR_SUCCESS) { | |
| 1158 return false; | |
| 1159 } | |
| 1160 DWORD bytes = 0; | |
| 1161 DWORD type = REG_MULTI_SZ; | |
| 1162 res = ::RegQueryValueEx(key, | |
| 1163 L"PendingFileRenameOperations", | |
| 1164 0, | |
| 1165 &type, | |
| 1166 NULL, | |
| 1167 &bytes); | |
| 1168 if (!(res == ERROR_SUCCESS && type == REG_MULTI_SZ)) { | |
| 1169 return false; | |
| 1170 } | |
| 1171 scoped_array<byte> buf(new byte[bytes]); | |
| 1172 memset(buf.get(), 0, bytes); | |
| 1173 res = ::RegQueryValueEx(key, | |
| 1174 L"PendingFileRenameOperations", | |
| 1175 0, | |
| 1176 NULL, | |
| 1177 buf.get(), | |
| 1178 &bytes); | |
| 1179 if (res != ERROR_SUCCESS) { | |
| 1180 return false; | |
| 1181 } | |
| 1182 const wchar_t* multi_str = reinterpret_cast<const wchar_t*>(buf.get()); | |
| 1183 size_t count = bytes / sizeof(*multi_str); | |
| 1184 const size_t kMaxRegistryValueLen = 1024 * 1024; // 1MB | |
| 1185 if (!(count >= 2 && | |
| 1186 count < kMaxRegistryValueLen && | |
| 1187 multi_str[count - 2] == L'\0' && | |
| 1188 multi_str[count - 1] == L'\0')) { | |
| 1189 return false; | |
| 1190 } | |
| 1191 // The file names in the PFR list are prefixed by \??\. | |
| 1192 CString file_name = L"\\??\\" + file_name_; | |
| 1193 return FindFirstInMultiString(multi_str, count, file_name) != -1; | |
| 1194 } | |
| 1195 | |
| 1196 int FileLogWriter::FindFirstInMultiString(const wchar_t* multi_str, | |
| 1197 size_t count, | |
| 1198 const wchar_t* str) { | |
| 1199 const wchar_t* p = multi_str; | |
| 1200 size_t i = 0; | |
| 1201 while (i < count) { | |
| 1202 p = multi_str + i; | |
| 1203 if (lstrcmp(p, str) == 0) { | |
| 1204 return i; | |
| 1205 } else { | |
| 1206 size_t len = lstrlen(p); | |
| 1207 i += len + 1; | |
| 1208 } | |
| 1209 } | |
| 1210 return -1; | |
| 1211 } | |
| 1212 | |
| 1213 void FileLogWriter::OutputMessage(const OutputInfo* output_info) { | |
| 1214 if (!initialized_) { | |
| 1215 Initialize(); | |
| 1216 } | |
| 1217 | |
| 1218 if (!valid_) { | |
| 1219 return; | |
| 1220 } | |
| 1221 | |
| 1222 // Acquire the mutex. | |
| 1223 if (!GetMutex()) { | |
| 1224 return; | |
| 1225 } | |
| 1226 | |
| 1227 // Move to end of file. | |
| 1228 DWORD pos = ::SetFilePointer(log_file_, 0, NULL, FILE_END); | |
| 1229 int64 stop_gap_file_size = kStopGapLogFileSizeFactor * | |
| 1230 static_cast<int64>(max_file_size_); | |
| 1231 if (pos >= stop_gap_file_size) { | |
| 1232 if (!TruncateLoggingFile()) { | |
| 1233 // Logging stops until the log can be archived over since we do not | |
| 1234 // want to overfill the disk. | |
| 1235 return; | |
| 1236 } | |
| 1237 } | |
| 1238 pos = ::SetFilePointer(log_file_, 0, NULL, FILE_END); | |
| 1239 | |
| 1240 // Write the date, followed by a CRLF | |
| 1241 DWORD written_size = 0; | |
| 1242 if (output_info->msg1) { | |
| 1243 if (log_file_wide_) { | |
| 1244 ::WriteFile(log_file_, output_info->msg1, | |
| 1245 lstrlen(output_info->msg1) * sizeof(wchar_t), &written_size, | |
| 1246 NULL); | |
| 1247 } else { | |
| 1248 CStringA msg(WideToAnsiDirect(output_info->msg1)); | |
| 1249 ::WriteFile(log_file_, msg.GetString(), msg.GetLength(), &written_size, | |
| 1250 NULL); | |
| 1251 } | |
| 1252 } | |
| 1253 | |
| 1254 if (output_info->msg2) { | |
| 1255 if (log_file_wide_) { | |
| 1256 ::WriteFile(log_file_, output_info->msg2, | |
| 1257 lstrlen(output_info->msg2) * sizeof(wchar_t), &written_size, | |
| 1258 NULL); | |
| 1259 } else { | |
| 1260 CStringA msg(WideToAnsiDirect(output_info->msg2)); | |
| 1261 ::WriteFile(log_file_, msg.GetString(), msg.GetLength(), &written_size, | |
| 1262 NULL); | |
| 1263 } | |
| 1264 } | |
| 1265 | |
| 1266 if (log_file_wide_) { | |
| 1267 ::WriteFile(log_file_, L"\r\n", 2 * sizeof(wchar_t), &written_size, NULL); | |
| 1268 } else { | |
| 1269 ::WriteFile(log_file_, "\r\n", 2, &written_size, NULL); | |
| 1270 } | |
| 1271 | |
| 1272 ReleaseMutex(); | |
| 1273 } | |
| 1274 | |
| 1275 bool FileLogWriter::GetMutex() { | |
| 1276 if (!log_file_mutex_) { | |
| 1277 return false; | |
| 1278 } | |
| 1279 | |
| 1280 DWORD res = ::WaitForSingleObject(log_file_mutex_, kMaxMutexWaitTimeMs); | |
| 1281 if (res != WAIT_OBJECT_0 && res != WAIT_ABANDONED) { | |
| 1282 ::OutputDebugString(SPRINTF(L"LOG_SYSTEM: [%s]: " | |
| 1283 L"Could not acquire logging mutex %s\n", | |
| 1284 proc_name_, log_file_mutex_name_)); | |
| 1285 valid_ = false; | |
| 1286 return false; | |
| 1287 } | |
| 1288 | |
| 1289 return true; | |
| 1290 } | |
| 1291 | |
| 1292 void FileLogWriter::ReleaseMutex() { | |
| 1293 if (log_file_mutex_) { | |
| 1294 ::ReleaseMutex(log_file_mutex_); | |
| 1295 } | |
| 1296 } | |
| 1297 | |
| 1298 // OutputDebugStringLogWriter. | |
| 1299 OutputDebugStringLogWriter* OutputDebugStringLogWriter::Create() { | |
| 1300 return new OutputDebugStringLogWriter(); | |
| 1301 } | |
| 1302 | |
| 1303 OutputDebugStringLogWriter::OutputDebugStringLogWriter() {} | |
| 1304 | |
| 1305 OutputDebugStringLogWriter::~OutputDebugStringLogWriter() { | |
| 1306 Logging* logger = GetLogging(); | |
| 1307 if (logger && logger->IsLoggingAlreadyEnabled()) { | |
| 1308 // OutputInfo info(LEVEL_WARNING, NULL, kEndOfLogMessage); | |
| 1309 // OutputMessage(&info); | |
| 1310 } | |
| 1311 Cleanup(); | |
| 1312 } | |
| 1313 | |
| 1314 void OutputDebugStringLogWriter::OutputMessage(const OutputInfo* output_info) { | |
| 1315 // Combine everything into one string so that messages coming from | |
| 1316 // multiple threads don't get interleaved. | |
| 1317 ::OutputDebugString(SPRINTF(L"%s%s\n", output_info->msg1, output_info->msg2)); | |
| 1318 } | |
| 1319 | |
| 1320 // OverrideConfigLogWriter. | |
| 1321 OverrideConfigLogWriter* OverrideConfigLogWriter::Create(LogCategory category, | |
| 1322 LogLevel level, LogWriter* log_writer, bool force_logging_enabled) { | |
| 1323 return new OverrideConfigLogWriter(category, | |
| 1324 level, | |
| 1325 log_writer, | |
| 1326 force_logging_enabled); | |
| 1327 } | |
| 1328 | |
| 1329 OverrideConfigLogWriter::OverrideConfigLogWriter(LogCategory category, | |
| 1330 LogLevel level, | |
| 1331 LogWriter* log_writer, | |
| 1332 bool force_logging_enabled) | |
| 1333 : category_(category), | |
| 1334 level_(level), | |
| 1335 log_writer_(log_writer), | |
| 1336 force_logging_enabled_(force_logging_enabled) {} | |
| 1337 | |
| 1338 void OverrideConfigLogWriter::Cleanup() { | |
| 1339 if (log_writer_) { | |
| 1340 delete log_writer_; | |
| 1341 } | |
| 1342 } | |
| 1343 | |
| 1344 bool OverrideConfigLogWriter::WantsToLogRegardless() const { | |
| 1345 return force_logging_enabled_; | |
| 1346 } | |
| 1347 | |
| 1348 bool OverrideConfigLogWriter::IsCatLevelEnabled(LogCategory category, | |
| 1349 LogLevel level) const { | |
| 1350 if (category != category_) { | |
| 1351 return false; | |
| 1352 } | |
| 1353 if (level > level_) { | |
| 1354 return false; | |
| 1355 } | |
| 1356 return true; | |
| 1357 } | |
| 1358 | |
| 1359 void OverrideConfigLogWriter::OutputMessage(const OutputInfo* output_info) { | |
| 1360 if (log_writer_) { | |
| 1361 log_writer_->OutputMessage(output_info); | |
| 1362 } | |
| 1363 return; | |
| 1364 } | |
| 1365 | |
| 1366 } // namespace omaha | |
| 1367 | |
| 1368 #endif // LOGGING | |
| 1369 | |
| OLD | NEW |
|---|
Chromium Code Reviews
Issue 624713003:
Keep only base/extractor.[cc|h]. (Closed)
Base URL: https://chromium.googlesource.com/external/omaha.git@master