New issue
Advanced search Search tips

Issue 636554 link

Starred by 2 users

Issue metadata

Status: Archived
Owner:
Closed: Sep 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 3
Type: Bug

Blocking:
issue 585504



Sign in to add a comment

Don't spam logs by calling not-yet-started D-Bus services at boot

Project Member Reported by derat@chromium.org, Aug 10 2016

Issue description

I see a message like this in Chrome's system log after booting a ToT samus:

[2133:2133:0809/143856:ERROR:object_proxy.cc(583)] Failed to call method: org.torproject.tlsdate.CanSetTime: object_path= /org/torproject/tlsdate: org.freedesktop.DBus.Error.ServiceUnknown: The name org.torproject.tlsdate was not provided by any .service files

Chrome should avoid calling tlsdate over D-Bus until the bus has said that the service is available.
 

Comment 1 by derat@chromium.org, Aug 10 2016

Summary: Don't spam logs by calling not-yet-started D-Bus services at boot (was: Don't spam logs about tlsdate at boot)
A zillion classes do this, so I'm repurposing this bug.
Project Member

Comment 2 by bugdroid1@chromium.org, Aug 10 2016

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

commit 501900f5a00aec0af5b5e9ed62ae933aead7fffa
Author: derat <derat@chromium.org>
Date: Wed Aug 10 23:52:36 2016

chromeos: Don't spam logs with update_engine D-Bus errors.

Make UpdateEngineClientImpl wait to get update_engine's
initial status until D-Bus has notified us that it's
available.

BUG= 636554 

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

[modify] https://crrev.com/501900f5a00aec0af5b5e9ed62ae933aead7fffa/chromeos/dbus/update_engine_client.cc

Project Member

Comment 3 by bugdroid1@chromium.org, Aug 11 2016

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

commit 08c5efaa7689e8a51c780ec117adaed7cd035842
Author: derat <derat@chromium.org>
Date: Thu Aug 11 03:18:37 2016

chromeos: Update update_engine D-Bus availability code.

Rename a method in UpdateEngineClient and add an error
message to reflect the way that
dbus::ObjectProxy::WaitForServiceToBeAvailable() actually
works.

BUG= 636554 
TBR=stevenjb@chromium.org

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

[modify] https://crrev.com/08c5efaa7689e8a51c780ec117adaed7cd035842/chromeos/dbus/update_engine_client.cc

Project Member

Comment 4 by bugdroid1@chromium.org, Aug 11 2016

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

commit 709228f565b22a2115bdbbac2f6b804055699d07
Author: derat <derat@chromium.org>
Date: Thu Aug 11 17:29:23 2016

chromeos: Don't spam logs with tlsdate D-Bus errors at boot.

Make SystemClockClientImpl avoid making its initial call to
tlsdate to check if the time can be set until D-Bus has
notified it that tlsdate is available.

BUG= 636554 

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

[modify] https://crrev.com/709228f565b22a2115bdbbac2f6b804055699d07/chromeos/dbus/system_clock_client.cc
[modify] https://crrev.com/709228f565b22a2115bdbbac2f6b804055699d07/chromeos/dbus/system_clock_client.h

Project Member

Comment 5 by bugdroid1@chromium.org, Aug 23 2016

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

commit 66e73f0329fbc2953bcc65d07d548a00441e625c
Author: derat <derat@chromium.org>
Date: Tue Aug 23 15:45:17 2016

chromeos: Avoid org.neard.Manager D-Bus log spam.

Make NfcManagerClientImpl defer making its initial call to
get neard's properties until D-Bus has notified Chrome that
neard is available.

BUG= 636554 
TBR=stevenjb@chromium.org

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

[modify] https://crrev.com/66e73f0329fbc2953bcc65d07d548a00441e625c/chromeos/dbus/nfc_client_unittest.cc
[modify] https://crrev.com/66e73f0329fbc2953bcc65d07d548a00441e625c/chromeos/dbus/nfc_manager_client.cc
[modify] https://crrev.com/66e73f0329fbc2953bcc65d07d548a00441e625c/dbus/mock_object_proxy.h

Project Member

Comment 6 by bugdroid1@chromium.org, Sep 8 2016

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

commit 2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece
Author: derat <derat@chromium.org>
Date: Thu Sep 08 21:35:51 2016

dbus: Make ObjectManager get objects after service is ready.

Make dbus::ObjectManager automatically fetch managed objects
after the remote service becomes available. Also remove
Bus::GetManagedObjects(), which produces a large amount of
log spam due to some services not yet being ready. (It was
called by chromeos::DBusThreadManager and
bluez::BluezDBusManager at startup.)

BUG= 636554 

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

