Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Lei Yu]

An issue that is related to missed match callbacks is noticed and it
causes the inconsistency between object-mapper and the dbus objects.

Steps to reproduce on g220a QEMU (it is not 100% reproducible and when
it occurs it likely occurs on the first try when BMC boots)

1. Generate several logging entries
2. Call logging service's DeleteAll
3. Check the objects of logging service, all entries are deleted
 ```
 # busctl tree xyz.openbmc_project.Logging
 `-/xyz
   `-/xyz/openbmc_project
     `-/xyz/openbmc_project/logging
       `-/xyz/openbmc_project/logging/internal
         `-/xyz/openbmc_project/logging/internal/manager
 ```
4. Check the entries via object-mapper, it gets the entries
 ```
 # busctl call xyz.openbmc_project.ObjectMapper
/xyz/openbmc_project/object_mapper xyz.openbmc_project.ObjectMapper
GetObject sas /xyz/openbmc_project/logging/entry/1 0
 a{sas} 1 "xyz.openbmc_project.Logging" 8
"org.freedesktop.DBus.Introspectable" "org.freedesktop.DBus.Peer"
"org.freedesktop.DBus.Properties"
"xyz.openbmc_project.Association.Definitions" "xyz.open
bmc_project.Common.FilePath" "xyz.openbmc_project.Logging.Entry"
"xyz.openbmc_project.Object.Delete"
"xyz.openbmc_project.Software.Version"
 ```
5. I could verify that the DBus object does not really exist:
 ```
 # busctl introspect "xyz.openbmc_project.Logging"
/xyz/openbmc_project/logging/entry/1
 Failed to introspect object /xyz/openbmc_project/logging/entry/1 of
service xyz.openbmc_project.Logging: Unknown object
'/xyz/openbmc_project/logging/entry/1'.
 ```

I also added some logs in my service to get callbacks of the
interfacesRemoved signal, and it shows that I really do not get the
callbacks for some objects.
For example, in one test I have 41 logging entries, and my service
only gets `interfacesRemoved` callback for entry 18~41, this causes
the object-mapper to show the remaining 1~17 entries while they do not
really exist on DBus.

This looks like some fundamental issue in dbus-broker or sdbusplus.
Is there anyone who hits the similar issue?

-- 
BRs,
Lei YU

FW: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Shantappa Teekappanavar]

[-- Attachment #1: Type: text/plain, Size: 3060 bytes --]

Hi Lei,

I've hit this same exact issue on few of our platforms. Like as you said, I agree it is not 100% reproducible . But once the issue is hit, it is kind of persistent on that system.

I tried adding entries, deleting one at a time or Delete All, with the hope of flushing out the paths. But so far no success.

I agree that there is some sort of fundamental issue...

-Teeks

From: Adriana Kobylak <anoo@linux.ibm.com>
Sent: Monday, March 28, 2022 2:42 PM
To: Shantappa Teekappanavar <Shantappa.Teekappanavar@ibm.com>
Subject: Fwd: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects




Begin forwarded message:

From: Lei Yu <yulei.sh@bytedance.com<mailto:yulei.sh@bytedance.com>>
Subject: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
Date: March 28, 2022 at 8:19:40 AM CDT
To: openbmc <openbmc@lists.ozlabs.org<mailto:openbmc@lists.ozlabs.org>>

An issue that is related to missed match callbacks is noticed and it
causes the inconsistency between object-mapper and the dbus objects.

Steps to reproduce on g220a QEMU (it is not 100% reproducible and when
it occurs it likely occurs on the first try when BMC boots)

1. Generate several logging entries
2. Call logging service's DeleteAll
3. Check the objects of logging service, all entries are deleted
```
# busctl tree xyz.openbmc_project.Logging
`-/xyz
  `-/xyz/openbmc_project
    `-/xyz/openbmc_project/logging
      `-/xyz/openbmc_project/logging/internal
        `-/xyz/openbmc_project/logging/internal/manager
```
4. Check the entries via object-mapper, it gets the entries
```
# busctl call xyz.openbmc_project.ObjectMapper
/xyz/openbmc_project/object_mapper xyz.openbmc_project.ObjectMapper
GetObject sas /xyz/openbmc_project/logging/entry/1 0
a{sas} 1 "xyz.openbmc_project.Logging" 8
"org.freedesktop.DBus.Introspectable" "org.freedesktop.DBus.Peer"
"org.freedesktop.DBus.Properties"
"xyz.openbmc_project.Association.Definitions" "xyz.open
bmc_project.Common.FilePath" "xyz.openbmc_project.Logging.Entry"
"xyz.openbmc_project.Object.Delete"
"xyz.openbmc_project.Software.Version"
```
5. I could verify that the DBus object does not really exist:
```
# busctl introspect "xyz.openbmc_project.Logging"
/xyz/openbmc_project/logging/entry/1
Failed to introspect object /xyz/openbmc_project/logging/entry/1 of
service xyz.openbmc_project.Logging: Unknown object
'/xyz/openbmc_project/logging/entry/1'.
```

