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>
diff --git a/service/src/mainapp.cpp b/service/src/mainapp.cpp
index 60ec796..c71e78e 100644
--- a/service/src/mainapp.cpp
+++ b/service/src/mainapp.cpp
@@ -277,44 +277,52 @@
     conn->async_method_call(
         [&server, &conn](boost::system::error_code ec,
                          const std::variant<uint64_t>& value) {
-            if (ec)
+            if (!ec)
             {
-                phosphor::logging::log<phosphor::logging::level::ERR>(
-                    "async_method_call error: FinishTimestamp failed");
-                return;
-            }
-            if (std::get<uint64_t>(value))
-            {
-                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 @@
         [&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);
             }