Add detailed logs for a received, transmitted, or dropped IPv6 message (#1515)

This commit adds detailed logs (at `info` level) when an IPv6
message is received, transmitted or dropped (due to tx failures).
The log contains the following information about the IPv6 message:

- The message length (in bytes),
- The protocol (TCP/UDP/ICMP6, etc.),
- Checksum value for UDP or TCP,
- MAC address of source/dest (short or extended address),
- Message security (enabled/disabled),
- Message's source and destination IPv6 addresses,
- In case of tx failure, error causing the drop (CCA, No Ack, ...).

src/core/mac/mac_frame.cpp

@@ -31,6 +31,15 @@
  *   This file implements IEEE 802.15.4 header generation and processing.
  */
 
+#ifdef OPENTHREAD_CONFIG_FILE
+#include OPENTHREAD_CONFIG_FILE
+#else
+#include <openthread-config.h>
+#endif
+
+#include <stdio.h>
+#include <string.h>
+
 #include <common/code_utils.hpp>
 #include <common/debug.hpp>
 #include <mac/mac_frame.hpp>
@@ -45,6 +54,28 @@ void ExtAddress::Set(const Ip6::Address &aIpAddress)
     m8[0] ^= 0x02;
 }
 
+const char *Address::ToString(char *aBuf, uint16_t aSize) const
+{
+    switch (mLength)
+    {
+    case sizeof(ShortAddress):
+        snprintf(aBuf, aSize, "0x%04x", mShortAddress);
+        break;
+
+    case sizeof(ExtAddress):
+        snprintf(aBuf, aSize, "%02x:%02x:%02x:%02x:%02x:%02x:%02x:%02x",
+                 mExtAddress.m8[0], mExtAddress.m8[1], mExtAddress.m8[2], mExtAddress.m8[3],
+                 mExtAddress.m8[4], mExtAddress.m8[5], mExtAddress.m8[6], mExtAddress.m8[7]);
+        break;
+
+    default:
+        snprintf(aBuf, aSize, "Unknown");
+        break;
+    }
+
+    return aBuf;
+}
+
 ThreadError Frame::InitMacHeader(uint16_t aFcf, uint8_t aSecurityControl)
 {
     uint8_t *bytes = GetPsdu();

src/core/mac/mac_frame.hpp

@@ -154,12 +154,28 @@ private:
  */
 struct Address
 {
+    enum
+    {
+        kAddressStringSize =  24,    ///< Max chars needed for a string representation of address (@sa ToString()).
+    };
+
     uint8_t mLength;                 ///< Length of address in bytes.
     union
     {
         ShortAddress mShortAddress;  ///< The IEEE 802.15.4 Short Address.
         ExtAddress mExtAddress;      ///< The IEEE 802.15.4 Extended Address.
     };
+
+    /**
+     * This method converts an address object to a NULL-terminated string.
+     *
+     * @param[out]  aBuf   A pointer to the buffer.
+     * @param[in]   aSize  The maximum size of the buffer.
+     *
+     * @returns A pointer to the char string buffer.
+     *
+     */
+    const char *ToString(char *aBuf, uint16_t aSize) const;
 };
 
 /**

src/core/net/ip6.cpp

@@ -1074,5 +1074,55 @@ otInstance *Ip6::GetInstance(void)
     return otInstanceFromIp6(this);
 }
 
+const char *Ip6::IpProtoToString(IpProto aIpProto)
+{
+    const char *retval;
+
+    switch (aIpProto)
+    {
+    case kProtoHopOpts:
+        retval = "HopOpts";
+        break;
+
+    case kProtoTcp:
+        retval = "TCP";
+        break;
+
+    case kProtoUdp:
+        retval = "UDP";
+        break;
+
+    case kProtoIp6:
+        retval = "IP6";
+        break;
+
+    case kProtoRouting:
+        retval = "Routing";
+        break;
+
+    case kProtoFragment:
+        retval = "Frag";
+        break;
+
+    case kProtoIcmp6:
+        retval = "ICMP6";
+        break;
+
+    case kProtoNone:
+        retval = "None";
+        break;
+
+    case kProtoDstOpts:
+        retval = "DstOpts";
+        break;
+
+    default:
+        retval = "Unknown";
+        break;
+    }
+
+    return retval;
+}
+
 }  // namespace Ip6
 }  // namespace Thread

src/core/net/ip6.hpp

@@ -347,6 +347,14 @@ public:
      */
     const PriorityQueue &GetSendQueue(void) const { return mSendQueue; }
 
+    /**
+     * This static method converts an `IpProto` enumeration to a string.
+     *
+     * @returns The string representation of an IP protocol enumeration.
+     *
+     */
+    static const char *IpProtoToString(IpProto aIpProto);
+
     Routes mRoutes;
     Icmp mIcmp;
     Udp mUdp;

src/core/net/ip6_address.cpp

@@ -297,6 +297,7 @@ const char *Address::ToString(char *aBuf, uint16_t aSize) const
              HostSwap16(mFields.m16[2]), HostSwap16(mFields.m16[3]),
              HostSwap16(mFields.m16[4]), HostSwap16(mFields.m16[5]),
              HostSwap16(mFields.m16[6]), HostSwap16(mFields.m16[7]));
