New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 654038 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Last visit 16 days ago
Closed: Dec 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

ARC log spam during login

Project Member Reported by derat@chromium.org, Oct 7 2016

Issue description

In a ToT build, there's a bunch of ARC spam in the Chrome user log:

7821:7821:1007/132634:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::WifiEnabledStateChanged not available.
...
[7821:7821:1007/132634:VERBOSE1:arc_bridge_service_impl.cc(51)] Session started
[7821:7821:1007/132634:VERBOSE1:arc_bridge_service_impl.cc(78)] Prerequisites changed. state=0, session_started=1
[7821:7821:1007/132634:INFO:arc_bridge_service_impl.cc(84)] Prerequisites met, starting ARC
...
[7821:7821:1007/132635:VERBOSE1:arc_net_host_impl.cc(629)] New default network: /service/1
...
[7821:7821:1007/132635:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::WifiEnabledStateChanged not available.
...
[7821:7821:1007/132635:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::DefaultNetworkChanged not available.
...
[7821:7821:1007/132635:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132636:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::WifiEnabledStateChanged not available.
...
[7821:7821:1007/132636:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::WifiEnabledStateChanged not available.
...
[7821:7821:1007/132636:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132637:INFO:arc_bridge_service_impl.cc(130)] ARC ready
[7821:7821:1007/132637:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132638:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132638:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::WifiEnabledStateChanged not available.
[7821:7821:1007/132638:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::NetInstance::ScanCompleted not available.
[7821:7821:1007/132639:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132640:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132641:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132642:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.
[7821:7821:1007/132643:VERBOSE1:arc_net_host_impl.cc(597)] GetDefaultNetwork: default network is /service/1
[7821:7821:1007/132643:VERBOSE1:instance_holder.h(52)] Instance for arc::mojom::ProcessInstance::RequestProcessList not available.

The messages like "Session started", "ARC ready", and so on seem useful and not too noisy, but the "not available" ones maybe not so much. Is it fine to remove that VLOG(1) from instance_holder.h?

As an aside, is there a notification or observer interface or something that whoever's calling this can use to be notified when ARC and/or various mojo services are ready? It looks like some code is polling right now (see once-a-second RequestProcessList messages), which both wastes CPU time during login and means that we don't actually start using the service as quickly as we could once it's finally ready.

 
Cc: drinkcat@chromium.org osh...@chromium.org bhthompson@chromium.org hidehiko@chromium.org abodenha@chromium.org yusukes@chromium.org
Labels: -Pri-3 M-55 Pri-1
The once-per-second log spam is really overwhelming, and now on Beta channel, too: 8872.35.0 / 55.0.2883.35

For an example, see:
https://feedback.corp.google.com/#/Report/15828032849

The "Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available." message starts within 2 seconds of start of chrome_user_log, and repeats every second, except when the lock screen is not shown:

2016-11-04 09:42:50.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>NetInstan<IPv6: 5>WifiEnabledStateChanged not available.
...
2016-11-04 09:42:52.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-04 09:42:53.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-04 09:42:53.000 8 1237:1237: user_session_manager.cc(1712): Launching browser...
2016-11-04 09:42:54.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-04 09:42:55.000 8 1237:1237: oauth2_login_verifier.cc(67): MergeSession successful.
2016-11-04 09:42:55.000 8 1237:1237: oauth2_login_manager.cc(305): OAuth2 refresh and/or GAIA token verification succeeded.
2016-11-04 09:42:55.000 8 1237:1237: oauth2_login_verifier.cc(82): ListAccounts successful.
2016-11-04 09:42:56.000 8 1237:1237: input_events_blocker.cc(20): InputEventsBlocker 0xfc20efc0 destroyed.
2016-11-04 09:42:56.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-04 09:42:57.000 6 1237:1237: arc_bridge_service_impl.cc(130): ARC ready
2016-11-04 09:42:58.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-04 09:43:01.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
...
2016-11-04 09:43:01.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>NetInstan<IPv6: 5>WifiEnabledStateChanged not available.
2016-11-04 09:43:02.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
...
2016-11-09 10:21:12.000 8 1237:1237: arc_policy_bridge.cc(277): ArcPolicyBridg<IPv6: 3>OnPolicyInstanceClosed
2016-11-09 10:21:12.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
....
2016-11-11 15:50:24.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.
2016-11-11 15:50:25.000 8 1237:1237: instance_holder.h(52): Instance for ar<IPv6: 4>mojom<IPv6: 1>ProcessInstan<IPv6: 5>RequestProcessList not available.


Status: Started (was: Assigned)
Project Member

Comment 4 by bugdroid1@chromium.org, Dec 1 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/edea73c00927636fe885af9205c668633e65a691

commit edea73c00927636fe885af9205c668633e65a691
Author: lhchavez <lhchavez@chromium.org>
Date: Thu Dec 01 02:45:12 2016

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

Review-Url: https://codereview.chromium.org/2541843003
Cr-Commit-Position: refs/heads/master@{#435534}

[modify] https://crrev.com/edea73c00927636fe885af9205c668633e65a691/chrome/browser/chromeos/arc/process/arc_process_service.cc
[modify] https://crrev.com/edea73c00927636fe885af9205c668633e65a691/chrome/browser/chromeos/arc/process/arc_process_service.h
[modify] https://crrev.com/edea73c00927636fe885af9205c668633e65a691/components/arc/net/arc_net_host_impl.cc
[modify] https://crrev.com/edea73c00927636fe885af9205c668633e65a691/components/arc/net/arc_net_host_impl.h

Status: Fixed (was: Started)
Labels: Merge-Request-56 Merge-Request-55
It would be very nice to get this onto R55 to make it easier to debug any issues on the forth-coming Stable channel release.

Comment 8 by dimu@chromium.org, Dec 2 2016

Labels: -Merge-Request-55 Merge-Review-55 Hotlist-Merge-Review
[Automated comment] Less than 2 weeks to go before stable on M55, manual review required.

Comment 9 by dimu@chromium.org, Dec 2 2016

Labels: -Merge-Request-56 Merge-Approved-56 Hotlist-Merge-Approved
Your change meets the bar and is auto-approved for M56 (branch: 2924)
Project Member

Comment 10 by sheriffbot@chromium.org, Dec 5 2016

This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Labels: -Merge-Approved-56
Project Member

Comment 12 by bugdroid1@chromium.org, Dec 5 2016

Labels: -merge-approved-56 merge-merged-2924
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/26ed24fd38f8c2b64ced3d3bb61ac04686d698ba

commit 26ed24fd38f8c2b64ced3d3bb61ac04686d698ba
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Mon Dec 05 17:21:49 2016

[Merge M-56] 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
TBR=yusukes@chromium.org

Review-Url: https://codereview.chromium.org/2541843003
Cr-Commit-Position: refs/heads/master@{#435534}
(cherry picked from commit edea73c00927636fe885af9205c668633e65a691)

Review URL: https://codereview.chromium.org/2553713002 .

Cr-Commit-Position: refs/branch-heads/2924@{#334}
Cr-Branched-From: 3a87aecc31cd1ffe751dd72c04e5a96a1fc8108a-refs/heads/master@{#433059}

[modify] https://crrev.com/26ed24fd38f8c2b64ced3d3bb61ac04686d698ba/chrome/browser/chromeos/arc/process/arc_process_service.cc
[modify] https://crrev.com/26ed24fd38f8c2b64ced3d3bb61ac04686d698ba/chrome/browser/chromeos/arc/process/arc_process_service.h
[modify] https://crrev.com/26ed24fd38f8c2b64ced3d3bb61ac04686d698ba/components/arc/net/arc_net_host_impl.cc
[modify] https://crrev.com/26ed24fd38f8c2b64ced3d3bb61ac04686d698ba/components/arc/net/arc_net_host_impl.h

Please merge to M55 as per the merge request.
M-55 is already on Stable so in general we should target this of M56 
How risky is this change?
Status: Verified (was: Fixed)

Sign in to add a comment