PEL: Wait a bit after host up before sending PELs

Wait a minute after the host state switches to running before sending
any PELs to the host.  This applies both on a normal boot and also when
the BMC is rebooted when the host is already up.

This is being done for 2 reasons:
1) Give some relief to the PLDM traffic and CPU load that occurs after a
   BMC reboot when the host is already up, because the host will also be
   exchanging PLDM PDRs with the BMC then and pretty much every
   application is also starting up at the time as well.
2) A lot of times on a normal boot the host notifier code ends up having
   to do a few retries when it first starts sending the PELs because the
   first few commands fail, possibly because the code on the receiving
   end isn't quite ready yet.

I arrived at that amount of time by deciding 30 seconds was reasonable,
and then doubling it just to be sure.  During testing of the reboots the
minute timeout gave plenty of time for the BMC to get back to BMC ready.

Signed-off-by: Matt Spinler <spinler@us.ibm.com>
Change-Id: I0929a4acdda0a9fe8fbdcd624c5821a642ad83a6
diff --git a/extensions/openpower-pels/host_interface.hpp b/extensions/openpower-pels/host_interface.hpp
index 11319fc..d19c2cb 100644
--- a/extensions/openpower-pels/host_interface.hpp
+++ b/extensions/openpower-pels/host_interface.hpp
@@ -110,6 +110,19 @@
         return _defaultHostFullRetryDelay;
     }
 
+    /**
+     * @brief Returns the amount of time to wait after the host is up
+     *        before sending commands.
+     *
+     * In this class to help with mocking.
+     *
+     * @return milliseconds - The amount of time to wait
+     */
+    virtual std::chrono::milliseconds getHostUpDelay() const
+    {
+        return _defaultHostUpDelay;
+    }
+
     using ResponseFunction = std::function<void(ResponseStatus)>;
 
     /**
@@ -226,6 +239,12 @@
      *        was full before sending the PEL again.
      */
     const std::chrono::milliseconds _defaultHostFullRetryDelay{60000};
+
+    /**
+     * @brief The default amount of time to wait after the host is up
+     *        before sending up the PELs.
+     */
+    const std::chrono::milliseconds _defaultHostUpDelay{60000};
 };
 
 } // namespace pels
diff --git a/extensions/openpower-pels/host_notifier.cpp b/extensions/openpower-pels/host_notifier.cpp
index 496f1c3..a89af1d 100644
--- a/extensions/openpower-pels/host_notifier.cpp
+++ b/extensions/openpower-pels/host_notifier.cpp
@@ -33,7 +33,10 @@
                 std::bind(std::mem_fn(&HostNotifier::retryTimerExpired), this)),
     _hostFullTimer(
         _hostIface->getEvent(),
-        std::bind(std::mem_fn(&HostNotifier::hostFullTimerExpired), this))
+        std::bind(std::mem_fn(&HostNotifier::hostFullTimerExpired), this)),
+    _hostUpTimer(
+        _hostIface->getEvent(),
+        std::bind(std::mem_fn(&HostNotifier::hostUpTimerExpired), this))
 {
     // Subscribe to be told about new PELs.
     _repo.subscribeToAdds(subscriptionName,
@@ -64,7 +67,8 @@
     // Start sending logs if the host is running
     if (!_pelQueue.empty() && _dataIface.isHostUp())
     {
-        doNewLogNotify();
+        log<level::DEBUG>("Host is already up at startup");
+        _hostUpTimer.restartOnce(_hostIface->getHostUpDelay());
     }
 }
 
@@ -74,6 +78,12 @@
     _dataIface.unsubscribeFromHostStateChange(subscriptionName);
 }
 
+void HostNotifier::hostUpTimerExpired()
+{
+    log<level::DEBUG>("Host up timer expired");
+    doNewLogNotify();
+}
+
 bool HostNotifier::addPELToQueue(const PEL& pel)
 {
     if (enqueueRequired(pel.id()))
@@ -172,8 +182,8 @@
 
     _pelQueue.push_back(pel.id());
 
-    // Notify shouldn't happen if host is down or full
-    if (!_dataIface.isHostUp() || _hostFull)
+    // Notify shouldn't happen if host is down, not up long enough, or full
+    if (!_dataIface.isHostUp() || _hostFull || _hostUpTimer.isEnabled())
     {
         return;
     }
@@ -321,8 +331,7 @@
     if (hostUp && !_pelQueue.empty())
     {
         log<level::DEBUG>("Host state change to on");
-
-        doNewLogNotify();
+        _hostUpTimer.restartOnce(_hostIface->getHostUpDelay());
     }
     else if (!hostUp)
     {
@@ -344,6 +353,11 @@
         {
             _hostFullTimer.setEnabled(false);
         }
+
+        if (_hostUpTimer.isEnabled())
+        {
+            _hostUpTimer.setEnabled(false);
+        }
     }
 }
 
