New issue
Advanced search Search tips

Issue 844258 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Closed: Jun 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Spammy name_value_pairs_parser.cc warnings about duplicated keys

Project Member Reported by derat@chromium.org, May 18 2018

Issue description

I see a bunch of a bunch of spammy warnings at the beginning of /var/log/chrome/chrome in a ToT caroline build (r559727):

[3650:3650:0517/171705.066236:VERBOSE1:drm_device_handle.cc(87)] Succeeded authenticating /dev/dri/card0 in 0 ms with 1 attempt(s)
[3650:3770:0517/171705.155269:WARNING:name_value_pairs_parser.cc(55)] Key block_devmode already has value (error), ignoring new value: 0
[3650:3770:0517/171705.155327:WARNING:name_value_pairs_parser.cc(55)] Key customization_id already has value SAMSUNG-CAROLINE, ignoring new value: SAMSUNG-CAROLINE
[3650:3770:0517/171705.155347:WARNING:name_value_pairs_parser.cc(55)] Key rlz_brand_code already has value SMAK, ignoring new value: SMAK
[3650:3770:0517/171705.155392:WARNING:name_value_pairs_parser.cc(55)] Key ubind_attribute already has value =Ci4KIDvcXJNGRh2Kgqvk3O5vnRAQ8GIL0bYESFQ62vz6nijpEAEaCGNhcm9saW5lEPT_tA0=, ignoring new value: =Ci4KIDvcXJNGRh2Kgqvk3O5vnRAQ8GIL0bYESFQ62vz6nijpEAEaCGNhcm9saW5lEPT_tA0=
[3650:3770:0517/171705.155412:WARNING:name_value_pairs_parser.cc(55)] Key gbind_attribute already has value =Ci4KIOj_LNXASp8BnKMLtupk9rQ1z0Qbwf1nfJJYQx0j7mZ2EAAaCGNhcm9saW5lEOPi-7IO, ignoring new value: =Ci4KIOj_LNXASp8BnKMLtupk9rQ1z0Qbwf1nfJJYQx0j7mZ2EAAaCGNhcm9saW5lEOPi-7IO
[3650:3770:0517/171705.155448:WARNING:name_value_pairs_parser.cc(55)] Key rlz_brand_code already has value SMAK, ignoring new value: SMAK
[3650:3770:0517/171705.155465:WARNING:name_value_pairs_parser.cc(55)] Key customization_id already has value SAMSUNG-CAROLINE, ignoring new value: SAMSUNG-CAROLINE
[3650:3770:0517/171705.155480:WARNING:name_value_pairs_parser.cc(55)] Key region already has value us, ignoring new value: us
[3650:3770:0517/171705.155495:WARNING:name_value_pairs_parser.cc(55)] Key ActivateDate already has value 2017-47, ignoring new value: 2017-47
[3650:3770:0517/171705.155510:WARNING:name_value_pairs_parser.cc(55)] Key block_devmode already has value (error), ignoring new value: 0
[3650:3770:0517/171705.155524:WARNING:name_value_pairs_parser.cc(55)] Key check_enrollment already has value 0, ignoring new value: 0
[3650:3650:0517/171705.158548:WARNING:statistics_provider.cc(330)] Statistics loaded after waiting 6ms.

chromeos/system/name_value_pairs_parser.cc looks like it's general-purpose code, but I'm guessing from the warning at the end (which is also non-actionable) that this is from the calls in StatisticsProviderImpl::LoadMachineStatistics in chromeos/system/statistics_provider.cc:

  parser.GetNameValuePairsFromFile(machine_info_path,
                                   kMachineHardwareInfoEq,
                                   kMachineHardwareInfoDelim);
  parser.GetNameValuePairsFromFile(base::FilePath(kEchoCouponFile),
                                   kEchoCouponEq,
                                   kEchoCouponDelim);
  parser.GetNameValuePairsFromFile(vpd_path,
                                   kVpdEq,
                                   kVpdDelim);

/tmp/machine-info is gone by now, but based on the contents of /mnt/stateful_partition/unencrypted/cache/vpd/echo/vpd_echo.txt and /mnt/stateful_partition/unencrypted/cache/vpd/filtered.txt, I'm guessing that we're duplicating some fields between /tmp/machine-info and /mnt/stateful_partition/unencrypted/cache/vpd/filtered.txt. Is this expected?

It's probably easy to at least make name_value_pairs_parser.cc not log this warning when the value it just read is the same as what it already has. I'm also fine with changing this to DVLOG(1) (and would probably prefer doing that).
 

Comment 1 by derat@chromium.org, May 18 2018

More warnings from the same area:

