shill: Expose Service's disconnect and misconnect history as properties.
These history properties are exposed as real-time timestamps in the
same format as in logs. Also, replace use of timeval in history with a
Timestamp struct encapsulating monotonic and wall-clock times.
BUG=chromium-os:36924
TEST=lumpy and x86-alex unit tests; tested on device by dropping the
connection and list-services
CQ-DEPEND=I5e1852af18381995c30c5e1f356d3c2745c44d2f
Change-Id: Icb41077ab99262e236790fc30a11c26bccd90d43
Reviewed-on: https://gerrit.chromium.org/gerrit/39244
Commit-Ready: Darin Petkov <petkov@chromium.org>
Reviewed-by: Darin Petkov <petkov@chromium.org>
Tested-by: Darin Petkov <petkov@chromium.org>
diff --git a/doc/service-api.txt b/doc/service-api.txt
index 3353764..774df14 100644
--- a/doc/service-api.txt
+++ b/doc/service-api.txt
@@ -316,6 +316,15 @@
This value may be used to retrieve and manipulate
Layer 3 configuration state.
+ array{string} Diagnostics.Disconnects [readonly]
+
+ History (wall-clock timestamps) of connection drops.
+
+ array{string} Diagnostics.Misconnects [readonly]
+
+ History (wall-clock timestamps) of failed connection
+ attempts.
+
string EAP.Identity [readwrite]
The client identity string used in setting up
diff --git a/mock_time.h b/mock_time.h
index ae253bc..1d4ef9f 100644
--- a/mock_time.h
+++ b/mock_time.h
@@ -19,6 +19,7 @@
MOCK_METHOD1(GetTimeMonotonic, int(struct timeval *tv));
MOCK_METHOD2(GetTimeOfDay, int(struct timeval *tv, struct timezone *tz));
+ MOCK_METHOD0(GetNow, Timestamp());
private:
DISALLOW_COPY_AND_ASSIGN(MockTime);
diff --git a/service.cc b/service.cc
index 353e114..61758b3 100644
--- a/service.cc
+++ b/service.cc
@@ -28,7 +28,6 @@
#include "shill/property_accessor.h"
#include "shill/refptr_types.h"
#include "shill/service_dbus_adaptor.h"
-#include "shill/shill_time.h"
#include "shill/sockets.h"
#include "shill/store_interface.h"
@@ -235,12 +234,10 @@
NULL);
store_.RegisterConstUint8(flimflam::kSignalStrengthProperty, &strength_);
store_.RegisterString(flimflam::kUIDataProperty, &ui_data_);
- // flimflam::kWifiAuthMode: Registered in WiFiService
- // flimflam::kWifiHiddenSsid: Registered in WiFiService
- // flimflam::kWifiFrequency: Registered in WiFiService
- // flimflam::kWifiPhyMode: Registered in WiFiService
- // flimflam::kWifiHexSsid: Registered in WiFiService
-
+ HelpRegisterConstDerivedStrings(shill::kDiagnosticsDisconnectsProperty,
+ &Service::GetDisconnectsProperty);
+ HelpRegisterConstDerivedStrings(shill::kDiagnosticsMisconnectsProperty,
+ &Service::GetMisconnectsProperty);
metrics_->RegisterService(this);
static_ip_parameters_.PlumbPropertyStore(&store_);
@@ -759,7 +756,7 @@
}
struct timeval period = (const struct timeval){ 0 };
size_t threshold = 0;
- deque<struct timeval> *events = NULL;
+ deque<Timestamp> *events = NULL;
if (IsConnected()) {
LOG(INFO) << "Noting an unexpected connection drop.";
period.tv_sec = kDisconnectsMonitorSeconds;
@@ -776,12 +773,11 @@
return;
}
// Discard old events first.
- struct timeval now = (const struct timeval){ 0 };
- time_->GetTimeMonotonic(&now);
+ Timestamp now = time_->GetNow();
while (!events->empty()) {
if (events->size() < static_cast<size_t>(kMaxDisconnectEventHistory)) {
struct timeval elapsed = (const struct timeval){ 0 };
- timersub(&now, &events->front(), &elapsed);
+ timersub(&now.monotonic, &events->front().monotonic, &elapsed);
if (timercmp(&elapsed, &period, <)) {
break;
}
@@ -1068,6 +1064,13 @@
Uint16Accessor(new CustomAccessor<Service, uint16>(this, get, set)));
}
+void Service::HelpRegisterConstDerivedStrings(
+ const string &name, Strings(Service::*get)(Error *error)) {
+ store_.RegisterDerivedStrings(
+ name,
+ StringsAccessor(new CustomAccessor<Service, Strings>(this, get, NULL)));
+}
+
void Service::HelpRegisterWriteOnlyDerivedString(
const string &name,
void(Service::*set)(const string &, Error *),
@@ -1266,6 +1269,25 @@
adaptor_->EmitStringChanged(flimflam::kProxyConfigProperty, proxy_config_);
}
+// static
+Strings Service::ExtractWallClockToStrings(
+ const deque<Timestamp> ×tamps) {
+ Strings strings;
+ for (deque<Timestamp>::const_iterator it = timestamps.begin();
+ it != timestamps.end(); ++it) {
+ strings.push_back(it->wall_clock);
+ }
+ return strings;
+}
+
+Strings Service::GetDisconnectsProperty(Error */*error*/) {
+ return ExtractWallClockToStrings(disconnects_);
+}
+
+Strings Service::GetMisconnectsProperty(Error */*error*/) {
+ return ExtractWallClockToStrings(misconnects_);
+}
+
void Service::SaveToProfile() {
if (profile_.get() && profile_->GetConstStorage()) {
profile_->UpdateService(this);
diff --git a/service.h b/service.h
index 660cf69..41c5f75 100644
--- a/service.h
+++ b/service.h
@@ -5,7 +5,6 @@
#ifndef SHILL_SERVICE_H_
#define SHILL_SERVICE_H_
-#include <sys/time.h>
#include <time.h>
#include <deque>
@@ -25,6 +24,7 @@
#include "shill/callbacks.h"
#include "shill/property_store.h"
#include "shill/refptr_types.h"
+#include "shill/shill_time.h"
#include "shill/static_ip_parameters.h"
#include "shill/technology.h"
@@ -46,7 +46,6 @@
class ServiceAdaptorInterface;
class Sockets;
class StoreInterface;
-class Time;
// A Service is a uniquely named entity, which the system can
// connect in order to begin sending and receiving network traffic.
@@ -467,6 +466,8 @@
const std::string &name,
std::string(Service::*get)(Error *),
void(Service::*set)(const RpcIdentifier&, Error *));
+ void HelpRegisterConstDerivedStrings(
+ const std::string &name, Strings(Service::*get)(Error *error));
// Expose a property over RPC, with the name |name|.
//
// Reads of the property will be handled by invoking |get|.
@@ -608,6 +609,11 @@
std::string GetProxyConfig(Error *error);
void SetProxyConfig(const std::string &proxy_config, Error *error);
+ static Strings ExtractWallClockToStrings(
+ const std::deque<Timestamp> ×tamps);
+ Strings GetDisconnectsProperty(Error *error);
+ Strings GetMisconnectsProperty(Error *error);
+
void ReEnableAutoConnectTask();
// Disables autoconnect and posts a task to re-enable it after a cooldown.
// Note that autoconnect could be disabled for other reasons as well.
@@ -647,10 +653,8 @@
// Whether or not this service has ever reached kStateConnected.
bool has_ever_connected_;
- // TODO(petkov): Expose these as read-only service properties
- // (crosbug.com/36924).
- std::deque<struct timeval> disconnects_; // Connection drops.
- std::deque<struct timeval> misconnects_; // Failures to connect.
+ std::deque<Timestamp> disconnects_; // Connection drops.
+ std::deque<Timestamp> misconnects_; // Failures to connect.
base::CancelableClosure reenable_auto_connect_task_;
uint64 auto_connect_cooldown_milliseconds_ ;
diff --git a/service_unittest.cc b/service_unittest.cc
index 7852537..7e80af3 100644
--- a/service_unittest.cc
+++ b/service_unittest.cc
@@ -44,6 +44,7 @@
using testing::_;
using testing::AnyNumber;
using testing::AtLeast;
+using testing::DefaultValue;
using testing::DoAll;
using testing::HasSubstr;
using testing::Mock;
@@ -68,6 +69,7 @@
storage_id_(ServiceUnderTest::kStorageId),
power_manager_(new MockPowerManager(NULL, &proxy_factory_)) {
service_->time_ = &time_;
+ DefaultValue<Timestamp>::Set(Timestamp());
service_->diagnostics_reporter_ = &diagnostics_reporter_;
mock_manager_.running_ = true;
mock_manager_.set_power_manager(power_manager_); // Passes ownership.
@@ -109,8 +111,23 @@
service_->NoteDisconnectEvent();
}
- deque<struct timeval> *GetDisconnects() { return &service_->disconnects_; }
- deque<struct timeval> *GetMisconnects() { return &service_->misconnects_; }
+ deque<Timestamp> *GetDisconnects() {
+ return &service_->disconnects_;
+ }
+ deque<Timestamp> *GetMisconnects() {
+ return &service_->misconnects_;
+ }
+
+ Timestamp GetTimestamp(int monotonic_seconds, const string &wall_clock) {
+ struct timeval monotonic = { .tv_sec = monotonic_seconds, .tv_usec = 0 };
+ return Timestamp(monotonic, wall_clock);
+ }
+
+ void PushTimestamp(deque<Timestamp> *timestamps,
+ int monotonic_seconds,
+ const string &wall_clock) {
+ timestamps->push_back(GetTimestamp(monotonic_seconds, wall_clock));
+ }
int GetDisconnectsMonitorSeconds() {
return Service::kDisconnectsMonitorSeconds;
@@ -132,6 +149,10 @@
return Service::kMaxDisconnectEventHistory;
}
+ static Strings ExtractWallClockToStrings(const deque<Timestamp> ×tamps) {
+ return Service::ExtractWallClockToStrings(timestamps);
+ }
+
MockManager mock_manager_;
MockDiagnosticsReporter diagnostics_reporter_;
MockTime time_;
@@ -1019,16 +1040,14 @@
}
TEST_F(ServiceTest, NoteDisconnectEventInvoked) {
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>((const struct timeval){ 0 }),
- Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(Timestamp()));
SetStateField(Service::kStateOnline);
service_->SetState(Service::kStateIdle);
EXPECT_FALSE(GetDisconnects()->empty());
}
TEST_F(ServiceTest, NoteDisconnectEventNonEvent) {
- EXPECT_CALL(time_, GetTimeMonotonic(_)).Times(0);
+ EXPECT_CALL(time_, GetNow()).Times(0);
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(0);
// Explicit disconnect is a non-event.
@@ -1061,54 +1080,50 @@
}
TEST_F(ServiceTest, NoteDisconnectEventDisconnectOnce) {
+ const int kNow = 5;
EXPECT_FALSE(service_->explicitly_disconnected());
SetStateField(Service::kStateOnline);
- static const struct timeval now = { .tv_sec = 5, .tv_usec = 0 };
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(GetTimestamp(kNow, "")));
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(0);
NoteDisconnectEvent();
ASSERT_EQ(1, GetDisconnects()->size());
- EXPECT_EQ(now.tv_sec, GetDisconnects()->front().tv_sec);
+ EXPECT_EQ(kNow, GetDisconnects()->front().monotonic.tv_sec);
EXPECT_TRUE(GetMisconnects()->empty());
}
TEST_F(ServiceTest, NoteDisconnectEventDisconnectThreshold) {
EXPECT_FALSE(service_->explicitly_disconnected());
SetStateField(Service::kStateOnline);
- static const struct timeval now = { .tv_sec = 5, .tv_usec = 0 };
+ const int kNow = 6;
for (int i = 0; i < GetReportDisconnectsThreshold() - 1; i++) {
- GetDisconnects()->push_back(now);
+ PushTimestamp(GetDisconnects(), kNow, "");
}
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(GetTimestamp(kNow, "")));
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(1);
NoteDisconnectEvent();
EXPECT_EQ(GetReportDisconnectsThreshold(), GetDisconnects()->size());
}
TEST_F(ServiceTest, NoteDisconnectEventMisconnectOnce) {
+ const int kNow = 7;
EXPECT_FALSE(service_->explicitly_disconnected());
SetStateField(Service::kStateConfiguring);
- static const struct timeval now = { .tv_sec = 7, .tv_usec = 0 };
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(GetTimestamp(kNow, "")));
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(0);
NoteDisconnectEvent();
EXPECT_TRUE(GetDisconnects()->empty());
ASSERT_EQ(1, GetMisconnects()->size());
- EXPECT_EQ(now.tv_sec, GetMisconnects()->front().tv_sec);
+ EXPECT_EQ(kNow, GetMisconnects()->front().monotonic.tv_sec);
}
TEST_F(ServiceTest, NoteDisconnectEventMisconnectThreshold) {
EXPECT_FALSE(service_->explicitly_disconnected());
SetStateField(Service::kStateConfiguring);
- static const struct timeval now = { .tv_sec = 7, .tv_usec = 0 };
+ const int kNow = 8;
for (int i = 0; i < GetReportMisconnectsThreshold() - 1; i++) {
- GetMisconnects()->push_back(now);
+ PushTimestamp(GetMisconnects(), kNow, "");
}
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(GetTimestamp(kNow, "")));
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(1);
NoteDisconnectEvent();
EXPECT_EQ(GetReportMisconnectsThreshold(), GetMisconnects()->size());
@@ -1118,39 +1133,72 @@
EXPECT_FALSE(service_->explicitly_disconnected());
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(0);
for (int i = 0; i < 2; i++) {
- struct timeval now = (const struct timeval){ 0 };
- deque<struct timeval> *events = NULL;
+ int now = 0;
+ deque<Timestamp> *events = NULL;
if (i == 0) {
SetStateField(Service::kStateConnected);
- now.tv_sec = GetDisconnectsMonitorSeconds() + 1;
+ now = GetDisconnectsMonitorSeconds() + 1;
events = GetDisconnects();
} else {
SetStateField(Service::kStateAssociating);
- now.tv_sec = GetMisconnectsMonitorSeconds() + 1;
+ now = GetMisconnectsMonitorSeconds() + 1;
events = GetMisconnects();
}
- events->push_back((const struct timeval){ 0 });
- events->push_back((const struct timeval){ 0 });
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ PushTimestamp(events, 0, "");
+ PushTimestamp(events, 0, "");
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(GetTimestamp(now, "")));
NoteDisconnectEvent();
ASSERT_EQ(1, events->size());
- EXPECT_EQ(now.tv_sec, events->front().tv_sec);
+ EXPECT_EQ(now, events->front().monotonic.tv_sec);
}
}
TEST_F(ServiceTest, NoteDisconnectEventDiscardExcessive) {
EXPECT_FALSE(service_->explicitly_disconnected());
SetStateField(Service::kStateOnline);
- static const struct timeval now = (const struct timeval){ 0 };
for (int i = 0; i < 2 * GetMaxDisconnectEventHistory(); i++) {
- GetDisconnects()->push_back(now);
+ PushTimestamp(GetDisconnects(), 0, "");
}
- EXPECT_CALL(time_, GetTimeMonotonic(_))
- .WillOnce(DoAll(SetArgumentPointee<0>(now), Return(0)));
+ EXPECT_CALL(time_, GetNow()).WillOnce(Return(Timestamp()));
EXPECT_CALL(diagnostics_reporter_, OnConnectivityEvent()).Times(1);
NoteDisconnectEvent();
EXPECT_EQ(GetMaxDisconnectEventHistory(), GetDisconnects()->size());
}
+TEST_F(ServiceTest, ConvertTimestampsToStrings) {
+ EXPECT_TRUE(ExtractWallClockToStrings(deque<Timestamp>()).empty());
+
+ const Timestamp kValues[] = {
+ GetTimestamp(123, "2012-12-09T12:41:22"),
+ GetTimestamp(234, "2012-12-31T23:59:59")
+ };
+ Strings strings =
+ ExtractWallClockToStrings(
+ deque<Timestamp>(kValues, kValues + arraysize(kValues)));
+ EXPECT_GT(arraysize(kValues), 0);
+ ASSERT_EQ(arraysize(kValues), strings.size());
+ for (size_t i = 0; i < arraysize(kValues); i++) {
+ EXPECT_EQ(kValues[i].wall_clock, strings[i]);
+ }
+}
+
+TEST_F(ServiceTest, DiagnosticsProperties) {
+ const string kWallClock0 = "2012-12-09T12:41:22";
+ const string kWallClock1 = "2012-12-31T23:59:59";
+ PropertyStoreInspector inspector(&service_->store());
+ Strings values;
+
+ PushTimestamp(GetDisconnects(), 0, kWallClock0);
+ ASSERT_TRUE(
+ inspector.GetStringsProperty(kDiagnosticsDisconnectsProperty, &values));
+ ASSERT_EQ(1, values.size());
+ EXPECT_EQ(kWallClock0, values[0]);
+
+ PushTimestamp(GetMisconnects(), 0, kWallClock1);
+ ASSERT_TRUE(
+ inspector.GetStringsProperty(kDiagnosticsMisconnectsProperty, &values));
+ ASSERT_EQ(1, values.size());
+ EXPECT_EQ(kWallClock1, values[0]);
+}
+
} // namespace shill
diff --git a/shill_time.cc b/shill_time.cc
index f3b212d..7d3519d 100644
--- a/shill_time.cc
+++ b/shill_time.cc
@@ -6,6 +6,10 @@
#include <time.h>
+#include <base/stringprintf.h>
+
+using std::string;
+
namespace shill {
namespace {
@@ -42,4 +46,24 @@
return gettimeofday(tv, tz);
}
+Timestamp Time::GetNow() {
+ struct timeval now_monotonic = (const struct timeval){ 0 };
+ GetTimeMonotonic(&now_monotonic);
+ struct timeval now_wall_clock = (const struct timeval){ 0 };
+ GetTimeOfDay(&now_wall_clock, NULL);
+ struct tm local_time = (const struct tm){ 0 };
+ localtime_r(&now_wall_clock.tv_sec, &local_time);
+ // There're two levels of formatting -- first most of the timestamp is printed
+ // into |format|, then the resulting string is used to insert the microseconds
+ // (note the %%06u format string).
+ char format[64];
+ size_t length = strftime(format, sizeof(format),
+ "%Y-%m-%dT%H:%M:%S.%%06u%z", &local_time);
+ string wall_clock = "<unknown>";
+ if (length && length < sizeof(format)) {
+ wall_clock = base::StringPrintf(format, now_wall_clock.tv_usec);
+ }
+ return Timestamp(now_monotonic, wall_clock);
+}
+
} // namespace shill
diff --git a/shill_time.h b/shill_time.h
index 17d748f..c6b4a38 100644
--- a/shill_time.h
+++ b/shill_time.h
@@ -7,10 +7,27 @@
#include <sys/time.h>
+#include <string>
+
#include <base/lazy_instance.h>
namespace shill {
+// Timestamp encapsulates a |monotonic| time that can be used to compare the
+// relative order and distance of events as well as a |wall_clock| time that can
+// be used for presenting the time in human-readable format. Note that the
+// monotonic clock does not necessarily advance during suspend.
+struct Timestamp {
+ Timestamp() : monotonic((const struct timeval){ 0 }) {}
+ Timestamp(const struct timeval &in_monotonic,
+ const std::string &in_wall_clock)
+ : monotonic(in_monotonic),
+ wall_clock(in_wall_clock) {}
+
+ struct timeval monotonic;
+ std::string wall_clock;
+};
+
// A "sys/time.h" abstraction allowing mocking in tests.
class Time {
public:
@@ -24,6 +41,9 @@
// gettimeofday
virtual int GetTimeOfDay(struct timeval *tv, struct timezone *tz);
+ // Returns a snapshot of the current time.
+ virtual Timestamp GetNow();
+
protected:
Time();