derat: Assigning to you since it seems that you intended these warnings not to be logged, normally but, at least on dev-channel devices, we still configure ChromeOS to log them.

You're referring to  issue 644796 , right? I don't think there's any regression here. I didn't add these messages and don't know how important they are. I downgraded them from LOG(WARNING) to VLOG(1) earlier, and I think that's the state that they're still in.

session_manager adds "*/ui/ozone/*=1" to --vmodule. If that's not useful to anyone, I'm happy to remove it.

Which specific warnings are we talking about? If you have a list, I can look at them on a case by case basis.

Here's what I see in /var/log/chrome/chrome on a recent lumpy build. Note that these are verbose messages, not warnings.

[704:704:0217/124407.995050:VERBOSE1:drm_device_handle.cc(83)] Succeeded authenticating /dev/dri/card0 in 0 ms with 1 attempt(s)
[704:704:0217/124408.024713:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument
[704:704:0217/124408.648937:VERBOSE1:drm_display_host_manager.cc(242)] Got display event ADD for /dev/dri/card0
[704:704:0217/124408.650577:VERBOSE1:drm_display_host_manager.cc(242)] Got display event ADD for /dev/dri/card1
[704:1038:0217/124408.660169:VERBOSE1:drm_device_handle.cc(83)] Succeeded authenticating /dev/dri/card1 in 0 ms with 1 attempt(s)
[1030:1065:0217/124408.734726:VERBOSE1:drm_device_manager.cc(54)] Could not initialize DRM device for /sys/devices/platform/vgem/drm/card1
[1030:1065:0217/124409.269106:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument
[1030:1065:0217/124409.425474:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=19 connector=24 origin=0,0 size=1280x800
[1030:1065:0217/124409.440209:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument
[1030:1065:0217/125236.658007:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument
[1030:1065:0217/125236.659920:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=19 connector=24 origin=0,0 size=0x0
[1030:1065:0217/151324.638992:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument
[1030:1065:0217/151324.640865:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=19 connector=24 origin=0,0 size=1280x800
[1030:1065:0217/151324.825772:VERBOSE1:drm_util.cc(204)] Unable to get cursor width capability: Invalid argument

If none of these are useful in debugging reports from write-protected devices, I'm happy to get rid of the vmodule pattern that's making them get logged.

If some of them are unexpected and indicate serious problems, they should be LOG(WARNING) or LOG(ERROR) instead (but I'm skeptical that that's the case since they've been around for so long).

If these are only useful for development, we should also drop the pattern, and developers should just turn on logging on their local devices using /etc/chrome_dev.conf.

I would say most of these are useful to know what's going on when debugging multi-monitor issues. There is one exception though, the cursor width capability which is optional and not present on our older kernels. That should be turned into a debug message.

Thanks! Just sent https://codereview.chromium.org/2692423009/ to drop the cursor messages (I guess I could've changed them to VERBOSE2, but *shrug*... I don't think anyone's going to look at them).

Wez, I can pass the torch to you if you want to argue in favor of getting rid of the other messages. :-)

I've found the display related log messages very helpful when debugging crashes from users on two recent bugs, just to add a data point.

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

commit 8ab6039ad645ba8111d6d4ed89d216ab06a9fce1
Author: derat <derat@chromium.org>
Date: Tue Feb 21 15:02:54 2017

ozone: Remove useless logging about cursor dimensions.

Remove VERBOSE1 message when querying the cursor width or
height fails. These make Chrome OS logs harder to read, and
the condition is expected on older kernels.

BUG= 682079 

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

[modify] https://crrev.com/8ab6039ad645ba8111d6d4ed89d216ab06a9fce1/ui/ozone/platform/drm/common/drm_util.cc

I think the remaining DRM messages just refer to exceptional and/or one-time events, like devices being initialized and displays getting connected.

I'm not familiar with what's important on the ScreenManager side. Kyle, can you do a scrub of those messages to make sure we're not logging any warnings or errors that don't refer to real problems that we plan to fix?

And on a related note, session_manager currently does the following:

  // Turn on logging about external displays being connected and disconnected.
  // Different behavior is seen from different displays and these messages are
  // used to determine what happened within feedback reports.
  builder->AddVmodulePattern("*/ui/display/manager/chromeos/*=1");
  builder->AddVmodulePattern("*/ash/display/*=1");

I'm not a fan of these wildcard patterns, as they often make us log a bunch of stuff that we don't care about, like this message from a file that happens to be under //ash/display:

[702:702:0221/092319.333336:VERBOSE1:display_color_manager_chromeos.cc(217)] No ICC file found with product id: 4ca34231 for display id: 21571318625337344

If there are particular files that we care about on the display-configuration side, we should maybe list them individually instead.

Or maybe we should just use LOG(INFO) for messages that we always we want to log and drop all this vmodule silliness. :-/ (There may be a presubmit check preventing that, but maybe we can exclude Chrome OS paths? Having a log level that we're not allowed to use because we don't trust ourselves to use it sparingly feels... non-ideal.)

I'll look through what is getting logged from ash/display and ui/display/manager/chromeos this week.

I looked over VLOG(1) and LOG(WARNING) around some of this code. I can remove the spammy ones that aren't useful after looking a bit further into the Ozone ones.

ui/ozone/platform/drm/:
https://cs.chromium.org/search/?q=(%22VLOG(1)%22+OR+%22LOG(WARNING)%22)+file:%5Esrc/ui/ozone/platform/drm/+package:%5Echromium$&type=cs

It looks like many of the VLOG(1) statements are normal things that happen during display configuration. So they aren't errors or anything unexpected. I'll have to talk to the Ozone people who originally added them and see why!

ash/display/:
https://cs.chromium.org/search/?q=(%22VLOG(1)%22+OR+%22LOG(WARNING)%22)+file:%5Esrc/ash/display/+package:%5Echromium$&type=cs

The only VLOG(1) are normal events related to color correct and that pattern could probably be removed from login_manager/chrome_setup.cc.

ui/display/:
https://cs.chromium.org/search/?q=(%22VLOG(1)%22+OR+%22LOG(WARNING)%22)+file:%5Esrc/ui/display/manager/chromeos+package:%5Echromium$&type=cs

This can be removed, I added it to observer a bug that I couldn't reproduce.
https://cs.chromium.org/chromium/src/ui/display/manager/chromeos/display_change_observer.cc?q=(%22VLOG(1)%22+OR+%22LOG(WARNING)%22)+(file:%5Esrc/ash/display/+OR+file:%5Esrc/ui/display/+OR+file:%5Esrc/ui/ozone/platform/drm/)+package:%5Echromium$&l=297&dr=C

These shouldn't be getting logged normally. So VLOG(2) or VLOG(1) and change the pattern.
https://cs.chromium.org/chromium/src/ui/display/manager/chromeos/touchscreen_util.cc?q=(%22VLOG(1)%22+OR+%22LOG(WARNING)%22)+(file:%5Esrc/ash/display/+OR+file:%5Esrc/ui/display/+OR+file:%5Esrc/ui/ozone/platform/drm/)+package:%5Echromium$&l=279&dr=C

Re #11: VLOGs are not supposed to be errors.

Please don't remove any VLOGs in ui/ozone/platform/drm (not the remaining ones). None of the logs are "spammy" as they're triggered only on display configuration events (either hardware events or user triggered events). Display configuration events are very infrequent.

If anyone still thinks they're "spammy", can we break it down to is it spammy in tests or on user devices? If it is related to tests, can we disable the VLOGs for ui/ozone in those tests?

If there are events that we would like to be able to be aware of in users' logs but happen regularly (i.e. are not unexpected), can I direct you to device_event_log.cc?

Having output sent to stdio for every chrome run makes parsing through test output, developer run output, and feedback reports more challenging.

Specifically VLOG is intended to be disabled by default and only enabled through a flag. Occasionally we may enable VLOG for certain types of events while investigating the cause of a failure, however such logging should not persist once the failure cause is identified.

Issue 636184 has more details about device_event_log. As I understand it, these can be included in feedback reports (something might need to be set to get them included) but not written to disk.

Correct, logging using, e.g. POWER_LOG(EVENT) << "Some event" will show up in feedback reports under 'device_event_log'. I think that adding a 'DISPLAY' type for the device log would be very helpful in general.

Re #13: Thank you for pointing that out, I didn't know we had that. I think that would fine. Steven, could you please provide some detail on how we should be using device_event_log.h?

What type should we be using with DEVICE_LOG? Should we create a new type? (probably something generic).

I see device_event_log::Initialize() is only called from browser UI. Most of the logs in question are coming from the GPU process. Presumably we should be initializing it somewhere in the GPU code; I'm guessing in GpuMain() before sandbox?

Kyle, if you're taking a look at some of the logs, you might be able to fix the TODO related to the warning in https://cs.chromium.org/chromium/src/ui/ozone/platform/drm/gpu/screen_manager.cc?rcl=138ae10a7041202a4ac73b2dd21b1dc7e3634f3d&l=101

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

commit 39484cbb5b2e2089054e2cd642e03bbe817f42af
Author: kylechar <kylechar@chromium.org>
Date: Mon Feb 27 17:04:09 2017

Remove unneeded verbose logging for displays.

Change log statements from ui/display/manager/chromeos/ that were being
logged in Chrome OS devices unnecessarily. Remove a VLOG(1) added by me
to observe the fix to a bug on beta channel. I believe the bug is fixed
and this isn't necessary anymore. Also change a LOG(WARNNING) to
VLOG(2) for unmatched touchscreen displays. Not all displays are
touchscreens, so this shouldn't be a warning.

BUG= 682079 

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

[modify] https://crrev.com/39484cbb5b2e2089054e2cd642e03bbe817f42af/ui/display/manager/chromeos/display_change_observer.cc
[modify] https://crrev.com/39484cbb5b2e2089054e2cd642e03bbe817f42af/ui/display/manager/chromeos/touchscreen_util.cc

Hmm, I didn't realize these events would be coming from a separate process. Using DEVICE_LOG from a separate process would not work as expected. Making it work should be doable but would require more effort.

In the meanwhile, if we were to reduce the default logging to events that do not usually occur (e.g. related to a second display or changing display configuration after startup) that would be acceptable.

I would prefer to avoid a strategy of "hide logging during tests" since:
a) It could be surprising while debugging a test.
b) Extra logging in feedback report stdout and developer runs is also a problem.

I will also happily LGTM changes that switch "important VLOG(1)s that we will always want to see" to LOG(INFO). Bonus points if you do it without starting a new thread about logging levels on chromium-dev.

Re #18:
a) Why would it be surprising? VLOG is explicitly made for this case. We don't expect the test to fail, so why not default to a low verbosity level and increase it if a test fails (or the developer could increase it while debugging)?

b) Sure, there's more logs to go through, but it's easier to do 'grep -v' for VLOGs rather than not have enough to go by.

To me, it still seems this is motivated by logs generated in test runs. In this case, I can see why we wouldn't want all these VLOGs (and I think we should just disable them in tests then).

Am I wrong? If I'm wrong, how many of these VLOGs (minus the cursor one which was removed) are you seeing during a normal user session? What do you consider too much?

Perhaps we should take a look at a concrete user log to see how many there are? My impression is there's a few during startup and when a display related event occurs (external monitor, turning screen off, sleep).

Why can't we wait on DEVICE_LOG working in the GPU process?

Re #19: If I remember correctly we had a discussion on why these shouldn't be LOG(INFO) and at that point everything was updated to VLOG(1). It was done specifically so we can control when to enable/disable them. It seems we're now going back and forth between the two.

I'd be more inclined to look at making some VLOG(2) while DEVICE_LOG support is added to the GPU process. But even then I'd defer this decision to kylechar@ and marcheu@ since they're the ones that would likely have to triage any relevant issues.

Re #20: I filed this bug specifically because the chrome_log on my
Chromebox was getting filled up with these messages, making it harder to
see when warnings or errors are logged.

To put this in context, on desktop anything logged with VLOG is not output
unless the user explicitly enables it via the command-line. If we had a
simple way for the user to choose their log verbosity then leaving VLOGs in
place would make sense, since a user seeing some issue can increase log
verbosity to get diagnostic output - the problem here is really that we
have some modules permanently configured to log verbosely under CrOS.

About the messages: it depends what exactly we are talking about, but if these are the messages that happen only on startup or on monitor hotplug, I'm interested in keeping them. These are super helpful to debug things. If you are seeing messages that are recurring, they are probably not useful anyway.

The messages I'm seeing are logged every time the system sleeps & resumes
(which is more or less every time I come back to the device after being
away for more than a few minutes).

Yeah these are the monitor configuration messages, I would rather keep them, otherwise we are blind when debugging these issues in the field.

#20: Right now, we're using VLOG(1) for many messages that we always plan to log. To do this, we need to add a bunch of patterns via --vmodule, which:

a) makes Chrome's command line harder to read
b) has broken Chrome in the past (due to hitting length limits over IPC)
c) often results in us logging things that we don't actually care about (due to overly-broad wildcard patterns in an attempt to not bloat the command line)

As far as I'm aware, the main reason we started doing this was due to a blanket ban on LOG(INFO) in Chrome, but it's put us in what feels to me like a worse situation than if we'd instead limited ourselves to using LOG(INFO) for informational things that we always want to log, as it was initially intended.

Steven, do you think it would be feasible to make DEVICE_LOG messages get written to disk (perhaps with buffering and frequent rotation)? That feels like it would be an easy drop-in replacement for many of the things that we currently use VLOG(1)-plus-vmodule for. I don't know how much work it'd be, but I'm happy to file a new bug for further discussion.

Personally I don't think that any logging that makes it harder for every
developer to find legitimate warnings or errors is bad, whether it is
LOG(INFO) or VLOG(1) enabled via session_manager. I have no opinion WRT
which of those is less bad.

We have talked about writing DEVICE_LOG to disk but haven't bothered since
it doesn't serve a whole lot of purpose (the logs do go to feedback
reports). If it would help in some way I have no problem with writing those
logs to disk.

