[logging] Refactored logged messages

Many messages are logged in the scope that doesn't seem to be
appropriate (errors as progress, very detail info as progress etc.)

* Briefly reviewed ChipLog calls and changed scopes where it
seemed to be valuable

For nrfconnect:
* Added setting gn chip logging flags depending on Kconfig
CONFIG_MATTER_LOG_LEVEL option
* Disabled not used shell modules
* Changed Zephyr modules default log level from info to warning
(all Zephyr modules are set to warning and only those that are
important are set to info)

config/nrfconnect/app/sample-defaults.conf

@@ -22,6 +22,7 @@ CONFIG_STD_CPP14=y
 CONFIG_LOG=y
 CONFIG_LOG_MODE_MINIMAL=y
 CONFIG_MATTER_LOG_LEVEL_DBG=y
+CONFIG_LOG_DEFAULT_LEVEL=2
 CONFIG_PRINTK_SYNC=y
 CONFIG_ASSERT=y
 CONFIG_HW_STACK_PROTECTION=y
@@ -107,3 +108,12 @@ CONFIG_MBEDTLS_POLY1305_C=n
 CONFIG_MBEDTLS_CHACHAPOLY_C=n
 CONFIG_MBEDTLS_GCM_C=n
 CONFIG_MBEDTLS_RSA_C=n
+
+# Disable not used shell modules
+CONFIG_SENSOR_SHELL=n
+CONFIG_DEVICE_SHELL=n
+CONFIG_DATE_SHELL=n
+CONFIG_DEVMEM_SHELL=n
+CONFIG_MCUBOOT_SHELL=n
+CONFIG_CLOCK_CONTROL_NRF_SHELL=n
+CONFIG_FLASH_SHELL=n

config/nrfconnect/chip-module/CMakeLists.txt

@@ -63,8 +63,8 @@ macro(chip_gn_arg_string ARG STRING)
     string(APPEND CHIP_GN_ARGS "--arg-string\n${ARG}\n${STRING}\n")
 endmacro()
 
-macro(chip_gn_arg_bool ARG BOOLEAN)
-    if (${BOOLEAN})
+macro(chip_gn_arg_bool ARG)
+    if (${ARGN})
         string(APPEND CHIP_GN_ARGS "--arg\n${ARG}\ntrue\n")
     else()
         string(APPEND CHIP_GN_ARGS "--arg\n${ARG}\nfalse\n")
