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

Issue 736011 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Sep 8
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug

Blocked on:
issue 691646



Sign in to add a comment

chrome: runaway log message fill /var

Project Member Reported by gwendal@chromium.org, Jun 22 2017

Issue description

I left a machine (chromeos4-row8-rack10-host13, sentry) with R59 idle, /var got full:

CHROMEOS_RELEASE_APPID={E020B8D4-CA96-4599-84DA-5017455418AE}
CHROMEOS_BOARD_APPID={E020B8D4-CA96-4599-84DA-5017455418AE}
CHROMEOS_CANARY_APPID={90F229CE-83E2-4FAF-8479-E368A34938B1}
DEVICETYPE=CHROMEBOOK
CHROMEOS_ARC_VERSION=3861378
CHROMEOS_ARC_ANDROID_SDK_VERSION=25
GOOGLE_RELEASE=9415.0.0
CHROMEOS_DEVSERVER=
CHROMEOS_RELEASE_BUILDER_PATH=sentry-release/R59-9415.0.0

The reason is /var/log/chrome:
lrwxrwxrwx. 1 chronos chronos         38 Jun  8 13:18 chrome -> /var/log/chrome/chrome_20170608-131823
-rw-r--r--. 1 chronos chronos 2219008000 Jun 22 10:04 chrome_20170608-131823


Looking in the file, it is filled due to 2 messages:
cut -d ']' -f 1 chrome_20170608-131823 | cut -d ':' -f 5 | sort | uniq -c | sort -r
9731696 instance_holder.h(67)
9731681 event_rewriter_chromeos.cc(390)
   1669 gaia_screen_handler.cc(457)
     11 arc_util.cc(48)
      6 name_value_pairs_parser.cc(55)
      4 service_manager.cc(480)
      4 device_event_log_impl.cc(137)


The file is file with these 2 messages, write over 40x per second:

[1160:1160:0622/094918.551771:ERROR:event_rewriter_chromeos.cc(390)] Device ID 6 is unknown.
[1160:1160:0622/094918.552811:VERBOSE1:instance_holder.h(67)] Instance for arc::mojom::AudioInstance::NotifyVolumeState not available.


The file is not removed or trimmed by /usr/sbin/chromeos-cleanup-logs, as it is still in use.

We need to:
- prevent chrome from writing these messages
- chromeos-cleanup-logs should trim the log file(s) more through-fully.
 
first 1000 line of the log file, the reset is mostly the infinite loop of message above.
chrome.log
112 KB View Download
Labels: -Pri-2 Pri-1
Owner: elijahtaylor@chromium.org
Status: Assigned (was: Untriaged)
Elijah, can you find an owner for this? It seems pretty bad.

I don't think we changed anything here recently in mustash land.

Comment 3 by uekawa@google.com, Jun 23 2017

Cc: hidehiko@chromium.org
(hmmm Why are we always dumping arc logs at vlog=1 level ?)

Cc: lhchavez@chromium.org
We set the flag (thank you, Luis, for help me find this):
https://chromium.git.corp.google.com/chromiumos/platform2/+/3a5d607d1c2d425562dabb5e44821f6f73129363/login_manager/chrome_setup.cc#428

Cc: kpschoedel@chromium.org
Owner: lhchavez@chromium.org
Luis, can you look at the instance_holder one at least?  Seems like something is repeatedly trying to get an interface that doesn't exist.  Can we either fix this broken pattern or reduce/remove the log?

+kpschoedel for the event rewriter log (cursory git blame implicates you)
#5 — There are two preconditions for the ‘Device ID’ message:

1. Processing a keystroke (one for each message, so, something is handing it keystrokes at that rate).

2. |ui::InputDeviceManager| does not include that device in |GetKeyboardDevices()|, or (probably less likely) does not exist.

I've been away from this for a couple years, but my first guess would be an input device, maybe a simulated volume key, that is not correctly registered with InputManager and is repeating continuously.
Owner: kpschoedel@chromium.org
Mitigation for the audio bridge spam: https://chromium-review.googlesource.com/c/549195/

Although there's probably something else that needs to be fixed to avoid spamming ArcAudioBridge::SendVolumeState() to begin with.
Project Member

Comment 8 by bugdroid1@chromium.org, Jun 26 2017

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

commit a986cb967239b43e68109063b8a4a8174d9d4149
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Mon Jun 26 23:49:40 2017

arc: Avoid logspam in the audio bridge

This mitigates a runaway logging loop by avoiding to acquire the
instance when we know it won't be possible to acquire.

BUG= 736011 
TEST=Could not repro, but it should produce less spam

Change-Id: I24642d799baebf7ea1a8dd5abcc759e97c2efc37
Reviewed-on: https://chromium-review.googlesource.com/549195
Commit-Queue: Luis Hector Chavez <lhchavez@chromium.org>
Reviewed-by: Hidehiko Abe <hidehiko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#482470}
[modify] https://crrev.com/a986cb967239b43e68109063b8a4a8174d9d4149/components/arc/audio/arc_audio_bridge.cc
[modify] https://crrev.com/a986cb967239b43e68109063b8a4a8174d9d4149/components/arc/audio/arc_audio_bridge.h

Owner: ----
Status: Available (was: Assigned)
Someone (not me, possibly ARC) should identify (a) why there are continuously repeating volume keystrokes, and/or (b) why the source device isn't correctly described by InputDeviceManager.

Project Member

Comment 10 by sheriffbot@chromium.org, Jun 29 2018

Labels: Hotlist-Recharge-Cold
Status: Untriaged (was: Available)
This issue has been Available for over a year. If it's no longer important or seems unlikely to be fixed, please consider closing it out. If it is important, please re-triage the issue.

Sorry for the inconvenience if the bug really should have been left as Available.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Components: Platform>Apps>ARC
Owner: elijahtaylor@chromium.org
Status: Assigned (was: Untriaged)
This bug has an owner, thus, it's been triaged. Changing status to "assigned".
Status: Fixed (was: Assigned)

Sign in to add a comment