Delayed match callback with sdbusplus asio APIs

[Ed Tanous]

On Thu, Mar 10, 2022 at 9:17 PM Lei Yu <yulei.sh at bytedance.com> wrote:
>
> This mail is to describe an issue that the match signal's callback is
> delayed if it's using sdbusplus asio APIs.
>
> # TL;DR
> If the app is using sync DBus calls and using asio to register a match
> callback, the callback may be delayed if it occurs when the sync DBus
> call is ongoing.
> Note the issue does not occur if it's not using asio APIs.

You're doing blocking calls in an async daemon.  That's why your code
has a bug in it.

One such example is on line 89:
auto reply = bus.call(method);

That will block the main event reactor until it returns.  Take a look
at something like bmcweb for how to do async method calls without
blocking the main reactor.

>
> # Details
>
> Pasted a full buildable source at https://pastebin.com/KEmpvDzp
> The code
> * Registers a match for host power status, and print the changes.
> * Uses a timer to get sensors via sync DBus calls.
>
> With this code, it's very easy to reproduce the above issue in QEMU,
> just toggle the `RequestedHostTransition` to On and Off for a few
> times:
> # busctl set-property xyz.openbmc_project.State.Host0
> /xyz/openbmc_project/state/host0 xyz.openbmc_project.State.Host
> RequestedHostTransition s xyz.openbmc_project.State.Host.Transition.On
> # busctl set-property xyz.openbmc_project.State.Host0
> /xyz/openbmc_project/state/host0 xyz.openbmc_project.State.Host
> RequestedHostTransition s
> xyz.openbmc_project.State.Host.Transition.Off
>
> We can see the journal logs:
> # journalctl | grep -e test_asio -e "Moving to \"Off" -e "POWER_OUT set to 0"
> Mar 11 04:59:25 power-control[195]: POWER_OUT set to 0
> Mar 11 04:59:25 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.On
> Mar 11 04:59:33 power-control[195]: Host0: Moving to "Off" state
> Mar 11 04:59:37 power-control[195]: POWER_OUT set to 0
> Mar 11 04:59:45 power-control[195]: Host0: Moving to "Off" state
> Mar 11 04:59:48 power-control[195]: POWER_OUT set to 0
> Mar 11 04:59:56 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.Off
> Mar 11 04:59:56 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.On
> Mar 11 04:59:56 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.Off
> Mar 11 04:59:56 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.On
> Mar 11 04:59:56 test_asio[23478]: aiso callback, property:
> RequestedHostTransition, value:
> xyz.openbmc_project.State.Host.Transition.Off
> Mar 11 04:59:56 power-control[195]: Host0: Moving to "Off" state
>
> In the log, `POWER_OUT set to 0` means RequestedHostTransition is set
> to On, and `Host0: Moving to "Off" state` means it's set to Off.
> You can see that test_asio's callback is not triggered during
> 04:59:33~04:59:48, and it's triggered for multiple times on 04:59:56.
>
> # More info
> * If the sync DBus calls are removed, the issue is not reproduced.
> * If I do not use asio at all, and use sync DBus calls with
> `sdeventplus::utility::Timer`, the issue is not reproduced.
>
> That is to say, this issue only occurs when asio and sync DBus calls are mixed.
>
>
> @Ed Tanous @William Kennington @Patrick Williams Could you kindly
> check the above behavior and let's see what could be wrong?
>
> Thanks!
>
> --
> BRs,
> Lei YU