@@ -214,6 +214,10 @@ chip_gn_arg_bool  ("chip_build_tests"                       CONFIG_CHIP_BUILD_TE
 chip_gn_arg_bool  ("chip_monolithic_tests"                  CONFIG_CHIP_BUILD_TESTS)
 chip_gn_arg_bool  ("chip_inet_config_enable_tcp_endpoint"   CONFIG_CHIP_BUILD_TESTS)
 chip_gn_arg_bool  ("chip_build_libshell"                    CONFIG_CHIP_LIB_SHELL)
+chip_gn_arg_bool  ("chip_error_logging"                     CONFIG_MATTER_LOG_LEVEL GREATER_EQUAL 1)
+chip_gn_arg_bool  ("chip_progress_logging"                  CONFIG_MATTER_LOG_LEVEL GREATER_EQUAL 3)
+chip_gn_arg_bool  ("chip_detail_logging"                    CONFIG_MATTER_LOG_LEVEL GREATER_EQUAL 4)
+chip_gn_arg_bool  ("chip_automation_logging"                "false")
 
 if (CONFIG_CHIP_ROTATING_DEVICE_ID)
     chip_gn_arg_bool("chip_enable_rotating_device_id"          "true")

examples/lighting-app/nrfconnect/prj.conf

@@ -37,6 +37,7 @@ CONFIG_BT_DEVICE_NAME="MatterLight"
 # Additional configs for debbugging experience.
 CONFIG_THREAD_NAME=y
 CONFIG_MPU_STACK_GUARD=y
+CONFIG_RESET_ON_FATAL_ERROR=n
 
 # CHIP configuration
 CONFIG_CHIP_PROJECT_CONFIG="main/include/CHIPProjectConfig.h"

examples/lock-app/nrfconnect/prj.conf

@@ -38,6 +38,7 @@ CONFIG_BT_DEVICE_NAME="MatterLock"
 # Additional configs for debbugging experience.
 CONFIG_THREAD_NAME=y
 CONFIG_MPU_STACK_GUARD=y
+CONFIG_RESET_ON_FATAL_ERROR=n
 
 # CHIP configuration
 CONFIG_CHIP_PROJECT_CONFIG="main/include/CHIPProjectConfig.h"

src/app/EventManagement.cpp

@@ -183,7 +183,7 @@ CHIP_ERROR EventManagement::CopyToNextBuffer(CircularEventBuffer * apEventBuffer
     err = writer.Finalize();
     SuccessOrExit(err);
 
-    ChipLogProgress(EventLogging, "Copy Event to next buffer with priority %u", static_cast<unsigned>(nextBuffer->GetPriority()));
+    ChipLogDetail(EventLogging, "Copy Event to next buffer with priority %u", static_cast<unsigned>(nextBuffer->GetPriority()));
 exit:
     if (err != CHIP_NO_ERROR)
     {

src/app/InteractionModelEngine.cpp

@@ -315,7 +315,7 @@ CHIP_ERROR InteractionModelEngine::OnReadInitialRequest(Messaging::ExchangeConte
     if (aInteractionType == ReadHandler::InteractionType::Subscribe && ((handlerPoolCapacity - GetNumActiveReadHandlers()) == 1) &&
         !HasActiveRead())
     {
-        ChipLogProgress(InteractionModel, "Reserve the last ReadHandler for IM read Interaction");
+        ChipLogDetail(InteractionModel, "Reserve the last ReadHandler for IM read Interaction");
         aStatus = Protocols::InteractionModel::Status::ResourceExhausted;
         return CHIP_NO_ERROR;
     }
@@ -474,8 +474,8 @@ CHIP_ERROR InteractionModelEngine::OnMessageReceived(Messaging::ExchangeContext
 
 void InteractionModelEngine::OnResponseTimeout(Messaging::ExchangeContext * ec)
 {
-    ChipLogProgress(InteractionModel, "Time out! Failed to receive IM response from Exchange: " ChipLogFormatExchange,
-                    ChipLogValueExchange(ec));
+    ChipLogError(InteractionModel, "Time out! Failed to receive IM response from Exchange: " ChipLogFormatExchange,
+                 ChipLogValueExchange(ec));
 }
 
 void InteractionModelEngine::AddReadClient(ReadClient * apReadClient)

src/app/ReadClient.cpp

@@ -553,8 +553,8 @@ CHIP_ERROR ReadClient::ProcessReportData(System::PacketBufferHandle && aPayload)
 
 void ReadClient::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive report data from Exchange: " ChipLogFormatExchange,
-                    ChipLogValueExchange(apExchangeContext));
+    ChipLogError(DataManagement, "Time out! failed to receive report data from Exchange: " ChipLogFormatExchange,
+                 ChipLogValueExchange(apExchangeContext));
     Close(CHIP_ERROR_TIMEOUT);
 }
 
@@ -888,7 +888,7 @@ bool ReadClient::ResubscribeIfNeeded()
     uint32_t intervalMsec  = 0;
     if (mReadPrepareParams.mResubscribePolicy == nullptr)
     {
-        ChipLogProgress(DataManagement, "mResubscribePolicy is null");
+        ChipLogDetail(DataManagement, "mResubscribePolicy is null");
         return false;
     }
     mReadPrepareParams.mResubscribePolicy(mNumRetries, intervalMsec, shouldResubscribe);
@@ -901,7 +901,7 @@ bool ReadClient::ResubscribeIfNeeded()
         System::Clock::Milliseconds32(intervalMsec), OnResubscribeTimerCallback, this);
     if (err != CHIP_NO_ERROR)
     {
-        ChipLogProgress(DataManagement, "Fail to resubscribe with error %" CHIP_ERROR_FORMAT, err.Format());
+        ChipLogError(DataManagement, "Fail to resubscribe with error %" CHIP_ERROR_FORMAT, err.Format());
         return false;
     }
 

src/app/ReadHandler.cpp

@@ -290,8 +290,8 @@ CHIP_ERROR ReadHandler::OnUnknownMsgType(Messaging::ExchangeContext * apExchange
 
 void ReadHandler::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive status response from Exchange: " ChipLogFormatExchange,
-                    ChipLogValueExchange(apExchangeContext));
+    ChipLogError(DataManagement, "Time out! failed to receive status response from Exchange: " ChipLogFormatExchange,
+                 ChipLogValueExchange(apExchangeContext));
     Close();
 }
 
@@ -706,7 +706,7 @@ void ReadHandler::OnUnblockHoldReportCallback(System::Layer * apSystemLayer, voi
 {
     VerifyOrReturn(apAppState != nullptr);
     ReadHandler * readHandler = static_cast<ReadHandler *>(apAppState);
-    ChipLogProgress(DataManagement, "Unblock report hold after min %d seconds", readHandler->mMinIntervalFloorSeconds);
+    ChipLogDetail(DataManagement, "Unblock report hold after min %d seconds", readHandler->mMinIntervalFloorSeconds);
     readHandler->mHoldReport = false;
     if (readHandler->mDirty)
     {
@@ -722,14 +722,14 @@ void ReadHandler::OnRefreshSubscribeTimerSyncCallback(System::Layer * apSystemLa
     VerifyOrReturn(apAppState != nullptr);
     ReadHandler * readHandler = static_cast<ReadHandler *>(apAppState);
     readHandler->mHoldSync    = false;
-    ChipLogProgress(DataManagement, "Refresh subscribe timer sync after %d seconds",
-                    readHandler->mMaxIntervalCeilingSeconds - readHandler->mMinIntervalFloorSeconds);
+    ChipLogDetail(DataManagement, "Refresh subscribe timer sync after %d seconds",
+                  readHandler->mMaxIntervalCeilingSeconds - readHandler->mMinIntervalFloorSeconds);
     InteractionModelEngine::GetInstance()->GetReportingEngine().ScheduleRun();
 }
 
 CHIP_ERROR ReadHandler::RefreshSubscribeSyncTimer()
 {
-    ChipLogProgress(DataManagement, "Refresh Subscribe Sync Timer with max %d seconds", mMaxIntervalCeilingSeconds);
+    ChipLogDetail(DataManagement, "Refresh Subscribe Sync Timer with max %d seconds", mMaxIntervalCeilingSeconds);
     InteractionModelEngine::GetInstance()->GetExchangeManager()->GetSessionManager()->SystemLayer()->CancelTimer(
         OnUnblockHoldReportCallback, this);
     InteractionModelEngine::GetInstance()->GetExchangeManager()->GetSessionManager()->SystemLayer()->CancelTimer(

src/app/WriteClient.cpp

@@ -498,8 +498,8 @@ CHIP_ERROR WriteClient::OnMessageReceived(Messaging::ExchangeContext * apExchang
 
 void WriteClient::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive write response from Exchange: " ChipLogFormatExchange,
-                    ChipLogValueExchange(apExchangeContext));
+    ChipLogError(DataManagement, "Time out! failed to receive write response from Exchange: " ChipLogFormatExchange,
+                 ChipLogValueExchange(apExchangeContext));
 
     if (mpCallback != nullptr)
     {

src/app/WriteHandler.cpp

@@ -163,8 +163,8 @@ CHIP_ERROR WriteHandler::OnMessageReceived(Messaging::ExchangeContext * apExchan
 
 void WriteHandler::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContext)
 {
-    ChipLogProgress(DataManagement, "Time out! failed to receive status response from Exchange: " ChipLogFormatExchange,
-                    ChipLogValueExchange(apExchangeContext));
+    ChipLogError(DataManagement, "Time out! failed to receive status response from Exchange: " ChipLogFormatExchange,
+                 ChipLogValueExchange(apExchangeContext));
     Close();
 }
 

src/app/app-platform/ContentAppPlatform.cpp

@@ -52,7 +52,7 @@ EmberAfStatus emberAfExternalAttributeReadCallback(EndpointId endpoint, ClusterI
 {
     uint16_t endpointIndex = emberAfGetDynamicIndexFromEndpoint(endpoint);
 
-    ChipLogProgress(DeviceLayer, "emberAfExternalAttributeReadCallback endpoint %d ", endpointIndex);
+    ChipLogDetail(DeviceLayer, "emberAfExternalAttributeReadCallback endpoint %d ", endpointIndex);
 
     EmberAfStatus ret = EMBER_ZCL_STATUS_FAILURE;
 
@@ -70,7 +70,7 @@ EmberAfStatus emberAfExternalAttributeWriteCallback(EndpointId endpoint, Cluster
 {
     uint16_t endpointIndex = emberAfGetDynamicIndexFromEndpoint(endpoint);
 
-    ChipLogProgress(DeviceLayer, "emberAfExternalAttributeWriteCallback endpoint %d ", endpointIndex);
+    ChipLogDetail(DeviceLayer, "emberAfExternalAttributeWriteCallback endpoint %d ", endpointIndex);
 
     EmberAfStatus ret = EMBER_ZCL_STATUS_FAILURE;
 
@@ -124,7 +124,7 @@ EndpointId ContentAppPlatform::AddContentApp(ContentApp * app, EmberAfEndpointTy
                 }
                 else if (ret != EMBER_ZCL_STATUS_DUPLICATE_EXISTS)
                 {
-                    ChipLogProgress(DeviceLayer, "Adding ContentApp error=%d", ret);
+                    ChipLogError(DeviceLayer, "Adding ContentApp error=%d", ret);
                     return kNoCurrentEndpointId;
                 }
                 // Handle wrap condition
@@ -136,7 +136,7 @@ EndpointId ContentAppPlatform::AddContentApp(ContentApp * app, EmberAfEndpointTy
         }
         index++;
     }
-    ChipLogProgress(DeviceLayer, "Failed to add dynamic endpoint: No endpoints available!");
+    ChipLogError(DeviceLayer, "Failed to add dynamic endpoint: No endpoints available!");
     return kNoCurrentEndpointId;
 }
 
@@ -168,7 +168,7 @@ EndpointId ContentAppPlatform::RemoveContentApp(ContentApp * app)
 
 void ContentAppPlatform::SetupAppPlatform()
 {
-    ChipLogProgress(DeviceLayer, "AppPlatform::SetupAppPlatform()");
+    ChipLogDetail(DeviceLayer, "AppPlatform::SetupAppPlatform()");
 
     // Clear out the device database
     uint8_t index = 0;
@@ -189,8 +189,8 @@ void ContentAppPlatform::SetupAppPlatform()
         mCurrentEndpointId = emberAfFixedEndpointCount();
     }
 
-    ChipLogProgress(DeviceLayer, "emberAfFixedEndpointCount()=%d mCurrentEndpointId=%d", emberAfFixedEndpointCount(),
-                    mCurrentEndpointId);
+    ChipLogDetail(DeviceLayer, "emberAfFixedEndpointCount()=%d mCurrentEndpointId=%d", emberAfFixedEndpointCount(),
+                  mCurrentEndpointId);
 
     // Disable last fixed endpoint, which is used as a placeholder for all of the
     // supported clusters so that ZAP will generated the requisite code.
@@ -238,8 +238,8 @@ ContentApp * ContentAppPlatform::LoadContentAppByClient(uint16_t vendorId, uint1
     CHIP_ERROR err = mContentAppFactory->LookupCatalogVendorApp(vendorId, productId, &vendorApp);
     if (err != CHIP_NO_ERROR)
     {
-        ChipLogProgress(DeviceLayer, "GetLoadContentAppByVendorId() - failed to find an app for vendorId %d, productId %d",
-                        vendorId, productId);
+        ChipLogError(DeviceLayer, "GetLoadContentAppByVendorId() - failed to find an app for vendorId %d, productId %d", vendorId,
+                     productId);
         return nullptr;
     }
     return LoadContentAppInternal(&vendorApp);
@@ -255,8 +255,8 @@ ContentApp * ContentAppPlatform::LoadContentApp(const CatalogVendorApp & vendorA
     CHIP_ERROR err = mContentAppFactory->ConvertToPlatformCatalogVendorApp(vendorApp, &destinationApp);
     if (err != CHIP_NO_ERROR)
     {
-        ChipLogProgress(DeviceLayer, "GetLoadContentApp() - failed to find an app for catalog vendorId %d, appId %s",
-                        vendorApp.catalogVendorId, vendorApp.applicationId);
+        ChipLogError(DeviceLayer, "GetLoadContentApp() - failed to find an app for catalog vendorId %d, appId %s",
+                     vendorApp.catalogVendorId, vendorApp.applicationId);
         return nullptr;
     }
     return LoadContentAppInternal(&destinationApp);
@@ -272,8 +272,8 @@ ContentApp * ContentAppPlatform::GetContentApp(const CatalogVendorApp & vendorAp
     CHIP_ERROR err = mContentAppFactory->ConvertToPlatformCatalogVendorApp(vendorApp, &destinationApp);
     if (err != CHIP_NO_ERROR)
     {
-        ChipLogProgress(DeviceLayer, "GetContentApp() - failed to find an app for catalog vendorId %d, appId %s",
-                        vendorApp.catalogVendorId, vendorApp.applicationId);
+        ChipLogError(DeviceLayer, "GetContentApp() - failed to find an app for catalog vendorId %d, appId %s",
+                     vendorApp.catalogVendorId, vendorApp.applicationId);
         return nullptr;
     }
     return GetContentAppInternal(&destinationApp);

src/app/clusters/bindings/bindings.cpp

@@ -233,7 +233,7 @@ void AddBindingEntry(const EmberBindingTableEntry & entry)
         if (err != CHIP_NO_ERROR)
         {
             // Unicast connection failure can happen if peer is offline. We'll retry connection on-demand.
-            ChipLogProgress(
+            ChipLogError(
                 Zcl, "Binding: Failed to create session for unicast binding to device " ChipLogFormatX64 ": %" CHIP_ERROR_FORMAT,
                 ChipLogValueX64(entry.nodeId), err.Format());
         }

src/app/clusters/general-diagnostics-server/general-diagnostics-server.cpp

@@ -189,15 +189,15 @@ class GeneralDiagnosticsDelegate : public DeviceLayer::ConnectivityManagerDelega
     // Gets called when any network interface on the Node is updated.
     void OnNetworkInfoChanged() override
     {
-        ChipLogProgress(Zcl, "GeneralDiagnosticsDelegate: OnNetworkInfoChanged");
+        ChipLogDetail(Zcl, "GeneralDiagnosticsDelegate: OnNetworkInfoChanged");
 
         ReportAttributeOnAllEndpoints(GeneralDiagnostics::Attributes::NetworkInterfaces::Id);
     }
 
     // Gets called when the device has been rebooted.
     void OnDeviceRebooted(chip::DeviceLayer::BootReasonType bootReason) override
     {
-        ChipLogProgress(Zcl, "GeneralDiagnosticsDelegate: OnDeviceRebooted");
+        ChipLogDetail(Zcl, "GeneralDiagnosticsDelegate: OnDeviceRebooted");
 
         ReportAttributeOnAllEndpoints(GeneralDiagnostics::Attributes::BootReasons::Id);
 
@@ -217,7 +217,7 @@ class GeneralDiagnosticsDelegate : public DeviceLayer::ConnectivityManagerDelega
     void OnHardwareFaultsDetected(GeneralFaults<kMaxHardwareFaults> & previous,
                                   GeneralFaults<kMaxHardwareFaults> & current) override
     {
-        ChipLogProgress(Zcl, "GeneralDiagnosticsDelegate: OnHardwareFaultsDetected");
+        ChipLogDetail(Zcl, "GeneralDiagnosticsDelegate: OnHardwareFaultsDetected");
 
         for (auto endpointId : EnabledEndpointsWithServerCluster(GeneralDiagnostics::Id))
         {
@@ -243,7 +243,7 @@ class GeneralDiagnosticsDelegate : public DeviceLayer::ConnectivityManagerDelega
     // Get called when the Node detects a radio fault has been raised.
     void OnRadioFaultsDetected(GeneralFaults<kMaxRadioFaults> & previous, GeneralFaults<kMaxRadioFaults> & current) override
     {
-        ChipLogProgress(Zcl, "GeneralDiagnosticsDelegate: OnHardwareFaultsDetected");
+        ChipLogDetail(Zcl, "GeneralDiagnosticsDelegate: OnRadioFaultsDetected");
 
         for (auto endpointId : EnabledEndpointsWithServerCluster(GeneralDiagnostics::Id))
         {
@@ -269,7 +269,7 @@ class GeneralDiagnosticsDelegate : public DeviceLayer::ConnectivityManagerDelega
     // Get called when the Node detects a network fault has been raised.
     void OnNetworkFaultsDetected(GeneralFaults<kMaxNetworkFaults> & previous, GeneralFaults<kMaxNetworkFaults> & current) override
     {
-        ChipLogProgress(Zcl, "GeneralDiagnosticsDelegate: OnHardwareFaultsDetected");
+        ChipLogDetail(Zcl, "GeneralDiagnosticsDelegate: OnNetworkFaultsDetected");
 
         for (auto endpointId : EnabledEndpointsWithServerCluster(GeneralDiagnostics::Id))
         {

src/app/clusters/software-diagnostics-server/software-diagnostics-server.cpp

@@ -130,7 +130,7 @@ class SoftwareDiagnosticsDelegate : public DeviceLayer::SoftwareDiagnosticsDeleg
     // Gets called when a software fault that has taken place on the Node.
     void OnSoftwareFaultDetected(SoftwareDiagnostics::Structs::SoftwareFaultStruct::Type & softwareFault) override
     {
-        ChipLogProgress(Zcl, "SoftwareDiagnosticsDelegate: OnSoftwareFaultDetected");
+        ChipLogDetail(Zcl, "SoftwareDiagnosticsDelegate: OnSoftwareFaultDetected");
 
         for (auto endpoint : EnabledEndpointsWithServerCluster(SoftwareDiagnostics::Id))
         {

src/app/reporting/Engine.cpp

@@ -728,8 +728,8 @@ CHIP_ERROR Engine::ScheduleBufferPressureEventDelivery(uint32_t aBytesWritten)
     GetMinEventLogPosition(minEventLogPosition);
     if (aBytesWritten - minEventLogPosition > CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD)
     {
-        ChipLogProgress(DataManagement, "<RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD %d, schedule engine run",
-                        CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD);
+        ChipLogDetail(DataManagement, "<RE> Buffer overfilled CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD %d, schedule engine run",
+                      CHIP_CONFIG_EVENT_LOGGING_BYTE_THRESHOLD);
         return ScheduleRun();
     }
     return CHIP_NO_ERROR;