device_event_log_impl.cc 18 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521
  1. // Copyright 2014 The Chromium Authors. All rights reserved.
  2. // Use of this source code is governed by a BSD-style license that can be
  3. // found in the LICENSE file.
  4. #include "components/device_event_log/device_event_log_impl.h"
  5. #include <cmath>
  6. #include <list>
  7. #include <set>
  8. #include "base/bind.h"
  9. #include "base/containers/adapters.h"
  10. #include "base/json/json_string_value_serializer.h"
  11. #include "base/json/json_writer.h"
  12. #include "base/location.h"
  13. #include "base/logging.h"
  14. #include "base/process/process_handle.h"
  15. #include "base/strings/string_tokenizer.h"
  16. #include "base/strings/string_util.h"
  17. #include "base/strings/stringprintf.h"
  18. #include "base/strings/utf_string_conversions.h"
  19. #include "base/values.h"
  20. #include "build/build_config.h"
  21. namespace device_event_log {
  22. namespace {
  23. const char* const kLogLevelName[] = {"Error", "User", "Event", "Debug"};
  24. const char kLogTypeNetworkDesc[] = "Network";
  25. const char kLogTypePowerDesc[] = "Power";
  26. const char kLogTypeLoginDesc[] = "Login";
  27. const char kLogTypeBluetoothDesc[] = "Bluetooth";
  28. const char kLogTypeUsbDesc[] = "USB";
  29. const char kLogTypeHidDesc[] = "HID";
  30. const char kLogTypeMemoryDesc[] = "Memory";
  31. const char kLogTypePrinterDesc[] = "Printer";
  32. const char kLogTypeFidoDesc[] = "FIDO";
  33. const char kLogTypeSerialDesc[] = "Serial";
  34. const char kLogTypeCameraDesc[] = "Camera";
  35. enum class ShowTime {
  36. kNone,
  37. kTimeWithMs,
  38. kUnix,
  39. };
  40. std::string GetLogTypeString(LogType type) {
  41. switch (type) {
  42. case LOG_TYPE_NETWORK:
  43. return kLogTypeNetworkDesc;
  44. case LOG_TYPE_POWER:
  45. return kLogTypePowerDesc;
  46. case LOG_TYPE_LOGIN:
  47. return kLogTypeLoginDesc;
  48. case LOG_TYPE_BLUETOOTH:
  49. return kLogTypeBluetoothDesc;
  50. case LOG_TYPE_USB:
  51. return kLogTypeUsbDesc;
  52. case LOG_TYPE_HID:
  53. return kLogTypeHidDesc;
  54. case LOG_TYPE_MEMORY:
  55. return kLogTypeMemoryDesc;
  56. case LOG_TYPE_PRINTER:
  57. return kLogTypePrinterDesc;
  58. case LOG_TYPE_FIDO:
  59. return kLogTypeFidoDesc;
  60. case LOG_TYPE_SERIAL:
  61. return kLogTypeSerialDesc;
  62. case LOG_TYPE_CAMERA:
  63. return kLogTypeCameraDesc;
  64. case LOG_TYPE_UNKNOWN:
  65. break;
  66. }
  67. NOTREACHED();
  68. return "Unknown";
  69. }
  70. LogType GetLogTypeFromString(base::StringPiece desc) {
  71. std::string desc_lc = base::ToLowerASCII(desc);
  72. for (int i = 0; i < LOG_TYPE_UNKNOWN; ++i) {
  73. auto type = static_cast<LogType>(i);
  74. std::string log_desc_lc = base::ToLowerASCII(GetLogTypeString(type));
  75. if (desc_lc == log_desc_lc)
  76. return type;
  77. }
  78. NOTREACHED() << "Unrecogized LogType: " << desc;
  79. return LOG_TYPE_UNKNOWN;
  80. }
  81. std::string DateAndTimeWithMicroseconds(const base::Time& time) {
  82. base::Time::Exploded exploded;
  83. time.LocalExplode(&exploded);
  84. // base::Time::Exploded does not include microseconds, but sometimes we need
  85. // microseconds, so append '.' + usecs to the end of the formatted string.
  86. int usecs = static_cast<int>(fmod(time.ToDoubleT() * 1000000, 1000000));
  87. return base::StringPrintf("%04d/%02d/%02d %02d:%02d:%02d.%06d", exploded.year,
  88. exploded.month, exploded.day_of_month,
  89. exploded.hour, exploded.minute, exploded.second,
  90. usecs);
  91. }
  92. std::string TimeWithSeconds(const base::Time& time) {
  93. base::Time::Exploded exploded;
  94. time.LocalExplode(&exploded);
  95. return base::StringPrintf("%02d:%02d:%02d", exploded.hour, exploded.minute,
  96. exploded.second);
  97. }
  98. std::string TimeWithMillieconds(const base::Time& time) {
  99. base::Time::Exploded exploded;
  100. time.LocalExplode(&exploded);
  101. return base::StringPrintf("%02d:%02d:%02d.%03d", exploded.hour,
  102. exploded.minute, exploded.second,
  103. exploded.millisecond);
  104. }
  105. #if BUILDFLAG(IS_POSIX)
  106. std::string UnixTime(const base::Time& time) {
  107. base::Time::Exploded utc_exploded, exploded;
  108. time.UTCExplode(&utc_exploded);
  109. time.LocalExplode(&exploded);
  110. // Note: |timezone_hours| is only used to display the correct timezone UTC
  111. // offset (which alas is not conveniently provided in Time::Exploded).
  112. // Thus, we don't have to account for any date shift, it is already considered
  113. // in |exploded| (i.e. exploded.day may not match utc_exploded.day).
  114. int timezone_hours = exploded.hour - utc_exploded.hour;
  115. if (timezone_hours >= 12)
  116. timezone_hours = 24 - timezone_hours;
  117. else if (timezone_hours <= -12)
  118. timezone_hours = 24 + timezone_hours;
  119. char sign = timezone_hours > 0 ? '+' : '-';
  120. // See note in DateAndTimeWithMicroseconds.
  121. int usecs = static_cast<int>(fmod(time.ToDoubleT() * 1000000, 1000000));
  122. // This format is consistent with the date/time format in /var/log/messages
  123. // and /var/log/net.log, e.g: 2020-01-23T01:23:45.678901-07:00.
  124. // Note: %+02d does not respect the '0', resulting in e.g. +7:00.
  125. return base::StringPrintf(
  126. "%04d-%02d-%02dT%02d:%02d:%02d.%06d%c%02d:00", exploded.year,
  127. exploded.month, exploded.day_of_month, exploded.hour, exploded.minute,
  128. exploded.second, usecs, sign, std::abs(timezone_hours));
  129. }
  130. #endif
  131. std::string LogEntryToString(const DeviceEventLogImpl::LogEntry& log_entry,
  132. ShowTime show_time,
  133. bool show_file,
  134. bool show_type,
  135. bool show_level) {
  136. std::string line;
  137. if (show_time == ShowTime::kTimeWithMs)
  138. line += "[" + TimeWithMillieconds(log_entry.time) + "] ";
  139. #if BUILDFLAG(IS_POSIX)
  140. if (show_time == ShowTime::kUnix)
  141. line += UnixTime(log_entry.time) + " ";
  142. #endif
  143. if (show_type)
  144. line += GetLogTypeString(log_entry.log_type) + ": ";
  145. if (show_level) {
  146. const char* kLevelDesc[] = {"ERROR", "USER", "EVENT", "DEBUG"};
  147. line += std::string(kLevelDesc[log_entry.log_level]);
  148. #if BUILDFLAG(IS_POSIX)
  149. if (show_time == ShowTime::kUnix) {
  150. // Format the level consistently with /var/log/messages.
  151. line += base::StringPrintf(" chrome[%d]", base::GetCurrentProcId());
  152. }
  153. #endif
  154. line += ": ";
  155. }
  156. if (show_file) {
  157. line += base::StringPrintf("%s:%d ", log_entry.file.c_str(),
  158. log_entry.file_line);
  159. }
  160. line += log_entry.event;
  161. if (log_entry.count > 1)
  162. line += base::StringPrintf(" (%d)", log_entry.count);
  163. return line;
  164. }
  165. void LogEntryToDictionary(const DeviceEventLogImpl::LogEntry& log_entry,
  166. base::DictionaryValue* output) {
  167. output->SetString("timestamp", DateAndTimeWithMicroseconds(log_entry.time));
  168. output->SetString("timestampshort", TimeWithSeconds(log_entry.time));
  169. output->SetString("level", kLogLevelName[log_entry.log_level]);
  170. output->SetString("type", GetLogTypeString(log_entry.log_type));
  171. output->SetString("file", base::StringPrintf("%s:%d ", log_entry.file.c_str(),
  172. log_entry.file_line));
  173. output->SetString("event", log_entry.event);
  174. }
  175. std::string LogEntryAsJSON(const DeviceEventLogImpl::LogEntry& log_entry) {
  176. base::DictionaryValue entry_dict;
  177. LogEntryToDictionary(log_entry, &entry_dict);
  178. std::string json;
  179. JSONStringValueSerializer serializer(&json);
  180. if (!serializer.Serialize(entry_dict)) {
  181. LOG(ERROR) << "Failed to serialize to JSON";
  182. }
  183. return json;
  184. }
  185. void SendLogEntryToVLogOrErrorLog(
  186. const DeviceEventLogImpl::LogEntry& log_entry) {
  187. if (log_entry.log_level != LOG_LEVEL_ERROR && !VLOG_IS_ON(1))
  188. return;
  189. const ShowTime show_time = ShowTime::kTimeWithMs;
  190. const bool show_file = true;
  191. const bool show_type = true;
  192. const bool show_level = log_entry.log_level != LOG_LEVEL_ERROR;
  193. std::string output =
  194. LogEntryToString(log_entry, show_time, show_file, show_type, show_level);
  195. if (log_entry.log_level == LOG_LEVEL_ERROR)
  196. LOG(ERROR) << output;
  197. else
  198. VLOG(1) << output;
  199. }
  200. bool LogEntryMatches(const DeviceEventLogImpl::LogEntry& first,
  201. const DeviceEventLogImpl::LogEntry& second) {
  202. return first.file == second.file && first.file_line == second.file_line &&
  203. first.log_level == second.log_level &&
  204. first.log_type == second.log_type && first.event == second.event;
  205. }
  206. bool LogEntryMatchesTypes(const DeviceEventLogImpl::LogEntry& entry,
  207. const std::set<LogType>& include_types,
  208. const std::set<LogType>& exclude_types) {
  209. if (include_types.empty() && exclude_types.empty())
  210. return true;
  211. if (!include_types.empty() && include_types.count(entry.log_type))
  212. return true;
  213. if (!exclude_types.empty() && !exclude_types.count(entry.log_type))
  214. return true;
  215. return false;
  216. }
  217. void GetFormat(const std::string& format_string,
  218. ShowTime* show_time,
  219. bool* show_file,
  220. bool* show_type,
  221. bool* show_level,
  222. bool* format_json) {
  223. base::StringTokenizer tokens(format_string, ",");
  224. *show_time = ShowTime::kNone;
  225. *show_file = false;
  226. *show_type = false;
  227. *show_level = false;
  228. *format_json = false;
  229. while (tokens.GetNext()) {
  230. base::StringPiece tok = tokens.token_piece();
  231. if (tok == "time") {
  232. *show_time = ShowTime::kTimeWithMs;
  233. } else if (tok == "unixtime") {
  234. #if BUILDFLAG(IS_POSIX)
  235. *show_time = ShowTime::kUnix;
  236. #else
  237. *show_time = ShowTime::kTimeWithMs;
  238. #endif
  239. } else if (tok == "file") {
  240. *show_file = true;
  241. } else if (tok == "type") {
  242. *show_type = true;
  243. } else if (tok == "level") {
  244. *show_level = true;
  245. } else if (tok == "json") {
  246. *format_json = true;
  247. }
  248. }
  249. }
  250. void GetLogTypes(const std::string& types,
  251. std::set<LogType>* include_types,
  252. std::set<LogType>* exclude_types) {
  253. base::StringTokenizer tokens(types, ",");
  254. while (tokens.GetNext()) {
  255. base::StringPiece tok = tokens.token_piece();
  256. if (base::StartsWith(tok, "non-")) {
  257. LogType type = GetLogTypeFromString(tok.substr(4));
  258. if (type != LOG_TYPE_UNKNOWN)
  259. exclude_types->insert(type);
  260. } else {
  261. LogType type = GetLogTypeFromString(tok);
  262. if (type != LOG_TYPE_UNKNOWN)
  263. include_types->insert(type);
  264. }
  265. }
  266. }
  267. // Update count and time for identical events to avoid log spam.
  268. void IncreaseLogEntryCount(const DeviceEventLogImpl::LogEntry& new_entry,
  269. DeviceEventLogImpl::LogEntry* cur_entry) {
  270. ++cur_entry->count;
  271. cur_entry->log_level = std::min(cur_entry->log_level, new_entry.log_level);
  272. cur_entry->time = base::Time::Now();
  273. }
  274. } // namespace
  275. // static
  276. void DeviceEventLogImpl::SendToVLogOrErrorLog(const char* file,
  277. int file_line,
  278. LogType log_type,
  279. LogLevel log_level,
  280. const std::string& event) {
  281. LogEntry entry(file, file_line, log_type, log_level, event);
  282. SendLogEntryToVLogOrErrorLog(entry);
  283. }
  284. DeviceEventLogImpl::DeviceEventLogImpl(
  285. scoped_refptr<base::SingleThreadTaskRunner> task_runner,
  286. size_t max_entries)
  287. : task_runner_(task_runner), max_entries_(max_entries) {
  288. DCHECK(task_runner_);
  289. }
  290. DeviceEventLogImpl::~DeviceEventLogImpl() {}
  291. void DeviceEventLogImpl::AddEntry(const char* file,
  292. int file_line,
  293. LogType log_type,
  294. LogLevel log_level,
  295. const std::string& event) {
  296. LogEntry entry(file, file_line, log_type, log_level, event);
  297. if (!task_runner_->RunsTasksInCurrentSequence()) {
  298. task_runner_->PostTask(
  299. FROM_HERE, base::BindOnce(&DeviceEventLogImpl::AddLogEntry,
  300. weak_ptr_factory_.GetWeakPtr(), entry));
  301. return;
  302. }
  303. AddLogEntry(entry);
  304. }
  305. void DeviceEventLogImpl::AddEntryWithTimestampForTesting(
  306. const char* file,
  307. int file_line,
  308. LogType log_type,
  309. LogLevel log_level,
  310. const std::string& event,
  311. base::Time time) {
  312. LogEntry entry(file, file_line, log_type, log_level, event, time);
  313. if (!task_runner_->RunsTasksInCurrentSequence()) {
  314. task_runner_->PostTask(
  315. FROM_HERE, base::BindOnce(&DeviceEventLogImpl::AddLogEntry,
  316. weak_ptr_factory_.GetWeakPtr(), entry));
  317. return;
  318. }
  319. AddLogEntry(entry);
  320. }
  321. void DeviceEventLogImpl::AddLogEntry(const LogEntry& entry) {
  322. DCHECK(task_runner_->RunsTasksInCurrentSequence());
  323. if (!entries_.empty()) {
  324. LogEntry& last = entries_.back();
  325. if (LogEntryMatches(last, entry)) {
  326. IncreaseLogEntryCount(entry, &last);
  327. return;
  328. }
  329. }
  330. if (entries_.size() >= max_entries_)
  331. RemoveEntry();
  332. entries_.push_back(entry);
  333. SendLogEntryToVLogOrErrorLog(entry);
  334. }
  335. void DeviceEventLogImpl::RemoveEntry() {
  336. const size_t max_error_entries = max_entries_ / 2;
  337. DCHECK(max_error_entries < entries_.size());
  338. // Remove the first (oldest) non-error entry, or the oldest entry if more
  339. // than half the entries are errors.
  340. size_t error_count = 0;
  341. for (auto iter = entries_.begin(); iter != entries_.end(); ++iter) {
  342. if (iter->log_level != LOG_LEVEL_ERROR) {
  343. entries_.erase(iter);
  344. return;
  345. }
  346. if (++error_count > max_error_entries)
  347. break;
  348. }
  349. // Too many error entries, remove the oldest entry.
  350. entries_.pop_front();
  351. }
  352. std::string DeviceEventLogImpl::GetAsString(StringOrder order,
  353. const std::string& format,
  354. const std::string& types,
  355. LogLevel max_level,
  356. size_t max_events) {
  357. DCHECK(task_runner_->RunsTasksInCurrentSequence());
  358. if (entries_.empty())
  359. return "No Log Entries.";
  360. ShowTime show_time;
  361. bool show_file, show_type, show_level, format_json;
  362. GetFormat(format, &show_time, &show_file, &show_type, &show_level,
  363. &format_json);
  364. std::set<LogType> include_types, exclude_types;
  365. GetLogTypes(types, &include_types, &exclude_types);
  366. std::string result;
  367. base::Value log_entries(base::Value::Type::LIST);
  368. if (order == OLDEST_FIRST) {
  369. size_t offset = 0;
  370. if (max_events > 0 && max_events < entries_.size()) {
  371. // Iterate backwards through the list skipping uninteresting entries to
  372. // determine the first entry to include.
  373. size_t shown_events = 0;
  374. size_t num_entries = 0;
  375. for (const LogEntry& entry : base::Reversed(entries_)) {
  376. ++num_entries;
  377. if (!LogEntryMatchesTypes(entry, include_types, exclude_types))
  378. continue;
  379. if (entry.log_level > max_level)
  380. continue;
  381. if (++shown_events >= max_events)
  382. break;
  383. }
  384. offset = entries_.size() - num_entries;
  385. }
  386. for (const LogEntry& entry : entries_) {
  387. if (offset > 0) {
  388. --offset;
  389. continue;
  390. }
  391. if (!LogEntryMatchesTypes(entry, include_types, exclude_types))
  392. continue;
  393. if (entry.log_level > max_level)
  394. continue;
  395. if (format_json) {
  396. log_entries.Append(LogEntryAsJSON(entry));
  397. } else {
  398. result += LogEntryToString(entry, show_time, show_file, show_type,
  399. show_level);
  400. result += "\n";
  401. }
  402. }
  403. } else {
  404. size_t nlines = 0;
  405. // Iterate backwards through the list to show the most recent entries first.
  406. for (const LogEntry& entry : base::Reversed(entries_)) {
  407. if (!LogEntryMatchesTypes(entry, include_types, exclude_types))
  408. continue;
  409. if (entry.log_level > max_level)
  410. continue;
  411. if (format_json) {
  412. log_entries.Append(LogEntryAsJSON(entry));
  413. } else {
  414. result += LogEntryToString(entry, show_time, show_file, show_type,
  415. show_level);
  416. result += "\n";
  417. }
  418. if (max_events > 0 && ++nlines >= max_events)
  419. break;
  420. }
  421. }
  422. if (format_json) {
  423. JSONStringValueSerializer serializer(&result);
  424. serializer.Serialize(log_entries);
  425. }
  426. return result;
  427. }
  428. void DeviceEventLogImpl::ClearAll() {
  429. entries_.clear();
  430. }
  431. void DeviceEventLogImpl::Clear(const base::Time& begin, const base::Time& end) {
  432. auto begin_it = std::find_if(
  433. entries_.begin(), entries_.end(),
  434. [begin](const LogEntry& entry) { return entry.time >= begin; });
  435. auto end_rev_it =
  436. std::find_if(entries_.rbegin(), entries_.rend(),
  437. [end](const LogEntry& entry) { return entry.time <= end; });
  438. entries_.erase(begin_it, end_rev_it.base());
  439. }
  440. int DeviceEventLogImpl::GetCountByLevelForTesting(LogLevel level) {
  441. int count = 0;
  442. for (const auto& entry : entries_) {
  443. if (entry.log_level == level)
  444. ++count;
  445. }
  446. return count;
  447. }
  448. DeviceEventLogImpl::LogEntry::LogEntry(const char* filedesc,
  449. int file_line,
  450. LogType log_type,
  451. LogLevel log_level,
  452. const std::string& event)
  453. : file_line(file_line),
  454. log_type(log_type),
  455. log_level(log_level),
  456. time(base::Time::Now()),
  457. count(1) {
  458. base::TrimWhitespaceASCII(event, base::TRIM_ALL, &this->event);
  459. if (filedesc) {
  460. file = filedesc;
  461. size_t last_slash_pos = file.find_last_of("\\/");
  462. if (last_slash_pos != std::string::npos) {
  463. file.erase(0, last_slash_pos + 1);
  464. }
  465. }
  466. }
  467. DeviceEventLogImpl::LogEntry::LogEntry(const char* filedesc,
  468. int file_line,
  469. LogType log_type,
  470. LogLevel log_level,
  471. const std::string& event,
  472. base::Time time_for_testing)
  473. : LogEntry(filedesc, file_line, log_type, log_level, event) {
  474. time = time_for_testing;
  475. }
  476. DeviceEventLogImpl::LogEntry::LogEntry(const LogEntry& other) = default;
  477. } // namespace device_event_log