The problem with DEVICE_LOG is that it does not support multiple processes.

I would suggest:
1) DEVICE_LOG for any useful state that can be logged by the browser
process.
2) VLOG(1) or LOG(INFO) for non browser process logging that only occurs on
a state change that wouldn't normally occur in a test or developer build.

Re #25: Ahh, thanks for the explanation. Sure, we can move them to LOG(INFO) in the meantime.

+1 to finding a way to use DEVICE_LOG for these.

I'm pretty sure the reason the log statements are VLOG(1) + vmodule pattern is that LOG(INFO) doesn't get written to the log file. I tested switching VLOG(1) to LOG(INFO) and log statements that were in /var/log/chrome/chrome are no longer there.

It seems like there is a desire to keep the existing drm event and display configuration log statements. I can remove the unnecessary ones in ash/display/ for colour correction. Otherwise is there anything else left to do in short term (at least until DEVICE_LOG will work)?

The fact that DEVICE_LOG only works with one process is going to be interesting with mus+ash and splitting the browser process into multiple processes. I'll file a different bug for that though.

Re #28: Check /var/log/ui/ui.LATEST ... different logs go to different files. The other possibility is /home/chronos/user/log/chrome.

I don't get anything with grep -r in /var/log/* or /home/chronos/user/log/* after changing from VLOG(1) to LOG(INFO). I think there is a default logging severity level (in addition to verbosity level).