I also added some logs in my service to get callbacks of the
interfacesRemoved signal, and it shows that I really do not get the
callbacks for some objects.
For example, in one test I have 41 logging entries, and my service
only gets `interfacesRemoved` callback for entry 18~41, this causes
the object-mapper to show the remaining 1~17 entries while they do not
really exist on DBus.

This looks like some fundamental issue in dbus-broker or sdbusplus.
Is there anyone who hits the similar issue?

--
BRs,
Lei YU


[-- Attachment #2: Type: text/html, Size: 6809 bytes --]

Re: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Lei Yu]

Additional information:

I tried to use `dbus-monitor --system
"type='signal',interface='org.freedesktop.DBus.ObjectManager',member='InterfacesRemoved'"
| tee /tmp/interfacesRemoved.log` to capture the signals when deleting
logging log entries.
It does show that some missing signals, e.g. below link shows that it
dose not get the interfacesRemoved signal for
/xyz/openbmc_project/logging/entry/1

https://pastebin.com/EgFpeLxK

So this looks like a dbus (or dbus-broker) issue instead of sdbusplus issue.

On Tue, Mar 29, 2022 at 5:51 AM Shantappa Teekappanavar
<Shantappa.Teekappanavar@ibm.com> wrote:
>
> Hi Lei,
>
>
>
> I've hit this same exact issue on few of our platforms. Like as you said, I agree it is not 100% reproducible . But once the issue is hit, it is kind of persistent on that system.
>
>
>
> I tried adding entries, deleting one at a time or Delete All, with the hope of flushing out the paths. But so far no success.
>
>
>
> I agree that there is some sort of fundamental issue...
>
>
>
> -Teeks
>
>
>
> From: Adriana Kobylak <anoo@linux.ibm.com>
> Sent: Monday, March 28, 2022 2:42 PM
> To: Shantappa Teekappanavar <Shantappa.Teekappanavar@ibm.com>
> Subject: Fwd: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
>
>
>
>
>
>
>
> Begin forwarded message:
>
>
>
> From: Lei Yu <yulei.sh@bytedance.com>
>
> Subject: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
>
> Date: March 28, 2022 at 8:19:40 AM CDT
>
> To: openbmc <openbmc@lists.ozlabs.org>
>
>
>
> An issue that is related to missed match callbacks is noticed and it
> causes the inconsistency between object-mapper and the dbus objects.
>
> Steps to reproduce on g220a QEMU (it is not 100% reproducible and when
> it occurs it likely occurs on the first try when BMC boots)
>
> 1. Generate several logging entries
> 2. Call logging service's DeleteAll
> 3. Check the objects of logging service, all entries are deleted
> ```
> # busctl tree xyz.openbmc_project.Logging
> `-/xyz
>   `-/xyz/openbmc_project
>     `-/xyz/openbmc_project/logging
>       `-/xyz/openbmc_project/logging/internal
>         `-/xyz/openbmc_project/logging/internal/manager
> ```
> 4. Check the entries via object-mapper, it gets the entries
> ```
> # busctl call xyz.openbmc_project.ObjectMapper
> /xyz/openbmc_project/object_mapper xyz.openbmc_project.ObjectMapper
> GetObject sas /xyz/openbmc_project/logging/entry/1 0
> a{sas} 1 "xyz.openbmc_project.Logging" 8
> "org.freedesktop.DBus.Introspectable" "org.freedesktop.DBus.Peer"
> "org.freedesktop.DBus.Properties"
> "xyz.openbmc_project.Association.Definitions" "xyz.open
> bmc_project.Common.FilePath" "xyz.openbmc_project.Logging.Entry"
> "xyz.openbmc_project.Object.Delete"
> "xyz.openbmc_project.Software.Version"
> ```
> 5. I could verify that the DBus object does not really exist:
> ```
> # busctl introspect "xyz.openbmc_project.Logging"
> /xyz/openbmc_project/logging/entry/1
> Failed to introspect object /xyz/openbmc_project/logging/entry/1 of
> service xyz.openbmc_project.Logging: Unknown object
> '/xyz/openbmc_project/logging/entry/1'.
> ```
>
> I also added some logs in my service to get callbacks of the
> interfacesRemoved signal, and it shows that I really do not get the
> callbacks for some objects.
> For example, in one test I have 41 logging entries, and my service
> only gets `interfacesRemoved` callback for entry 18~41, this causes
> the object-mapper to show the remaining 1~17 entries while they do not
> really exist on DBus.
>
> This looks like some fundamental issue in dbus-broker or sdbusplus.
> Is there anyone who hits the similar issue?
>
> --
> BRs,
> Lei YU
>
>



-- 
BRs,
Lei YU

Re: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Lei Yu]

On Tue, Mar 29, 2022 at 2:20 PM Lei Yu <yulei.sh@bytedance.com> wrote:
>
> Additional information:
>
> I tried to use `dbus-monitor --system
> "type='signal',interface='org.freedesktop.DBus.ObjectManager',member='InterfacesRemoved'"
> | tee /tmp/interfacesRemoved.log` to capture the signals when deleting
> logging log entries.
> It does show that some missing signals, e.g. below link shows that it
> dose not get the interfacesRemoved signal for
> /xyz/openbmc_project/logging/entry/1
>
> https://pastebin.com/EgFpeLxK
>
> So this looks like a dbus (or dbus-broker) issue instead of sdbusplus issue.

Now it's figured out how to reproduce the issue:
1. Generate several logging entries
2. Reboot BMC
3. Call logging service's DeleteAll

And the issue occurs, the log entries exist before BMC boot will not
get interfacesRemoved signal.

It turns out that the issue is in phosphor-logging, that when it
restore the log entries from the filesystem it does not call
`emit_object_added()` and thus dbus will not generate
interfacesAdded/Removed signals.

A patch is sent to
https://gerrit.openbmc-project.xyz/c/openbmc/phosphor-logging/+/52445
for review.

> On Tue, Mar 29, 2022 at 5:51 AM Shantappa Teekappanavar
> <Shantappa.Teekappanavar@ibm.com> wrote:
> >
> > Hi Lei,
> >
> >
> >
> > I've hit this same exact issue on few of our platforms. Like as you said, I agree it is not 100% reproducible . But once the issue is hit, it is kind of persistent on that system.
> >
> >
> >
> > I tried adding entries, deleting one at a time or Delete All, with the hope of flushing out the paths. But so far no success.
> >
> >
> >
> > I agree that there is some sort of fundamental issue...
> >
> >
> >
> > -Teeks
> >
> >
> >
> > From: Adriana Kobylak <anoo@linux.ibm.com>
> > Sent: Monday, March 28, 2022 2:42 PM
> > To: Shantappa Teekappanavar <Shantappa.Teekappanavar@ibm.com>
> > Subject: Fwd: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
> >
> >
> >
> >
> >
> >
> >
> > Begin forwarded message:
> >
> >
> >
> > From: Lei Yu <yulei.sh@bytedance.com>
> >
> > Subject: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
> >
> > Date: March 28, 2022 at 8:19:40 AM CDT
> >
> > To: openbmc <openbmc@lists.ozlabs.org>
> >
> >
> >
> > An issue that is related to missed match callbacks is noticed and it
> > causes the inconsistency between object-mapper and the dbus objects.
> >
> > Steps to reproduce on g220a QEMU (it is not 100% reproducible and when
> > it occurs it likely occurs on the first try when BMC boots)
> >
> > 1. Generate several logging entries
> > 2. Call logging service's DeleteAll
> > 3. Check the objects of logging service, all entries are deleted
> > ```
> > # busctl tree xyz.openbmc_project.Logging
> > `-/xyz
> >   `-/xyz/openbmc_project
> >     `-/xyz/openbmc_project/logging
> >       `-/xyz/openbmc_project/logging/internal
> >         `-/xyz/openbmc_project/logging/internal/manager
> > ```
> > 4. Check the entries via object-mapper, it gets the entries
> > ```
> > # busctl call xyz.openbmc_project.ObjectMapper
> > /xyz/openbmc_project/object_mapper xyz.openbmc_project.ObjectMapper
> > GetObject sas /xyz/openbmc_project/logging/entry/1 0
> > a{sas} 1 "xyz.openbmc_project.Logging" 8
> > "org.freedesktop.DBus.Introspectable" "org.freedesktop.DBus.Peer"
> > "org.freedesktop.DBus.Properties"
> > "xyz.openbmc_project.Association.Definitions" "xyz.open
> > bmc_project.Common.FilePath" "xyz.openbmc_project.Logging.Entry"
> > "xyz.openbmc_project.Object.Delete"
> > "xyz.openbmc_project.Software.Version"
> > ```
> > 5. I could verify that the DBus object does not really exist:
> > ```
> > # busctl introspect "xyz.openbmc_project.Logging"
> > /xyz/openbmc_project/logging/entry/1
> > Failed to introspect object /xyz/openbmc_project/logging/entry/1 of
> > service xyz.openbmc_project.Logging: Unknown object
> > '/xyz/openbmc_project/logging/entry/1'.
> > ```
> >
> > I also added some logs in my service to get callbacks of the
> > interfacesRemoved signal, and it shows that I really do not get the
> > callbacks for some objects.
> > For example, in one test I have 41 logging entries, and my service
> > only gets `interfacesRemoved` callback for entry 18~41, this causes
> > the object-mapper to show the remaining 1~17 entries while they do not
> > really exist on DBus.
> >
> > This looks like some fundamental issue in dbus-broker or sdbusplus.
> > Is there anyone who hits the similar issue?
> >
> > --
> > BRs,
> > Lei YU
> >
> >
>
>
>
> --
> BRs,
> Lei YU



