[SL-ONLY] Feature/silabs tracing logs formating

src/platform/silabs/silabs_utils.cpp

@@ -0,0 +1,38 @@
+/*
+ *
+ *    Copyright (c) 2020 Project CHIP Authors
+ *    Copyright (c) 2022 Silabs.
+ *    All rights reserved.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+
+#include "silabs_utils.h"
+#include "SoftwareFaultReports.h"
+#include <MatterConfig.h>
+
+void appError(int err)
+{
+    char faultMessage[30] = { 0 }; // App Critical Error: + 10 digit + null character
+    snprintf(faultMessage, sizeof faultMessage, "App Critical Error:%d", err);
+    SILABS_LOG("!!!!!!!!!!!! %s !!!!!!!!!!!", faultMessage);
+    chip::DeviceLayer::Silabs::OnSoftwareFaultEventHandler(faultMessage);
+    vTaskSuspendAll();
+    /* Force an assert. */
+    chipAbort();
+}
+
+void appError(CHIP_ERROR error)
+{
+    appError(static_cast<int>(error.AsInteger()));
+}

src/platform/silabs/silabs_utils.h

@@ -0,0 +1,43 @@
+/*
+ *
+ *    Copyright (c) 2020 Project CHIP Authors
+ *    Copyright (c) 2022 Silabs.
+ *    All rights reserved.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+
+#pragma once
+
+// EFR Logging
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+void silabsInitLog(void);
+
+void silabsLog(const char * aFormat, ...);
+#define SILABS_LOG(...) silabsLog(__VA_ARGS__);
+void appError(int err);
+
+#ifdef __cplusplus
+}
+
+// Output logs to RTT by defaults
+#ifndef SILABS_LOG_OUT_UART
+#define SILABS_LOG_OUT_UART 0
+#endif
+
+#include <lib/core/CHIPError.h>
+void appError(CHIP_ERROR error);
+#endif

src/platform/silabs/tracing/SilabsTracing.cpp

@@ -34,7 +34,48 @@ namespace chip {
 namespace Tracing {
 namespace Silabs {
 
-// TODO add string mapping to log the operation names and types
+const char * TimeTraceOperationString[] = {
+    [static_cast<int>(TimeTraceOperation::kSpake2p)]                 = "Spake2p",
+    [static_cast<int>(TimeTraceOperation::kPake1)]                   = "Pake1",
+    [static_cast<int>(TimeTraceOperation::kPake2)]                   = "Pake2",
+    [static_cast<int>(TimeTraceOperation::kPake3)]                   = "Pake3",
+    [static_cast<int>(TimeTraceOperation::kOperationalCredentials)]  = "OperationalCredentials",
+    [static_cast<int>(TimeTraceOperation::kAttestationVerification)] = "AttestationVerification",
+    [static_cast<int>(TimeTraceOperation::kCSR)]                     = "CSR",
+    [static_cast<int>(TimeTraceOperation::kNOC)]                     = "NOC",
+    [static_cast<int>(TimeTraceOperation::kTransportLayer)]          = "TransportLayer",
+    [static_cast<int>(TimeTraceOperation::kTransportSetup)]          = "TransportSetup",
+    [static_cast<int>(TimeTraceOperation::kFindOperational)]         = "FindOperational",
+    [static_cast<int>(TimeTraceOperation::kCaseSession)]             = "CaseSession",
+    [static_cast<int>(TimeTraceOperation::kSigma1)]                  = "Sigma1",
+    [static_cast<int>(TimeTraceOperation::kSigma2)]                  = "Sigma2",
+    [static_cast<int>(TimeTraceOperation::kSigma3)]                  = "Sigma3",
+    [static_cast<int>(TimeTraceOperation::kOTA)]                     = "OTA",
+    [static_cast<int>(TimeTraceOperation::kImageUpload)]             = "ImageUpload",
+    [static_cast<int>(TimeTraceOperation::kImageVerification)]       = "ImageVerification",
+    [static_cast<int>(TimeTraceOperation::kAppApplyTime)]            = "AppApplyTime",
+    [static_cast<int>(TimeTraceOperation::kBootup)]                  = "Bootup",
+    [static_cast<int>(TimeTraceOperation::kSilabsInit)]              = "SilabsInit",
+    [static_cast<int>(TimeTraceOperation::kMatterInit)]              = "MatterInit",
+    [static_cast<int>(TimeTraceOperation::kBufferFull)]              = "BufferFull",
+    [static_cast<int>(TimeTraceOperation::kNumTraces)]               = "NumTraces",
+};
+
+const char * OperationTypeToString(OperationType type)
+{
+    switch (type)
+    {
+    case OperationType::kBegin:
+        return "Begin";
+    case OperationType::kEnd:
+        return "End";
+    case OperationType::kInstant:
+        return "Instant";
+    default:
+        return "Unknown";
+    }
+}
+
 namespace {
 constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
 } // namespace
@@ -43,6 +84,29 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData<kPersistentTimeTr
     // TODO implement the Persistent Array class and use it here for logging the watermark array
 };
 
+int TimeTracker::ToCharArray(MutableByteSpan & buffer) const
+{
+    switch (mType)
+    {
+    case OperationType::kBegin:
+        return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
+                        "TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(),
+                        TimeTraceOperationString[to_underlying(mOperation)], OperationTypeToString(mType), mError.AsInteger());
+    case OperationType::kEnd:
+        return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
+                        "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32
+                        " ms, Operation: %s, Type: %s, Error: 0x%" PRIx32,
+                        mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count(),
+                        TimeTraceOperationString[to_underlying(mOperation)], OperationTypeToString(mType), mError.AsInteger());
+    case OperationType::kInstant:
+        return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
+                        "TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(),
+                        TimeTraceOperationString[to_underlying(mOperation)], OperationTypeToString(mType), mError.AsInteger());
+    default:
+        return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type");
+    }
+}
+
 SilabsTracer SilabsTracer::sInstance;
 
 SilabsTracer::SilabsTracer()
@@ -78,7 +142,7 @@ CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * stor
     return CHIP_NO_ERROR;
 }
 
-void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
+CHIP_ERROR SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
 {
     // Log the start time of the operation
     auto & tracker     = mLatestTimeTrackers[static_cast<size_t>(aOperation)];
@@ -90,10 +154,10 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
     auto & watermark = mWatermarks[static_cast<size_t>(aOperation)];
     watermark.mTotalCount++;
 
-    OutputTrace(tracker);
+    return OutputTrace(tracker);
 }
 
-void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error)
+CHIP_ERROR SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error)
 {
     auto & tracker   = mLatestTimeTrackers[static_cast<size_t>(aOperation)];
     tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp();
@@ -127,28 +191,28 @@ void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error)
         }
     }
 
-    OutputTrace(tracker);
+    return OutputTrace(tracker);
 }
 
-void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error)
+CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error)
 {
     TimeTracker tracker;
     tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp();
     tracker.mEndTime   = tracker.mStartTime;
     tracker.mOperation = aOperation;
     tracker.mType      = OperationType::kInstant;
     tracker.mError     = error;
-    OutputTrace(tracker);
+    return OutputTrace(tracker);
 }
 
 CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker)
 {
     VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED);
-    ChipLogProgress(DeviceLayer,
-                    "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Operation: %" PRIu8 ", Type: %" PRIu8
-                    ", Error: %" CHIP_ERROR_FORMAT,
-                    tracker.mStartTime.count(), tracker.mEndTime.count(), static_cast<uint8_t>(tracker.mOperation),
-                    static_cast<uint8_t>(tracker.mType), tracker.mError.Format());
+    // Allocate a buffer to store the trace
+    uint8_t buffer[kMaxTraceSize];
+    MutableByteSpan span(buffer);
+    tracker.ToCharArray(span);
+    ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal
     return CHIP_NO_ERROR;
 }
 
@@ -168,10 +232,11 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker)
         TimeTracker resourceExhaustedTracker = tracker;
         resourceExhaustedTracker.mStartTime  = System::SystemClock().GetMonotonicTimestamp();
         resourceExhaustedTracker.mEndTime    = resourceExhaustedTracker.mStartTime;
-        resourceExhaustedTracker.mOperation  = TimeTraceOperation::kNumTraces;
+        resourceExhaustedTracker.mOperation  = TimeTraceOperation::kBufferFull;
         resourceExhaustedTracker.mType       = OperationType::kInstant;
         resourceExhaustedTracker.mError      = CHIP_ERROR_BUFFER_TOO_SMALL;
         mTimeTrackerList.Insert(resourceExhaustedTracker);
+        mBufferedTrackerCount++;
         return CHIP_ERROR_BUFFER_TOO_SMALL;
     }
     else
@@ -189,10 +254,11 @@ CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation)
 
     VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED);
     ChipLogProgress(DeviceLayer,
-                    "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32
+                    "Operation: %s, TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32
                     ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "",
-                    index, watermark.mTotalCount, watermark.mSuccessfullCount, watermark.mMaxTimeMs.count(),
-                    watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), watermark.mCountAboveAvg);
+                    TimeTraceOperationString[to_underlying(aOperation)], watermark.mTotalCount, watermark.mSuccessfullCount,
+                    watermark.mMaxTimeMs.count(), watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(),
+                    watermark.mCountAboveAvg);
 
     return CHIP_NO_ERROR;
 }
@@ -272,24 +338,33 @@ CHIP_ERROR SilabsTracer::LoadWatermarks()
     return CHIP_NO_ERROR;
 }
 
-#if CONFIG_BUILD_FOR_HOST_UNIT_TEST
-size_t SilabsTracer::GetTraceCount()
-{
-    return mBufferedTrackerCount;
-}
-
-CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const
+CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const
 {
     auto * current = mTimeTrackerList.head;
-    for (size_t i = 0; i < index && current != nullptr; ++i)
+    while (current != nullptr)
     {
+        if (current->mValue.mOperation == aOperation)
+        {
+            // Check if the buffer is large enough
+            auto requiredSize = current->mValue.GetSize();
+
+            if (requiredSize < 0)
+            {
+                return CHIP_ERROR_INTERNAL;
+            }
+
+            if (static_cast<size_t>(requiredSize) >= buffer.size())
+            {
+                return CHIP_ERROR_BUFFER_TOO_SMALL;
+            }
+
+            current->mValue.ToCharArray(buffer);
+            return CHIP_NO_ERROR;
+        }
         current = current->mpNext;
     }
-    VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT);
-    trace = reinterpret_cast<const char *>(&current->mValue);
-    return CHIP_NO_ERROR;
+    return CHIP_ERROR_NOT_FOUND;
 }
-#endif
 
 } // namespace Silabs
 } // namespace Tracing