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 at 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 at 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 at linux.ibm.com>
> > Sent: Monday, March 28, 2022 2:42 PM
> > To: Shantappa Teekappanavar <Shantappa.Teekappanavar at ibm.com>
> > Subject: Fwd: Missed interfacesRemoved signal callbacks in object-mapper results in invalidated DBus objects
> >
> >
> >
> >
> >
> >
> >
> > Begin forwarded message:
> >
> >
> >
> > From: Lei Yu <yulei.sh at 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 at 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