-- 
BRs,
Lei YU

Re: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Patrick Williams]

[-- Attachment #1: Type: text/plain, Size: 343 bytes --]

On Mon, Mar 28, 2022 at 09:19:40PM +0800, Lei Yu wrote:

> This looks like some fundamental issue in dbus-broker or sdbusplus.
> Is there anyone who hits the similar issue?

I've have a write-up on what I intend to do about this issue at:
    https://www.stwcx.xyz/blog/2022/04/01/sdbusplus-object-signals.html

-- 
Patrick Williams

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Lei Yu]

On Sat, Apr 2, 2022 at 4:54 AM Patrick Williams <patrick@stwcx.xyz> wrote:
>
> On Mon, Mar 28, 2022 at 09:19:40PM +0800, Lei Yu wrote:
>
> > This looks like some fundamental issue in dbus-broker or sdbusplus.
> > Is there anyone who hits the similar issue?
>
> I've have a write-up on what I intend to do about this issue at:
>     https://www.stwcx.xyz/blog/2022/04/01/sdbusplus-object-signals.html

Thanks! It's a nice article and clarifies the different cases.
But I still have a question about `Permanent Sub-Objects`:

> We never want the sub-object to deal with its own lifetime signals! If we did they’d also be the lifetime signals for the parent object because they are all residing at the same dbus object-path

