Add logging to remote commands

Add logging to remote commands

BUG=602572
Committed: https://crrev.com/481a291fd77a809b5f5844192d674709679c776d
Cr-Commit-Position: refs/heads/master@{#397998}

[Marton Hunyady, 2016-05-04 13:47:31]

hunyadym@chromium.org changed reviewers:
+ atwilson@chromium.org, thakis@chromium.org

[Marton Hunyady, 2016-05-04 13:47:31]

hunyadym@chromium.org changed reviewers:
+ atwilson@chromium.org, thakis@chromium.org

[Marton Hunyady, 2016-05-04 13:47:32]

atwilson: PTAL
thakis: PTAL at user_activity_detector.*

[Marton Hunyady, 2016-05-04 13:47:32]

atwilson: PTAL
thakis: PTAL at user_activity_detector.*

[Andrew T Wilson (Slow), 2016-05-04 14:43:23]

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:68:
LOG(WARNING) << "Reboot command already has been executed.";
Change this to something like: "Ignoring reboot command issued before current
boot - delta = " << delta;

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:79:
LOG(WARNING) << "Rebooting in " << reboot_delay << ".";
Add a unit here, e.g. "Rebooting in 1234 msecs."

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc:123:
LOG(ERROR) << "Upload failure: authentication error.";
Just have one log that is "Upload failure: " << error_code. That is sufficient.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/status_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/status_uploader.cc:138: << " ago, data upload is
not allowed.";
Can we also show how soon after boot the input happened, using
base::SysInfo::Uptime()?

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/system_log_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:209: LOG(ERROR) << "Upload
failed, retrying later.";
Log the error code.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:213: // No more retries.
Log error code (unless it's logged elsewhere)

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_command_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_command_job.cc:92:
LOG(ERROR) << "Remote command " << unique_id_ << " expired.";
Maybe also print issued_time() and the current time, or just the age? Or is that
already logged by subclasses?

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_commands_service.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_commands_service.cc:149: <<
" finished with result " << result_string;
This is OK, but you could also just print out the raw result.get_result() value
instead of mapping to a string (less code, and we can easily decode what the raw
value means)

[Marton Hunyady, 2016-05-09 13:48:15]

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:68:
LOG(WARNING) << "Reboot command already has been executed.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Change this to something like: "Ignoring reboot command issued before current
> boot - delta = " << delta;

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:79:
LOG(WARNING) << "Rebooting in " << reboot_delay << ".";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Add a unit here, e.g. "Rebooting in 1234 msecs."

reboot_delay is a base::TimeDelta, so it currently prints something like
"Rebooting in 565.426s."

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc:123:
LOG(ERROR) << "Upload failure: authentication error.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Just have one log that is "Upload failure: " << error_code. That is
sufficient.

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/status_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/status_uploader.cc:138: << " ago, data upload is
not allowed.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Can we also show how soon after boot the input happened, using
> base::SysInfo::Uptime()?

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/system_log_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:209: LOG(ERROR) << "Upload
failed, retrying later.";
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Log the error code.

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:213: // No more retries.
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Log error code (unless it's logged elsewhere)

Done.

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_command_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_command_job.cc:92:
LOG(ERROR) << "Remote command " << unique_id_ << " expired.";
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Maybe also print issued_time() and the current time, or just the age? Or is
that
> already logged by subclasses?

Done, I'm logging the estimated age of the command too.

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_commands_service.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_commands_service.cc:149: <<
" finished with result " << result_string;
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> This is OK, but you could also just print out the raw result.get_result()
value
> instead of mapping to a string (less code, and we can easily decode what the
raw
> value means)

Done.

[Marton Hunyady, 2016-05-09 13:48:16]

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:68:
LOG(WARNING) << "Reboot command already has been executed.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Change this to something like: "Ignoring reboot command issued before current
> boot - delta = " << delta;

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_reboot_job.cc:79:
LOG(WARNING) << "Rebooting in " << reboot_delay << ".";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Add a unit here, e.g. "Rebooting in 1234 msecs."

reboot_delay is a base::TimeDelta, so it currently prints something like
"Rebooting in 565.426s."

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/remote_commands/device_command_screenshot_job.cc:123:
LOG(ERROR) << "Upload failure: authentication error.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Just have one log that is "Upload failure: " << error_code. That is
sufficient.

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/status_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/status_uploader.cc:138: << " ago, data upload is
not allowed.";
On 2016/05/04 14:43:22, Andrew T Wilson (Slow) wrote:
> Can we also show how soon after boot the input happened, using
> base::SysInfo::Uptime()?

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
File chrome/browser/chromeos/policy/system_log_uploader.cc (right):

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:209: LOG(ERROR) << "Upload
failed, retrying later.";
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Log the error code.

Done.

https://codereview.chromium.org/1923943003/diff/60001/chrome/browser/chromeos...
chrome/browser/chromeos/policy/system_log_uploader.cc:213: // No more retries.
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Log error code (unless it's logged elsewhere)

Done.

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_command_job.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_command_job.cc:92:
LOG(ERROR) << "Remote command " << unique_id_ << " expired.";
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> Maybe also print issued_time() and the current time, or just the age? Or is
that
> already logged by subclasses?

Done, I'm logging the estimated age of the command too.

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
File components/policy/core/common/remote_commands/remote_commands_service.cc
(right):

https://codereview.chromium.org/1923943003/diff/60001/components/policy/core/...
components/policy/core/common/remote_commands/remote_commands_service.cc:149: <<
" finished with result " << result_string;
On 2016/05/04 14:43:23, Andrew T Wilson (Slow) wrote:
> This is OK, but you could also just print out the raw result.get_result()
value
> instead of mapping to a string (less code, and we can easily decode what the
raw
> value means)

Done.

[Andrew T Wilson (Slow), 2016-05-10 17:49:50]

lgtm

[Nico, 2016-05-13 14:33:00]

I don't understand the motivation behind this CL. In general, we _don't_ want
client side logging, unless we're debugging something. This seems to add logging
just for logging's sake. Why?

[Marton Hunyady, 2016-05-13 15:10:45]

On 2016/05/13 14:33:00, Nico wrote:
> I don't understand the motivation behind this CL. In general, we _don't_ want
> client side logging, unless we're debugging something. This seems to add
logging
> just for logging's sake. Why?

There are a lot of unsuccessful remote commands on kiosks, and since kiosk
system logs are uploaded regularly, we can find out what was the reason. See
b/28071620 and b/28068258 for details.

[Andrew T Wilson (Slow), 2016-05-18 12:00:49]

On 2016/05/13 15:10:45, Marton wrote:
> On 2016/05/13 14:33:00, Nico wrote:
> > I don't understand the motivation behind this CL. In general, we _don't_
want
> > client side logging, unless we're debugging something. This seems to add
> logging
> > just for logging's sake. Why?
> 
> There are a lot of unsuccessful remote commands on kiosks, and since kiosk
> system logs are uploaded regularly, we can find out what was the reason. See
> b/28071620 and b/28068258 for details.

Also, remote commands are rare so they won't be generating significant log spam.

[Nico, 2016-05-18 20:15:45]

If you're adding this to debug something, please add a TODO to remove them once
debugging is done. Ideally link the removal to a public bug, not an internal
one.

[Nico, 2016-05-18 20:16:28]

See also https://www.chromium.org/developers/coding-style#TOC-Logging

[Andrew T Wilson (Slow), 2016-05-19 13:48:03]

On 2016/05/18 20:16:28, Nico (vacation May 19 to 22) wrote:
> See also https://www.chromium.org/developers/coding-style#TOC-Logging

None of these suggestions are appropriate in our case when we need to do
diagnostics on failures that have happened in the field. And we are not adding
these to address a specific bug, but to instead to expose more information in
the logs around the functioning of the remote commands subsystem in general - we
did not add a TODO to remove these logs, because the intent is to include this
information in the logs on an ongoing basis for diagnostic purposes.

One example use would be for an admin who wants to understand why screenshots
are not allowed on a given device - they should be able to look at the logs and
see "Oh, I see, there have been touch events generated on the device since
session start".

Do you have any feedback for the changes to user_activity_detector.h/cc (which
does not include any new logging)?

[Nico, 2016-05-25 13:24:12]

On 2016/05/19 13:48:03, Andrew T Wilson (Slow) wrote:
> On 2016/05/18 20:16:28, Nico (vacation May 19 to 22) wrote:
> > See also https://www.chromium.org/developers/coding-style#TOC-Logging
> 
> None of these suggestions are appropriate in our case when we need to do
> diagnostics on failures that have happened in the field. And we are not adding
> these to address a specific bug, but to instead to expose more information in
> the logs around the functioning of the remote commands subsystem in general -
we
> did not add a TODO to remove these logs, because the intent is to include this
> information in the logs on an ongoing basis for diagnostic purposes.

This does not lgtm.

[Andrew T Wilson (Slow), 2016-06-03 15:39:12]

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging.h
File base/chromeos/logging.h (right):

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging....
base/chromeos/logging.h:13: // in the system log of the device.
Should we wrap this in #if defined(OS_CHROMEOS)? I think so (or make them no-ops
if not OS_CHROMEOS)

[Nico, 2016-06-04 01:25:00]

Thanks, this lgtm, but a question / suggestion:

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging.h
File base/chromeos/logging.h (right):

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging....
base/chromeos/logging.h:1: // Copyright (c) 2012 The Chromium Authors. All
rights reserved.
2016, no (c)

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging....
base/chromeos/logging.h:13: // in the system log of the device.
On 2016/06/03 15:39:12, Andrew T Wilson (Slow) wrote:
> Should we wrap this in #if defined(OS_CHROMEOS)? I think so (or make them
no-ops
> if not OS_CHROMEOS)

I think making them noops on non-OS_CHROMEOS probably makes the client code
nicer to read (?)

https://codereview.chromium.org/1923943003/diff/190001/base/chromeos/logging.h
File base/chromeos/logging.h (right):

https://codereview.chromium.org/1923943003/diff/190001/base/chromeos/logging....
base/chromeos/logging.h:16: #define CHROMEOS_SYSLOG(severity) LOG(severity)
Do you need separate severities for syslog entries? From what you described, it
sounded like the syslog is just a single file -- maybe this could always log at
a fixed level (say INFO, or what have you), then people don't have to decide on
a warning level when they want to use this?

https://codereview.chromium.org/1923943003/diff/190001/chrome/browser/chromeo...
File chrome/browser/chromeos/policy/upload_job_impl.cc (right):

https://codereview.chromium.org/1923943003/diff/190001/chrome/browser/chromeo...
chrome/browser/chromeos/policy/upload_job_impl.cc:183: LOG(WARNING) << "Upload
job started";
syslog

[Marton Hunyady, 2016-06-06 08:28:54]

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging.h
File base/chromeos/logging.h (right):

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging....
base/chromeos/logging.h:1: // Copyright (c) 2012 The Chromium Authors. All
rights reserved.
On 2016/06/04 01:24:59, Nico wrote:
> 2016, no (c)

Done.

https://codereview.chromium.org/1923943003/diff/150001/base/chromeos/logging....
base/chromeos/logging.h:13: // in the system log of the device.
On 2016/06/04 01:24:59, Nico wrote:
> On 2016/06/03 15:39:12, Andrew T Wilson (Slow) wrote:
> > Should we wrap this in #if defined(OS_CHROMEOS)? I think so (or make them
> no-ops
> > if not OS_CHROMEOS)
> 
> I think making them noops on non-OS_CHROMEOS probably makes the client code
> nicer to read (?)

I made them noops, because otherwise I also need to wrap some of the logging in
the remote_commands package.

https://codereview.chromium.org/1923943003/diff/190001/base/chromeos/logging.h
File base/chromeos/logging.h (right):

https://codereview.chromium.org/1923943003/diff/190001/base/chromeos/logging....
base/chromeos/logging.h:16: #define CHROMEOS_SYSLOG(severity) LOG(severity)
On 2016/06/04 01:25:00, Nico wrote:
> Do you need separate severities for syslog entries? From what you described,
it
> sounded like the syslog is just a single file -- maybe this could always log
at
> a fixed level (say INFO, or what have you), then people don't have to decide
on
> a warning level when they want to use this?

I think it's better to separate the failures (e.g. we couldn't upload) from
status (e.g. we started uploading). The system log uploaded to the admins
contains the log levels.

