[ncp] add timestamp to log metadata fields (#4439)

This change adds an information about the timestamp to the log
metadata that is calculated with the formula: <timestamp_base> +
<time_from_start_in_ms>. The <timestamp_base> value is set to 0 by
default and can be changed with a new SPINEL property:
SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE formatted as X (uint64_t).

src/ncp/ncp_base.cpp

@@ -248,6 +248,7 @@ NcpBase::NcpBase(Instance *aInstance)
     , mRxSpinelOutOfOrderTidCounter(0)
     , mTxSpinelFrameCounter(0)
     , mDidInitialUpdates(false)
+    , mLogTimestampBase(0)
 {
     assert(mInstance != NULL);
 
@@ -630,6 +631,7 @@ void NcpBase::Log(otLogLevel aLogLevel, otLogRegion aLogRegion, const char *aLog
     SuccessOrExit(error = mEncoder.WriteUtf8(aLogString));
     SuccessOrExit(error = mEncoder.WriteUint8(ConvertLogLevel(aLogLevel)));
     SuccessOrExit(error = mEncoder.WriteUintPacked(ConvertLogRegion(aLogRegion)));
+    SuccessOrExit(error = mEncoder.WriteUint64(mLogTimestampBase + otPlatAlarmMilliGetNow()));
     SuccessOrExit(error = mEncoder.EndFrame());
 
 exit:
@@ -2257,6 +2259,26 @@ exit:
 }
 #endif // OPENTHREAD_CONFIG_LOG_LEVEL_DYNAMIC_ENABLE
 
+template <> otError NcpBase::HandlePropertySet<SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE>(void)
+{
+    uint64_t timestampBase = 0;
+    otError  error         = OT_ERROR_NONE;
+    uint32_t currentTime   = otPlatAlarmMilliGetNow();
+
+    SuccessOrExit(error = mDecoder.ReadUint64(timestampBase));
+    VerifyOrExit(timestampBase >= currentTime, error = OT_ERROR_INVALID_ARGS);
+
+    mLogTimestampBase = timestampBase - currentTime;
+
+exit:
+    return error;
+}
+
+template <> otError NcpBase::HandlePropertyGet<SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE>(void)
+{
+    return mEncoder.WriteUint64(mLogTimestampBase);
+}
+
 template <> otError NcpBase::HandlePropertyGet<SPINEL_PROP_PHY_CHAN_SUPPORTED>(void)
 {
 #if OPENTHREAD_RADIO

src/ncp/ncp_base.hpp

@@ -608,6 +608,8 @@ protected:
     uint32_t mTxSpinelFrameCounter;         // Number of sent (outbound) spinel frames.
 
     bool mDidInitialUpdates;
+
+    uint64_t mLogTimestampBase; // Timestamp base used for logging
 };
 
 } // namespace Ncp

src/ncp/ncp_base_dispatcher.cpp

@@ -320,6 +320,7 @@ NcpBase::PropertyHandler NcpBase::FindGetPropertyHandler(spinel_prop_key_t aKey)
         OT_NCP_GET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_TEST_ASSERT),
         OT_NCP_GET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_NCP_LOG_LEVEL),
         OT_NCP_GET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_TEST_WATCHDOG),
+        OT_NCP_GET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE),
     };
 
 #undef OT_NCP_GET_HANDLER_ENTRY
@@ -515,6 +516,7 @@ NcpBase::PropertyHandler NcpBase::FindSetPropertyHandler(spinel_prop_key_t aKey)
 #if OPENTHREAD_CONFIG_LOG_LEVEL_DYNAMIC_ENABLE
         OT_NCP_SET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_NCP_LOG_LEVEL),
 #endif
+        OT_NCP_SET_HANDLER_ENTRY(SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE),
     };
 
 #undef OT_NCP_SET_HANDLER_ENTRY

src/ncp/spinel.h

@@ -2991,6 +2991,7 @@ enum
      *         `SPINEL_NCP_LOG_LEVEL_<level>`)
      *    `i`: OpenThread Log region (as per definition in enumeration
      *         `SPINEL_NCP_LOG_REGION_<region>).
+     *    `X`: Log timestamp = <timestamp_base> + <current_time_ms>
      *
      */
     SPINEL_PROP_STREAM_LOG = SPINEL_PROP_STREAM__BEGIN + 4,
@@ -3932,6 +3933,14 @@ enum
      */
     SPINEL_PROP_DEBUG_TEST_WATCHDOG = SPINEL_PROP_DEBUG__BEGIN + 2,
 
+    /// The NCP timestamp base
+    /** Format: X (write-only)
+     *
+     * This property controls the time base value that is used for logs timestamp field calulation.
+     *
+     */
+    SPINEL_PROP_DEBUG_LOG_TIMESTAMP_BASE = SPINEL_PROP_DEBUG__BEGIN + 3,
+
     SPINEL_PROP_DEBUG__END = 0x4400,
 
     SPINEL_PROP_EXPERIMENTAL__BEGIN = 2000000,