Add additional logs for intel-ipmi-oem and smbios-mdrv1debug-smbios-MDRv1

4 files changed, 479 insertions, 3 deletions

diff --git a/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem/0001-Add-additional-logs-for-debugging.patch b/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem/0001-Add-additional-logs-for-debugging.patch
new file mode 100644
index 0000000000..b6eb21a388
--- /dev/null
+++ b/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem/0001-Add-additional-logs-for-debugging.patch
@@ -0,0 +1,112 @@
+From f5019e62c9d8cdaea611c63e1f24a3357d97ff7e Mon Sep 17 00:00:00 2001
+From: Nikita Kosenkov <NKosenkov@IBS.RU>
+Date: Tue, 19 Jul 2022 14:35:48 +0300
+Subject: [PATCH] Add additional logs for debugging
+
+---
+ src/smbioshandler.cpp | 39 ++++++++++++++++++++++++++++++++++-----
+ 1 file changed, 34 insertions(+), 5 deletions(-)
+
+diff --git a/src/smbioshandler.cpp b/src/smbioshandler.cpp
+index c737f43..5145c05 100644
+--- a/src/smbioshandler.cpp
++++ b/src/smbioshandler.cpp
+@@ -318,8 +318,8 @@ ipmi_ret_t cmd_region_write(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+                             ipmi_request_t request, ipmi_response_t response,
+                             ipmi_data_len_t data_len, ipmi_context_t context)
+ {
+-    phosphor::logging::log<phosphor::logging::level::ERR>(
+-        "DEBUG: exec MDRV1 cmd_region_write !!!");
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: MDRV1 cmd_region_write exec");
+ 
+     auto requestData = reinterpret_cast<const RegionWriteRequest*>(request);
+     uint8_t regionId = requestData->regionId - 1;
+@@ -371,7 +371,12 @@ ipmi_ret_t cmd_region_write(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+     }
+     if (requestData->sessionId != std::get<uint8_t>(value))
+     {
+-        return IPMI_CC_OEM_SET_IN_PROCESS;
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: MDRV1 cmd_region_write requestData->sessionId != std::get<uint8_t>(value)",
++                phosphor::logging::entry("REQSESSIONID=%X", requestData->sessionId),
++                phosphor::logging::entry("MDRV1SESSIONID=%X", std::get<uint8_t>(value)));
++
++        //return IPMI_CC_OEM_SET_IN_PROCESS;
+     }
+ 
+     std::copy(&(requestData->length), &(requestData->data[requestData->length]),
+@@ -398,8 +403,15 @@ ipmi_ret_t cmd_region_write(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+     }
+     reply.read(res);
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: MDRV1 cmd_region_write reply result",
++            phosphor::logging::entry("REPLYRES=%s", res.c_str()));
++
+     if (res == "NoData")
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: MDRV1 cmd_region_write res == 'NoData'");
++
+         return IPMI_CC_PARM_OUT_OF_RANGE;
+     }
+     else if (res != "Success")
+@@ -409,6 +421,9 @@ ipmi_ret_t cmd_region_write(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+         return IPMI_CC_UNSPECIFIED_ERROR;
+     }
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: MDRV1 cmd_region_write complete");
++
+     return IPMI_CC_OK;
+ }
+ 
+@@ -416,8 +431,8 @@ ipmi_ret_t cmd_region_lock(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+                            ipmi_request_t request, ipmi_response_t response,
+                            ipmi_data_len_t data_len, ipmi_context_t context)
+ {
+-    phosphor::logging::log<phosphor::logging::level::ERR>(
+-        "DEBUG: exec MDRV1 cmd_region_lock !!!");
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: MDRV1 cmd_region_lock exec");
+ 
+     auto requestData = reinterpret_cast<const RegionLockRequest*>(request);
+     uint8_t regionId = requestData->regionId - 1;
+@@ -457,6 +472,9 @@ ipmi_ret_t cmd_region_lock(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+     {
+         if (regionLockUnlocked == std::get<uint8_t>(value))
+         {
++            phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: MDRV1 cmd_region_lock requestData->lockPolicy == regionLockUnlocked");
++
+             return IPMI_CC_PARAMETER_NOT_SUPPORT_IN_PRESENT_STATE;
+         }
+     }
+@@ -471,6 +489,9 @@ ipmi_ret_t cmd_region_lock(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+         {
+             if (requestData->lockPolicy != regionLockStrict)
+             {
++                 phosphor::logging::log<phosphor::logging::level::INFO>(
++                    "DEBUG: MDRV1 cmd_region_lock requestData->lockPolicy != regionLockStrict");
++
+                 return IPMI_CC_OEM_SET_IN_PROCESS;
+             }
+         }
+@@ -492,8 +513,16 @@ ipmi_ret_t cmd_region_lock(ipmi_netfn_t netfn, ipmi_cmd_t cmd,
+     }
+     reply.read(lockResponse);
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: MDRV1 cmd_region_lock reply result",
++            phosphor::logging::entry("REPLYRES=%d", res));
++
+     *data_len = sizeof(lockResponse);
+     *res = lockResponse;
++
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: MDRV1 cmd_region_lock complete");
++    
+     return IPMI_CC_OK;
+ }
+ 
diff --git a/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem_git.bbappend b/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem_git.bbappend
index c526567174..d9c63ce7a2 100644
--- a/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem_git.bbappend
+++ b/meta-ibs/meta-common/recipes-ibs/ipmi/intel-ipmi-oem_git.bbappend
@@ -2,5 +2,8 @@ SRCREV = "429b085783f258da89d5c5b2979ba7030aef4d2b"
 
 FILESEXTRAPATHS:prepend := "${THISDIR}/${PN}:"
 
-SRC_URI += "file://0001-intel-ipmi-oem-add-logs.patch"
+SRC_URI = "git://github.com/openbmc/intel-ipmi-oem;branch=master;protocol=https \
+           file://0001-intel-ipmi-oem-add-logs.patch \
+           file://0001-Add-additional-logs-for-debugging.patch \
+           "
 
diff --git a/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1.bb b/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1.bb
index d8c904441e..9b233bc6a0 100644
--- a/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1.bb
+++ b/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1.bb
@@ -8,8 +8,11 @@ LICENSE = "Apache-2.0"
 LIC_FILES_CHKSUM = "file://LICENSE;md5=e3fc50a88d0a364313df4b21ef20c29e"
 
 
-SRC_URI = "git://git.sila.ru/openbmc/smbios-mdrv1.git;protocol=http;branch=master"
-SRC_URI += "file://smbios-mdrv1.service"
+SRC_URI = "git://git.sila.ru/openbmc/smbios-mdrv1.git;protocol=http;branch=master \
+           file://smbios-mdrv1.service \
+           file://smbios-mdrv1.service \
+           file://0001-Add-additional-logs-for-debugging.patch \
+           "
 
 # Modify these as desired
 PV = "1.0+git${SRCPV}"
diff --git a/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1/0001-Add-additional-logs-for-debugging.patch b/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1/0001-Add-additional-logs-for-debugging.patch
new file mode 100644
index 0000000000..7ad1296041
--- /dev/null
+++ b/meta-ibs/meta-common/recipes-ibs/smbios/smbios-mdrv1/0001-Add-additional-logs-for-debugging.patch
@@ -0,0 +1,358 @@
+From bf5da84ea7af1e385eae00c827a1615b39b157b3 Mon Sep 17 00:00:00 2001
+From: Nikita Kosenkov <NKosenkov@IBS.RU>
+Date: Tue, 19 Jul 2022 14:26:00 +0300
+Subject: [PATCH] Add additional logs for debugging
+
+---
+ include/smbios.hpp | 34 +++++++++++++++++++++-----
+ src/cpu.cpp        | 43 ++++++++++++++++++++++++++++++++
+ src/manager.cpp    | 61 ++++++++++++++++++++++++++++++++++++++--------
+ 3 files changed, 122 insertions(+), 16 deletions(-)
+
+diff --git a/include/smbios.hpp b/include/smbios.hpp
+index a36ff34..673caa1 100644
+--- a/include/smbios.hpp
++++ b/include/smbios.hpp
+@@ -18,6 +18,7 @@
+ #include <map>
+ #include <cstdint>
+ #include <string>
++#include <phosphor-logging/elog.hpp>
+ 
+ static constexpr uint16_t mdrSmbiosSize = 32 * 1024;    // 32K
+ static constexpr uint16_t mdrAcpiTableSize = 32 * 1024; // 32K
+@@ -113,6 +114,7 @@ typedef enum
+ } SmbiosType;
+ 
+ static constexpr uint8_t separateLen = 2;
++
+ // To get the point of next smbios item
+ static inline uint8_t *smbiosNextPtr(uint8_t *smbiosDataIn)
+ {
+@@ -140,9 +142,19 @@ static inline uint8_t *smbiosTypePtr(uint8_t *smbiosDataIn, uint8_t typeId)
+ {
+     if (smbiosDataIn == nullptr)
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbiosTypePtr smbiosDataIn == nullptr");
++
+         return nullptr;
+     }
++
+     char *smbiosData = reinterpret_cast<char *>(smbiosDataIn);
++
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: smbiosTypePtr smbiosData",
++        phosphor::logging::entry("SMBIOSDATA=%s", smbiosData)
++        );
++
+     while ((*smbiosData != '\0') || (*(smbiosData + 1) != '\0'))
+     {
+         if (*smbiosData != typeId)
+@@ -155,6 +167,12 @@ static inline uint8_t *smbiosTypePtr(uint8_t *smbiosDataIn, uint8_t typeId)
+                 len++;
+                 if (len >= mdrSmbiosSize) // To avoid endless loop
+                 {
++                    phosphor::logging::log<phosphor::logging::level::INFO>(
++                        "DEBUG: smbiosTypePtr len >= mdrSmbiosSize",
++                        phosphor::logging::entry("LEN=%d", (int)len),
++                        phosphor::logging::entry("MDRSIZE=%d", (int)mdrSmbiosSize)
++                        );
++
+                     return nullptr;
+                 }
+             }
+@@ -169,27 +187,31 @@ static inline uint8_t *smbiosTypePtr(uint8_t *smbiosDataIn, uint8_t typeId)
+ static inline std::string positionToString(uint8_t positionNum,
+                                            uint8_t structLen, uint8_t *dataIn)
+ {
+-    if (dataIn == nullptr)
++    if (dataIn == nullptr || positionNum == 0)
+     {
+         return "";
+     }
+-    char *target;
+-    uint8_t stringLen = 0;
+     uint16_t limit = mdrSmbiosSize; // set a limit to avoid endless loop
+ 
+-    target = reinterpret_cast<char *>(dataIn + structLen);
++    char* target = reinterpret_cast<char*>(dataIn + structLen);
++    if (target == nullptr)
++    {
++        return "";
++    }
+     for (uint8_t index = 1; index < positionNum; index++)
+     {
+         for (; *target != '\0'; target++)
+         {
+             limit--;
+-            if (limit < 1)
++            // When target = dataIn + structLen + limit,
++            // following target++ will be nullptr
++            if (limit < 1 || target == nullptr)
+             {
+                 return "";
+             }
+         }
+         target++;
+-        if (*target == '\0')
++        if (target == nullptr || *target == '\0')
+         {
+             return ""; // 0x00 0x00 means end of the entry.
+         }
+diff --git a/src/cpu.cpp b/src/cpu.cpp
+index b6ebb3a..4e94d8a 100644
+--- a/src/cpu.cpp
++++ b/src/cpu.cpp
+@@ -31,6 +31,10 @@ void Cpu::cpuSocket(uint8_t positionNum, uint8_t structLen, uint8_t *dataIn)
+ 
+     result = positionToString(positionNum, structLen, dataIn);
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: set CPU socket",
++        phosphor::logging::entry("CPUSOCKET=%s", result.c_str()));
++
+     processorSocket(result);
+ }
+ 
+@@ -45,10 +49,18 @@ void Cpu::cpuType(uint8_t value)
+         cpuTypeTable.find(value);
+     if (it == cpuTypeTable.end())
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU type",
++            phosphor::logging::entry("CPUTYPE=%s", "Unknown Processor Type"));
++
+         processorType("Unknown Processor Type");
+     }
+     else
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU type",
++            phosphor::logging::entry("CPUTYPE=%s", it->second.c_str()));
++
+         processorType(it->second);
+     }
+ }
+@@ -63,10 +75,18 @@ void Cpu::cpuFamily(uint8_t value)
+     std::map<uint8_t, std::string>::const_iterator it = familyTable.find(value);
+     if (it == familyTable.end())
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU family",
++            phosphor::logging::entry("CPUFAMILY=%s", "Unknown Processor Family"));
++
+         processorFamily("Unknown Processor Family");
+     }
+     else
+     {
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU family",
++            phosphor::logging::entry("CPUFAMILY=%s", it->second.c_str()));
++
+         processorFamily(it->second);
+     }
+ }
+@@ -83,6 +103,10 @@ void Cpu::cpuManufacturer(uint8_t positionNum, uint8_t structLen,
+ 
+     result = positionToString(positionNum, structLen, dataIn);
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU manufacturer",
++            phosphor::logging::entry("CPUMANUF=%s", result.c_str()));
++
+     processorManufacturer(result);
+ }
+ 
+@@ -102,6 +126,10 @@ void Cpu::cpuVersion(uint8_t positionNum, uint8_t structLen, uint8_t *dataIn)
+ 
+     result = positionToString(positionNum, structLen, dataIn);
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU version",
++            phosphor::logging::entry("CPUVER=%s", result.c_str()));    
++
+     processorVersion(result);
+ }
+ 
+@@ -132,6 +160,9 @@ void Cpu::cpuCharacteristics(uint16_t value)
+         }
+     }
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: set CPU characteristics");
++
+     processor::characteristics(result);
+ }
+ 
+@@ -158,6 +189,9 @@ void Cpu::processorInfoUpdate(void)
+     dataIn = smbiosTypePtr(dataIn, processorsType);
+     if (dataIn == nullptr)
+     {
++         phosphor::logging::log<phosphor::logging::level::ERR>(
++            "DEBUG: smbiosTypePtr return nullptr");
++
+         return;
+     }
+ 
+@@ -166,15 +200,24 @@ void Cpu::processorInfoUpdate(void)
+         dataIn = smbiosNextPtr(dataIn);
+         if (dataIn == nullptr)
+         {
++            phosphor::logging::log<phosphor::logging::level::ERR>(
++                "DEBUG: smbiosNextPtr return nullptr");
++
+             return;
+         }
+         dataIn = smbiosTypePtr(dataIn, processorsType);
+         if (dataIn == nullptr)
+         {
++            phosphor::logging::log<phosphor::logging::level::ERR>(
++                "DEBUG: smbiosTypePtr return nullptr");
++
+             return;
+         }
+     }
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: cpu info check OK");
++
+     auto cpuInfo = reinterpret_cast<struct ProcessorInfo *>(dataIn);
+ 
+     cpuSocket(cpuInfo->socketDesignation, cpuInfo->length,
+diff --git a/src/manager.cpp b/src/manager.cpp
+index c3bdf4a..69db933 100644
+--- a/src/manager.cpp
++++ b/src/manager.cpp
+@@ -148,17 +148,26 @@ uint8_t MDR_V1::getTotalCpuSlot()
+         dataIn = smbiosTypePtr(dataIn, processorsType);
+         if (dataIn == nullptr)
+         {
++            phosphor::logging::log<phosphor::logging::level::INFO>(
++                "DEBUG: getTotalCpuSlot -> smbiosTypePtr return nullptr");
+             break;
+         }
+         num++;
+         dataIn = smbiosNextPtr(dataIn);
+         if (dataIn == nullptr)
+         {
++            phosphor::logging::log<phosphor::logging::level::ERR>(
++                "DEBUG: getTotalCpuSlot -> smbiosNextPtr return nullptr");
++
+             break;
+         }
+         limit--;
+     }
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++        "DEBUG: getTotalCpuSlot",
++        phosphor::logging::entry("SLOTNUM=%d", num));  
++
+     return num;
+ }
+ 
+@@ -167,22 +176,26 @@ void MDR_V1::systemInfoUpdate()
+     uint8_t num = 0;
+     std::string path;
+ 
+-    num = getTotalDimmSlot();
++    // num = getTotalDimmSlot();
+ 
+-    // Clear all dimm cpu interface first
+-    std::vector<std::unique_ptr<Dimm>>().swap(dimms);
+-    std::vector<std::unique_ptr<Cpu>>().swap(cpus);
++    // // Clear all dimm cpu interface first
++    // std::vector<std::unique_ptr<Dimm>>().swap(dimms);
++    // std::vector<std::unique_ptr<Cpu>>().swap(cpus);
+ 
+-    for (int index = 0; index < num; index++)
+-    {
+-        path = dimmPath + std::to_string(index);
+-        dimms.emplace_back(std::make_unique<phosphor::smbios::Dimm>(
+-            bus, path, index, &regionS[0]));
+-    }
++    // for (int index = 0; index < num; index++)
++    // {
++    //     path = dimmPath + std::to_string(index);
++    //     dimms.emplace_back(std::make_unique<phosphor::smbios::Dimm>(
++    //         bus, path, index, &regionS[0]));
++    // }
+ 
+     num = 0;
+     num = getTotalCpuSlot();
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: getTotalCpuSlot",
++            phosphor::logging::entry("SLOTNUM=%d", num));  
++
+     for (int index = 0; index < num; index++)
+     {
+         path = cpuPath + std::to_string(index);
+@@ -322,6 +335,11 @@ std::vector<uint8_t> MDR_V1::regionRead(uint8_t regionId, uint8_t length,
+ 
+ std::string MDR_V1::regionWrite(std::vector<uint8_t> wData)
+ {
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionWrite exec",
++            phosphor::logging::entry("DATASIZE=%d", (int)wData.size())
++            );
++
+     uint8_t regionId = wData[0];
+     if (regionId >= maxRegion)
+     {
+@@ -350,6 +368,12 @@ std::string MDR_V1::regionWrite(std::vector<uint8_t> wData)
+     timers[regionId]->start(usec);
+     timers[regionId]->setEnabled<std::true_type>();
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionWrite complete");
++
++    
++    regionComplete(regionId);
++
+     return "Success";
+ }
+ 
+@@ -397,6 +421,13 @@ uint8_t MDR_V1::regionLock(uint8_t u8SessionId, uint8_t regionId,
+ {
+     uint8_t reqSession;
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionLock exec",
++            phosphor::logging::entry("SESSIONID=%x", u8SessionId),
++            phosphor::logging::entry("REGIONID=%x", regionId),
++            phosphor::logging::entry("LOCKPOLICY=%x", u8LockPolicy)
++            );
++
+     if (regionId >= maxRegion)
+     {
+         phosphor::logging::log<phosphor::logging::level::ERR>(
+@@ -433,11 +464,18 @@ uint8_t MDR_V1::regionLock(uint8_t u8SessionId, uint8_t regionId,
+         timers[regionId]->setEnabled<std::true_type>();
+     }
+ 
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionLock complete");
++
+     return regionS[regionId].sessionId;
+ }
+ 
+ uint8_t MDR_V1::regionId(uint8_t value)
+ {
++    phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionId exec",
++            phosphor::logging::entry("REGIONID=%x", value));
++
+     globalRegionId = value;
+ 
+     sdbusplus::xyz::openbmc_project::Smbios::server::MDR_V1::lockPolicy(
+@@ -449,6 +487,9 @@ uint8_t MDR_V1::regionId(uint8_t value)
+     sdbusplus::xyz::openbmc_project::Smbios::server::MDR_V1::sessionId(
+         regionS[value].sessionId);
+ 
++        phosphor::logging::log<phosphor::logging::level::INFO>(
++            "DEBUG: smbios MDRV1 regionId complete");
++
+     return sdbusplus::xyz::openbmc_project::Smbios::server::MDR_V1::regionId(
+         value);
+ }