https://codereview.chromium.org/1923943003/diff/190001/chrome/browser/chromeo...
File chrome/browser/chromeos/policy/upload_job_impl.cc (right):

https://codereview.chromium.org/1923943003/diff/190001/chrome/browser/chromeo...
chrome/browser/chromeos/policy/upload_job_impl.cc:183: LOG(WARNING) << "Upload
job started";
On 2016/06/04 01:25:00, Nico wrote:
> syslog

Done.

[Marton Hunyady, 2016-06-06 09:17:57]

The CQ bit was checked by hunyadym@chromium.org

[Marton Hunyady, 2016-06-06 09:17:57]

The patchset sent to the CQ was uploaded after l-g-t-m from
atwilson@chromium.org, thakis@chromium.org
Link to the patchset: https://codereview.chromium.org/1923943003/#ps210001
(title: "Syslog logging in upload_job_impl")

[commit-bot: I haz the power, 2016-06-06 09:18:06]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1923943003/210001

[commit-bot: I haz the power, 2016-06-06 09:32:44]

Committed patchset #12 (id:210001)

[commit-bot: I haz the power, 2016-06-06 09:34:35]

Description was changed from

==========
Add logging to remote commands

BUG=602572
==========

to

==========
Add logging to remote commands

BUG=602572

Committed: https://crrev.com/481a291fd77a809b5f5844192d674709679c776d
Cr-Commit-Position: refs/heads/master@{#397998}
==========

[commit-bot: I haz the power, 2016-06-06 09:34:36]

Patchset 12 (id:??) landed as
https://crrev.com/481a291fd77a809b5f5844192d674709679c776d
Cr-Commit-Position: refs/heads/master@{#397998}