Fix: PFR CPLD boot complete checkpoint 9

Sometimes BMC boot complete Checkpoint 9 is not been
set which is causing the BMC WDT trigger running in CPLD.
This commit has a correction in timer thread which is used
for checking BMC boot complete and setting checkpoint.
Also enhanced debug logs for identifing any further issues
in checkpoint.

Tested:
 Flashed image on PFR enabled system and it boots fine.

Change-Id: I94c7c716ebcebf533fa5a6c8066a2fb3b96f7646
Signed-off-by: AppaRao Puli <apparao.puli@linux.intel.com>

3 files changed, 47 insertions, 31 deletions

diff --git a/intel-pfr-manager/libpfr/inc/file.hpp b/intel-pfr-manager/libpfr/inc/file.hpp
index 1fbc62a..5532169 100644
--- a/intel-pfr-manager/libpfr/inc/file.hpp
+++ b/intel-pfr-manager/libpfr/inc/file.hpp
@@ -99,6 +99,9 @@ class I2CFile
         int retries = 3;
         while (i2c_smbus_write_byte_data(fd, offset, value) < 0)
         {
+            phosphor::logging::log<phosphor::logging::level::WARNING>(
+                "PFR: I2c write failed, retrying....",
+                phosphor::logging::entry("COUNT=%d", retries));
             if (!retries--)
             {
                 throw std::runtime_error("i2c_smbus_write_byte_data() failed");
diff --git a/intel-pfr-manager/libpfr/src/pfr.cpp b/intel-pfr-manager/libpfr/src/pfr.cpp
index a5316ba..3b011f6 100644
--- a/intel-pfr-manager/libpfr/src/pfr.cpp
+++ b/intel-pfr-manager/libpfr/src/pfr.cpp
@@ -253,6 +253,8 @@ int setBMCBootCheckpoint(const uint8_t checkPoint)
     {
         I2CFile cpldDev(i2cBusNumber, i2cSlaveAddress, O_RDWR | O_CLOEXEC);
         cpldDev.i2cWriteByteData(bmcBootCheckpoint, checkPoint);
+        phosphor::logging::log<phosphor::logging::level::INFO>(
+            "Successfully set the PFR CPLD checkpoint 9.");
         return 0;
     }
     catch (const std::exception& e)
diff --git a/intel-pfr-manager/service/src/mainapp.cpp b/intel-pfr-manager/service/src/mainapp.cpp
index 60ec796..c71e78e 100644
--- a/intel-pfr-manager/service/src/mainapp.cpp
+++ b/intel-pfr-manager/service/src/mainapp.cpp
@@ -277,44 +277,52 @@ void checkAndSetCheckpoint(sdbusplus::asio::object_server& server,
     conn->async_method_call(
         [&server, &conn](boost::system::error_code ec,
                          const std::variant<uint64_t>& value) {
-            if (ec)
-            {
-                phosphor::logging::log<phosphor::logging::level::ERR>(
-                    "async_method_call error: FinishTimestamp failed");
-                return;
-            }
-            if (std::get<uint64_t>(value))
+            if (!ec)
             {
-                if (!finishedSettingChkPoint)
+                if (std::get<uint64_t>(value))
                 {
-                    finishedSettingChkPoint = true;
-                    intel::pfr::setBMCBootCheckpoint(bmcBootFinishedChkPoint);
+                    phosphor::logging::log<phosphor::logging::level::INFO>(
+                        "PFR: BMC boot completed. Setting checkpoint 9.");
+                    if (!finishedSettingChkPoint)
+                    {
+                        finishedSettingChkPoint = true;
+                        intel::pfr::setBMCBootCheckpoint(
+                            bmcBootFinishedChkPoint);
+                    }
+                    return;
                 }
             }
             else
             {
-                // FIX-ME: Latest up-stream sync caused issue in receiving
-                // StartupFinished signal. Unable to get StartupFinished signal
-                // from systemd1 hence using poll method too, to trigger it
-                // properly.
-                constexpr size_t pollTimeout = 10; // seconds
-                initTimer->expires_after(std::chrono::seconds(pollTimeout));
-                initTimer->async_wait([&server, &conn](
-                                          const boost::system::error_code& ec) {
-                    if (ec == boost::asio::error::operation_aborted)
-                    {
-                        // Timer reset.
-                        return;
-                    }
-                    if (ec)
-                    {
-                        phosphor::logging::log<phosphor::logging::level::ERR>(
-                            "Set boot Checkpoint - async wait error.");
-                        return;
-                    }
-                    checkAndSetCheckpoint(server, conn);
-                });
+                // Failed to get data from systemd. System might not
+                // be ready yet. Attempt again for data.
+                phosphor::logging::log<phosphor::logging::level::ERR>(
+                    "PFR: aync call failed to get FinishTimestamp.",
+                    phosphor::logging::entry("MSG=%s", ec.message().c_str()));
             }
+            // FIX-ME: Latest up-stream sync caused issue in receiving
+            // StartupFinished signal. Unable to get StartupFinished signal
+            // from systemd1 hence using poll method too, to trigger it
+            // properly.
+            constexpr size_t pollTimeout = 10; // seconds
+            initTimer->expires_after(std::chrono::seconds(pollTimeout));
+            initTimer->async_wait([&server,
+                                   &conn](const boost::system::error_code& ec) {
+                if (ec == boost::asio::error::operation_aborted)
+                {
+                    // Timer reset.
+                    phosphor::logging::log<phosphor::logging::level::INFO>(
+                        "PFR: Set boot Checkpoint - Timer aborted or stopped.");
+                    return;
+                }
+                if (ec)
+                {
+                    phosphor::logging::log<phosphor::logging::level::ERR>(
+                        "PFR: Set boot Checkpoint - async wait error.");
+                    return;
+                }
+                checkAndSetCheckpoint(server, conn);
+            });
         },
         "org.freedesktop.systemd1", "/org/freedesktop/systemd1",
         "org.freedesktop.DBus.Properties", "Get",
@@ -356,6 +364,9 @@ int main()
         [&server, &conn](sdbusplus::message::message& msg) {
             if (!finishedSettingChkPoint)
             {
+                phosphor::logging::log<phosphor::logging::level::INFO>(
+                    "PFR: BMC boot completed(StartupFinished). Setting "
+                    "checkpoint 9.");
                 finishedSettingChkPoint = true;
                 intel::pfr::setBMCBootCheckpoint(bmcBootFinishedChkPoint);
             }