Fix bug with ReportingEngine not being run with short/0 min-reporting…

… intervals (#17426) (#18694)

* Fix bug.

* Review feedback

* Apply suggestions from code review

Co-authored-by: Boris Zbarsky <[email protected]>

* Regen

* Restyle

Co-authored-by: Boris Zbarsky <[email protected]>
(cherry picked from commit 9ff658c)

Co-authored-by: Jerry Johns <[email protected]>

src/app/ReadHandler.cpp

@@ -158,11 +158,7 @@ CHIP_ERROR ReadHandler::OnStatusResponse(Messaging::ExchangeContext * apExchange
     case HandlerState::AwaitingReportResponse:
         if (IsChunkedReport())
         {
-            MoveToState(HandlerState::GeneratingReports);
             mpExchangeCtx->WillSendMessage();
-
-            // Trigger ReportingEngine run for sending next chunk of data.
-            SuccessOrExit(err = InteractionModelEngine::GetInstance()->GetReportingEngine().ScheduleRun());
         }
         else if (IsType(InteractionType::Subscribe))
         {
@@ -183,14 +179,19 @@ CHIP_ERROR ReadHandler::OnStatusResponse(Messaging::ExchangeContext * apExchange
             }
             else
             {
-                MoveToState(HandlerState::GeneratingReports);
                 mpExchangeCtx = nullptr;
             }
         }
         else
         {
+            //
+            // We're done processing a read, so let's close out and return.
+            //
             Close();
+            return CHIP_NO_ERROR;
         }
+
+        MoveToState(HandlerState::GeneratingReports);
         break;
 
     case HandlerState::GeneratingReports:
@@ -390,8 +391,6 @@ CHIP_ERROR ReadHandler::ProcessReadRequest(System::PacketBufferHandle && aPayloa
     ReturnErrorOnFailure(readRequestParser.ExitContainer());
     MoveToState(HandlerState::GeneratingReports);
 
-    ReturnErrorOnFailure(InteractionModelEngine::GetInstance()->GetReportingEngine().ScheduleRun());
-
     mpExchangeCtx->WillSendMessage();
 
     // There must be no code after the WillSendMessage() call that can cause
@@ -617,11 +616,25 @@ const char * ReadHandler::GetStateStr() const
 
 void ReadHandler::MoveToState(const HandlerState aTargetState)
 {
+    if (aTargetState == mState)
+    {
+        return;
+    }
+
     if (IsAwaitingReportResponse() && aTargetState != HandlerState::AwaitingReportResponse)
     {
         InteractionModelEngine::GetInstance()->GetReportingEngine().OnReportConfirm();
     }
 
+    //
+    // If we just unblocked sending reports, let's go ahead and schedule the reporting
+    // engine to run to kick that off.
+    //
+    if (aTargetState == HandlerState::GeneratingReports)
+    {
+        InteractionModelEngine::GetInstance()->GetReportingEngine().ScheduleRun();
+    }
+
     mState = aTargetState;
     ChipLogDetail(DataManagement, "IM RH moving to [%s]", GetStateStr());
 }
@@ -670,7 +683,6 @@ CHIP_ERROR ReadHandler::SendSubscribeResponse()
     ReturnErrorOnFailure(RefreshSubscribeSyncTimer());
 
     mIsPrimingReports = false;
-    MoveToState(HandlerState::GeneratingReports);
     return mpExchangeCtx->SendMessage(Protocols::InteractionModel::MsgType::SubscribeResponse, std::move(packet));
 }
 
@@ -754,8 +766,6 @@ CHIP_ERROR ReadHandler::ProcessSubscribeRequest(System::PacketBufferHandle && aP
     ReturnErrorOnFailure(subscribeRequestParser.ExitContainer());
     MoveToState(HandlerState::GeneratingReports);
 
-    InteractionModelEngine::GetInstance()->GetReportingEngine().ScheduleRun();
-
     mpExchangeCtx->WillSendMessage();
 
     return CHIP_NO_ERROR;

src/app/ReadHandler.h

@@ -288,8 +288,8 @@ class ReadHandler : public Messaging::ExchangeDelegate
     enum class HandlerState
     {
         Idle,                   ///< The handler has been initialized and is ready
-        GeneratingReports,      ///< The handler has received either a Read or Subscribe request and is the process of generating a
-                                ///< report.
+        GeneratingReports,      ///< The handler has is now capable of generating reports and may generate one immediately
+                                ///< or later when other criteria are satisfied (e.g hold-off for min reporting interval).
         AwaitingReportResponse, ///< The handler has sent the report to the client and is awaiting a status response.
         AwaitingDestruction,    ///< The object has completed its work and is awaiting destruction by the application.
     };

src/app/tests/TestReadInteraction.cpp

@@ -1823,6 +1823,12 @@ void TestReadInteraction::TestSubscribeWildcard(nlTestSuite * apSuite, void * ap
 
             ctx.DrainAndServiceIO();
 
+            //
+            // Not sure why I had to add this, and didn't have cycles to figure out why.
+            // Tracked in Issue #17528.
+            //
+            ctx.DrainAndServiceIO();
+
             NL_TEST_ASSERT(apSuite, delegate.mGotReport);
             // Mock endpoint3 has 13 attributes in total, and we subscribed twice.
             // And attribute 3/2/4 is a list with 6 elements and list chunking is applied to it, thus we should receive ( 13 + 6 ) *

src/controller/python/test/test_scripts/cluster_objects.py

@@ -187,6 +187,41 @@ def subUpdate(path: TypedAttributePath, transaction: SubscriptionTransaction):
 
         sub.Shutdown()
 
+    @classmethod
+    @base.test_case
+    async def TestSubscribeZeroMinInterval(cls, devCtrl):
+        '''
+        This validates receiving subscription reports for two attributes at a time in quick succession after issuing a command that results in attribute side-effects.
+        Specifically, it relies on the fact that the second attribute is changed in a different execution context than the first. This ensures that we pick-up the first
+        attribute change and generate a notification, and validating that shortly after that, we generate a second report for the second change.
+
+        This is done using subscriptions with a min reporting interval of 0 to ensure timely notification of the above. An On() command is sent to the OnOff cluster
+        which should simultaneously set the state to On as well as set the level to 254.
+        '''
+        logger.info("Test Subscription With MinInterval of 0")
+        sub = await devCtrl.ReadAttribute(nodeid=NODE_ID, attributes=[Clusters.OnOff, Clusters.LevelControl], reportInterval=(0, 60))
+        data = sub.GetAttributes()
+
+        logger.info("Sending off command")
+
+        req = Clusters.OnOff.Commands.Off()
+        await devCtrl.SendCommand(nodeid=NODE_ID, endpoint=1, payload=req)
+
+        logger.info("Sending on command")
+
+        req = Clusters.OnOff.Commands.On()
+        await devCtrl.SendCommand(nodeid=NODE_ID, endpoint=1, payload=req)
+
+        # Wait for the report containing both attributes to arrive to us.
+        await asyncio.sleep(2)
+
+        logger.info("Checking read back value is indeed 254")
+
+        if (data[1][Clusters.LevelControl][Clusters.LevelControl.Attributes.CurrentLevel] != 254):
+            raise ValueError("Current Level should have been 254")
+
+        sub.Shutdown()
+
     @classmethod
     @base.test_case
     async def TestReadAttributeRequests(cls, devCtrl):
@@ -515,6 +550,7 @@ async def RunTest(cls, devCtrl):
             await cls.TestReadEventRequests(devCtrl, 1)
             await cls.TestReadWriteAttributeRequestsWithVersion(devCtrl)
             await cls.TestReadAttributeRequests(devCtrl)
+            await cls.TestSubscribeZeroMinInterval(devCtrl)
             await cls.TestSubscribeAttribute(devCtrl)
             await cls.TestMixedReadAttributeAndEvents(devCtrl)
             # Note: Write will change some attribute values, always put it after read tests