[3650:3650:0517/171705.311531:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[3650:3650:0517/171705.311626:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
...
[3650:3650:0517/171705.372574:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[3650:3650:0517/171705.388824:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[3650:3650:0517/171705.389763:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
...
[3650:3650:0517/171705.453423:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N

Comment 2 by tnagel@chromium.org, May 18 2018

This looks like a bug as we *should* overwrite error values:

[3650:3770:0517/171705.155510:WARNING:name_value_pairs_parser.cc(55)] Key block_devmode already has value (error), ignoring new value: 0

Related: I've filed issue 841293 for the (possible) deprecation of /tmp/machine-info but I don't have the bandwidth to drive this right now.
Project Member

Comment 3 by bugdroid1@chromium.org, May 22 2018

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

commit 4effbf7686e977c114e384b07f66b5c369b53cb4
Author: Daniel Erat <derat@chromium.org>
Date: Tue May 22 06:53:21 2018

chromeos: Reduce name_value_pairs_parser.cc log spam.

Make NameValuePairsParser::AddNameValuePair stop logging a
warning whenever it sees a duplicated key with the same
value that was loaded earlier.

Bug:  844258 
Change-Id: I2a1963458e1f49200b843d974541fb5607928261
Reviewed-on: https://chromium-review.googlesource.com/1067134
Reviewed-by: Thiemo Nagel <tnagel@chromium.org>
Commit-Queue: Dan Erat <derat@chromium.org>
Cr-Commit-Position: refs/heads/master@{#560501}
[modify] https://crrev.com/4effbf7686e977c114e384b07f66b5c369b53cb4/chromeos/system/name_value_pairs_parser.cc

Project Member

Comment 4 by bugdroid1@chromium.org, May 22 2018

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

commit fd24c7c7294e67700147e46e27b117d4423a4b80
Author: Thiemo Nagel <tnagel@chromium.org>
Date: Tue May 22 13:59:41 2018

chromeos: NameValuePairsParser cleanup

Removed unused GetSingleValueFromTool() method and made two helper
methods private.

Bug:  844258 
Change-Id: I9e29c2b36d93d1278edac2a5e8cc506c270b2c79
Reviewed-on: https://chromium-review.googlesource.com/1068939
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: Thiemo Nagel <tnagel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#560555}
[modify] https://crrev.com/fd24c7c7294e67700147e46e27b117d4423a4b80/chromeos/system/name_value_pairs_parser.cc
[modify] https://crrev.com/fd24c7c7294e67700147e46e27b117d4423a4b80/chromeos/system/name_value_pairs_parser.h
[modify] https://crrev.com/fd24c7c7294e67700147e46e27b117d4423a4b80/chromeos/system/name_value_pairs_parser_unittest.cc

Comment 5 by emaxx@chromium.org, May 23 2018

Cc: emaxx@chromium.org
Labels: Enterprise-Triaged

Comment 6 by derat@chromium.org, May 25 2018

Owner: derat@chromium.org
Status: Started (was: Available)
Project Member

Comment 7 by bugdroid1@chromium.org, May 30 2018

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

commit fcd54faf8187b9145be524876d75703057ff795a
Author: Daniel Erat <derat@chromium.org>
Date: Wed May 30 23:12:12 2018

chromeos: Drop "(error)" values from crossystem.

Update StatisticsProvider to drop pairs received from
crossystem that have "(error)" values. NameValuePairsParser
ignores duplicate values, so we should get rid of these so
they don't prevent us from saving real values later.

Also downgrade a "Statistics loaded after waiting ___ ms"
LOG(WARNING) to VLOG(1), since this seems to be the common
case on a caroline ToT device and it just ends up cluttering
the logs.

Bug:  844258 
Change-Id: Idf869617a03992e51a720359b4ebfdac91dec6e9
Reviewed-on: https://chromium-review.googlesource.com/1072706
Reviewed-by: Thiemo Nagel <tnagel@chromium.org>
Commit-Queue: Dan Erat <derat@chromium.org>
Cr-Commit-Position: refs/heads/master@{#563053}
[modify] https://crrev.com/fcd54faf8187b9145be524876d75703057ff795a/chromeos/system/name_value_pairs_parser.cc
[modify] https://crrev.com/fcd54faf8187b9145be524876d75703057ff795a/chromeos/system/name_value_pairs_parser.h
[modify] https://crrev.com/fcd54faf8187b9145be524876d75703057ff795a/chromeos/system/name_value_pairs_parser_unittest.cc
[modify] https://crrev.com/fcd54faf8187b9145be524876d75703057ff795a/chromeos/system/statistics_provider.cc

Comment 8 by derat@chromium.org, Jun 13 2018

Here's what I see now:

...
[5548:5548:0612/143203.641528:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[5548:5548:0612/143203.641616:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
...
[5548:5548:0612/143203.690954:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[5548:5548:0612/143203.700887:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[5548:5548:0612/143203.701059:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N
[5548:5548:0612/143203.728934:WARNING:statistics_provider.cc(415)] Requested statistic not found: Product_S/N

I think I'm just going to delete this message.

a) The comment above kMachineInfoSerialNumberKeys in chromeos/system/statistics_provider.cc specifically says that "Product_S/N" is "known *not* to be present on caroline".

b) StatisticsProviderImpl::GetMachineStatistic() already returns bool to indicate whether the requested statistic was found or not. If it's not there but was supposed to be, the caller is in the best place to know that, and that's where the error should be logged.
Project Member

Comment 9 by bugdroid1@chromium.org, Jun 13 2018

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

commit 635d13f01f880321810c161da7cdc456a2bf2c87
Author: Daniel Erat <derat@chromium.org>
Date: Wed Jun 13 13:42:52 2018

chromeos: Downgrade StatisticsProvider warnings to VLOG(1).

Change several LOG(WARNINGS) in chromeos::StatisticsProvider
to VLOG(1) to reduce log spam:

- "Requested statistic not found: ..."
- "Requested machine flag not found: ..."
- "CrOS region set to '...'"

Bug:  844258 
Change-Id: I4a375f39ec919a62543366104d31367db715c54a
Reviewed-on: https://chromium-review.googlesource.com/1098473
Reviewed-by: Thiemo Nagel <tnagel@chromium.org>
Reviewed-by: Igor <igorcov@chromium.org>
Commit-Queue: Dan Erat <derat@chromium.org>
Cr-Commit-Position: refs/heads/master@{#566819}
[modify] https://crrev.com/635d13f01f880321810c161da7cdc456a2bf2c87/chromeos/system/statistics_provider.cc

Comment 10 by derat@chromium.org, Jun 13 2018

Status: Fixed (was: Started)
Status: Verified (was: Fixed)
As verified in M68.0.3440.31 10718.28.0 beta blaze, the issue has been fixed as examined the warning messages in the log file.

Sign in to add a comment