arc: Reduce logspam when ARC is not enabled/available

arc: Reduce logspam when ARC is not enabled/available

There are some Chrome services that unconditionally try to call ARC
code, and the latter will print stuff to the log if it's not enabled or
avilable (yet). This change ensures that we only attempt to contact ARC
when it is actually ready for the most chatty services: net and process.

BUG=654038
TEST=Opted out of ARC, did not see any logs

Committed: https://crrev.com/edea73c00927636fe885af9205c668633e65a691
Cr-Commit-Position: refs/heads/master@{#435534}

[Luis Héctor Chávez, 2016-11-30 22:22:48]

The CQ bit was checked by lhchavez@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-11-30 22:23:09]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[Luis Héctor Chávez, 2016-11-30 22:26:27]

lhchavez@chromium.org changed reviewers:
+ abhishekbh@google.com, yusukes@chromium.org

[Luis Héctor Chávez, 2016-11-30 22:26:28]

yusukes@ PTAL
abhishekbh@ FYI

[commit-bot: I haz the power, 2016-11-30 22:50:56]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-30 22:50:57]

Dry run: This issue passed the CQ dry run.

[Yusuke Sato, 2016-11-30 23:29:40]

some questions below:

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
File chrome/browser/chromeos/arc/process/arc_process_service.cc (right):

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
chrome/browser/chromeos/arc/process/arc_process_service.cc:248: return false;
I think this would also remove legit logs when the user has opted in to ARC but
the instance is not ready for some reason.

