From 513037a7e88db35a9fa98773a755fb0bfb2b129d Mon Sep 17 00:00:00 2001 From: Anton Date: Fri, 12 Apr 2024 10:55:10 -0700 Subject: [PATCH] Add logTrace API for Kabuki to log instrumentation events through JS h5vcc API (#2877) Add a ringbuffer to the watchdog to hold events emitted from logEvent() API. InstrumentationLog is thread-safe. LogTrace(snapshot of event log) is added to the violation json when violation is created. b/327680765 Change-Id: I73159740487d7e791e8a0238999b5b06f1e2ae47 (cherry picked from commit 6d4c825e9716db3c6eebf96fbeff0aca34e55069) --- cobalt/BUILD.gn | 1 + cobalt/h5vcc/h5vcc_crash_log.cc | 30 +++++ cobalt/h5vcc/h5vcc_crash_log.h | 6 + cobalt/h5vcc/h5vcc_crash_log.idl | 15 +++ cobalt/watchdog/BUILD.gn | 7 +- cobalt/watchdog/instrumentation_log.cc | 63 ++++++++++ cobalt/watchdog/instrumentation_log.h | 59 ++++++++++ cobalt/watchdog/instrumentation_log_test.cc | 122 ++++++++++++++++++++ cobalt/watchdog/watchdog.cc | 30 +++-- cobalt/watchdog/watchdog.h | 8 ++ cobalt/watchdog/watchdog_test.cc | 53 +++++++++ 11 files changed, 385 insertions(+), 9 deletions(-) create mode 100644 cobalt/watchdog/instrumentation_log.cc create mode 100644 cobalt/watchdog/instrumentation_log.h create mode 100644 cobalt/watchdog/instrumentation_log_test.cc diff --git a/cobalt/BUILD.gn b/cobalt/BUILD.gn index 92fe9dc4d66f..d6acce9863de 100644 --- a/cobalt/BUILD.gn +++ b/cobalt/BUILD.gn @@ -40,6 +40,7 @@ group("gn_all") { "//cobalt/renderer/sandbox:scaling_text_sandbox", "//cobalt/speech/sandbox:speech_sandbox", "//cobalt/ui_navigation/scroll_engine:scroll_engine_tests", + "//cobalt/watchdog:watchdog_test", "//cobalt/web:web_test", "//cobalt/web_animations:web_animations_test", "//cobalt/webdriver:webdriver_test", diff --git a/cobalt/h5vcc/h5vcc_crash_log.cc b/cobalt/h5vcc/h5vcc_crash_log.cc index 39c545c9da23..a11a3adb5915 100644 --- a/cobalt/h5vcc/h5vcc_crash_log.cc +++ b/cobalt/h5vcc/h5vcc_crash_log.cc @@ -226,5 +226,35 @@ void H5vccCrashLog::SetPersistentSettingWatchdogCrash(bool can_trigger_crash) { if (watchdog) watchdog->SetPersistentSettingWatchdogCrash(can_trigger_crash); } +bool H5vccCrashLog::LogEvent(const std::string& event) { + watchdog::Watchdog* watchdog = watchdog::Watchdog::GetInstance(); + if (!watchdog) { + return false; + } + + return watchdog->LogEvent(event); +} + +script::Sequence H5vccCrashLog::GetLogTrace() { + watchdog::Watchdog* watchdog = watchdog::Watchdog::GetInstance(); + + script::Sequence sequence; + if (watchdog) { + std::vector logTrace = watchdog->GetLogTrace(); + for (std::size_t i = 0; i < logTrace.size(); ++i) { + sequence.push_back(logTrace[i]); + } + } + + return sequence; +} + +void H5vccCrashLog::ClearLog() { + watchdog::Watchdog* watchdog = watchdog::Watchdog::GetInstance(); + if (watchdog) { + watchdog->ClearLog(); + } +} + } // namespace h5vcc } // namespace cobalt diff --git a/cobalt/h5vcc/h5vcc_crash_log.h b/cobalt/h5vcc/h5vcc_crash_log.h index e01d23e44841..0e5fa5cf985e 100644 --- a/cobalt/h5vcc/h5vcc_crash_log.h +++ b/cobalt/h5vcc/h5vcc_crash_log.h @@ -91,6 +91,12 @@ class H5vccCrashLog : public script::Wrappable { void SetPersistentSettingWatchdogCrash(bool can_trigger_crash); + bool LogEvent(const std::string& event); + + script::Sequence GetLogTrace(); + + void ClearLog(); + DEFINE_WRAPPABLE_TYPE(H5vccCrashLog); private: diff --git a/cobalt/h5vcc/h5vcc_crash_log.idl b/cobalt/h5vcc/h5vcc_crash_log.idl index e60e0abd825e..0596c0d24ec3 100644 --- a/cobalt/h5vcc/h5vcc_crash_log.idl +++ b/cobalt/h5vcc/h5vcc_crash_log.idl @@ -108,4 +108,19 @@ interface H5vccCrashLog { // Sets a persistent Watchdog setting that determines whether or not a // Watchdog violation will trigger a crash. void setPersistentSettingWatchdogCrash(boolean can_trigger_crash); + + // Appends a string event to a ring buffer. These log events can be appended + // from JS code. When watchdog violation is created, a snapshot of + // that buffer is attached to a violation. Identical sequential events + // are de-duplicated. + // Max event length is 256. Ring buffer size is 128. + boolean logEvent(DOMString event); + + // Returns a snapshot (a "logTrace") of ring buffer of log events. + // This can be used to read a logTrace at arbitrary moment, + // without any violation. + sequence getLogTrace(); + + // Clears the ring buffer of log events. + void clearLog(); }; diff --git a/cobalt/watchdog/BUILD.gn b/cobalt/watchdog/BUILD.gn index 131d334ebecd..92bb7f35cfe7 100644 --- a/cobalt/watchdog/BUILD.gn +++ b/cobalt/watchdog/BUILD.gn @@ -14,6 +14,8 @@ static_library("watchdog") { sources = [ + "instrumentation_log.cc", + "instrumentation_log.h", "watchdog.cc", "watchdog.h", ] @@ -29,7 +31,10 @@ static_library("watchdog") { target(gtest_target_type, "watchdog_test") { testonly = true - sources = [ "watchdog_test.cc" ] + sources = [ + "instrumentation_log_test.cc", + "watchdog_test.cc", + ] deps = [ ":watchdog", diff --git a/cobalt/watchdog/instrumentation_log.cc b/cobalt/watchdog/instrumentation_log.cc new file mode 100644 index 000000000000..7eccf9170b49 --- /dev/null +++ b/cobalt/watchdog/instrumentation_log.cc @@ -0,0 +1,63 @@ +// Copyright 2024 The Cobalt Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#include "cobalt/watchdog/instrumentation_log.h" + +#include +#include + +namespace cobalt { +namespace watchdog { + +bool InstrumentationLog::LogEvent(const std::string& event) { + if (event.length() > kMaxEventLenBytes) { + SB_DLOG(ERROR) << "[Watchdog] Log event exceeds max: " << kMaxEventLenBytes; + return false; + } + + starboard::ScopedLock scoped_lock(buffer_mutex_); + buffer_.SaveToBuffer(event); + + return true; +} + +std::vector InstrumentationLog::GetLogTrace() { + std::vector traceEvents; + + starboard::ScopedLock scoped_lock(buffer_mutex_); + for (auto it = buffer_.Begin(); it; ++it) { + traceEvents.push_back(**it); + } + + return traceEvents; +} + +base::Value InstrumentationLog::GetLogTraceAsValue() { + base::Value log_trace_value = base::Value(base::Value::Type::LIST); + + starboard::ScopedLock scoped_lock(buffer_mutex_); + for (auto it = buffer_.Begin(); it; ++it) { + log_trace_value.GetList().emplace_back(**it); + } + + return log_trace_value; +} + +void InstrumentationLog::ClearLog() { + starboard::ScopedLock scoped_lock(buffer_mutex_); + buffer_.Clear(); +} + +} // namespace watchdog +} // namespace cobalt diff --git a/cobalt/watchdog/instrumentation_log.h b/cobalt/watchdog/instrumentation_log.h new file mode 100644 index 000000000000..599a1986215b --- /dev/null +++ b/cobalt/watchdog/instrumentation_log.h @@ -0,0 +1,59 @@ +// Copyright 2024 The Cobalt Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#ifndef COBALT_WATCHDOG_INSTRUMENTATION_LOG_H_ +#define COBALT_WATCHDOG_INSTRUMENTATION_LOG_H_ + +#include +#include + +#include "base/containers/ring_buffer.h" +#include "base/values.h" +#include "starboard/common/mutex.h" + +namespace cobalt { +namespace watchdog { + +constexpr int kBufferSize = 128; +constexpr int kMaxEventLenBytes = 256; + +// Wrapper class on top of base::RingBuffer for tracking log events emitted +// through logEvent() h5vcc API. There's an optimization: identical sequential +// events added back to back are folded into single event. +class InstrumentationLog { + public: + // Append a single event to the end of the buffer. + bool LogEvent(const std::string& event); + + // Returns a snapshot of the ring buffer. + // Vector of kBufferSize strings at max. + std::vector GetLogTrace(); + + // Same as GetLogTrace() but converted to base::Value for json serialization. + base::Value GetLogTraceAsValue(); + + // Empty the ring buffer. + void ClearLog(); + + private: + base::RingBuffer buffer_; + + // Mutex to guard buffer operations. E.g. LogEvent() called from h5vcc API + // handler and getLogTrace() called from watchdog monitoring thread. + starboard::Mutex buffer_mutex_; +}; + +} // namespace watchdog +} // namespace cobalt +#endif // COBALT_WATCHDOG_INSTRUMENTATION_LOG_H_ diff --git a/cobalt/watchdog/instrumentation_log_test.cc b/cobalt/watchdog/instrumentation_log_test.cc new file mode 100644 index 000000000000..1f77de00e1b0 --- /dev/null +++ b/cobalt/watchdog/instrumentation_log_test.cc @@ -0,0 +1,122 @@ +// Copyright 2024 The Cobalt Authors. All Rights Reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#include "cobalt/watchdog//instrumentation_log.h" + +#include +#include + +#include "base/json/json_reader.h" +#include "base/json/json_writer.h" +#include "starboard/common/file.h" +#include "testing/gtest/include/gtest/gtest.h" + +namespace cobalt { +namespace watchdog { + +class InstrumentationLogTest : public testing::Test { + protected: + InstrumentationLog* instrumentation_log_; +}; + +TEST_F(InstrumentationLogTest, CanCallLogEvent) { + InstrumentationLog log; + log.LogEvent("abc"); + + ASSERT_EQ(log.GetLogTrace().size(), 1); +} + +TEST_F(InstrumentationLogTest, LogEventReturnsFalseOnMaxLenExceed) { + InstrumentationLog log; + + std::string maxLenEvent(kMaxEventLenBytes, 'a'); + ASSERT_TRUE(log.LogEvent(maxLenEvent)); + + std::string exceedingLenEvent(kMaxEventLenBytes + 1, 'a'); + ASSERT_FALSE(log.LogEvent(exceedingLenEvent)); +} + +TEST_F(InstrumentationLogTest, GetLogTraceReturnsEventsInOrder) { + InstrumentationLog log; + + for (int i = 0; i < kBufferSize; i++) { + log.LogEvent(std::to_string(i)); + } + + log.LogEvent("1"); + log.LogEvent("2"); + log.LogEvent("3"); + log.LogEvent("4"); + log.LogEvent("5"); + + ASSERT_EQ(log.GetLogTrace().at(kBufferSize - 1 - 4), "1"); + ASSERT_EQ(log.GetLogTrace().at(kBufferSize - 1 - 3), "2"); + ASSERT_EQ(log.GetLogTrace().at(kBufferSize - 1 - 2), "3"); + ASSERT_EQ(log.GetLogTrace().at(kBufferSize - 1 - 1), "4"); + ASSERT_EQ(log.GetLogTrace().at(kBufferSize - 1), "5"); +} + +TEST_F(InstrumentationLogTest, GetLogTraceCanReturnDuplicateEvents) { + InstrumentationLog log; + + log.LogEvent("1"); + log.LogEvent("1"); + log.LogEvent("1"); + + ASSERT_EQ(log.GetLogTrace().at(0), "1"); + ASSERT_EQ(log.GetLogTrace().at(1), "1"); + ASSERT_EQ(log.GetLogTrace().at(2), "1"); +} + +TEST_F(InstrumentationLogTest, CanGetEmptyTraceAsValue) { + InstrumentationLog log; + + ASSERT_EQ(log.GetLogTraceAsValue().GetList().size(), 0); +} + +TEST_F(InstrumentationLogTest, CanGetLogTraceAsValue) { + InstrumentationLog log; + + log.LogEvent("1"); + log.LogEvent("2"); + log.LogEvent("3"); + + ASSERT_EQ(log.GetLogTraceAsValue().GetList().at(0).GetString(), "1"); + ASSERT_EQ(log.GetLogTraceAsValue().GetList().at(1).GetString(), "2"); + ASSERT_EQ(log.GetLogTraceAsValue().GetList().at(2).GetString(), "3"); +} + +TEST_F(InstrumentationLogTest, CanClearLog) { + InstrumentationLog log; + + log.LogEvent("1"); + log.LogEvent("2"); + log.LogEvent("3"); + + ASSERT_EQ(log.GetLogTrace().size(), 3); + + log.ClearLog(); + ASSERT_EQ(log.GetLogTrace().size(), 0); +} + +TEST_F(InstrumentationLogTest, CanClearEmptyLog) { + InstrumentationLog log; + ASSERT_EQ(log.GetLogTrace().size(), 0); + + log.ClearLog(); + ASSERT_EQ(log.GetLogTrace().size(), 0); +} + +} // namespace watchdog +} // namespace cobalt diff --git a/cobalt/watchdog/watchdog.cc b/cobalt/watchdog/watchdog.cc index f328ec100b8a..d8142bcca975 100644 --- a/cobalt/watchdog/watchdog.cc +++ b/cobalt/watchdog/watchdog.cc @@ -269,9 +269,10 @@ bool Watchdog::MonitorClient(void* context, Client* client, void Watchdog::UpdateViolationsMap(void* context, Client* client, SbTimeMonotonic time_delta) { // Gets violation dictionary with key client name from violations map. + Watchdog* watchdog_instance = static_cast(context); + base::Value* violation_dict = - (static_cast(context)->GetViolationsMap()) - ->FindKey(client->name); + (watchdog_instance->GetViolationsMap())->FindKey(client->name); // Checks if new unique violation. bool new_violation = false; @@ -317,14 +318,18 @@ void Watchdog::UpdateViolationsMap(void* context, Client* client, base::Value(std::to_string( (time_delta - client->time_interval_microseconds) / 1000))); base::Value registered_clients(base::Value::Type::LIST); - for (auto& it : static_cast(context)->client_map_) { + for (auto& it : watchdog_instance->client_map_) { registered_clients.GetList().emplace_back(base::Value(it.first)); } - for (auto& it : static_cast(context)->client_list_) { + for (auto& it : watchdog_instance->client_list_) { registered_clients.GetList().emplace_back(base::Value(it->name)); } violation.SetKey("registeredClients", registered_clients.Clone()); + violation.SetKey( + "logTrace", + watchdog_instance->instrumentation_log_.GetLogTraceAsValue()); + // Adds new violation to violations map. if (violation_dict == nullptr) { base::Value dict(base::Value::Type::DICTIONARY); @@ -332,7 +337,7 @@ void Watchdog::UpdateViolationsMap(void* context, Client* client, base::Value list(base::Value::Type::LIST); list.GetList().emplace_back(violation.Clone()); dict.SetKey("violations", list.Clone()); - (static_cast(context)->GetViolationsMap()) + (watchdog_instance->GetViolationsMap()) ->SetKey(client->name, dict.Clone()); } else { base::Value* violations = violation_dict->FindKey("violations"); @@ -350,11 +355,10 @@ void Watchdog::UpdateViolationsMap(void* context, Client* client, "violationDurationMilliseconds", base::Value(std::to_string(violation_duration + (time_delta / 1000)))); } - static_cast(context)->pending_write_ = true; + watchdog_instance->pending_write_ = true; int violations_count = 0; - for (const auto& it : - (static_cast(context)->GetViolationsMap())->DictItems()) { + for (const auto& it : (watchdog_instance->GetViolationsMap())->DictItems()) { base::Value& violation_dict = it.second; base::Value* violations = violation_dict.FindKey("violations"); violations_count += violations->GetList().size(); @@ -762,6 +766,16 @@ void Watchdog::SetPersistentSettingWatchdogCrash(bool can_trigger_crash) { std::make_unique(can_trigger_crash)); } +bool Watchdog::LogEvent(const std::string& event) { + return instrumentation_log_.LogEvent(event); +} + +std::vector Watchdog::GetLogTrace() { + return instrumentation_log_.GetLogTrace(); +} + +void Watchdog::ClearLog() { instrumentation_log_.ClearLog(); } + #if defined(_DEBUG) // Sleeps threads for Watchdog debugging. void Watchdog::MaybeInjectDebugDelay(const std::string& name) { diff --git a/cobalt/watchdog/watchdog.h b/cobalt/watchdog/watchdog.h index aed2ec1db177..9d65233a7c8a 100644 --- a/cobalt/watchdog/watchdog.h +++ b/cobalt/watchdog/watchdog.h @@ -23,6 +23,7 @@ #include "base/values.h" #include "cobalt/base/application_state.h" #include "cobalt/persistent_storage/persistent_settings.h" +#include "cobalt/watchdog/instrumentation_log.h" #include "cobalt/watchdog/singleton.h" #include "starboard/common/atomic.h" #include "starboard/common/condition_variable.h" @@ -108,6 +109,11 @@ class Watchdog : public Singleton { bool GetPersistentSettingWatchdogCrash(); void SetPersistentSettingWatchdogCrash(bool can_trigger_crash); + // LogTrace API. See instrumentation_log.h for more information. + bool LogEvent(const std::string& event); + std::vector GetLogTrace(); + void ClearLog(); + #if defined(_DEBUG) // Sleeps threads based off of environment variables for Watchdog debugging. void MaybeInjectDebugDelay(const std::string& name); @@ -174,6 +180,8 @@ class Watchdog : public Singleton { starboard::ConditionVariable(mutex_); // The frequency in microseconds of monitor loops. int64_t watchdog_monitor_frequency_; + // Captures string events emitted from Kabuki via logEvent() h5vcc API. + InstrumentationLog instrumentation_log_; #if defined(_DEBUG) starboard::Mutex delay_mutex_; diff --git a/cobalt/watchdog/watchdog_test.cc b/cobalt/watchdog/watchdog_test.cc index 6668c2a8d9e0..5568df1b414f 100644 --- a/cobalt/watchdog/watchdog_test.cc +++ b/cobalt/watchdog/watchdog_test.cc @@ -636,5 +636,58 @@ TEST_F(WatchdogTest, EvictOldWatchdogViolations) { ASSERT_EQ(watchdog_->GetWatchdogViolations({}, false), ""); } +TEST_F(WatchdogTest, CanGetLogTrace) { + watchdog_->LogEvent("1"); + watchdog_->LogEvent("2"); + + std::vector expected = {"1", "2"}; + ASSERT_EQ(watchdog_->GetLogTrace(), expected); +} + +TEST_F(WatchdogTest, CanClearLog) { + watchdog_->LogEvent("1"); + watchdog_->LogEvent("2"); + + watchdog_->ClearLog(); + + ASSERT_EQ(watchdog_->GetLogTrace().size(), 0); +} + +TEST_F(WatchdogTest, ViolationContainsLogTrace) { + watchdog_->Register("test-name", "test-desc", base::kApplicationStateStarted, + kWatchdogMonitorFrequency); + watchdog_->Ping("test-name", "test-ping"); + + watchdog_->LogEvent("1"); + watchdog_->LogEvent("2"); + watchdog_->LogEvent("3"); + + SbThreadSleep(kWatchdogSleepDuration); + + std::string json = watchdog_->GetWatchdogViolations(); + std::unique_ptr violations_map = base::JSONReader::Read(json); + base::Value* violations = + violations_map->FindKey("test-name")->FindKey("violations"); + base::Value* logTrace = violations->GetList()[0].FindKey("logTrace"); + + ASSERT_EQ(logTrace->GetList().size(), 3); +} + +TEST_F(WatchdogTest, ViolationContainsEmptyLogTrace) { + watchdog_->Register("test-name", "test-desc", base::kApplicationStateStarted, + kWatchdogMonitorFrequency); + watchdog_->Ping("test-name", "test-ping"); + + SbThreadSleep(kWatchdogSleepDuration); + + std::string json = watchdog_->GetWatchdogViolations(); + std::unique_ptr violations_map = base::JSONReader::Read(json); + base::Value* violations = + violations_map->FindKey("test-name")->FindKey("violations"); + base::Value* logTrace = violations->GetList()[0].FindKey("logTrace"); + + ASSERT_EQ(logTrace->GetList().size(), 0); +} + } // namespace watchdog } // namespace cobalt