Add/Update the logs in Mac class (#1629)

This commit contains the following changes:

- Updates logs for a failed tx or rx to include info about the
  frame (len, seq number, type, src/dst address, etc.).

- Adds detailed logs about transmitted or received Beacon frames
  (network name, xpanid, protocol id, version, joinability, native
  flag, ...)

- Adds helper method `ToInfoString()` to `Frame` and `BeaconPyalod`
  classes to provide a debug info string representation of the
  object.

include/openthread/types.h

@@ -193,6 +193,7 @@ typedef enum ThreadError
      * Received a duplicated frame.
      */
     kThreadError_Duplicated = 31,
+
     kThreadError_Error = 255,
 } ThreadError;
 

src/core/api/link_api.cpp

@@ -308,7 +308,7 @@ void HandleActiveScanResult(void *aContext, Mac::Frame *aFrame)
     otActiveScanResult result;
 
     VerifyOrExit(aFrame != NULL, aInstance->mActiveScanCallback(NULL, aInstance->mActiveScanCallbackContext));
-    Mac::Mac::ConvertBeaconToActiveScanResult(aFrame, result);
+    aInstance->mThreadNetif.GetMac().ConvertBeaconToActiveScanResult(aFrame, result);
     aInstance->mActiveScanCallback(&result, aInstance->mActiveScanCallbackContext);
 
 exit:

src/core/mac/mac.cpp

@@ -270,6 +270,7 @@ ThreadError Mac::ConvertBeaconToActiveScanResult(Frame *aBeaconFrame, otActiveSc
     Beacon *beacon = NULL;
     BeaconPayload *beaconPayload = NULL;
     uint8_t payloadLength;
+    char stringBuffer[BeaconPayload::kInfoStringSize];
 
     memset(&aResult, 0, sizeof(otActiveScanResult));
 
@@ -299,6 +300,10 @@ ThreadError Mac::ConvertBeaconToActiveScanResult(Frame *aBeaconFrame, otActiveSc
         memcpy(&aResult.mExtendedPanId, beaconPayload->GetExtendedPanId(), sizeof(aResult.mExtendedPanId));
     }
 
+    otLogInfoMac(GetInstance(), "Received Beacon, %s", beaconPayload->ToInfoString(stringBuffer, sizeof(stringBuffer)));
+
+    (void)stringBuffer;
+
 exit:
     return error;
 }
@@ -634,7 +639,7 @@ void Mac::SendBeaconRequest(Frame &aFrame)
     aFrame.SetDstAddr(kShortAddrBroadcast);
     aFrame.SetCommandId(Frame::kMacCmdBeaconRequest);
 
-    otLogDebgMac(GetInstance(), "Sent Beacon Request");
+    otLogInfoMac(GetInstance(), "Sending Beacon Request");
 }
 
 void Mac::SendBeacon(Frame &aFrame)
@@ -644,6 +649,7 @@ void Mac::SendBeacon(Frame &aFrame)
     uint16_t fcf;
     Beacon *beacon = NULL;
     BeaconPayload *beaconPayload = NULL;
+    char stringBuffer[BeaconPayload::kInfoStringSize];
 
     // initialize MAC header
     fcf = Frame::kFcfFrameBeacon | Frame::kFcfDstAddrNone | Frame::kFcfSrcAddrExt;
@@ -682,7 +688,9 @@ void Mac::SendBeacon(Frame &aFrame)
 
     aFrame.SetPayloadLength(beaconLength);
 
-    otLogDebgMac(GetInstance(), "Sent Beacon");
+    otLogInfoMac(GetInstance(), "Sending Beacon, %s", beaconPayload->ToInfoString(stringBuffer, sizeof(stringBuffer)));
+
+    (void)stringBuffer;
 }
 
 void Mac::ProcessTransmitSecurity(Frame &aFrame)
@@ -836,7 +844,7 @@ void Mac::HandleBeginTransmit(void)
     if (sendFrame.GetAckRequest() && !(otPlatRadioGetCaps(GetInstance()) & kRadioCapsAckTimeout))
     {
         mMacTimer.Start(kAckTimeout);
-        otLogDebgMac(GetInstance(), "ack timer start");
+        otLogDebgMac(GetInstance(), "Ack timer start");
     }
 
     if (mPcapCallback)