Can we instead use ArcBridgeService::GetEnabled() here or even in
GetInstanceForMethod()?

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
File components/arc/net/arc_net_host_impl.cc (right):

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
components/arc/net/arc_net_host_impl.cc:301: if (observing_network_state_) {
Do we need the check? I think the convention in Chromium is that
RemoveObserver(p) is no-op when |p| is not in the list.

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
components/arc/net/arc_net_host_impl.cc:322: if (!observing_network_state_)
same

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
components/arc/net/arc_net_host_impl.cc:662: DCHECK(observing_network_state_);
same

[Luis Héctor Chávez, 2016-11-30 23:45:08]

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
File chrome/browser/chromeos/arc/process/arc_process_service.cc (right):

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
chrome/browser/chromeos/arc/process/arc_process_service.cc:248: return false;
On 2016/11/30 23:29:39, Yusuke Sato wrote:
> I think this would also remove legit logs when the user has opted in to ARC
but
> the instance is not ready for some reason.
> 
> Can we instead use ArcBridgeService::GetEnabled() here or even in
> GetInstanceForMethod()?

ArcBridgeService::GetEnabled() unfortunately does not paint the whole picture :(
The two services that call this are already gated upon that, but still manage to
produce logspam.

The fundamental problem is that the calls to RequestAppProcessList()  shouldn't
be made in the first place unless |instance_ready_| is true. One of the callers
cannot be safely notified of this because it is a singleton, and outlives
ArcBridgeService, so it cannot register itself as an Observer (or rather, it
can, but then the observer list will DCHECK upon destruction since it won't be
empty). The other caller does behave correctly by only calling this after the
instance is ready, because it does observe the readiness of the process
instance.

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
File components/arc/net/arc_net_host_impl.cc (right):

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
components/arc/net/arc_net_host_impl.cc:301: if (observing_network_state_) {
On 2016/11/30 23:29:39, Yusuke Sato wrote:
> Do we need the check? I think the convention in Chromium is that
> RemoveObserver(p) is no-op when |p| is not in the list.

Yes, but
https://cs.chromium.org/chromium/src/chromeos/network/network_state_handler.c...
also does logging. It might be a bit confusing for the log readers to see that
something is unregistering but never registering for event notification.

[Yusuke Sato, 2016-11-30 23:59:30]

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
File chrome/browser/chromeos/arc/process/arc_process_service.cc (right):

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
chrome/browser/chromeos/arc/process/arc_process_service.cc:248: return false;
On 2016/11/30 23:45:08, Luis Héctor Chávez wrote:
> On 2016/11/30 23:29:39, Yusuke Sato wrote:
> > I think this would also remove legit logs when the user has opted in to ARC
> but
> > the instance is not ready for some reason.
> > 
> > Can we instead use ArcBridgeService::GetEnabled() here or even in
> > GetInstanceForMethod()?
> 
> ArcBridgeService::GetEnabled() unfortunately does not paint the whole picture
:(
> The two services that call this are already gated upon that, but still manage
to
> produce logspam.
> 
> The fundamental problem is that the calls to RequestAppProcessList() 
shouldn't
> be made in the first place unless |instance_ready_| is true. One of the
callers
> cannot be safely notified of this because it is a singleton, and outlives
> ArcBridgeService, so it cannot register itself as an Observer (or rather, it
> can, but then the observer list will DCHECK upon destruction since it won't be
> empty). The other caller does behave correctly by only calling this after the
> instance is ready, because it does observe the readiness of the process
> instance.

The DCHECK in ~ObserverList<> is actually an optional feature, and
components/arc/'s observer_list_ doesn't seem to use it.

 template <class ObserverType, bool check_empty = false>
 class ObserverList : public ObserverListBase<ObserverType> {

We can probably fix the caller and remove the instance_ready_ member variable? I
feel like that's probably a cleaner fix. WDYT?

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
File components/arc/net/arc_net_host_impl.cc (right):

https://codereview.chromium.org/2541843003/diff/1/components/arc/net/arc_net_...
components/arc/net/arc_net_host_impl.cc:301: if (observing_network_state_) {
On 2016/11/30 23:45:08, Luis Héctor Chávez wrote:
> On 2016/11/30 23:29:39, Yusuke Sato wrote:
> > Do we need the check? I think the convention in Chromium is that
> > RemoveObserver(p) is no-op when |p| is not in the list.
> 
> Yes, but
>
https://cs.chromium.org/chromium/src/chromeos/network/network_state_handler.c...
> also does logging. It might be a bit confusing for the log readers to see that
> something is unregistering but never registering for event notification.

Acknowledged.

[Yusuke Sato, 2016-12-01 02:29:21]

lgtm

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
File chrome/browser/chromeos/arc/process/arc_process_service.cc (right):

https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
chrome/browser/chromeos/arc/process/arc_process_service.cc:248: return false;
Chatted with Luis offline. Let's keep the member variable as-is. Since some of
the users of this function and ArcBridgeService are created roughly at the same
time in the Main() function, adding dependency on ABS seems like a bad idea.
Small modifications to Main() may break things.

As we chatted offline, to prevent future logspam issues, please consider adding
opt-in check to GetInstanceForMethod(). Doing it in a different CL is just fine.

[Luis Héctor Chávez, 2016-12-01 02:40:29]

On 2016/12/01 02:29:21, Yusuke Sato wrote:
> lgtm
> 
>
https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
> File chrome/browser/chromeos/arc/process/arc_process_service.cc (right):
> 
>
https://codereview.chromium.org/2541843003/diff/1/chrome/browser/chromeos/arc...
> chrome/browser/chromeos/arc/process/arc_process_service.cc:248: return false;
> Chatted with Luis offline. Let's keep the member variable as-is. Since some of
> the users of this function and ArcBridgeService are created roughly at the
same
> time in the Main() function, adding dependency on ABS seems like a bad idea.
> Small modifications to Main() may break things.
> 
> As we chatted offline, to prevent future logspam issues, please consider
adding
> opt-in check to GetInstanceForMethod(). Doing it in a different CL is just
fine.

Will do!

[Luis Héctor Chávez, 2016-12-01 02:40:36]

The CQ bit was checked by lhchavez@chromium.org

[commit-bot: I haz the power, 2016-12-01 02:41:04]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-12-01 02:45:18]

CQ is committing da patch.

Bot data: {"patchset_id": 1, "attempt_start_ts": 1480560036112680, "parent_rev":
"440df618b876e1dfef23b0506fa514423e137ee0", "commit_rev":
"a97a953d740d51ca86e0a80bf6c783fd938fc91b"}

[commit-bot: I haz the power, 2016-12-01 02:45:46]

Committed patchset #1 (id:1)

[commit-bot: I haz the power, 2016-12-01 02:48:57]

Description was changed from

==========
arc: Reduce logspam when ARC is not enabled/available

There are some Chrome services that unconditionally try to call ARC
code, and the latter will print stuff to the log if it's not enabled or
avilable (yet). This change ensures that we only attempt to contact ARC
when it is actually ready for the most chatty services: net and process.

BUG=654038
TEST=Opted out of ARC, did not see any logs
==========

to

==========
arc: Reduce logspam when ARC is not enabled/available

There are some Chrome services that unconditionally try to call ARC
code, and the latter will print stuff to the log if it's not enabled or
avilable (yet). This change ensures that we only attempt to contact ARC
when it is actually ready for the most chatty services: net and process.

BUG=654038
TEST=Opted out of ARC, did not see any logs

Committed: https://crrev.com/edea73c00927636fe885af9205c668633e65a691
Cr-Commit-Position: refs/heads/master@{#435534}
==========

[commit-bot: I haz the power, 2016-12-01 02:49:00]

Patchset 1 (id:??) landed as
https://crrev.com/edea73c00927636fe885af9205c668633e65a691
Cr-Commit-Position: refs/heads/master@{#435534}