[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/chromeos/dbus/dbus_thread_manager.cc
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/dbus/bus.cc
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/dbus/bus.h
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/dbus/mock_object_manager.h
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/dbus/object_manager.cc
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/dbus/object_manager.h
[modify] https://crrev.com/2ef7d0eda3fe8cb8a73c3ce977b8f1768cd32ece/device/bluetooth/dbus/bluez_dbus_manager.cc

Project Member

Comment 7 by bugdroid1@chromium.org, Sep 16 2016

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

commit 8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2
Author: derat <derat@chromium.org>
Date: Fri Sep 16 16:06:43 2016

chromeos: Avoid cryptohome D-Bus log spam at boot.

Make EnterpriseInstallAttributes defer running its
consistency check (which calls cryptohome's TpmIsOwned
method over D-Bus) until the cryptohome service is
available.

Also fix an apparent bug where the check was retried five
times the intended number of times.

BUG= 636554 

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

[modify] https://crrev.com/8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2/chrome/browser/chromeos/policy/enterprise_install_attributes.cc
[modify] https://crrev.com/8f07351eab26e3b2d49fd4aa3c81f19e9656d6c2/chrome/browser/chromeos/policy/enterprise_install_attributes.h

Comment 8 by derat@chromium.org, Sep 16 2016

Status: Fixed (was: Started)
I think that all of these messages are gone now!

Comment 9 by derat@chromium.org, Sep 16 2016

Cc: xiy...@chromium.org
Status: Started (was: Fixed)
I take that back; there's still some repeated cryptohome spam related to easy unlock:

[1912:1912:0916/102203:ERROR:object_proxy.cc(583)] Failed to call method: org.chromium.CryptohomeInterface.GetKeyDataEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
[1912:1912:0916/102203:ERROR:easy_unlock_get_keys_operation.cc(61)] Easy unlock failed to get key data, code=1

I see this repeated four times when booting a samus device.
It is probably from attempting to ready easy unlock key data on the focused user before cryptohomed is ready.

Think the call stack is roughly:
focused user pod change (on start, tab or click on a pod) ->
EasyUnlockServiceSignin::LoadCurrentUserDataIfNeeded ->
LoadDataForUser ->
EasyUnlockKeyManager::GetDeviceDataList ->
EasyUnlockGetKeysOperation::GetKeyData ->
calls cryptohome GetKeyDataEx

We probably can add a cryptohome service ready wait somewhere in the stack.

Comment 11 by derat@chromium.org, Sep 16 2016

Cc: tbarzic@chromium.org
Thanks, looks like it.

Using WaitForServiceToBeAvailable() will speed this up since we'll call the service as soon as it's available instead of waiting longer than necessary for a retry delay.
Project Member

Comment 12 by bugdroid1@chromium.org, Sep 16 2016

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

commit e704807ee8bdb5829fb147f59b74e3a218f4de04
Author: derat <derat@chromium.org>
Date: Fri Sep 16 18:38:40 2016

chromeos: Avoid EasyUnlockGetKeysOperation D-Bus log spam.

Make EasyUnlockGetKeysOperation wait for the cryptohome
D-Bus service to be available before making a GetKeyDataEx
method call to it. Otherwise, we get repeated log spam at
boot:

  [1912:1912:0916/102203:ERROR:object_proxy.cc(583)] Failed to call method: org.chromium.CryptohomeInterface.GetKeyDataEx: object_path= /org/chromium/Cryptohome: org.freedesktop.DBus.Error.ServiceUnknown: The name org.chromium.Cryptohome was not provided by any .service files
  [1912:1912:0916/102203:ERROR:easy_unlock_get_keys_operation.cc(61)] Easy unlock failed to get key data, code=1

BUG= 636554 

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

[modify] https://crrev.com/e704807ee8bdb5829fb147f59b74e3a218f4de04/chrome/browser/chromeos/login/easy_unlock/easy_unlock_get_keys_operation.cc
[modify] https://crrev.com/e704807ee8bdb5829fb147f59b74e3a218f4de04/chrome/browser/chromeos/login/easy_unlock/easy_unlock_get_keys_operation.h

Comment 13 by derat@chromium.org, Sep 16 2016

Status: Fixed (was: Started)
Labels: VerifyIn-55

Comment 15 by dchan@google.com, Nov 19 2016

Labels: VerifyIn-56

Comment 16 by dchan@google.com, Jan 21 2017

Labels: VerifyIn-57

Comment 17 by dchan@google.com, Mar 4 2017

Labels: VerifyIn-58

Comment 18 by dchan@google.com, Apr 17 2017

Labels: VerifyIn-59

Comment 19 by dchan@google.com, May 30 2017

Labels: VerifyIn-60
Labels: VerifyIn-61

Comment 21 by dchan@chromium.org, Oct 14 2017

Status: Archived (was: Fixed)

Sign in to add a comment