@@ -976,7 +984,7 @@ void Mac::HandleMacTimer(void)
         break;
 
     case kStateTransmitData:
-        otLogDebgMac(GetInstance(), "ack timer fired");
+        otLogDebgMac(GetInstance(), "Ack timer fired");
         otPlatRadioReceive(GetInstance(), mChannel);
         mCounters.mTxTotal++;
 
@@ -1012,7 +1020,7 @@ void Mac::HandleReceiveTimer(void *aContext)
 
 void Mac::HandleReceiveTimer(void)
 {
-    otLogDebgMac(GetInstance(), "data poll timeout!");
+    otLogDebgMac(GetInstance(), "Data poll timeout");
 
     for (Receiver *receiver = mReceiveHead; receiver; receiver = receiver->mNext)
     {
@@ -1029,7 +1037,6 @@ void Mac::SentFrame(ThreadError aError)
 {
     Frame &sendFrame(*mTxFrame);
     Sender *sender;
-    Address dstAddr;
 
     mTransmitAttempts++;
 
@@ -1041,33 +1048,12 @@ void Mac::SentFrame(ThreadError aError)
     case kThreadError_ChannelAccessFailure:
     case kThreadError_Abort:
     case kThreadError_NoAck:
+    {
+        char stringBuffer[Frame::kInfoStringSize];
 
-        sendFrame.GetDstAddr(dstAddr);
+        otLogInfoMac(GetInstance(), "Frame tx failed, error:%s, attempt:%d/%d, %s", otThreadErrorToString(aError),
-
+                     mTransmitAttempts, sendFrame.GetMaxTxAttempts(),
-        switch (dstAddr.mLength)
+                     sendFrame.ToInfoString(stringBuffer, sizeof(stringBuffer)));
-        {
-        case sizeof(ShortAddress):
-            otLogInfoMac(GetInstance(), "Tx failed - Error: %s (%d) - SeqNum: %d - Attempt %d/%d - Dst (short): %04x",
-                         otThreadErrorToString(aError), aError, sendFrame.GetSequence(), mTransmitAttempts,
-                         sendFrame.GetMaxTxAttempts(), dstAddr.mShortAddress);
-            break;
-
-        case sizeof(ExtAddress):
-            otLogInfoMac(GetInstance(), "Tx failed - Error: %s (%d) - SeqNum: %d - Attempt %d/%d - "
-                         "Dst: %02x:%02x:%02x:%02x:%02x:%02x:%02x:%02x",
-                         otThreadErrorToString(aError), aError, sendFrame.GetSequence(), mTransmitAttempts,
-                         sendFrame.GetMaxTxAttempts(), dstAddr.mExtAddress.m8[0], dstAddr.mExtAddress.m8[1],
-                         dstAddr.mExtAddress.m8[2], dstAddr.mExtAddress.m8[3], dstAddr.mExtAddress.m8[4],
-                         dstAddr.mExtAddress.m8[5], dstAddr.mExtAddress.m8[6], dstAddr.mExtAddress.m8[7]);
-            break;
-
-        default:
-            otLogInfoMac(GetInstance(), "Tx failed - Error: %s (%d) - SeqNum: %d - Attempt %d/%d",
-                         otThreadErrorToString(aError), aError, sendFrame.GetSequence(), mTransmitAttempts,
-                         sendFrame.GetMaxTxAttempts());
-            break;
-        }
-
         otDumpDebgMac(GetInstance(), "TX ERR", sendFrame.GetHeader(), 16);
 
         if (!RadioSupportsRetries() &&
@@ -1078,7 +1064,9 @@ void Mac::SentFrame(ThreadError aError)
             ExitNow();
         }
 
+        (void)stringBuffer;
         break;
+    }
 
     default:
         assert(false);
@@ -1348,11 +1336,10 @@ void Mac::ReceiveDoneTask(Frame *aFrame, ThreadError aError)
         break;
 
     case sizeof(ShortAddress):
-        otLogDebgMac(GetInstance(), "Received from short address %x", srcaddr.mShortAddress);
+        otLogDebgMac(GetInstance(), "Received frame from short address 0x%04x", srcaddr.mShortAddress);
 
         if (neighbor == NULL)
         {
-            otLogDebgMac(GetInstance(), "drop not neighbor");
             ExitNow(error = kThreadError_UnknownNeighbor);
         }
 
@@ -1370,7 +1357,6 @@ void Mac::ReceiveDoneTask(Frame *aFrame, ThreadError aError)
     // Duplicate Address Protection
     if (memcmp(&srcaddr.mExtAddress, &mExtAddress, sizeof(srcaddr.mExtAddress)) == 0)
     {
-        otLogDebgMac(GetInstance(), "duplicate address received");
         ExitNow(error = kThreadError_InvalidSourceAddress);
     }
 
@@ -1521,7 +1507,19 @@ exit:
 
     if (error != kThreadError_None)
     {
-        otLogDebgMacErr(GetInstance(), error, "Dropping received frame");
+        if (aFrame == NULL)
+        {
+            otLogInfoMac(GetInstance(), "Frame rx failed, error:%s", otThreadErrorToString(error));
+        }
+        else
+        {
+            char stringBuffer[Frame::kInfoStringSize];
+
+            otLogInfoMac(GetInstance(), "Frame rx failed, error:%s, %s", otThreadErrorToString(error),
+                         aFrame->ToInfoString(stringBuffer, sizeof(stringBuffer)));
+
+            (void)stringBuffer;
+        }
 
         switch (error)
         {
@@ -1575,7 +1573,7 @@ ThreadError Mac::HandleMacCommand(Frame &aFrame)
     {
     case Frame::kMacCmdBeaconRequest:
         mCounters.mRxBeaconRequest++;
-        otLogDebgMac(GetInstance(), "Received Beacon Request");
+        otLogInfoMac(GetInstance(), "Received Beacon Request");
 
         if (mBeaconsEnabled)
         {

src/core/mac/mac.hpp

@@ -250,7 +250,7 @@ public:
     ThreadError ActiveScan(uint32_t aScanChannels, uint16_t aScanDuration, ActiveScanHandler aHandler, void *aContext);
 
     /**
-     * This static method converts a beacon frame to an active scan result of type `otActiveScanResult`.
+     * This method converts a beacon frame to an active scan result of type `otActiveScanResult`.
      *
      * @param[in]  aBeaconFrame             A pointer to a beacon frame.
      * @param[out] aResult                  A reference to `otActiveScanResult` where the result is stored.
@@ -260,7 +260,7 @@ public:
      * @retval kThreadError_Parse           Failed parsing the beacon frame.
      *
      */
-    static ThreadError ConvertBeaconToActiveScanResult(Frame *aBeaconFrame, otActiveScanResult &aResult);
+    ThreadError ConvertBeaconToActiveScanResult(Frame *aBeaconFrame, otActiveScanResult &aResult);
 
     /**
      * This function pointer is called during an "Energy Scan" when the result for a channel is ready or the scan

src/core/mac/mac_frame.cpp

@@ -63,13 +63,13 @@ const char *Address::ToString(char *aBuf, uint16_t aSize) const
         break;
 
     case sizeof(ExtAddress):
-        snprintf(aBuf, aSize, "%02x:%02x:%02x:%02x:%02x:%02x:%02x:%02x",
+        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");
+        snprintf(aBuf, aSize, "None");
         break;
     }
 
@@ -1032,6 +1032,90 @@ uint8_t *Frame::GetFooter(void)
     return GetPsdu() + GetPsduLength() - GetFooterLength();
 }
 
+const char *Frame::ToInfoString(char *aBuf, uint16_t aSize)
+{
+    uint8_t type, commandId;
+    Address src, dst;
+    const char *typeStr;
+    char stringBuffer[10];
+    char srcStringBuffer[Address::kAddressStringSize];
+    char dstStringBuffer[Address::kAddressStringSize];
+
+    type = GetType();
+
+    switch (type)
+    {
+    case kFcfFrameBeacon:
+        typeStr = "Beacon";
+        break;
+
+    case kFcfFrameData:
+        typeStr = "Data";
+        break;
+
+    case kFcfFrameAck:
+        typeStr = "Ack";
+        break;
+
+    case kFcfFrameMacCmd:
+        if (GetCommandId(commandId) != kThreadError_None)
+        {
+            commandId = 0xff;
+        }
+
+        switch (commandId)
+        {
+        case kMacCmdDataRequest:
+            typeStr = "Cmd(DataReq)";
+            break;
+
+        case kMacCmdBeaconRequest:
+            typeStr = "Cmd(BeaconReq)";
+            break;
+
+        default:
+            snprintf(stringBuffer, sizeof(stringBuffer), "Cmd(%d)", commandId);
+            typeStr = stringBuffer;
+            break;
+        }
+
+        break;
+
+    default:
+        snprintf(stringBuffer, sizeof(stringBuffer), "%d", type);
+        typeStr = stringBuffer;
+        break;
+    }
+
+    if (GetSrcAddr(src) == kThreadError_None)
+    {
+        src.mLength = 0;
+    }
+
+    if (GetDstAddr(dst) == kThreadError_None)
+    {
+        dst.mLength = 0;
+    }
+
+    snprintf(aBuf, aSize, "len:%d, seqnum:%d, type:%s, src:%s, dst:%s, sec:%s, ackreq:%s", GetLength(), GetSequence(),
+             typeStr, src.ToString(srcStringBuffer, sizeof(srcStringBuffer)),
+             dst.ToString(dstStringBuffer, sizeof(dstStringBuffer)), GetSecurityEnabled() ? "yes" : "no",
+             GetAckRequest() ? "yes" : "no");
+
+    return aBuf;
+}
+
+const char *BeaconPayload::ToInfoString(char *aBuf, uint16_t aSize)
+{
+    const uint8_t *xpanid = GetExtendedPanId();
+
+    snprintf(aBuf, aSize, "name:%s, xpanid:%02x%02x%02x%02x%02x%02x%02x%02x, id:%d ver:%d, joinable:%s, native:%s",
+             GetNetworkName(), xpanid[0], xpanid[1], xpanid[2], xpanid[3], xpanid[4], xpanid[5], xpanid[6], xpanid[7],
+             GetProtocolId(), GetProtocolVersion(), IsJoiningPermitted() ? "yes" : "no", IsNative() ? "yes" : "no");
+
+    return aBuf;
+}
+
 }  // namespace Mac
 }  // namespace Thread
 

src/core/mac/mac_frame.hpp

@@ -156,7 +156,7 @@ struct Address
 {
     enum
     {
-        kAddressStringSize =  24,    ///< Max chars needed for a string representation of address (@sa ToString()).
+        kAddressStringSize = 18,     ///< Max chars needed for a string representation of address (@sa ToString()).
     };
 
     uint8_t mLength;                 ///< Length of address in bytes.
@@ -254,6 +254,8 @@ public:
         kMacCmdBeaconRequest               = 7,
         kMacCmdCoordinatorRealignment      = 8,
         kMacCmdGtsRequest                  = 9,
+
+        kInfoStringSize =  110,   ///< Max chars needed for the info string representation (@sa ToInfoString()).
     };
 
     /**
@@ -747,6 +749,17 @@ public:
      */
     uint8_t *GetFooter(void);
 
+    /**
+     * This method returns information about the frame object as a NULL-terminated string.
+     *
+     * @param[out]  aBuf   A pointer to the string buffer
+     * @param[in]   aSize  The maximum size of the string buffer.
+     *
+     * @returns A pointer to the char string buffer.
+     *
+     */
+    const char *ToInfoString(char *aBuf, uint16_t aSize);
+
 private:
     uint8_t *FindSequence(void);
     uint8_t *FindDstPanId(void);
@@ -815,6 +828,7 @@ public:
         kProtocolId       = 3,                      ///< Thread Protocol ID.
         kNetworkNameSize  = 16,                     ///< Size of Thread Network Name (bytes).
         kExtPanIdSize     = 8,                      ///< Size of Thread Extended PAN ID.
+        kInfoStringSize   = 92,                     ///< Max chars for the info string (@sa ToInfoString()).
     };
 
     enum
@@ -947,6 +961,17 @@ public:
      */
     void SetExtendedPanId(const uint8_t *aExtPanId) { memcpy(mExtendedPanId, aExtPanId, sizeof(mExtendedPanId)); }
 
+    /**
+     * This method returns information about the Beacon as a NULL-terminated string.
+     *
+     * @param[out]  aBuf   A pointer to the string buffer
+     * @param[in]   aSize  The maximum size of the string buffer.
+     *
+     * @returns A pointer to the char string buffer.
+     *
+     */
+    const char *ToInfoString(char *aBuf, uint16_t aSize);
+
 private:
     uint8_t  mProtocolId;
     uint8_t  mFlags;