Generalize network_event_log -> device_event_log

chromeos/dbus/power_manager_client.cc

Index: chromeos/dbus/power_manager_client.cc
diff --git a/chromeos/dbus/power_manager_client.cc b/chromeos/dbus/power_manager_client.cc
index 52b69098515d806dfeecc48642ffbb1daa0a3990..998f3104fd985f5a4d13480678f9f53ef17e915b 100644
--- a/chromeos/dbus/power_manager_client.cc
+++ b/chromeos/dbus/power_manager_client.cc
@@ -27,6 +27,7 @@
 #include "chromeos/dbus/power_manager/policy.pb.h"
 #include "chromeos/dbus/power_manager/power_supply_properties.pb.h"
 #include "chromeos/dbus/power_manager/suspend.pb.h"
+#include "chromeos/device_event_log.h"
 #include "dbus/bus.h"
 #include "dbus/message.h"
 #include "dbus/object_path.h"
@@ -157,14 +158,17 @@ class PowerManagerClientImpl : public PowerManagerClient {
   }
 
   virtual void RequestSuspend() override {
+    POWER_LOG(USER) << "RequestSuspend";
     SimpleMethodCallToPowerManager(power_manager::kRequestSuspendMethod);
   }
 
   virtual void RequestRestart() override {
+    POWER_LOG(USER) << "RequestRestart";
     SimpleMethodCallToPowerManager(power_manager::kRequestRestartMethod);
   }
 
   virtual void RequestShutdown() override {
+    POWER_LOG(USER) << "RequestShutdown";
     SimpleMethodCallToPowerManager(power_manager::kRequestShutdownMethod);
   }
 
