Improve IM logging (#10318)

* Improve IM logging - Fix several typos and grammatical mistakes - Normalize command logging to be done in Data Management layer - Remove generated logging in im-cluster-command-handler.zapt since it duplicates logging that can be done one level lower (and is always done anyway) - Add more details to command responses with status - Remove nuisance log of `AttributePath is not interested` that was not actionable or useful * Restyled * Ran ZAP regen * Apply review comments: remove unneeded casts * Fix enum class cast removed by mistake * Apply suggestions from code review Co-authored-by: Boris Zbarsky <[email protected]> * Apply review comments * Restyled * Fix build after MEI switch * Restyled * Regenerated ZAP * Restyled by autopep8 * Regenerated ZAP * Restyle Co-authored-by: Boris Zbarsky <[email protected]> Co-authored-by: Restyled.io <[email protected]>
project-chip · Oct 27, 2021 · 1306488 · 1306488
1 parent 9816917
commit 1306488
Show file tree

Hide file tree

Showing 19 changed files with 37 additions and 97 deletions.
diff --git a/src/app/CommandHandler.cpp b/src/app/CommandHandler.cpp
@@ -115,11 +115,17 @@ CHIP_ERROR CommandHandler::ProcessCommandDataElement(CommandDataElement::Parser
     err = aCommandElement.GetData(&commandDataReader);
     if (CHIP_END_OF_TLV == err)
     {
+        ChipLogDetail(DataManagement,
+                      "Received command without data for Endpoint=%" PRIu16 " Cluster=" ChipLogFormatMEI
+                      " Command=" ChipLogFormatMEI,
+                      endpointId, ChipLogValueMEI(clusterId), ChipLogValueMEI(commandId));
         err = CHIP_NO_ERROR;
-        ChipLogDetail(DataManagement, "Received command without data for cluster " ChipLogFormatMEI, ChipLogValueMEI(clusterId));
     }
     if (CHIP_NO_ERROR == err)
     {
+        ChipLogDetail(DataManagement,
+                      "Received command for Endpoint=%" PRIu16 " Cluster=" ChipLogFormatMEI " Command=" ChipLogFormatMEI,
+                      endpointId, ChipLogValueMEI(clusterId), ChipLogValueMEI(commandId));
         DispatchSingleClusterCommand(ConcreteCommandPath(endpointId, clusterId, commandId), commandDataReader, this);
     }
 

diff --git a/src/app/CommandSender.cpp b/src/app/CommandSender.cpp
@@ -153,6 +153,29 @@ CHIP_ERROR CommandSender::ProcessCommandDataElement(CommandDataElement::Parser &
             hasDataResponse = true;
             err             = aCommandElement.GetData(&commandDataReader);
         }
+
+        if (err != CHIP_NO_ERROR)
+        {
+            ChipLogError(DataManagement, "Received malformed Command Response, err=%" CHIP_ERROR_FORMAT, err.Format());
+        }
+        else
+        {
+            if (hasDataResponse)
+            {
+                ChipLogProgress(DataManagement,
+                                "Received Command Response Data, Endpoint=%" PRIu16 " Cluster=" ChipLogFormatMEI
+                                " Command=" ChipLogFormatMEI,
+                                endpointId, ChipLogValueMEI(clusterId), ChipLogValueMEI(commandId));
+            }
+            else
+            {
+                ChipLogProgress(DataManagement,
+                                "Received Command Response Status for Endpoint=%" PRIu16 " Cluster=" ChipLogFormatMEI
+                                " Command=" ChipLogFormatMEI " Status=0x%" PRIx16,
+                                endpointId, ChipLogValueMEI(clusterId), ChipLogValueMEI(commandId),
+                                to_underlying(statusIB.mStatus));
+            }
+        }
         SuccessOrExit(err);
 
         if (mpCallback != nullptr)

diff --git a/src/app/InteractionModelEngine.cpp b/src/app/InteractionModelEngine.cpp
@@ -222,7 +222,7 @@ CHIP_ERROR InteractionModelEngine::OnReadInitialRequest(Messaging::ExchangeConte
 {
     CHIP_ERROR err = CHIP_NO_ERROR;
 
-    ChipLogDetail(InteractionModel, "Receive %s request",
+    ChipLogDetail(InteractionModel, "Received %s request",
                   aInteractionType == ReadHandler::InteractionType::Subscribe ? "Subscribe" : "Read");
 
     for (auto & readHandler : mReadHandlers)
@@ -271,7 +271,7 @@ CHIP_ERROR InteractionModelEngine::OnWriteRequest(Messaging::ExchangeContext * a
 {
     CHIP_ERROR err = CHIP_NO_ERROR;
 
-    ChipLogDetail(InteractionModel, "Receive Write request");
+    ChipLogDetail(InteractionModel, "Received Write request");
 
     for (auto & writeHandler : mWriteHandlers)
     {
@@ -356,7 +356,7 @@ CHIP_ERROR InteractionModelEngine::OnMessageReceived(Messaging::ExchangeContext
 
 void InteractionModelEngine::OnResponseTimeout(Messaging::ExchangeContext * ec)
 {
-    ChipLogProgress(InteractionModel, "Time out! failed to receive echo response from Exchange: " ChipLogFormatExchange,
+    ChipLogProgress(InteractionModel, "Time out! Failed to receive IM response from Exchange: " ChipLogFormatExchange,
                     ChipLogValueExchange(ec));
 }
 
@@ -414,7 +414,7 @@ CHIP_ERROR InteractionModelEngine::PushFront(ClusterInfo *& aClusterInfoList, Cl
     ClusterInfo * last = aClusterInfoList;
     if (mpNextAvailableClusterInfo == nullptr)
     {
-        ChipLogProgress(InteractionModel, "There is no available cluster info in mClusterInfoPool");
+        ChipLogError(InteractionModel, "ClusterInfo pool full, cannot handle more entries!");
         return CHIP_ERROR_NO_MEMORY;
     }
     aClusterInfoList           = mpNextAvailableClusterInfo;
@@ -465,7 +465,6 @@ bool InteractionModelEngine::IsOverlappedAttributePath(ClusterInfo & aAttributeP
             }
         }
     }
-    ChipLogDetail(DataManagement, "AttributePath is not interested");
     return false;
 }
 

diff --git a/src/app/tests/integration/chip_im_responder.cpp b/src/app/tests/integration/chip_im_responder.cpp
@@ -104,10 +104,10 @@ void DispatchSingleClusterCommand(const ConcreteCommandPath & aCommandPath, chip
 void DispatchSingleClusterResponseCommand(const ConcreteCommandPath & aCommandPath, chip::TLV::TLVReader & aReader,
                                           CommandSender * apCommandObj)
 {
-    ChipLogDetail(Controller,
-                  "Received Cluster Command: Endpoint=%" PRIx16 " Cluster=" ChipLogFormatMEI " Command=" ChipLogFormatMEI,
-                  aCommandPath.mEndpointId, ChipLogValueMEI(aCommandPath.mClusterId), ChipLogValueMEI(aCommandPath.mCommandId));
     // Nothing todo.
+    (void) aCommandPath;
+    (void) aReader;
+    (void) apCommandObj;
 }
 
 CHIP_ERROR ReadSingleClusterData(const ConcreteAttributePath & aPath, TLV::TLVWriter * apWriter, bool * apDataExists)

diff --git a/src/app/zap-templates/templates/app/im-cluster-command-handler.zapt b/src/app/zap-templates/templates/app/im-cluster-command-handler.zapt
@@ -96,8 +96,6 @@ void Dispatch{{asUpperCamelCase side}}Command({{#if (isServer side)}}CommandHand
 
 void DispatchSingleClusterCommand(const ConcreteCommandPath & aCommandPath, TLV::TLVReader & aReader, CommandHandler * apCommandObj)
 {
-    ChipLogDetail(Zcl, "Received Cluster Command: Endpoint=%" PRIx16 " Cluster=" ChipLogFormatMEI " Command=" ChipLogFormatMEI, aCommandPath.mEndpointId, ChipLogValueMEI(aCommandPath.mClusterId), ChipLogValueMEI(aCommandPath.mCommandId));
-
     Compatibility::SetupEmberAfObjects(apCommandObj, aCommandPath);
 
     switch (aCommandPath.mClusterId)
@@ -123,8 +121,6 @@ void DispatchSingleClusterCommand(const ConcreteCommandPath & aCommandPath, TLV:
 
 void DispatchSingleClusterResponseCommand(const ConcreteCommandPath & aCommandPath, TLV::TLVReader & aReader, CommandSender * apCommandObj)
 {
-    ChipLogDetail(Zcl, "Received Cluster Command: Endpoint=%" PRIx16 " Cluster=" ChipLogFormatMEI " Command=" ChipLogFormatMEI, aCommandPath.mEndpointId, ChipLogValueMEI(aCommandPath.mClusterId), ChipLogValueMEI(aCommandPath.mCommandId));
-
     Compatibility::SetupEmberAfObjects(apCommandObj, aCommandPath);
 
     TLV::TLVType dataTlvType;

diff --git a/zzz_generated/all-clusters-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/all-clusters-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/bridge-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/bridge-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/controller-clusters/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/controller-clusters/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/lighting-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/lighting-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/lock-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/lock-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/ota-provider-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/ota-provider-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/ota-requestor-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/ota-requestor-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/pump-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/pump-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/pump-controller-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/pump-controller-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/temperature-measurement-app/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/temperature-measurement-app/zap-generated/IMClusterCommandHandler.cpp
diff --git a/zzz_generated/thermostat/zap-generated/IMClusterCommandHandler.cpp b/zzz_generated/thermostat/zap-generated/IMClusterCommandHandler.cpp