diff --git a/extensions/openpower-pels/host_notifier.hpp b/extensions/openpower-pels/host_notifier.hpp
index 24c3f6f..0c907e0 100644
--- a/extensions/openpower-pels/host_notifier.hpp
+++ b/extensions/openpower-pels/host_notifier.hpp
@@ -257,6 +257,14 @@
     void hostFullTimerExpired();
 
     /**
+     * @brief The function called when the host up retry timer
+     *        expires.
+     *
+     * It kicks off sending the new log commands.
+     */
+    void hostUpTimerExpired();
+
+    /**
      * @brief Stops an in progress command
      *
      * In progress meaning after the send but before the response.
@@ -320,6 +328,12 @@
     sdeventplus::utility::Timer<sdeventplus::ClockId::Monotonic> _hostFullTimer;
 
     /**
+     * @brief The host up timer, used to kick off sending commands to the
+     *        host after a delay after the host is up.
+     */
+    sdeventplus::utility::Timer<sdeventplus::ClockId::Monotonic> _hostUpTimer;
+
+    /**
      * @brief The object used to dispatch a new PEL send from the
      *        event loop, so the calling function can be returned from
      *        first.
diff --git a/test/openpower-pels/host_notifier_test.cpp b/test/openpower-pels/host_notifier_test.cpp
index 9a49a82..1906ba3 100644
--- a/test/openpower-pels/host_notifier_test.cpp
+++ b/test/openpower-pels/host_notifier_test.cpp
@@ -300,7 +300,7 @@
 
     dataIface.changeHostState(true);
 
-    runEvents(sdEvent, 1);
+    runEvents(sdEvent, 2);
 
     // It was sent up
     EXPECT_EQ(mockHostIface->numCmdsProcessed(), 1);
@@ -355,7 +355,7 @@
     HostNotifier notifier{repo, dataIface, std::move(hostIface)};
 
     // It should start sending PELs right away
-    runEvents(sdEvent, 2);
+    runEvents(sdEvent, 3);
 
     EXPECT_EQ(mockHostIface->numCmdsProcessed(), 2);
     EXPECT_EQ(notifier.queueSize(), 0);
@@ -466,7 +466,7 @@
     EXPECT_EQ(notifier.queueSize(), 1);
 
     // Dispatch it
-    runEvents(sdEvent, 1);
+    runEvents(sdEvent, 2);
 
     // It was sent and off the queue
     EXPECT_EQ(notifier.queueSize(), 0);
@@ -505,7 +505,7 @@
 
     dataIface.changeHostState(true);
 
-    runEvents(sdEvent, 2);
+    runEvents(sdEvent, 3);
 
     // The were both sent.
     EXPECT_EQ(mockHostIface->numCmdsProcessed(), 2);
@@ -518,7 +518,7 @@
 
     // Power back on and send them again
     dataIface.changeHostState(true);
-    runEvents(sdEvent, 2);
+    runEvents(sdEvent, 3);
 
     EXPECT_EQ(mockHostIface->numCmdsProcessed(), 4);
     EXPECT_EQ(notifier.queueSize(), 0);
diff --git a/test/openpower-pels/mocks.hpp b/test/openpower-pels/mocks.hpp
index da7c060..63786c4 100644
--- a/test/openpower-pels/mocks.hpp
+++ b/test/openpower-pels/mocks.hpp
@@ -146,6 +146,17 @@
     }
 
     /**
+     * @brief Returns the amount of time to wait after the host is up
+     *        before sending commands.
+     *
+     * @return milliseconds - The amount of time to wait
+     */
+    virtual std::chrono::milliseconds getHostUpDelay() const override
+    {
+        return std::chrono::milliseconds(0);
+    }
+
+    /**
      * @brief Returns the number of commands processed
      */
     size_t numCmdsProcessed() const