For example the `Value` and `Critical` objects in phosphor-hwmon:
1. when it's destructed, it will emit the interfacesRemoved signal for
the `Value` interface, but no such signal for the `Critical`
interface, is it? I do not think it's expected behavior.
2. It has the assumption that the service needs to know which is the
permanent `main` object, and which are the `sub` objects. What if the
service could not tell which is the main and which is the sub? I think
this makes it harder for sdbusplus' users to design the object
hierarchy, is it?


-- 
BRs,
Lei YU

Re: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects

[Patrick Williams]

[-- Attachment #1: Type: text/plain, Size: 3590 bytes --]

On Sat, Apr 02, 2022 at 11:33:57AM +0800, Lei Yu wrote:

> Thanks! It's a nice article and clarifies the different cases.

Thank you.

> But I still have a question about `Permanent Sub-Objects`:

> > We never want the sub-object to deal with its own lifetime signals! If we
> > did they’d also be the lifetime signals for the parent object because they 
> > are all residing at the same dbus object-path
> 
> For example the `Value` and `Critical` objects in phosphor-hwmon:
> 1. when it's destructed, it will emit the interfacesRemoved signal for
> the `Value` interface, but no such signal for the `Critical`
> interface, is it? I do not think it's expected behavior.

No, this is not the case.  Value _will_ emit the interfacesRemoved for
Threshold::Critical.  This is because Value (as the primary object) is
using emit_object_added() to signal the InterfacesAdded and it will use
emit_object_removed() in the destructor to signal the InterfacesRemoved.

I also wrote this:

    The systemd sd-bus API provides the following functions:

       * sd_bus_emit_interfaces_added
       * sd_bus_emit_interfaces_removed
       * sd_bus_emit_object_added
       * sd_bus_emit_object_removed

    The interface-level functions take a list of interfaces and create the
    corresponding Interfaces{Added,Removed} signal. The object-level functions
    are simply helper functions which create the signals for all interfaces the
    sd-bus ObjectManager is aware of having resided at that object-path.

The object-level functions have nothing to do with the interface types inside
the `object_t<...>`.  They send signals for *all* interfaces on the same
object path.  From the manpage:

       sd_bus_emit_object_added() and sd_bus_emit_object_removed() are convenience functions for emitting the
       InterfacesAdded or InterfacesRemoved signals for all interfaces registered on a specific object path,
       respectively. This includes any parent fallback vtables if they are not overridden by a more applicable
       child vtable. It also includes all the standard D-Bus interfaces implemented by sd-bus itself on any
       registered object.

Notice the "all interfaces registered on a specific object path" and
"includes all the standard D-Bus interfaces implemented by sd-bus
itself".  That means interfaces like `org.freedesktop.DBus.Properties`
even though those aren't part of the `object_t<...>` directly.

> 2. It has the assumption that the service needs to know which is the
> permanent `main` object, and which are the `sub` objects. What if the
> service could not tell which is the main and which is the sub? I think
> this makes it harder for sdbusplus' users to design the object
> hierarchy, is it?

I've been doing the conversions and I've done half a dozen so far and I
haven't really seen a case where it is a challenge to identify.  We
almost always have a `std::optional` or `std::unique_ptr` holding the
sub-object, which isn't constructed in 100% of the code paths.  If the
sub-object _were_ constructed 100% of the time, it would have just been
included in the original `object_t<...>`.

If you really have a case where you create interface X 50% of the time
and interface Y 50% of the time (and 25% of the time both), then neither
of them are the primary object and you'll probably need to use
`emit_interfaces_added` instead.  I haven't run across code that does
this yet and I can't really come up with a scenario either, so I didn't
document it in the article.

-- 
Patrick Williams

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]