From 6fc3432651efc3dc20e61343325e917104197530 Mon Sep 17 00:00:00 2001 From: Tennessee Carmel-Veilleux Date: Wed, 18 May 2022 21:34:39 -0400 Subject: [PATCH] Normalize NOC cluster logs (#18577) * Normalize NOC cluster logs - NOC cluster was using Info/Debug verbosity for errors - NOC cluster was not logging sufficient info for some errors - NOC cluster had a variety of asymmetrical log formats related to multiple authors. - NOC cluster was using emberAfPrintln() instead of ChipLog*() This PR cleans up the logging and normalizes it Fixes #18384 Testing done: - Unit tests and cert tests pass - Logging audited on a cert test run for funkiness, none found * Restyled by clang-format * Apply review comments Co-authored-by: Restyled.io --- .../operational-credentials-server.cpp | 92 ++++++++++--------- 1 file changed, 49 insertions(+), 43 deletions(-) diff --git a/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp b/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp index e47e0f9fd9d983..ba08f5bb04a0aa 100644 --- a/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp +++ b/src/app/clusters/operational-credentials-server/operational-credentials-server.cpp @@ -81,10 +81,16 @@ CHIP_ERROR CreateAccessControlEntryForNewFabricAdministrator(const Access::Subje ReturnErrorOnFailure(entry.SetPrivilege(Access::Privilege::kAdminister)); ReturnErrorOnFailure(entry.SetAuthMode(Access::AuthMode::kCase)); ReturnErrorOnFailure(entry.AddSubject(nullptr, subject)); - ReturnErrorOnFailure(Access::GetAccessControl().CreateEntry(&subjectDescriptor, fabricIndex, nullptr, entry)); + CHIP_ERROR err = Access::GetAccessControl().CreateEntry(&subjectDescriptor, fabricIndex, nullptr, entry); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: ACL entry created for Fabric %X CASE Admin NodeId 0x" ChipLogFormatX64, - fabricIndex, ChipLogValueX64(subject)); + if (err != CHIP_NO_ERROR) + { + ChipLogError(Zcl, "OpCreds: Failed to add administrative node ACL entry: %" CHIP_ERROR_FORMAT, err.Format()); + return err; + } + + ChipLogProgress(Zcl, "OpCreds: ACL entry created for Fabric index 0x%x CASE Admin Subject 0x" ChipLogFormatX64, + static_cast(fabricIndex), ChipLogValueX64(subject)); return CHIP_NO_ERROR; } @@ -262,7 +268,7 @@ CHIP_ERROR ComputeAttestationSignature(app::CommandHandler * commandObj, FabricInfo * RetrieveCurrentFabric(CommandHandler * aCommandHandler) { FabricIndex index = aCommandHandler->GetAccessingFabricIndex(); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Finding fabric with fabricIndex 0x%x", static_cast(index)); + ChipLogDetail(Zcl, "OpCreds: Finding fabric with fabricIndex 0x%x", static_cast(index)); return Server::GetInstance().GetFabricTable().FindFabricWithIndex(index); } @@ -285,7 +291,7 @@ void CleanupFabricContext(SessionManager & sessionMgr, FabricIndex fabricIndex) void FailSafeCleanup(const chip::DeviceLayer::ChipDeviceEvent * event) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Call to FailSafeCleanup"); + ChipLogError(Zcl, "OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!"); FabricIndex fabricIndex = event->FailSafeTimerExpired.PeerFabricIndex; @@ -339,8 +345,6 @@ constexpr size_t kMaxRspLen = 900; void fabricListChanged() { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Call to fabricListChanged"); - // Currently, we only manage FabricsList attribute in endpoint 0, OperationalCredentials cluster is always required to be on // EP0. MatterReportingAttributeChangeCallback(0, OperationalCredentials::Id, OperationalCredentials::Attributes::Fabrics::Id); @@ -360,8 +364,7 @@ class OpCredsFabricTableDelegate : public chip::FabricTable::Delegate // Gets called when a fabric is deleted from KVS store void OnFabricDeletedFromStorage(FabricTable & fabricTable, FabricIndex fabricIndex) override { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Fabric index 0x%x was deleted from fabric storage.", - static_cast(fabricIndex)); + ChipLogProgress(Zcl, "OpCreds: Fabric index 0x%x was deleted from fabric storage.", static_cast(fabricIndex)); fabricListChanged(); // The Leave event SHOULD be emitted by a Node prior to permanently leaving the Fabric. @@ -405,11 +408,11 @@ class OpCredsFabricTableDelegate : public chip::FabricTable::Delegate // Safety check, but should not happen by the code paths involved VerifyOrReturn(fabric != nullptr); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, - "OpCreds: Fabric index 0x%x was retrieved from storage. FabricId 0x" ChipLogFormatX64 - ", NodeId 0x" ChipLogFormatX64 ", VendorId 0x%04X", - static_cast(fabric->GetFabricIndex()), ChipLogValueX64(fabric->GetFabricId()), - ChipLogValueX64(fabric->GetPeerId().GetNodeId()), fabric->GetVendorId()); + ChipLogProgress(Zcl, + "OpCreds: Fabric index 0x%x was retrieved from storage. FabricId 0x" ChipLogFormatX64 + ", NodeId 0x" ChipLogFormatX64 ", VendorId 0x%04X", + static_cast(fabric->GetFabricIndex()), ChipLogValueX64(fabric->GetFabricId()), + ChipLogValueX64(fabric->GetNodeId()), fabric->GetVendorId()); fabricListChanged(); } @@ -420,11 +423,11 @@ class OpCredsFabricTableDelegate : public chip::FabricTable::Delegate // Safety check, but should not happen by the code paths involved VerifyOrReturn(fabric != nullptr); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, - "OpCreds: Fabric index 0x%x was persisted to storage. FabricId " ChipLogFormatX64 - ", NodeId " ChipLogFormatX64 ", VendorId 0x%04X", - static_cast(fabric->GetFabricIndex()), ChipLogValueX64(fabric->GetFabricId()), - ChipLogValueX64(fabric->GetPeerId().GetNodeId()), fabric->GetVendorId()); + ChipLogProgress(Zcl, + "OpCreds: Fabric index 0x%x was persisted to storage. FabricId " ChipLogFormatX64 + ", NodeId " ChipLogFormatX64 ", VendorId 0x%04X", + static_cast(fabric->GetFabricIndex()), ChipLogValueX64(fabric->GetFabricId()), + ChipLogValueX64(fabric->GetNodeId()), fabric->GetVendorId()); fabricListChanged(); } }; @@ -433,8 +436,6 @@ OpCredsFabricTableDelegate gFabricDelegate; void MatterOperationalCredentialsPluginServerInitCallback(void) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table."); - registerAttributeAccessOverride(&gAttrAccess); Server::GetInstance().GetFabricTable().AddFabricDelegate(&gFabricDelegate); @@ -471,7 +472,7 @@ bool emberAfOperationalCredentialsClusterRemoveFabricCallback(app::CommandHandle MATTER_TRACE_EVENT_SCOPE("RemoveFabric", "OperationalCredentials"); auto & fabricBeingRemoved = commandData.fabricIndex; - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: RemoveFabric"); // TODO: Generate emberAfFabricClusterPrintln + ChipLogProgress(Zcl, "OpCreds: Received a RemoveFabric Command"); CHIP_ERROR err = DeleteFabricFromTable(fabricBeingRemoved); SuccessOrExit(err); @@ -525,7 +526,7 @@ bool emberAfOperationalCredentialsClusterUpdateFabricLabelCallback(app::CommandH auto & Label = commandData.label; auto ourFabricIndex = commandObj->GetAccessingFabricIndex(); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: UpdateFabricLabel"); + ChipLogProgress(Zcl, "OpCreds: Received an UpdateFabricLabel command"); for (auto & fabricInfo : Server::GetInstance().GetFabricTable()) { @@ -640,7 +641,7 @@ bool emberAfOperationalCredentialsClusterAddNOCCallback(app::CommandHandler * co uint8_t compressed_fabric_id_buffer[sizeof(uint64_t)]; MutableByteSpan compressed_fabric_id(compressed_fabric_id_buffer); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Received AddNOC command"); + ChipLogProgress(Zcl, "OpCreds: Received an AddNOC command"); if (nullptr == groupDataProvider) { @@ -734,12 +735,12 @@ bool emberAfOperationalCredentialsClusterAddNOCCallback(app::CommandHandler * co if (nocResponse != OperationalCertStatus::kSuccess) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed AddNOC request. Status %d", to_underlying(nocResponse)); + ChipLogError(Zcl, "OpCreds: Failed AddNOC request (err=%" CHIP_ERROR_FORMAT "). Status %d", err.Format(), + to_underlying(nocResponse)); } else { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: successfully created fabric index %u via AddNOC", - static_cast(fabricIndex)); + ChipLogProgress(Zcl, "OpCreds: successfully created fabric index 0x%x via AddNOC", static_cast(fabricIndex)); } return true; @@ -758,7 +759,7 @@ bool emberAfOperationalCredentialsClusterUpdateNOCCallback(app::CommandHandler * CHIP_ERROR err = CHIP_NO_ERROR; FabricIndex fabricIndex = 0; - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: an administrator requested an update to the NOC"); + ChipLogProgress(Zcl, "OpCreds: Received an UpdateNOC command"); FailSafeContext & failSafeContext = DeviceControlServer::DeviceControlSvr().GetFailSafeContext(); @@ -801,11 +802,12 @@ bool emberAfOperationalCredentialsClusterUpdateNOCCallback(app::CommandHandler * if (nocResponse != OperationalCertStatus::kSuccess) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed UpdateNOC request. Status %d", to_underlying(nocResponse)); + ChipLogError(Zcl, "OpCreds: Failed UpdateNOC request (err=%" CHIP_ERROR_FORMAT "). Sending Status %d", err.Format(), + to_underlying(nocResponse)); } else { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: UpdateNOC successful."); + ChipLogProgress(Zcl, "OpCreds: UpdateNOC successful."); } return true; @@ -831,18 +833,17 @@ bool emberAfOperationalCredentialsClusterCertificateChainRequestCallback( if (certificateType == kDACCertificate) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Certificate Chain request received for DAC"); + ChipLogProgress(Zcl, "OpCreds: Certificate Chain request received for DAC"); SuccessOrExit(err = dacProvider->GetDeviceAttestationCert(derBufSpan)); } else if (certificateType == kPAICertificate) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Certificate Chain request received for PAI"); + ChipLogProgress(Zcl, "OpCreds: Certificate Chain request received for PAI"); SuccessOrExit(err = dacProvider->GetProductAttestationIntermediateCert(derBufSpan)); } else { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Certificate Chain request received for unknown type: %d", - static_cast(certificateType)); + ChipLogError(Zcl, "OpCreds: Certificate Chain request received for unknown type: %d", static_cast(certificateType)); SuccessOrExit(err = CHIP_ERROR_INVALID_ARGUMENT); } @@ -852,7 +853,7 @@ bool emberAfOperationalCredentialsClusterCertificateChainRequestCallback( exit: if (err != CHIP_NO_ERROR) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed CertificateChainRequest: %s", ErrorStr(err)); + ChipLogError(Zcl, "OpCreds: Failed CertificateChainRequest: %" CHIP_ERROR_FORMAT, err.Format()); emberAfSendImmediateDefaultResponse(EMBER_ZCL_STATUS_FAILURE); } @@ -875,7 +876,7 @@ bool emberAfOperationalCredentialsClusterAttestationRequestCallback(app::Command MutableByteSpan certDeclSpan(certDeclBuf); Credentials::DeviceAttestationCredentialsProvider * dacProvider = Credentials::GetDeviceAttestationCredentialsProvider(); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: received an AttestationRequest"); + ChipLogProgress(Zcl, "OpCreds: Received an AttestationRequest command"); // TODO: retrieve vendor information to populate the fields below. uint32_t timestamp = 0; @@ -913,7 +914,7 @@ bool emberAfOperationalCredentialsClusterAttestationRequestCallback(app::Command exit: if (err != CHIP_NO_ERROR) { - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed AttestationRequest: %s", ErrorStr(err)); + ChipLogError(Zcl, "OpCreds: Failed AttestationRequest: %" CHIP_ERROR_FORMAT, err.Format()); emberAfSendImmediateDefaultResponse(EMBER_ZCL_STATUS_FAILURE); } @@ -925,7 +926,7 @@ bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler const Commands::CSRRequest::DecodableType & commandData) { MATTER_TRACE_EVENT_SCOPE("CSRRequest", "OperationalCredentials"); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: commissioner has requested a CSR"); + ChipLogProgress(Zcl, "OpCreds: Received a CSRRequest command"); CHIP_ERROR err = CHIP_NO_ERROR; Platform::ScopedMemoryBuffer csr; @@ -973,8 +974,13 @@ bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler VerifyOrExit(csr.Alloc(csrLength), err = CHIP_ERROR_NO_MEMORY); err = gFabricBeingCommissioned.GetOperationalKey()->NewCertificateSigningRequest(csr.Get(), csrLength); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: NewCertificateSigningRequest returned %" CHIP_ERROR_FORMAT, err.Format()); - SuccessOrExit(err); + if (err != CHIP_NO_ERROR) + { + ChipLogError(Zcl, "OpCreds: NewCertificateSigningRequest returned %" CHIP_ERROR_FORMAT, err.Format()); + SuccessOrExit(err); + } + ChipLogProgress(Zcl, "OpCreds: NewCertificateSigningRequest succeeded"); + VerifyOrExit(csrLength <= Crypto::kMAX_CSR_Length, err = CHIP_ERROR_INTERNAL); // Encode the NOCSR elements with the CSR and Nonce @@ -1011,7 +1017,7 @@ bool emberAfOperationalCredentialsClusterCSRRequestCallback(app::CommandHandler { // TODO: Replace this error handling with fail-safe since it's not transactional against root certs gFabricBeingCommissioned.Reset(); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed CSRRequest: %s", ErrorStr(err)); + ChipLogError(Zcl, "OpCreds: Failed CSRRequest: %" CHIP_ERROR_FORMAT, err.Format()); emberAfSendImmediateDefaultResponse(EMBER_ZCL_STATUS_FAILURE); } @@ -1027,7 +1033,7 @@ bool emberAfOperationalCredentialsClusterAddTrustedRootCertificateCallback( EmberAfStatus status = EMBER_ZCL_STATUS_SUCCESS; - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: commissioner has added a trusted root Cert"); + ChipLogProgress(Zcl, "OpCreds: Received an AddTrustedRootCertificate command"); FailSafeContext & failSafeContext = DeviceControlServer::DeviceControlSvr().GetFailSafeContext(); @@ -1046,7 +1052,7 @@ bool emberAfOperationalCredentialsClusterAddTrustedRootCertificateCallback( if (status != EMBER_ZCL_STATUS_SUCCESS) { gFabricBeingCommissioned.Reset(); - emberAfPrintln(EMBER_AF_PRINT_DEBUG, "OpCreds: Failed AddTrustedRootCert request."); + ChipLogProgress(Zcl, "OpCreds: Failed AddTrustedRootCertificate request"); } else {