[address-resolver] update/add logs in AddressResolver (#2196)

src/core/thread/address_resolver.cpp

@@ -104,7 +104,7 @@ void AddressResolver::Remove(uint8_t routerId)
     {
         if (Mle::Mle::GetRouterId(mCache[i].mRloc16) == routerId)
         {
-            InvalidateCacheEntry(mCache[i]);
+            InvalidateCacheEntry(mCache[i], kReasonRemovingRouterId);
         }
     }
 }
@@ -128,7 +128,7 @@ AddressResolver::Cache *AddressResolver::NewCacheEntry(void)
 
     if (rval != NULL)
     {
-        InvalidateCacheEntry(*rval);
+        InvalidateCacheEntry(*rval, kReasonEvictingForNewEntry);
     }
 
     return rval;
@@ -147,8 +147,32 @@ void AddressResolver::MarkCacheEntryAsUsed(Cache &aEntry)
     aEntry.mAge = 0;
 }
 
-void AddressResolver::InvalidateCacheEntry(Cache &aEntry)
+const char *AddressResolver::ConvertInvalidationReasonToString(InvalidationReason aReason)
 {
+    const char *str = "";
+
+    switch (aReason)
+    {
+    case kReasonRemovingRouterId:
+        str = "removing router id";
+        break;
+
+    case kReasonReceivedIcmpDstUnreachNoRoute:
+        str = "received icmp no route";
+        break;
+
+    case kReasonEvictingForNewEntry:
+        str = "evicting for new entry";
+        break;
+    }
+
+    return str;
+}
+
+void AddressResolver::InvalidateCacheEntry(Cache &aEntry, InvalidationReason aReason)
+{
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
+
     for (int i = 0; i < kCacheEntries; i++)
     {
         if (mCache[i].mAge > aEntry.mAge)
@@ -157,9 +181,29 @@ void AddressResolver::InvalidateCacheEntry(Cache &aEntry)
         }
     }
 
+    switch (aEntry.mState)
+    {
+    case Cache::kStateCached:
+        otLogInfoArp(GetInstance(), "Cache entry removed: %s, 0x%04x - %s",
+                     aEntry.mTarget.ToString(stringBuffer, sizeof(stringBuffer)), aEntry.mRloc16,
+                     ConvertInvalidationReasonToString(aReason));
+        break;
+
+    case Cache::kStateQuery:
+        otLogInfoArp(GetInstance(), "Cache entry (query mode) removed: %s, timeout:%d, retry:%d - %s",
+                     aEntry.mTarget.ToString(stringBuffer, sizeof(stringBuffer)), aEntry.mTimeout,
+                     aEntry.mRetryTimeout, ConvertInvalidationReasonToString(aReason));
+        break;
+
+    default:
+        break;
+    }
+
     aEntry.mAge = kCacheEntries - 1;
     aEntry.mState = Cache::kStateInvalid;
-    otLogInfoArp(GetInstance(), "cache entry removed!");
+
+    OT_UNUSED_VARIABLE(stringBuffer);
+    OT_UNUSED_VARIABLE(aReason);
 }
 
 otError AddressResolver::Resolve(const Ip6::Address &aEid, uint16_t &aRloc16)
@@ -235,6 +279,7 @@ otError AddressResolver::SendAddressQuery(const Ip6::Address &aEid)
     Coap::Header header;
     ThreadTargetTlv targetTlv;
     Ip6::MessageInfo messageInfo;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     header.Init(OT_COAP_TYPE_NON_CONFIRMABLE, OT_COAP_CODE_POST);
     header.AppendUriPathOptions(OT_URI_PATH_ADDRESS_QUERY);
@@ -254,7 +299,9 @@ otError AddressResolver::SendAddressQuery(const Ip6::Address &aEid)
 
     SuccessOrExit(error = netif.GetCoap().SendMessage(*message, messageInfo));
 
-    otLogInfoArp(GetInstance(), "Sent address query");
+    otLogInfoArp(GetInstance(), "Sending address query for %s", aEid.ToString(stringBuffer, sizeof(stringBuffer)));
+
+    OT_UNUSED_VARIABLE(stringBuffer);
 
 exit:
 