I thought LOG(INFO) was actively discouraged in favour of VLOG(); really
the problem here is that we're logging stuff useful for diagnostics all the
time, rather than just when there is something to diagnose.  I appreciate
that sometimes we need to diagnose retrospectively, but in general could we
address these use-cases by:

1. Leaving VLOG(1), VLOG(2) etc in-place.
2. Providing an option to enable "diagnostic" logging.

?

I think that we're always going to have messages that we want to log all the time (e.g. so we can see them in feedback reports submitted right after hard-to-repro issues are seen, or ones submitted by users who don't know how to turn on diagnostic logging). I've heard this from people on the enterprise team, and it sounds like some of the display-configuration messages also fall into this bucket.

If that's the case, using LOG(INFO) sparingly seems like a cleaner approach than using VLOG(1) in conjunction with often-overly-broad patterns that are permanently passed via --vmodule.

This is pretty far afield of what this bug was originally tracking, so closing it out after any additional useless display messages are dropped (is that just the color profile ones at this point?) and taking up further discussion in a different bug, email thread, or design doc sounds fine to me.

Sounds reasonable. I've sent a review to remove the */ash/display/*=1 from vmodule. I'll close the bug after that lands.

Re #32: Given that we're talking about ChromeOS specific logging, providing similar detail to system-level logs on other platforms, it might be good to explicitly call-out the use of LOG(INFO) as a special-case for ChromeOS - otherwise the guidelines at https://chromium.googlesource.com/chromium/src/+/master/styleguide/c++/c++.md#Logging only really talk about VLOG(), and people may get upset if they see LOG(INFO) being added.

Thanks for taking care of the original logspam issue. :)

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/3ff15bacbe5cfbb0ce8bbfb069adc334b829fd39

commit 3ff15bacbe5cfbb0ce8bbfb069adc334b829fd39
Author: kylechar <kylechar@chromium.org>
Date: Wed Mar 08 19:27:43 2017

login: Remove ash/display from vmodule flag.

The display configuration VLOGs that "*/ash/display/*=1" enable are no
longer useful. Most display configuration code has been moved from
ash/display/ to ui/display/manager/chromeos/.

BUG= chromium:682079 
TEST=Compiled chromeos-login succesfully.

Change-Id: If40f43ba167177ffa8a213792ea10a7447ef5494
Reviewed-on: https://chromium-review.googlesource.com/451606
Commit-Ready: Kyle Charbonneau <kylechar@chromium.org>
Tested-by: Kyle Charbonneau <kylechar@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/3ff15bacbe5cfbb0ce8bbfb069adc334b829fd39/login_manager/chrome_setup.cc

Verified in Chrome OS 9334.33.0, 58.0.3029.51.