+
     return aBuf;
 }
 

src/core/net/ip6_address.hpp

@@ -63,6 +63,7 @@ public:
     enum
     {
         kInterfaceIdentifierSize   = 8,  ///< Interface Identifier size in bytes.
+        kIp6AddressStringSize      = 40, ///< Max buffer size in bytes to store an IPv6 address in string format.
     };
 
     /**

src/core/thread/mesh_forwarder.cpp

@@ -42,9 +42,9 @@
 #include <common/message.hpp>
 #include <net/ip6.hpp>
 #include <net/ip6_filter.hpp>
+#include <net/tcp.hpp>
 #include <net/udp6.hpp>
 #include <net/netif.hpp>
-#include <net/udp6.hpp>
 #include <thread/mesh_forwarder.hpp>
 #include <thread/mle_router.hpp>
 #include <thread/mle.hpp>
@@ -91,7 +91,7 @@ MeshForwarder::MeshForwarder(ThreadNetif &aThreadNetif):
     mMacDest.mLength = 0;
 }
 
-otInstance *MeshForwarder::GetInstance()
+otInstance *MeshForwarder::GetInstance(void)
 {
     return mNetif.GetInstance();
 }
@@ -1778,6 +1778,11 @@ void MeshForwarder::HandleSentFrame(Mac::Frame &aFrame, ThreadError aError)
         }
     }
 
+    if (mMessageNextOffset >= mSendMessage->GetLength())
+    {
+        LogIp6Message(kMessageTransmit, *mSendMessage, macDest, aError);
+    }
+
     if (mSendMessage->GetDirectTransmission() == false && mSendMessage->IsChildPending() == false)
     {
         mSendQueue.Dequeue(*mSendMessage);
@@ -2121,7 +2126,7 @@ exit:
         if (message->GetOffset() >= message->GetLength())
         {
             mReassemblyList.Dequeue(*message);
-            HandleDatagram(*message, aMessageInfo);
+            HandleDatagram(*message, aMessageInfo, aMacSource);
         }
     }
     else
@@ -2209,7 +2214,7 @@ exit:
 
     if (error == kThreadError_None)
     {
-        HandleDatagram(*message, aMessageInfo);
+        HandleDatagram(*message, aMessageInfo, aMacSource);
     }
     else
     {
@@ -2222,8 +2227,11 @@ exit:
     }
 }
 
-ThreadError MeshForwarder::HandleDatagram(Message &aMessage, const ThreadMessageInfo &aMessageInfo)
+ThreadError MeshForwarder::HandleDatagram(Message &aMessage, const ThreadMessageInfo &aMessageInfo,
+                                          const Mac::Address &aMacSource)
 {
+    LogIp6Message(kMessageReceive, aMessage, aMacSource, kThreadError_None);
+
     return mNetif.GetIp6().HandleDatagram(aMessage, &mNetif, mNetif.GetInterfaceId(), &aMessageInfo, false);
 }
 
@@ -2270,4 +2278,75 @@ void MeshForwarder::HandleDataPollTimeout(void)
     }
 }
 
+#if OPENTHREAD_CONFIG_LOG_LEVEL >= OPENTHREAD_LOG_LEVEL_INFO
+
+void MeshForwarder::LogIp6Message(MessageAction aAction, const Message &aMessage, const Mac::Address &aMacAddress,
+                                  ThreadError aError)
+{
+    uint16_t checksum = 0;
+    Ip6::Header ip6Header;
+    Ip6::IpProto protocol;
+    char stringBuffer[(Ip6::Address::kIp6AddressStringSize > Mac::Address::kAddressStringSize) ?
+                      Ip6::Address::kIp6AddressStringSize : Mac::Address::kAddressStringSize];
+
+    VerifyOrExit(aMessage.GetType() == Message::kTypeIp6, ;);
+
+    VerifyOrExit(sizeof(ip6Header) == aMessage.Read(0, sizeof(ip6Header), &ip6Header), ;);
+    VerifyOrExit(ip6Header.IsVersion6(), ;);
+
+    protocol = ip6Header.GetNextHeader();
+
+    switch (protocol)
+    {
+    case Ip6::kProtoUdp:
+    {
+        Ip6::UdpHeader udpHeader;
+
+        VerifyOrExit(sizeof(udpHeader) == aMessage.Read(sizeof(ip6Header), sizeof(udpHeader), &udpHeader), ;);
+        checksum = udpHeader.GetChecksum();
+        break;
+    }
+
+    case Ip6::kProtoTcp:
+    {
+        Ip6::TcpHeader tcpHeader;
+
+        VerifyOrExit(sizeof(tcpHeader) == aMessage.Read(sizeof(ip6Header), sizeof(tcpHeader), &tcpHeader), ;);
+        checksum = tcpHeader.GetChecksum();
+        break;
+    }
+
+    default:
+        break;
+    }
+
+    otLogInfoMac(
+        GetInstance(),
+        "%s IPv6 %s msg, len:%d, chksum:%04x, %s:%s, sec:%s%s%s",
+        (aAction == kMessageReceive) ? "Rx" : ((aError == kThreadError_None) ? "Tx" : "Failed to Tx"),
+        Ip6::Ip6::IpProtoToString(protocol),
+        aMessage.GetLength(),
+        checksum,
+        (aAction == kMessageReceive) ? "from" : "to",
+        aMacAddress.ToString(stringBuffer, sizeof(stringBuffer)),
+        aMessage.IsLinkSecurityEnabled() ? "yes" : "no",
+        (aError == kThreadError_None) ? "" : ", error:",
+        (aError == kThreadError_None) ? "" : otThreadErrorToString(aError)
+    );
+
+    otLogInfoMac(GetInstance(), "src: %s", ip6Header.GetSource().ToString(stringBuffer, sizeof(stringBuffer)));
+    otLogInfoMac(GetInstance(), "dst: %s", ip6Header.GetDestination().ToString(stringBuffer, sizeof(stringBuffer)));
+
+exit:
+    return;
+}
+
+#else // #if OPENTHREAD_CONFIG_LOG_LEVEL >= OPENTHREAD_LOG_LEVEL_INFO
+
+void MeshForwarder::LogIp6Message(MessageAction, const Message &, const Mac::Address &, ThreadError)
+{
+}
+
+#endif //#if OPENTHREAD_CONFIG_LOG_LEVEL >= OPENTHREAD_LOG_LEVEL_INFO
+
 }  // namespace Thread

src/core/thread/mesh_forwarder.hpp

@@ -277,6 +277,12 @@ private:
         kMaxPollTriggeredTxAttempts = OPENTHREAD_CONFIG_MAX_TX_ATTEMPTS_INDIRECT_POLLS,
     };
 
+    enum MessageAction              ///< Defines the action parameter in `LogMessageInfo()` method.
+    {
+        kMessageReceive,            ///< Indicates that the message was received.
+        kMessageTransmit,           ///< Indicates that the message was sent.
+    };
+
     ThreadError CheckReachability(uint8_t *aFrame, uint8_t aFrameLength,
                                   const Mac::Address &aMeshSource, const Mac::Address &aMeshDest);
 
@@ -301,7 +307,8 @@ private:
     ThreadError SendEmptyFrame(Mac::Frame &aFrame);
     ThreadError UpdateIp6Route(Message &aMessage);
     ThreadError UpdateMeshRoute(Message &aMessage);
-    ThreadError HandleDatagram(Message &aMessage, const ThreadMessageInfo &aMessageInfo);
+    ThreadError HandleDatagram(Message &aMessage, const ThreadMessageInfo &aMessageInfo,
+                               const Mac::Address &aMacSource);
     void ClearReassemblyList(void);
 
     static void HandleReceivedFrame(void *aContext, Mac::Frame &aFrame);
@@ -330,6 +337,9 @@ private:
     ThreadError AddSrcMatchEntry(Child &aChild);
     void ClearSrcMatchEntry(Child &aChild);
 
+    void LogIp6Message(MessageAction aAction, const Message &aMessage, const Mac::Address &aMacAddress,
+                       ThreadError aError);
+
     Mac::Receiver mMacReceiver;
     Mac::Sender mMacSender;
     Timer mDiscoverTimer;