Hi Ben, Do you know who should own this?

Looks like it was an assertion on CHECK(!suspend_delay_registered_) in shill::PowerManager::OnPowerManagerAppeared.

Possible duplicate of bug 820741 ?

Weird, this one says SIGABRT but 820741 says SIGSEGV.  So I guess in some cases we're segfaulting, and in other cases we're hitting the CHECK() failure.

In feedback report 84967896997:

2018-01-23T13:18:54.073542+01:00 NOTICE kernel: [    0.000000] Linux version 4.4.86-11979-g09b49365a3c4 (chrome-bot@cros-beefy213-c2) (gcc version 4.9.x 20150123 (prerelease) (4.9.2_cos_gg_4.9.2-r166-0c5a656a1322e137fa4a251f2ccc6c4022918c0a_4.9.2-r166) ) #1 SMP PREEMPT Mon Jan 8 23:14:58 PST 2018

powerd.PREVIOUS=<multiline>
---------- START ----------
[0123/131854:INFO:main.cc(286)] vcsid 0.0.2-r2316-8bb2b0e4db3199843091b8c40cd9148f64709aa1
[0123/131854:INFO:main.cc(292)] System uptime: 3s
[0123/131854:INFO:udev.cc(82)] Watching FD 14 for udev events
[...]
[0123/131854:INFO:suspend_delay_controller.cc(62)] Registering suspend delay 72220673 (shill) of 19500 ms on behalf of :1.6
[0123/131854:INFO:daemon.cc(771)] On battery at 99% (displayed as 100%), 3.210/3.252Ah at 0.355A, 0s until empty (calculating)
[0123/131854:INFO:suspend_delay_controller.cc(62)] Registering dark suspend delay 72253441 (shill) of 19500 ms on behalf of :1.6
[0123/131854:INFO:daemon.cc(1058)] D-Bus org.chromium.SessionManager ownership changed to :1.8
[0123/131855:INFO:suspend_delay_controller.cc(121)] Unregistering suspend delay 72220673 (shill) due to D-Bus client :1.6 going away
[0123/131855:INFO:suspend_delay_controller.cc(121)] Unregistering dark suspend delay 72253441 (shill) due to D-Bus client :1.6 going away

2018-01-23T13:18:54.732314+01:00 INFO shill[949]: [INFO:manager.cc(275)] Manager started.
2018-01-23T13:18:54.747434+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendImminentsuccess: 1
2018-01-23T13:18:54.747955+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendDonesuccess: 1
2018-01-23T13:18:54.748645+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: DarkSuspendImminentsuccess: 1
[...]
2018-01-23T13:18:54.880698+01:00 INFO shill[949]: [INFO:wifi.cc(2289)] wlan0: enabled supplicant: absent proxy: null
2018-01-23T13:18:54.885265+01:00 INFO shill[949]: [INFO:manager.cc(1699)] Default physical service: 0 (not connected)
2018-01-23T13:18:54.885573+01:00 INFO shill[949]: [INFO:service.cc(314)] Suppressed autoconnect to service 0 (no endpoints)
2018-01-23T13:18:54.887332+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(331)] OnServiceOwnerChangedold:  new: :1.7
2018-01-23T13:18:54.889223+01:00 INFO shill[949]: [INFO:power_manager.cc(153)] OnPowerManagerAppeared
2018-01-23T13:18:54.889399+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=false)
2018-01-23T13:18:54.914793+01:00 INFO shill[949]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=true)
2018-01-23T13:18:54.917900+01:00 INFO shill[949]: [INFO:wifi.cc(2207)] WPA supplicant appeared.
2018-01-23T13:18:54.917931+01:00 INFO shill[949]: [INFO:wifi.cc(2289)] wlan0: enabled supplicant: present proxy: null
2018-01-23T13:18:55.199762+01:00 INFO shill[949]: [INFO:wifi.cc(324)] Scan on wlan0 from ConnectToSupplicant
2018-01-23T13:18:55.200213+01:00 INFO shill[949]: [INFO:power_manager.cc(153)] OnPowerManagerAppeared
2018-01-23T13:18:55.200622+01:00 CRIT shill[949]: [FATAL:power_manager.cc(154)] Check failed: !suspend_delay_registered_. #012/usr/lib64/libbase-core-395517.so(bas<IPv6: 7>ug<IPv6: 1>StackTr<IPv6: 8>StackTrace()+0x13) [0x7ad0fcab8153]#012
2018-01-23T13:18:55.200780+01:00 ERR shill[1042]: [FATAL:power_manager.cc(154)] Check failed: !suspend_delay_registered_. 
2018-01-23T13:18:55.200896+01:00 ERR shill[1042]: /usr/lib64/libbase-core-395517.so(bas<IPv6: 7>ug<IPv6: 1>StackTr<IPv6: 8>StackTrace()+0x13) [0x7ad0fcab8153]
2018-01-23T13:18:55.200921+01:00 ERR shill[1042]: 

