diff --git a/src/lib/support/logging/CHIPLogging.h b/src/lib/support/logging/CHIPLogging.h index a0bd7aa5919c03..a8b82dd5bf84b2 100644 --- a/src/lib/support/logging/CHIPLogging.h +++ b/src/lib/support/logging/CHIPLogging.h @@ -334,9 +334,28 @@ bool IsCategoryEnabled(uint8_t category); #define ChipLogValueExchangeId(id, isInitiator) id, ((isInitiator) ? 'i' : 'r') #define ChipLogFormatExchange ChipLogFormatExchangeId #define ChipLogValueExchange(ec) ChipLogValueExchangeId((ec)->GetExchangeId(), (ec)->IsInitiator()) -// A header's initiator boolean is the inverse of the exchange's. -#define ChipLogValueExchangeIdFromHeader(payloadHeader) \ +#define ChipLogValueExchangeIdFromSentHeader(payloadHeader) \ + ChipLogValueExchangeId((payloadHeader).GetExchangeID(), (payloadHeader).IsInitiator()) +// A received header's initiator boolean is the inverse of the exchange's. +#define ChipLogValueExchangeIdFromReceivedHeader(payloadHeader) \ ChipLogValueExchangeId((payloadHeader).GetExchangeID(), !(payloadHeader).IsInitiator()) +/** + * Logging helpers for protocol ids. A protocol id is a (vendor-id, + * protocol-id) pair. + */ +#define ChipLogFormatProtocolId "(%" PRIu16 ", %" PRIu16 ")" +#define ChipLogValueProtocolId(id) (id).GetVendorId(), (id).GetProtocolId() + +/** + * Logging helpers for message counters, so we format them consistently. + */ +#define ChipLogFormatMessageCounter "%" PRIu32 + +/** + * Logging helpers for message types, so we format them consistently. + */ +#define ChipLogFormatMessageType "0x%" PRIx8 + } // namespace Logging } // namespace chip diff --git a/src/messaging/ExchangeContext.cpp b/src/messaging/ExchangeContext.cpp index adac7a13267c5c..6455016983624f 100644 --- a/src/messaging/ExchangeContext.cpp +++ b/src/messaging/ExchangeContext.cpp @@ -50,10 +50,13 @@ using namespace chip::System; namespace chip { namespace Messaging { -static void DefaultOnMessageReceived(ExchangeContext * ec, Protocols::Id protocolId, uint8_t msgType, PacketBufferHandle && payload) +static void DefaultOnMessageReceived(ExchangeContext * ec, Protocols::Id protocolId, uint8_t msgType, uint32_t messageCounter, + PacketBufferHandle && payload) { - ChipLogError(ExchangeManager, "Dropping unexpected message %08" PRIX32 ":%d " ChipLogFormatExchange, - protocolId.ToFullyQualifiedSpecForm(), msgType, ChipLogValueExchange(ec)); + ChipLogError(ExchangeManager, + "Dropping unexpected message of type " ChipLogFormatMessageType " with protocolId " ChipLogFormatProtocolId + " and MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange, + msgType, ChipLogValueProtocolId(protocolId), messageCounter, ChipLogValueExchange(ec)); } bool ExchangeContext::IsInitiator() const @@ -459,7 +462,8 @@ CHIP_ERROR ExchangeContext::HandleMessage(uint32_t messageCounter, const Payload } else { - DefaultOnMessageReceived(this, payloadHeader.GetProtocolID(), payloadHeader.GetMessageType(), std::move(msgBuf)); + DefaultOnMessageReceived(this, payloadHeader.GetProtocolID(), payloadHeader.GetMessageType(), messageCounter, + std::move(msgBuf)); return CHIP_NO_ERROR; } } diff --git a/src/messaging/ExchangeMessageDispatch.cpp b/src/messaging/ExchangeMessageDispatch.cpp index 3bb55a9551b8c3..ee436b34def78d 100644 --- a/src/messaging/ExchangeMessageDispatch.cpp +++ b/src/messaging/ExchangeMessageDispatch.cpp @@ -58,7 +58,8 @@ CHIP_ERROR ExchangeMessageDispatch::SendMessage(SessionHandle session, uint16_t if (!payloadHeader.HasMessageType(Protocols::SecureChannel::MsgType::StandaloneAck)) { ChipLogDetail(ExchangeManager, - "Piggybacking Ack for MessageCounter:%08" PRIX32 " on exchange: " ChipLogFormatExchangeId, + "Piggybacking Ack for MessageCounter:" ChipLogFormatMessageCounter + " on exchange: " ChipLogFormatExchangeId, payloadHeader.GetAckMessageCounter().Value(), ChipLogValueExchangeId(exchangeId, isInitiator)); } #endif diff --git a/src/messaging/ExchangeMgr.cpp b/src/messaging/ExchangeMgr.cpp index 2d0fb231e96d97..e9d3204f6ac5f0 100644 --- a/src/messaging/ExchangeMgr.cpp +++ b/src/messaging/ExchangeMgr.cpp @@ -201,11 +201,11 @@ void ExchangeManager::OnMessageReceived(const PacketHeader & packetHeader, const { UnsolicitedMessageHandler * matchingUMH = nullptr; - ChipLogProgress( - ExchangeManager, - "Received message of type 0x%02x with vendorId 0x%04x and protocolId 0x%04x on exchange " ChipLogFormatExchangeId, - payloadHeader.GetMessageType(), payloadHeader.GetProtocolID().GetVendorId(), payloadHeader.GetProtocolID().GetProtocolId(), - ChipLogValueExchangeIdFromHeader(payloadHeader)); + ChipLogProgress(ExchangeManager, + "Received message of type " ChipLogFormatMessageType " with protocolId " ChipLogFormatProtocolId + " and MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchangeId, + payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()), + packetHeader.GetMessageCounter(), ChipLogValueExchangeIdFromReceivedHeader(payloadHeader)); MessageFlags msgFlags; if (isDuplicate == DuplicateMessage::Yes) diff --git a/src/messaging/ReliableMessageContext.cpp b/src/messaging/ReliableMessageContext.cpp index 050c66d040430d..6b8e9a8d6b4790 100644 --- a/src/messaging/ReliableMessageContext.cpp +++ b/src/messaging/ReliableMessageContext.cpp @@ -125,7 +125,10 @@ CHIP_ERROR ReliableMessageContext::FlushAcks() if (err == CHIP_NO_ERROR) { #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Flushed pending ack for MessageCounter:%08" PRIX32, mPendingPeerAckMessageCounter); + ChipLogDetail(ExchangeManager, + "Flushed pending ack for MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange, + mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext())); #endif } } @@ -165,7 +168,9 @@ CHIP_ERROR ReliableMessageContext::HandleRcvdAck(uint32_t ackMessageCounter) if (!GetReliableMessageMgr()->CheckAndRemRetransTable(this, ackMessageCounter)) { #if !defined(NDEBUG) - ChipLogError(ExchangeManager, "CHIP MessageCounter:%08" PRIX32 " not in RetransTable", ackMessageCounter); + ChipLogError(ExchangeManager, + "CHIP MessageCounter:" ChipLogFormatMessageCounter " not in RetransTable on exchange " ChipLogFormatExchange, + ackMessageCounter, ChipLogValueExchange(GetExchangeContext())); #endif err = CHIP_ERROR_INVALID_ACK_MESSAGE_COUNTER; // Optionally call an application callback with this error. @@ -173,7 +178,10 @@ CHIP_ERROR ReliableMessageContext::HandleRcvdAck(uint32_t ackMessageCounter) else { #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Removed CHIP MessageCounter:%08" PRIX32 " from RetransTable", ackMessageCounter); + ChipLogDetail(ExchangeManager, + "Removed CHIP MessageCounter:" ChipLogFormatMessageCounter + " from RetransTable on exchange " ChipLogFormatExchange, + ackMessageCounter, ChipLogValueExchange(GetExchangeContext())); #endif } @@ -206,7 +214,10 @@ CHIP_ERROR ReliableMessageContext::HandleNeedsAckInner(uint32_t messageCounter, if (messageFlags.Has(MessageFlagValues::kDuplicateMessage)) { #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Forcing tx of solitary ack for duplicate MessageCounter:%08" PRIX32, messageCounter); + ChipLogDetail(ExchangeManager, + "Forcing tx of solitary ack for duplicate MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange, + messageCounter, ChipLogValueExchange(GetExchangeContext())); #endif // Is there pending ack for a different message counter. bool wasAckPending = IsAckPending() && mPendingPeerAckMessageCounter != messageCounter; @@ -235,8 +246,10 @@ CHIP_ERROR ReliableMessageContext::HandleNeedsAckInner(uint32_t messageCounter, if (IsAckPending()) { #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Pending ack queue full; forcing tx of solitary ack for MessageCounter:%08" PRIX32, - mPendingPeerAckMessageCounter); + ChipLogDetail(ExchangeManager, + "Pending ack queue full; forcing tx of solitary ack for MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange, + mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext())); #endif // Send the Ack for the currently pending Ack in a SecureChannel::StandaloneAck message. ReturnErrorOnFailure(SendStandaloneAckMessage()); @@ -262,20 +275,27 @@ CHIP_ERROR ReliableMessageContext::SendStandaloneAckMessage() // Send the null message #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Sending Standalone Ack for MessageCounter:%08" PRIX32, mPendingPeerAckMessageCounter); + ChipLogDetail(ExchangeManager, + "Sending Standalone Ack for MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange, + mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext())); #endif CHIP_ERROR err = GetExchangeContext()->SendMessage(Protocols::SecureChannel::MsgType::StandaloneAck, std::move(msgBuf), BitFlags{ SendMessageFlags::kNoAutoRequestAck }); if (IsSendErrorNonCritical(err)) { - ChipLogError(ExchangeManager, "Non-crit err %" CHIP_ERROR_FORMAT " sending solitary ack", err.Format()); + ChipLogError(ExchangeManager, + "Non-crit err %" CHIP_ERROR_FORMAT " sending solitary ack for MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange, + err.Format(), mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext())); return CHIP_NO_ERROR; } if (err != CHIP_NO_ERROR) { - ChipLogError(ExchangeManager, "Failed to send Solitary ack for MessageCounter:%08" PRIX32 ":%" CHIP_ERROR_FORMAT, - mPendingPeerAckMessageCounter, err.Format()); + ChipLogError(ExchangeManager, + "Failed to send Solitary ack for MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange ":%" CHIP_ERROR_FORMAT, + mPendingPeerAckMessageCounter, ChipLogValueExchange(GetExchangeContext()), err.Format()); } return err; diff --git a/src/messaging/ReliableMessageMgr.cpp b/src/messaging/ReliableMessageMgr.cpp index ad99c66354d071..153d3f1873108d 100644 --- a/src/messaging/ReliableMessageMgr.cpp +++ b/src/messaging/ReliableMessageMgr.cpp @@ -88,8 +88,10 @@ void ReliableMessageMgr::TicklessDebugDumpRetransTable(const char * log) { if (entry.rc) { - ChipLogDetail(ExchangeManager, "EC:%04" PRIX16 " MessageCounter:%08" PRIX32 " NextRetransTimeCtr:%04" PRIX16, entry.rc, - entry.messageCounter, entry.nextRetransTimeTick); + ChipLogDetail(ExchangeManager, + "EC:" ChipLogFormatExchange " MessageCounter:" ChipLogFormatMessageCounter + " NextRetransTimeCtr:%04" PRIX16, + ChipLogValueExchange(entry.rc->GetExchangeContext()), entry.messageCounter, entry.nextRetransTimeTick); } } } @@ -150,8 +152,11 @@ void ReliableMessageMgr::ExecuteActions() { err = CHIP_ERROR_MESSAGE_NOT_ACKNOWLEDGED; - ChipLogError(ExchangeManager, "Failed to Send CHIP MessageCounter:%08" PRIX32 " sendCount: %" PRIu8 " max retries: %d", - messageCounter, sendCount, CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS); + ChipLogError(ExchangeManager, + "Failed to Send CHIP MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange + " sendCount: %" PRIu8 " max retries: %d", + messageCounter, ChipLogValueExchange(rc->GetExchangeContext()), sendCount, + CHIP_CONFIG_RMP_DEFAULT_MAX_RETRANS); // Remove from Table ClearRetransTable(entry); @@ -166,7 +171,10 @@ void ReliableMessageMgr::ExecuteActions() // If the retransmission was successful, update the passive timer entry.nextRetransTimeTick = static_cast(rc->GetActiveRetransmitTimeoutTick()); #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Retransmit MessageCounter:%08" PRIX32 " Send Cnt %d", messageCounter, entry.sendCount); + ChipLogDetail(ExchangeManager, + "Retransmitted MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange + " Send Cnt %d", + messageCounter, ChipLogValueExchange(rc->GetExchangeContext()), entry.sendCount); #endif } } @@ -339,7 +347,10 @@ bool ReliableMessageMgr::CheckAndRemRetransTable(ReliableMessageContext * rc, ui ClearRetransTable(entry); #if !defined(NDEBUG) - ChipLogDetail(ExchangeManager, "Rxd Ack; Removing MessageCounter:%08" PRIX32 " from Retrans Table", ackMessageCounter); + ChipLogDetail(ExchangeManager, + "Rxd Ack; Removing MessageCounter:" ChipLogFormatMessageCounter + " from Retrans Table on exchange " ChipLogFormatExchange, + ackMessageCounter, ChipLogValueExchange(rc->GetExchangeContext())); #endif return true; } @@ -361,8 +372,10 @@ CHIP_ERROR ReliableMessageMgr::SendFromRetransTable(RetransTableEntry * entry) { // Using same error message for all errors to reduce code size. ChipLogError(ExchangeManager, - "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:%08" PRIX32 ", send tries: %d", - CHIP_ERROR_INCORRECT_STATE.Format(), entry->retainedBuf.GetMessageCounter(), entry->sendCount); + "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange ", send tries: %d", + CHIP_ERROR_INCORRECT_STATE.Format(), entry->retainedBuf.GetMessageCounter(), + ChipLogValueExchange(rc->GetExchangeContext()), entry->sendCount); ClearRetransTable(*entry); return CHIP_ERROR_INCORRECT_STATE; } @@ -379,8 +392,10 @@ CHIP_ERROR ReliableMessageMgr::SendFromRetransTable(RetransTableEntry * entry) // Remove from table // Using same error message for all errors to reduce code size. ChipLogError(ExchangeManager, - "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:%08" PRIX32 ", send tries: %d", err.Format(), - entry->retainedBuf.GetMessageCounter(), entry->sendCount); + "Crit-err %" CHIP_ERROR_FORMAT " when sending CHIP MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchange ", send tries: %d", + err.Format(), entry->retainedBuf.GetMessageCounter(), ChipLogValueExchange(rc->GetExchangeContext()), + entry->sendCount); ClearRetransTable(*entry); } diff --git a/src/protocols/bdx/TransferFacilitator.cpp b/src/protocols/bdx/TransferFacilitator.cpp index 3347fa4c0770e4..4a3f2c27b2d66f 100644 --- a/src/protocols/bdx/TransferFacilitator.cpp +++ b/src/protocols/bdx/TransferFacilitator.cpp @@ -37,8 +37,8 @@ CHIP_ERROR TransferFacilitator::OnMessageReceived(chip::Messaging::ExchangeConte mExchangeCtx = ec; } - ChipLogDetail(BDX, "%s: message 0x%x protocol %u", __FUNCTION__, static_cast(payloadHeader.GetMessageType()), - payloadHeader.GetProtocolID().GetProtocolId()); + ChipLogDetail(BDX, "%s: message " ChipLogFormatMessageType " protocol " ChipLogFormatProtocolId, __FUNCTION__, + payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID())); CHIP_ERROR err = mTransfer.HandleMessageReceived(payloadHeader, std::move(payload), System::Clock::GetMonotonicMilliseconds()); if (err != CHIP_NO_ERROR) { diff --git a/src/transport/SecureMessageCodec.cpp b/src/transport/SecureMessageCodec.cpp index 1edc6668a5c4e3..c93fdc787e5a4a 100644 --- a/src/transport/SecureMessageCodec.cpp +++ b/src/transport/SecureMessageCodec.cpp @@ -68,8 +68,6 @@ CHIP_ERROR Encode(Transport::PeerConnectionState * state, PayloadHeader & payloa VerifyOrReturnError(CanCastTo(totalLen + taglen), CHIP_ERROR_INTERNAL); msgBuf->SetDataLength(static_cast(totalLen + taglen)); - ChipLogDetail(Inet, "Secure message was encrypted: Msg ID %" PRIu32, messageCounter); - ReturnErrorOnFailure(counter.Advance()); return CHIP_NO_ERROR; } diff --git a/src/transport/SecureSessionMgr.cpp b/src/transport/SecureSessionMgr.cpp index 41103b38be6ddb..5172d3fb488d70 100644 --- a/src/transport/SecureSessionMgr.cpp +++ b/src/transport/SecureSessionMgr.cpp @@ -111,6 +111,9 @@ CHIP_ERROR SecureSessionMgr::PrepareMessage(SessionHandle session, PayloadHeader packetHeader.SetSecureSessionControlMsg(true); } +#if CHIP_PROGRESS_LOGGING + NodeId destination; +#endif // CHIP_PROGRESS_LOGGING if (session.IsSecure()) { PeerConnectionState * state = GetPeerConnectionState(session); @@ -122,12 +125,9 @@ CHIP_ERROR SecureSessionMgr::PrepareMessage(SessionHandle session, PayloadHeader MessageCounter & counter = GetSendCounterForPacket(payloadHeader, *state); ReturnErrorOnFailure(SecureMessageCodec::Encode(state, payloadHeader, packetHeader, message, counter)); - ChipLogProgress(Inet, - "Build %s message %p to 0x" ChipLogFormatX64 " of type %d and protocolId %" PRIu32 - " on exchange " ChipLogFormatExchangeId " with MessageCounter %" PRIu32 ".", - "encrypted", &preparedMessage, ChipLogValueX64(state->GetPeerNodeId()), payloadHeader.GetMessageType(), - payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), ChipLogValueExchangeIdFromHeader(payloadHeader), - packetHeader.GetMessageCounter()); +#if CHIP_PROGRESS_LOGGING + destination = state->GetPeerNodeId(); +#endif // CHIP_PROGRESS_LOGGING } else { @@ -139,14 +139,19 @@ CHIP_ERROR SecureSessionMgr::PrepareMessage(SessionHandle session, PayloadHeader packetHeader.SetMessageCounter(messageCounter); - ChipLogProgress(Inet, - "Build %s message %p to 0x" ChipLogFormatX64 " of type %d and protocolId %" PRIu32 - " on exchange " ChipLogFormatExchangeId " with MessageCounter %" PRIu32 ".", - "plaintext", &preparedMessage, ChipLogValueX64(kUndefinedNodeId), payloadHeader.GetMessageType(), - payloadHeader.GetProtocolID().ToFullyQualifiedSpecForm(), ChipLogValueExchangeIdFromHeader(payloadHeader), - packetHeader.GetMessageCounter()); +#if CHIP_PROGRESS_LOGGING + destination = kUndefinedNodeId; +#endif // CHIP_PROGRESS_LOGGING } + ChipLogProgress(Inet, + "Prepared %s message %p to 0x" ChipLogFormatX64 " of type " ChipLogFormatMessageType + " and protocolId " ChipLogFormatProtocolId " on exchange " ChipLogFormatExchangeId + " with MessageCounter:" ChipLogFormatMessageCounter ".", + session.IsSecure() ? "encrypted" : "plaintext", &preparedMessage, ChipLogValueX64(destination), + payloadHeader.GetMessageType(), ChipLogValueProtocolId(payloadHeader.GetProtocolID()), + ChipLogValueExchangeIdFromSentHeader(payloadHeader), packetHeader.GetMessageCounter()); + ReturnErrorOnFailure(packetHeader.EncodeBeforeData(message)); preparedMessage = EncryptedPacketBufferHandle::MarkEncrypted(std::move(message)); @@ -175,8 +180,11 @@ CHIP_ERROR SecureSessionMgr::SendPreparedMessage(SessionHandle session, const En destination = &state->GetPeerAddress(); - ChipLogProgress(Inet, "Sending %s msg %p to 0x" ChipLogFormatX64 " at utc time: %" PRId64 " msec", "encrypted", - &preparedMessage, ChipLogValueX64(state->GetPeerNodeId()), System::Clock::GetMonotonicMilliseconds()); + ChipLogProgress(Inet, + "Sending %s msg %p with MessageCounter:" ChipLogFormatMessageCounter " to 0x" ChipLogFormatX64 + " at monotonic time: %" PRId64 " msec", + "encrypted", &preparedMessage, preparedMessage.GetMessageCounter(), ChipLogValueX64(state->GetPeerNodeId()), + System::Clock::GetMonotonicMilliseconds()); } else { @@ -184,8 +192,11 @@ CHIP_ERROR SecureSessionMgr::SendPreparedMessage(SessionHandle session, const En mUnauthenticatedSessions.MarkSessionActive(unauthenticated.Get()); destination = &unauthenticated->GetPeerAddress(); - ChipLogProgress(Inet, "Sending %s msg %p to 0x" ChipLogFormatX64 " at utc time: %" PRId64 " msec", "plaintext", - &preparedMessage, ChipLogValueX64(kUndefinedNodeId), System::Clock::GetMonotonicMilliseconds()); + ChipLogProgress(Inet, + "Sending %s msg %p with MessageCounter:" ChipLogFormatMessageCounter " to 0x" ChipLogFormatX64 + " at monotonic time: %" PRId64 " msec", + "plaintext", &preparedMessage, preparedMessage.GetMessageCounter(), ChipLogValueX64(kUndefinedNodeId), + System::Clock::GetMonotonicMilliseconds()); } PacketBufferHandle msgBuf = preparedMessage.CastToWritable(); @@ -194,7 +205,6 @@ CHIP_ERROR SecureSessionMgr::SendPreparedMessage(SessionHandle session, const En if (mTransportMgr != nullptr) { - ChipLogProgress(Inet, "Sending msg on generic transport"); return mTransportMgr->SendMessage(*destination, std::move(msgBuf)); } else @@ -342,7 +352,6 @@ void SecureSessionMgr::MessageDispatch(const PacketHeader & packetHeader, const CHIP_ERROR err = session->GetPeerMessageCounter().VerifyOrTrustFirst(packetHeader.GetMessageCounter()); if (err == CHIP_ERROR_DUPLICATE_MESSAGE_RECEIVED) { - ChipLogDetail(Inet, "Received a duplicate message with MessageCounter: %" PRIu32, packetHeader.GetMessageCounter()); isDuplicate = SecureSessionMgrDelegate::DuplicateMessage::Yes; err = CHIP_NO_ERROR; } @@ -353,6 +362,14 @@ void SecureSessionMgr::MessageDispatch(const PacketHeader & packetHeader, const PayloadHeader payloadHeader; ReturnOnFailure(payloadHeader.DecodeAndConsume(msg)); + if (isDuplicate == SecureSessionMgrDelegate::DuplicateMessage::Yes) + { + ChipLogDetail(Inet, + "Received a duplicate message with MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchangeId, + packetHeader.GetMessageCounter(), ChipLogValueExchangeIdFromSentHeader(payloadHeader)); + } + session->GetPeerMessageCounter().Commit(packetHeader.GetMessageCounter()); if (mCB != nullptr) @@ -415,7 +432,6 @@ void SecureSessionMgr::SecureMessageDispatch(const PacketHeader & packetHeader, err = state->GetSessionMessageCounter().GetPeerMessageCounter().Verify(packetHeader.GetMessageCounter()); if (err == CHIP_ERROR_DUPLICATE_MESSAGE_RECEIVED) { - ChipLogDetail(Inet, "Received a duplicate message with MessageCounter: %" PRIu32, packetHeader.GetMessageCounter()); isDuplicate = SecureSessionMgrDelegate::DuplicateMessage::Yes; err = CHIP_NO_ERROR; } @@ -432,11 +448,18 @@ void SecureSessionMgr::SecureMessageDispatch(const PacketHeader & packetHeader, VerifyOrExit(CHIP_NO_ERROR == SecureMessageCodec::Decode(state, payloadHeader, packetHeader, msg), ChipLogError(Inet, "Secure transport received message, but failed to decode it, discarding")); - if (isDuplicate == SecureSessionMgrDelegate::DuplicateMessage::Yes && !payloadHeader.NeedsAck()) + if (isDuplicate == SecureSessionMgrDelegate::DuplicateMessage::Yes) { - // If it's a duplicate message, but doesn't require an ack, let's drop it right here to save CPU - // cycles on further message processing. - ExitNow(err = CHIP_NO_ERROR); + ChipLogDetail(Inet, + "Received a duplicate message with MessageCounter:" ChipLogFormatMessageCounter + " on exchange " ChipLogFormatExchangeId, + packetHeader.GetMessageCounter(), ChipLogValueExchangeIdFromSentHeader(payloadHeader)); + if (!payloadHeader.NeedsAck()) + { + // If it's a duplicate message, but doesn't require an ack, let's drop it right here to save CPU + // cycles on further message processing. + ExitNow(err = CHIP_NO_ERROR); + } } if (packetHeader.GetFlags().Has(Header::FlagValues::kSecureSessionControlMessage))