@@ -288,13 +335,11 @@ void AddressResolver::HandleAddressNotification(Coap::Header &aHeader, Message &
     ThreadRloc16Tlv rloc16Tlv;
     ThreadLastTransactionTimeTlv lastTransactionTimeTlv;
     uint32_t lastTransactionTime;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     VerifyOrExit(aHeader.GetType() == OT_COAP_TYPE_CONFIRMABLE &&
                  aHeader.GetCode() == OT_COAP_CODE_POST);
 
-    otLogInfoArp(GetInstance(), "Received address notification from %04x",
-                 HostSwap16(aMessageInfo.GetPeerAddr().mFields.m16[7]));
-
     SuccessOrExit(ThreadTlv::GetTlv(aMessage, ThreadTlv::kTarget, sizeof(targetTlv), targetTlv));
     VerifyOrExit(targetTlv.IsValid());
 
@@ -313,6 +358,10 @@ void AddressResolver::HandleAddressNotification(Coap::Header &aHeader, Message &
         lastTransactionTime = lastTransactionTimeTlv.GetTime();
     }
 
+    otLogInfoArp(GetInstance(), "Received address notification from 0x%04x for %s to 0x%04x",
+                 HostSwap16(aMessageInfo.GetPeerAddr().mFields.m16[7]),
+                 targetTlv.GetTarget()->ToString(stringBuffer, sizeof(stringBuffer)), rloc16Tlv.GetRloc16());
+
     for (int i = 0; i < kCacheEntries; i++)
     {
         if (mCache[i].mTarget != *targetTlv.GetTarget())
@@ -349,9 +398,12 @@ void AddressResolver::HandleAddressNotification(Coap::Header &aHeader, Message &
             mCache[i].mState = Cache::kStateCached;
             MarkCacheEntryAsUsed(mCache[i]);
 
+            otLogInfoArp(GetInstance(), "Cache entry updated: %s, 0x%04x, lastTrans:%d", stringBuffer,
+                         rloc16Tlv.GetRloc16(), lastTransactionTime);
+
             if (netif.GetCoap().SendEmptyAck(aHeader, aMessageInfo) == OT_ERROR_NONE)
             {
-                otLogInfoArp(GetInstance(), "Sent address notification acknowledgment");
+                otLogInfoArp(GetInstance(), "Sending address notification acknowledgment");
             }
 
             netif.GetMeshForwarder().HandleResolved(*targetTlv.GetTarget(), OT_ERROR_NONE);
@@ -359,6 +411,8 @@ void AddressResolver::HandleAddressNotification(Coap::Header &aHeader, Message &
         }
     }
 
+    OT_UNUSED_VARIABLE(stringBuffer);
+
 exit:
     return;
 }
@@ -371,6 +425,7 @@ otError AddressResolver::SendAddressError(const ThreadTargetTlv &aTarget, const
     Message *message;
     Coap::Header header;
     Ip6::MessageInfo messageInfo;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     header.Init(aDestination == NULL ? OT_COAP_TYPE_NON_CONFIRMABLE : OT_COAP_TYPE_CONFIRMABLE,
                 OT_COAP_CODE_POST);
@@ -398,7 +453,10 @@ otError AddressResolver::SendAddressError(const ThreadTargetTlv &aTarget, const
 
     SuccessOrExit(error = netif.GetCoap().SendMessage(*message, messageInfo));
 
-    otLogInfoArp(GetInstance(), "Sent address error");
+    otLogInfoArp(GetInstance(), "Sending address error for target %s",
+                 aTarget.GetTarget()->ToString(stringBuffer, sizeof(stringBuffer)));
+
+    OT_UNUSED_VARIABLE(stringBuffer);
 
 exit:
 
@@ -418,8 +476,7 @@ void AddressResolver::HandleAddressError(void *aContext, otCoapHeader *aHeader,
         *static_cast<const Ip6::MessageInfo *>(aMessageInfo));
 }
 
-void AddressResolver::HandleAddressError(Coap::Header &aHeader, Message &aMessage,
-                                         const Ip6::MessageInfo &aMessageInfo)
+void AddressResolver::HandleAddressError(Coap::Header &aHeader, Message &aMessage, const Ip6::MessageInfo &aMessageInfo)
 {
     ThreadNetif &netif = GetNetif();
     otError error = OT_ERROR_NONE;
@@ -518,12 +575,11 @@ void AddressResolver::HandleAddressQuery(Coap::Header &aHeader, Message &aMessag
     ThreadLastTransactionTimeTlv lastTransactionTimeTlv;
     Child *children;
     uint8_t numChildren;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     VerifyOrExit(aHeader.GetType() == OT_COAP_TYPE_NON_CONFIRMABLE &&
                  aHeader.GetCode() == OT_COAP_CODE_POST);
 
-    otLogInfoArp(GetInstance(), "Received address query from %04x", HostSwap16(aMessageInfo.GetPeerAddr().mFields.m16[7]));
-
     SuccessOrExit(ThreadTlv::GetTlv(aMessage, ThreadTlv::kTarget, sizeof(targetTlv), targetTlv));
     VerifyOrExit(targetTlv.IsValid());
 
@@ -531,6 +587,10 @@ void AddressResolver::HandleAddressQuery(Coap::Header &aHeader, Message &aMessag
 
     lastTransactionTimeTlv.Init();
 
+    otLogInfoArp(GetInstance(), "Received address query from 0x%04x for target %s",
+                 HostSwap16(aMessageInfo.GetPeerAddr().mFields.m16[7]),
+                 targetTlv.GetTarget()->ToString(stringBuffer, sizeof(stringBuffer)));
+
     if (netif.IsUnicastAddress(*targetTlv.GetTarget()))
     {
         mlIidTlv.SetIid(netif.GetMle().GetMeshLocal64().GetIid());
@@ -563,6 +623,8 @@ void AddressResolver::HandleAddressQuery(Coap::Header &aHeader, Message &aMessag
         }
     }
 
+    OT_UNUSED_VARIABLE(stringBuffer);
+
 exit:
     return;
 }
@@ -578,6 +640,7 @@ void AddressResolver::SendAddressQueryResponse(const ThreadTargetTlv &aTargetTlv
     Coap::Header header;
     ThreadRloc16Tlv rloc16Tlv;
     Ip6::MessageInfo messageInfo;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     header.Init(OT_COAP_TYPE_CONFIRMABLE, OT_COAP_CODE_POST);
     header.AppendUriPathOptions(OT_URI_PATH_ADDRESS_NOTIFY);
@@ -603,7 +666,10 @@ void AddressResolver::SendAddressQueryResponse(const ThreadTargetTlv &aTargetTlv
 
     SuccessOrExit(error = netif.GetCoap().SendMessage(*message, messageInfo));
 
-    otLogInfoArp(GetInstance(), "Sent address notification");
+    otLogInfoArp(GetInstance(), "Sending address notification for target %s",
+                 aTargetTlv.GetTarget()->ToString(stringBuffer, sizeof(stringBuffer)));
+
+    OT_UNUSED_VARIABLE(stringBuffer);
 
 exit:
 
@@ -618,9 +684,10 @@ void AddressResolver::HandleTimer(Timer &aTimer)
     GetOwner(aTimer).HandleTimer();
 }
 
-void AddressResolver::HandleTimer()
+void AddressResolver::HandleTimer(void)
 {
     bool continueTimer = false;
+    char stringBuffer[Ip6::Address::kIp6AddressStringSize];
 
     for (int i = 0; i < kCacheEntries; i++)
     {
@@ -649,6 +716,9 @@ void AddressResolver::HandleTimer()
                     mCache[i].mRetryTimeout = kAddressQueryMaxRetryDelay;
                 }
 
+                otLogInfoArp(GetInstance(), "Timed out waiting for address notification for %s, retry: %d",
+                             mCache[i].mTarget.ToString(stringBuffer, sizeof(stringBuffer)), mCache[i].mRetryTimeout);
+
                 GetNetif().GetMeshForwarder().HandleResolved(mCache[i].mTarget, OT_ERROR_DROP);
             }
         }
@@ -662,6 +732,8 @@ void AddressResolver::HandleTimer()
     {
         mTimer.Start(kStateUpdatePeriod);
     }
+
+    OT_UNUSED_VARIABLE(stringBuffer);
 }
 
 void AddressResolver::HandleIcmpReceive(void *aContext, otMessage *aMessage, const otMessageInfo *aMessageInfo,
@@ -688,7 +760,7 @@ void AddressResolver::HandleIcmpReceive(Message &aMessage, const Ip6::MessageInf
         if (mCache[i].mState != Cache::kStateInvalid &&
             memcmp(&mCache[i].mTarget, &ip6Header.GetDestination(), sizeof(mCache[i].mTarget)) == 0)
         {
-            InvalidateCacheEntry(mCache[i]);
+            InvalidateCacheEntry(mCache[i], kReasonReceivedIcmpDstUnreachNoRoute);
             break;
         }
     }

src/core/thread/address_resolver.hpp

@@ -150,9 +150,18 @@ private:
         State             mState;
     };
 
+    enum InvalidationReason
+    {
+        kReasonRemovingRouterId,
+        kReasonReceivedIcmpDstUnreachNoRoute,
+        kReasonEvictingForNewEntry,
+    };
+
+    static const char *ConvertInvalidationReasonToString(InvalidationReason aReason);
+
     Cache *NewCacheEntry(void);
     void MarkCacheEntryAsUsed(Cache &aEntry);
-    void InvalidateCacheEntry(Cache &aEntry);
+    void InvalidateCacheEntry(Cache &aEntry, InvalidationReason aReason);
 
     otError SendAddressQuery(const Ip6::Address &aEid);
     otError SendAddressError(const ThreadTargetTlv &aTarget, const ThreadMeshLocalEidTlv &aEid,