2018-01-23T13:18:55.329028+01:00 INFO shill[1293]: [INFO:manager.cc(275)] Manager started.
2018-01-23T13:18:55.331074+01:00 INFO shill[1293]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendImminentsuccess: 1
2018-01-23T13:18:55.331617+01:00 INFO shill[1293]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendDonesuccess: 1
2018-01-23T13:18:55.332066+01:00 INFO shill[1293]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: DarkSuspendImminentsuccess: 1
[...]
2018-01-23T13:18:55.388653+01:00 INFO shill[1293]: [INFO:power_manager.cc(153)] OnPowerManagerAppeared
2018-01-23T13:18:55.388686+01:00 INFO shill[1293]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=false)
2018-01-23T13:18:55.390804+01:00 INFO shill[1293]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=true)


Similarly, in feedback report 81548362673:

powerd.LATEST=<multiline>
---------- START ----------
[1103/223600:INFO:main.cc(83)] vcsid 0.0.2-r1439-4f9ee960841d2b5647524987b68e71f1b81e25a4
[...]
[1103/223600:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 64946177 (shill) of 19500 ms on behalf of :1.5
[1103/223600:INFO:daemon.cc(1144)] D-Bus org.chromium.SessionManager ownership changed to :1.8
[1103/223600:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 64978945 (shill) of 19500 ms on behalf of :1.5
[1103/223600:INFO:daemon.cc(837)] On battery at 98% (displayed as 100%), 4.655/4.761Ah at 0.881A, 0s until empty (calculating)
[1103/223600:INFO:suspend_delay_controller.cc(123)] Unregistering suspend delay 64946177 (shill) due to D-Bus client :1.5 going away
[1103/223600:INFO:suspend_delay_controller.cc(123)] Unregistering dark suspend delay 64978945 (shill) due to D-Bus client :1.5 going away
[1103/223600:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 64946178 (shill) of 19500 ms on behalf of :1.11
[1103/223600:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 64978946 (shill) of 19500 ms on behalf of :1.11
[1103/223602:INFO:suspend_delay_controller.cc(63)] Registering suspend delay 64946179 (chrome) of 5000 ms on behalf of :1.13
[1103/223602:INFO:suspend_delay_controller.cc(63)] Registering dark suspend delay 64978947 (chrome) of 5000 ms on behalf of :1.13

2017-11-03T22:36:00.319652-07:00 INFO shill[779]: [INFO:manager.cc(261)] Manager started.
2017-11-03T22:36:00.320338-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendImminentsuccess: 1
2017-11-03T22:36:00.320548-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: SuspendDonesuccess: 1
2017-11-03T22:36:00.320738-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(352)] OnSignalConnected interface: org.chromium.PowerManager signal: DarkSuspendImminentsuccess: 1
[...]
2017-11-03T22:36:00.499886-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(331)] OnServiceOwnerChangedold:  new: :1.6
2017-11-03T22:36:00.499985-07:00 INFO shill[779]: [INFO:power_manager.cc(161)] OnPowerManagerAppeared
2017-11-03T22:36:00.500060-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=false)
2017-11-03T22:36:00.870220-07:00 INFO shill[779]: [INFO:chromeos_power_manager_proxy.cc(185)] RegisterSuspendDelayInternal(19500, dark=true)
2017-11-03T22:36:00.872060-07:00 INFO shill[779]: [INFO:power_manager.cc(161)] OnPowerManagerAppeared
2017-11-03T22:36:00.872370-07:00 CRIT shill[779]: [FATAL:power_manager.cc(162)] Check failed: !suspend_delay_registered_. #012/usr/lib64/libbase-core-395517.so(bas<IPv6: 8>ug<IPv6: 1>StackTr<IPv6: 9>StackTrace()+0x16) [0x7f468973e096]#012
2017-11-03T22:36:00.874115-07:00 ERR shill[826]: [FATAL:power_manager.cc(162)] Check failed: !suspend_delay_registered_. 
2017-11-03T22:36:00.874127-07:00 ERR shill[826]: /usr/lib64/libbase-core-395517.so(bas<IPv6: 8>ug<IPv6: 1>StackTr<IPv6: 9>StackTrace()+0x16) [0x7f468973e096]
2017-11-03T22:36:00.874136-07:00 ERR shill[826]: 
2017-11-03T22:36:00.923368-07:00 INFO shill[1510]: [INFO:manager.cc(261)] Manager started.


So OnPowerManagerAppeared really is getting called twice, ~300-400ms apart.  This is happening during boot.  powerd isn't actually restarting.

The ChromeosPowerManagerProxy c'tor registers OnServiceAvailable using WaitForServiceToBeAvailable. OnServiceAvailable registers OnServiceOwnerChanged using SetNameOwnerChangedCallback and posts service_appeared_callback_. OnServiceOwnerChanged posts service_vanished_callback_ if new_owner is empty or service_appeared_callback_ if it's nonempty.

Here's part of ObjectProxy::HandleNameOwnerChanged:

      service_name_owner_ = new_owner;
      bus_->GetOriginTaskRunner()->PostTask(
          FROM_HERE,
          base::Bind(&ObjectProxy::RunNameOwnerChangedCallback,
                     this, old_owner, new_owner));

      const bool service_is_available = !service_name_owner_.empty();
      if (service_is_available) {
        bus_->GetOriginTaskRunner()->PostTask(
            FROM_HERE,
            base::Bind(&ObjectProxy::RunWaitForServiceToBeAvailableCallbacks,
                       this, service_is_available));
      }

And see also this:

void ObjectProxy::RunNameOwnerChangedCallback(const std::string& old_owner,
                                              const std::string& new_owner) {
  bus_->AssertOnOriginThread();
  if (!name_owner_changed_callback_.is_null())
    name_owner_changed_callback_.Run(old_owner, new_owner);
}


So HandleNameOwnerChanged posts RunNameOwnerChangedCallback and also the method that runs OnServiceAvailable. I wonder if OnServiceAvailable is running first (I'm not sure whether there are guarantees about execution order for PostTask calls in the same message loop iteration) and registering OnServiceOwnerChanged before RunNameOwnerChangedCallback is executed, resulting in the second call you're seeing.

In any case, I think that my suggestion is to change shill's CHECK to an early return. :-P

Observed this crash on Orco build 10575.8.0/67.0.3396.12 with suspend/resume scenario by close/open the device lid and YouTube audio was playing.  

https://crash.corp.google.com/browse?stbtiq=8f10eec091e2c918

Sniffing dbus, I see two NameOwnerChange's on powerd startup:

signal time=1524526172.860910 sender=org.freedesktop.DBus -> destination=(null destination) serial=40 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.122" // Name with a new owner
   string ""       // Old owner
   string ":1.122" // New owner

signal time=1524526172.986911 sender=org.freedesktop.DBus -> destination=(null destination) serial=18 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.chromium.PowerManager"  // name with a new owner
   string ""                           // old owner
   string ":1.122"                     // new owner

and if I kill powerd:

signal time=1524526172.539181 sender=org.freedesktop.DBus -> destination=(null destination) serial=38 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.chromium.PowerManager"  // Name with a new owner
   string ":1.122"                     // old owner
   string ""                           // new owner

I expect that ObjectProxy only cares about the signals that mention "org.chromium.PowerManager", since unless that is stated, it has no idea that the signal is talking about powerd.


So there are a couple of different scenarios to consider:

If powerd is already running, a GOOD case looks like this:

 - ObjectProxy::WaitForServiceToBeAvailableInternal() calls ConnectToNameOwnerChangedSignal().  This is (somewhat surprisingly) a blocking operation: not only does it issue an AddMatch dbus call, it also issues a GetNameOwner dbus call, populating service_name_owner_.

 - Since dbus already knows PowerManager's owner (e.g. ":1.122"), the GetNameOwner calls succeeds.
 
 - service_name_owner_.empty() is now false, so WaitForServiceToBeAvailableInternal() posts a callback that eventually winds up in ChromeosPowerManagerProxy::OnServiceAvailable().

 - OnServiceAvailable() registers the ChromeosPowerManagerProxy::OnServiceOwnerChanged() callback.

 - OnServiceOwnerChanged() only ever gets called if powerd dies.  Thus: no duplicate OnPowerManagerAppeared().


If powerd is not already running, a GOOD case looks like this:

 - ObjectProxy::WaitForServiceToBeAvailableInternal() calls ConnectToNameOwnerChangedSignal().

 - ConnectToNameOwnerChangedSignal() -> UpdateNameOwnerAndBlock() is not able to obtain the service owner, so service_name_owner_ is set to an empty string.

 - service_name_owner_.empty() is now true, so WaitForServiceToBeAvailableInternal() does not post a callback to ChromeosPowerManagerProxy::OnServiceAvailable().

 - When powerd comes up, ObjectProxy eventually receives a NameOwnerChanged signal for powerd.

 - ObjectProxy::HandleNameOwnerChanged() tries to post a callback to shill's NameOwnerChangedCallback, but it's not registered yet so this is a no-op.

 - ObjectProxy::HandleNameOwnerChanged() then posts a callback that winds up in ChromeosPowerManagerProxy::OnServiceAvailable().

 - OnServiceAvailable() registers the ChromeosPowerManagerProxy::OnServiceOwnerChanged() callback.

 - OnServiceOwnerChanged() only ever gets called if powerd crashes.  Thus: no duplicate OnPowerManagerAppeared().


I suspect that in the BAD case, powerd's NameOwnerChanged signal is received during the blocking UpdateNameOwnerAndBlock() operation.  This is more complex:

 - ObjectProxy::WaitForServiceToBeAvailableInternal() calls ConnectToNameOwnerChangedSignal().

 - ConnectToNameOwnerChangedSignal() -> UpdateNameOwnerAndBlock() is able to obtain the service owner, so service_name_owner_ is set to a non-empty string.

 - During the blocking operation, a NameOwnerChanged signal is received prior to the `method return` reply.  The dbus event loop posts a call to ObjectProxy::HandleNameOwnerChanged() to deal with the pending signal (because you have to read it off the socket to see subsequent activity), then continues blocking until the `method return` message comes through.

 - service_name_owner_.empty() is false, so WaitForServiceToBeAvailableInternal() posts a task to run ObjectProxy::RunWaitForServiceToBeAvailableCallbacks().

 - ObjectProxy::HandleNameOwnerChanged() now executes, because it was the next pending task.

 - ObjectProxy::HandleNameOwnerChanged() posts a callback to ObjectProxy::RunNameOwnerChangedCallback().

 - ObjectProxy::HandleNameOwnerChanged() posts a callback to ObjectProxy::RunWaitForServiceToBeAvailableCallbacks().

 - ObjectProxy::RunWaitForServiceToBeAvailableCallbacks(), the next pending task from four steps up, invokes ChromeosPowerManagerProxy::OnServiceAvailable().

 - OnServiceAvailable() sets ObjectProxy::name_owner_changed_callback_ to ChromeosPowerManagerProxy::OnServiceOwnerChanged().

 - OnServiceAvailable() posts a task to run OnPowerManagerAppeared().

 - ObjectProxy::RunNameOwnerChangedCallback(), the next pending task, runs ChromeosPowerManagerProxy::OnServiceOwnerChanged().  (We see this in the logs right before the first OnPowerManagerAppeared.)

 - ObjectProxy::RunWaitForServiceToBeAvailableCallbacks(), the next pending task from five steps up, again invokes ChromeosPowerManagerProxy::OnServiceAvailable().

 - OnServiceAvailable() sets the OnServiceOwnerChanged callback again (a no-op) and then posts a second task to run OnPowerManagerAppeared().  This is what causes the crash.

My main reservation around this version is that it doesn't explain the 300-400ms time gap.  Maybe this only happens when the system is under heavy load.  But, I like it because it doesn't assume the event loop is reordering tasks.

WDYT?

Also, looks like the current arrangement is a result of  bug 541647  ("fatal error when PowerManager proxy appeared callback invoke twice in a row").

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9

commit a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Tue Apr 24 13:22:17 2018

shill: Make PowerManager dbus callbacks more robust

Ensure that OnPowerManagerAppeared() and OnPowerManagerVanished()
won't get called if |power_manager_proxy_| is deleted.  Ensure that
shill won't crash if OnPowerManagerAppeared() gets called twice.

BUG=chromium:820741
BUG= chromium:831264 
TEST=unit tests

Change-Id: Ic265ad794c63822e808d8fefed2c29c55afb2fac
Reviewed-on: https://chromium-review.googlesource.com/961620
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9/power_manager.cc
[modify] https://crrev.com/a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9/dbus/chromeos_power_manager_proxy.cc
[modify] https://crrev.com/a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9/dbus/chromeos_power_manager_proxy.h

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/9663dfd545af1bc46d811973f5bdef91dc049810

commit 9663dfd545af1bc46d811973f5bdef91dc049810
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Wed Apr 25 22:43:06 2018

shill: Make PowerManager dbus callbacks more robust

Ensure that OnPowerManagerAppeared() and OnPowerManagerVanished()
won't get called if |power_manager_proxy_| is deleted.  Ensure that
shill won't crash if OnPowerManagerAppeared() gets called twice.

BUG=chromium:820741
BUG= chromium:831264 
TEST=unit tests

Change-Id: Ic265ad794c63822e808d8fefed2c29c55afb2fac
Reviewed-on: https://chromium-review.googlesource.com/961620
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>
(cherry picked from commit a7a7d9d618631b38bb04eb5ed0e570d5a59cd5d9)

[modify] https://crrev.com/9663dfd545af1bc46d811973f5bdef91dc049810/power_manager.cc
[modify] https://crrev.com/9663dfd545af1bc46d811973f5bdef91dc049810/dbus/chromeos_power_manager_proxy.cc
[modify] https://crrev.com/9663dfd545af1bc46d811973f5bdef91dc049810/dbus/chromeos_power_manager_proxy.h

This is believed to be fixed; per https://goto.google.com/iwdlp we are no longer seeing this crash on canary channel.