@@ -202,7 +206,7 @@ class PowerManagerClientImpl : public PowerManagerClient {
         power_manager::kSetPolicyMethod);
     dbus::MessageWriter writer(&method_call);
     if (!writer.AppendProtoAsArrayOfBytes(policy)) {
-      LOG(ERROR) << "Error calling " << power_manager::kSetPolicyMethod;
+      POWER_LOG(ERROR) << "Error calling " << power_manager::kSetPolicyMethod;

[Daniel Erat, 2014/12/02 20:43:16]

does this still end up in a log file on disk? if i'm looking at a system that's
misbehaving i'd like this message to be easy to find. can POWER_LOG(ERROR)
messages be duplicated to the main chrome log?

[stevenjb, 2014/12/02 21:14:38]

POWER_LOG(ERROR) still logs to LOG(ERROR). Other levels go to VLOG(1) (but with
--vmodule=device_log*=1). Sound reasonable?

I've been thinking about the merits of also spooling the log to disk alongside
the chrome log, but that's not currently a priority.

[Daniel Erat, 2014/12/02 21:20:39]

cool, thanks. as long as ERROR ends up on disk i'm happy.

       return;
     }
     power_manager_proxy_->CallMethod(
@@ -339,8 +343,8 @@ class PowerManagerClientImpl : public PowerManagerClient {
   void SignalConnected(const std::string& interface_name,
                        const std::string& signal_name,
                        bool success) {
-    LOG_IF(WARNING, !success) << "Failed to connect to signal "
-                              << signal_name << ".";
+    if (!success)
+      POWER_LOG(ERROR) << "Failed to connect to signal " << signal_name << ".";
   }
 
   // Makes a method call to power manager with no arguments and no response.
@@ -355,15 +359,15 @@ class PowerManagerClientImpl : public PowerManagerClient {
 
   void NameOwnerChangedReceived(const std::string& old_owner,
                                 const std::string& new_owner) {
-    VLOG(1) << "Power manager restarted (old owner was "
-            << (old_owner.empty() ? "[none]" : old_owner.c_str())
-            << ", new owner is "
-            << (new_owner.empty() ? "[none]" : new_owner.c_str()) << ")";
+    POWER_LOG(EVENT) << "Power manager restarted. Old owner: "
+                     << (old_owner.empty() ? "[none]" : old_owner.c_str())
+                     << " New owner: "
+                     << (new_owner.empty() ? "[none]" : new_owner.c_str());
     suspend_is_pending_ = false;
     pending_suspend_id_ = -1;
     suspending_from_dark_resume_ = false;
     if (!new_owner.empty()) {
-      VLOG(1) << "Sending initial state to power manager";
+      POWER_LOG(EVENT) << "Sending initial state to power manager";
       RegisterSuspendDelays();
       SetIsProjecting(last_is_projecting_);
       FOR_EACH_OBSERVER(Observer, observers_, PowerManagerRestarted());
@@ -376,12 +380,16 @@ class PowerManagerClientImpl : public PowerManagerClient {
     bool user_initiated = 0;
     if (!(reader.PopInt32(&brightness_level) &&
           reader.PopBool(&user_initiated))) {
-      LOG(ERROR) << "Brightness changed signal had incorrect parameters: "
-                 << signal->ToString();
+      POWER_LOG(ERROR) << "Brightness changed signal had incorrect parameters: "
+                       << signal->ToString();
       return;
     }
-    VLOG(1) << "Brightness changed to " << brightness_level
-            << ": user initiated " << user_initiated;
+    device_event_log::LogLevel log_level =
+        user_initiated ? device_event_log::LOG_LEVEL_USER
+                       : device_event_log::LOG_LEVEL_EVENT;
+    DEVICE_LOG(device_event_log::LOG_TYPE_POWER, log_level)

[Daniel Erat, 2014/12/02 21:20:39]

please just use EVENT for both of these; we already log at USER when sending the
request

[stevenjb, 2014/12/03 00:16:03]

Looking at the results on my Pixel, this is a bit spammy, so I changed it to
DEBUG. Let me know if you'd prefer to change it to EVENT.

We weren't actually logging events for increase/decrease brightness requests so
I added them.

+        << "Brightness changed to " << brightness_level << ": user initiated "
+        << user_initiated;
     FOR_EACH_OBSERVER(Observer, observers_,
                       BrightnessChanged(brightness_level, user_initiated));
   }
@@ -390,8 +398,9 @@ class PowerManagerClientImpl : public PowerManagerClient {
     dbus::MessageReader reader(signal);
     power_manager::PeripheralBatteryStatus protobuf_status;
     if (!reader.PopArrayOfBytesAsProto(&protobuf_status)) {
-      LOG(ERROR) << "Unable to decode protocol buffer from "
-                 << power_manager::kPeripheralBatteryStatusSignal << " signal";
+      POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
+                       << power_manager::kPeripheralBatteryStatusSignal
+                       << " signal";
       return;
     }
 
@@ -399,29 +408,29 @@ class PowerManagerClientImpl : public PowerManagerClient {
     std::string name = protobuf_status.name();
     int level = protobuf_status.has_level() ? protobuf_status.level() : -1;
 
-    VLOG(1) << "Device battery status received " << level
-            << " for " << name << " at " << path;
+    POWER_LOG(EVENT) << "Device battery status received " << level << " for "
+                     << name << " at " << path;
 
     FOR_EACH_OBSERVER(Observer, observers_,
                       PeripheralBatteryStatusReceived(path, name, level));
   }
 
   void PowerSupplyPollReceived(dbus::Signal* signal) {
-    VLOG(1) << "Received power supply poll signal.";
+    POWER_LOG(DEBUG) << "Received power supply poll signal.";

[Daniel Erat, 2014/12/02 20:43:16]

why did you use different levels for this and for
PeripheralBatteryStatusReceived? they were both VLOG(1) before, and i believe
that they're both called in response to signals emitted periodically by powerd.

[stevenjb, 2014/12/02 21:14:38]

I guess it seemed more like a VLOG(2) to me since it's just a poll. I could make
both DEBUG or neither, whichever you prefer.

[Daniel Erat, 2014/12/02 21:20:39]

i think that these are sent every 30 seconds or so. these messages don't contain
much useful information (powerd logs more details when it's emitting the
signals), so i'm fine with DEBUG.

[stevenjb, 2014/12/03 00:16:03]

Done.

     dbus::MessageReader reader(signal);
     power_manager::PowerSupplyProperties protobuf;
     if (reader.PopArrayOfBytesAsProto(&protobuf)) {
       HandlePowerSupplyProperties(protobuf);
     } else {
-      LOG(ERROR) << "Unable to decode "
-                 << power_manager::kPowerSupplyPollSignal << "signal";
+      POWER_LOG(ERROR) << "Unable to decode "
+                       << power_manager::kPowerSupplyPollSignal << " signal";
     }
   }
 
   void OnGetPowerSupplyPropertiesMethod(dbus::Response* response) {
     if (!response) {
-      LOG(ERROR) << "Error calling "
-                 << power_manager::kGetPowerSupplyPropertiesMethod;
+      POWER_LOG(ERROR) << "Error calling "
+                       << power_manager::kGetPowerSupplyPropertiesMethod;
       return;
     }
 
@@ -430,9 +439,9 @@ class PowerManagerClientImpl : public PowerManagerClient {
     if (reader.PopArrayOfBytesAsProto(&protobuf)) {
       HandlePowerSupplyProperties(protobuf);
     } else {
-      LOG(ERROR) << "Unable to decode "
-                 << power_manager::kGetPowerSupplyPropertiesMethod
-                 << " response";
+      POWER_LOG(ERROR) << "Unable to decode "
+                       << power_manager::kGetPowerSupplyPropertiesMethod
+                       << " response";
     }
   }
 
@@ -440,15 +449,15 @@ class PowerManagerClientImpl : public PowerManagerClient {
       const GetScreenBrightnessPercentCallback& callback,
       dbus::Response* response) {
     if (!response) {
-      LOG(ERROR) << "Error calling "
-                 << power_manager::kGetScreenBrightnessPercentMethod;
+      POWER_LOG(ERROR) << "Error calling "
+                       << power_manager::kGetScreenBrightnessPercentMethod;
       return;
     }
     dbus::MessageReader reader(response);
     double percent = 0.0;
     if (!reader.PopDouble(&percent))
-      LOG(ERROR) << "Error reading response from powerd: "
-                 << response->ToString();
+      POWER_LOG(ERROR) << "Error reading response from powerd: "
+                       << response->ToString();
     callback.Run(percent);
   }
 
@@ -464,25 +473,26 @@ class PowerManagerClientImpl : public PowerManagerClient {
                                        const std::string& method_name,
                                        dbus::Response* response) {
     if (!response) {
-      LOG(ERROR) << "Error calling " << method_name;
+      POWER_LOG(ERROR) << "Error calling " << method_name;
       return;
     }
 
     dbus::MessageReader reader(response);
     power_manager::RegisterSuspendDelayReply protobuf;
     if (!reader.PopArrayOfBytesAsProto(&protobuf)) {
-      LOG(ERROR) << "Unable to parse reply from " << method_name;
+      POWER_LOG(ERROR) << "Unable to parse reply from " << method_name;
       return;
     }
 
     if (dark_suspend) {
       dark_suspend_delay_id_ = protobuf.delay_id();
       has_dark_suspend_delay_id_ = true;
-      VLOG(1) << "Registered dark suspend delay " << dark_suspend_delay_id_;
+      POWER_LOG(EVENT) << "Registered dark suspend delay "
+                       << dark_suspend_delay_id_;
     } else {
       suspend_delay_id_ = protobuf.delay_id();
       has_suspend_delay_id_ = true;
-      VLOG(1) << "Registered suspend delay " << suspend_delay_id_;
+      POWER_LOG(EVENT) << "Registered suspend delay " << suspend_delay_id_;
     }
   }
 
@@ -490,29 +500,31 @@ class PowerManagerClientImpl : public PowerManagerClient {
     std::string signal_name = signal->GetMember();
     if ((in_dark_resume && !has_dark_suspend_delay_id_) ||
         (!in_dark_resume && !has_suspend_delay_id_)) {
-      LOG(ERROR) << "Received unrequested " << signal_name << " signal";
+      POWER_LOG(ERROR) << "Received unrequested " << signal_name << " signal";
       return;
     }
 
     dbus::MessageReader reader(signal);
     power_manager::SuspendImminent proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
-      LOG(ERROR) << "Unable to decode protocol buffer from " << signal_name
-                 << " signal";
+      POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
+                       << signal_name << " signal";
       return;
     }
 
-    VLOG(1) << "Got " << signal_name << " signal announcing suspend attempt "
-            << proto.suspend_id();
+    POWER_LOG(EVENT) << "Got " << signal_name
+                     << " signal announcing suspend attempt "
+                     << proto.suspend_id();
 
     // If a previous suspend is pending from the same state we are currently in
     // (fully powered on or in dark resume), then something's gone a little
     // wonky.
-    if (suspend_is_pending_ &&
-        suspending_from_dark_resume_ == in_dark_resume) {
-      LOG(WARNING) << "Got " << signal_name << " signal about pending suspend "
-                   << "attempt " << proto.suspend_id() << " while still "
-                   << "waiting on attempt " << pending_suspend_id_;
+    if (suspend_is_pending_ && suspending_from_dark_resume_ == in_dark_resume) {
+      POWER_LOG(ERROR) << "Got " << signal_name
+                       << " signal about pending suspend attempt "
+                       << proto.suspend_id()
+                       << " while still waiting on attempt "
+                       << pending_suspend_id_;
     }
 
     pending_suspend_id_ = proto.suspend_id();
@@ -531,16 +543,17 @@ class PowerManagerClientImpl : public PowerManagerClient {
     dbus::MessageReader reader(signal);
     power_manager::SuspendDone proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
-      LOG(ERROR) << "Unable to decode protocol buffer from "
-                 << power_manager::kSuspendDoneSignal << " signal";
+      POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
+                       << power_manager::kSuspendDoneSignal << " signal";
       return;
     }
 
     const base::TimeDelta duration =
         base::TimeDelta::FromInternalValue(proto.suspend_duration());
-    VLOG(1) << "Got " << power_manager::kSuspendDoneSignal << " signal:"
-            << " suspend_id=" << proto.suspend_id()
-            << " duration=" << duration.InSeconds() << " sec";
+    POWER_LOG(EVENT) << "Got " << power_manager::kSuspendDoneSignal
+                     << " signal:"
+                     << " suspend_id=" << proto.suspend_id()
+                     << " duration=" << duration.InSeconds() << " sec";
 
     if (render_process_manager_delegate_)
       render_process_manager_delegate_->SuspendDone();
@@ -554,8 +567,8 @@ class PowerManagerClientImpl : public PowerManagerClient {
     dbus::MessageReader reader(signal);
     power_manager::IdleActionImminent proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
-      LOG(ERROR) << "Unable to decode protocol buffer from "
-                 << power_manager::kIdleActionImminentSignal << " signal";
+      POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
+                       << power_manager::kIdleActionImminentSignal << " signal";
       return;
     }
     FOR_EACH_OBSERVER(Observer, observers_,
@@ -571,15 +584,16 @@ class PowerManagerClientImpl : public PowerManagerClient {
     dbus::MessageReader reader(signal);
     power_manager::InputEvent proto;
     if (!reader.PopArrayOfBytesAsProto(&proto)) {
-      LOG(ERROR) << "Unable to decode protocol buffer from "
-                 << power_manager::kInputEventSignal << " signal";
+      POWER_LOG(ERROR) << "Unable to decode protocol buffer from "
+                       << power_manager::kInputEventSignal << " signal";
       return;
     }
 
     base::TimeTicks timestamp =
         base::TimeTicks::FromInternalValue(proto.timestamp());
-    VLOG(1) << "Got " << power_manager::kInputEventSignal << " signal:"
-            << " type=" << proto.type() << " timestamp=" << proto.timestamp();
+    POWER_LOG(EVENT) << "Got " << power_manager::kInputEventSignal << " signal:"
+                     << " type=" << proto.type()
+                     << " timestamp=" << proto.timestamp();
     switch (proto.type()) {
       case power_manager::InputEvent_Type_POWER_BUTTON_DOWN:
       case power_manager::InputEvent_Type_POWER_BUTTON_UP: {
@@ -622,7 +636,7 @@ class PowerManagerClientImpl : public PowerManagerClient {
     dbus::MessageWriter writer(&method_call);
 
     if (!writer.AppendProtoAsArrayOfBytes(protobuf_request)) {
-      LOG(ERROR) << "Error constructing message for " << method_name;
+      POWER_LOG(ERROR) << "Error constructing message for " << method_name;
       return;
     }
 
@@ -697,8 +711,8 @@ class PowerManagerClientImpl : public PowerManagerClient {
         power_manager::kPowerManagerInterface, method_name);
     dbus::MessageWriter writer(&method_call);
 
-    VLOG(1) << "Announcing readiness of suspend delay " << delay_id
-            << " for suspend attempt " << pending_suspend_id_;
+    POWER_LOG(EVENT) << "Announcing readiness of suspend delay " << delay_id
+                     << " for suspend attempt " << pending_suspend_id_;
     power_manager::SuspendReadinessInfo protobuf_request;
     protobuf_request.set_delay_id(delay_id);
     protobuf_request.set_suspend_id(pending_suspend_id_);
@@ -707,7 +721,7 @@ class PowerManagerClientImpl : public PowerManagerClient {
     suspend_is_pending_ = false;
 
     if (!writer.AppendProtoAsArrayOfBytes(protobuf_request)) {
-      LOG(ERROR) << "Error constructing message for " << method_name;
+      POWER_LOG(ERROR) << "Error constructing message for " << method_name;
       return;
     }
     power_manager_proxy_->CallMethod(
@@ -807,39 +821,41 @@ class PowerManagerClientStubImpl : public PowerManagerClient {
   }
 
   virtual void DecreaseScreenBrightness(bool allow_off) override {
-    VLOG(1) << "Requested to descrease screen brightness";
+    POWER_LOG(USER) << "Requested to descrease screen brightness";
     SetBrightness(brightness_ - 5.0, true);
   }
 
   virtual void IncreaseScreenBrightness() override {
-    VLOG(1) << "Requested to increase screen brightness";
+    POWER_LOG(USER) << "Requested to increase screen brightness";
     SetBrightness(brightness_ + 5.0, true);
   }
 
   virtual void SetScreenBrightnessPercent(double percent,
                                           bool gradual) override {
-    VLOG(1) << "Requested to set screen brightness to " << percent << "% "
-            << (gradual ? "gradually" : "instantaneously");
+    POWER_LOG(USER) << "Requested to set screen brightness to " << percent
+                    << "% " << (gradual ? "gradually" : "instantaneously");
     SetBrightness(percent, false);
   }
 
   virtual void GetScreenBrightnessPercent(
       const GetScreenBrightnessPercentCallback& callback) override {
+    POWER_LOG(USER) << "Requested to get screen brightness";
     callback.Run(brightness_);
   }
 
   virtual void DecreaseKeyboardBrightness() override {
-    VLOG(1) << "Requested to descrease keyboard brightness";
+    POWER_LOG(USER) << "Requested to descrease keyboard brightness";
   }
 
   virtual void IncreaseKeyboardBrightness() override {
-    VLOG(1) << "Requested to increase keyboard brightness";
+    POWER_LOG(USER) << "Requested to increase keyboard brightness";
   }
 
   virtual void RequestStatusUpdate() override {
-    base::MessageLoop::current()->PostTask(FROM_HERE,
-        base::Bind(&PowerManagerClientStubImpl::UpdateStatus,
-                   weak_ptr_factory_.GetWeakPtr()));
+    POWER_LOG(USER) << "Requested status update";
+    base::MessageLoop::current()->PostTask(
+        FROM_HERE, base::Bind(&PowerManagerClientStubImpl::UpdateStatus,
+                              weak_ptr_factory_.GetWeakPtr()));
   }
 
   virtual void RequestSuspend() override {}