Additional tracing for shutdown events

Hit an issue where a shutdown was called but all that is
traced is a msgQ pointer.  These traces should help associate the
msgQ pointer to an actual task being shutdown.

Change-Id: Ic22fdde1a146eec90f26d557e8af1ddec3c85c4e
CQ:SW443508
Reviewed-on: http://rchgit01.rchland.ibm.com/gerrit1/65766
Tested-by: Jenkins Server <pfd-jenkins+hostboot@us.ibm.com>
Tested-by: Jenkins OP Build CI <op-jenkins+hostboot@us.ibm.com>
Tested-by: Jenkins OP HW <op-hw-jenkins+hostboot@us.ibm.com>
Reviewed-by: Daniel M. Crowell <dcrowell@us.ibm.com>

src/include/usr/initservice/initserviceif.H

@@ -88,13 +88,16 @@ void registerBlock(void* i_vaddr, uint64_t i_size, BlockPriority i_priority);
 /**
  * @brief Register a service to be notified during shutdown
  *
+ * @param[in] i_compID, component registering event
  * @param[in] i_msgQ, A message queue to send a message to on shutdown
  * @param[in] i_msgType, The message type to send.
  * @param[in] i_priority, See EventPriority
+ *
  * @return true - i_msgQ registered
  *         false - i_msgQ already registered. Not registered again.
  */
-bool registerShutdownEvent(msg_q_t i_msgQ,
+bool registerShutdownEvent(compId_t i_compID,
+                           msg_q_t i_msgQ,
                            uint32_t i_msgType,
                            EventPriority_t i_priority = NO_PRIORITY);
 

src/usr/console/daemon.C

@@ -61,7 +61,7 @@ namespace CONSOLE
     {
         // Detach and register daemon with shutdown path.
         task_detach();
-        INITSERVICE::registerShutdownEvent(g_msgq, SYNC,
+        INITSERVICE::registerShutdownEvent(CONSOLE_COMP_ID, g_msgq, SYNC,
                                            INITSERVICE::CONSOLE_PRIORITY);
 
         // Create a default output UART device if there isn't already one.

src/usr/errl/errlmanager.C

@@ -218,8 +218,10 @@ void ErrlManager::msgQueueInit ()
     iv_msgQ = msg_q_create();
 
     // Register for error log manager shutdown event
-    INITSERVICE::registerShutdownEvent( iv_msgQ, ERRLOG_SHUTDOWN_TYPE,
-                                                  INITSERVICE::NO_PRIORITY );
+    INITSERVICE::registerShutdownEvent( ERRL_COMP_ID,
+                                        iv_msgQ,
+                                        ERRLOG_SHUTDOWN_TYPE,
+                                        INITSERVICE::NO_PRIORITY );
 
     TRACFCOMP( g_trac_errl, EXIT_MRK "ErrlManager::msgQueueInit" );
     return;

src/usr/initservice/baseinitsvc/initservice.C

@@ -72,9 +72,18 @@ namespace   SPLESS
 
 namespace   INITSERVICE
 {
+trace_desc_t *g_trac_initsvc = nullptr;
 
-trace_desc_t *g_trac_initsvc = NULL;
-TRAC_INIT(&g_trac_initsvc, "INITSVC", 2*KILOBYTE );
+/**
+ *  @brief  Instantiates trace object for INITSVC traces (if necessary)
+ */
+void initTrace()
+{
+    if ( nullptr == g_trac_initsvc )
+    {
+      TRACE::TracInit l_tmp(&g_trac_initsvc, "INITSVC", 2*KILOBYTE );
+    }
+}
 
 /**
  *  @brief  start() task entry procedure
@@ -83,6 +92,8 @@ TRAC_INIT(&g_trac_initsvc, "INITSVC", 2*KILOBYTE );
 extern "C"
 void* _start(void *ptr)
 {
+    initTrace();  // initialize trace descriptor for module start
+
     TRACFCOMP( g_trac_initsvc,
             "Executing Initialization Service module." );
 
@@ -615,6 +626,7 @@ InitService::InitService( ) :
     iv_iStep( 0 ),
     iv_iSubStep( 0 )
 {
+    initTrace();  // Initialize trace descriptor for external interface
     mutex_init(&iv_registryMutex);
 }
 
@@ -818,7 +830,9 @@ void InitService::doShutdown(uint64_t i_status,
             (i->msgPriority <= LAST_PRE_MEM_FLUSH_PRIORITY));
         ++i)
     {
-            TRACFCOMP(g_trac_initsvc,"notify priority=0x%x, queue=0x%x", i->msgPriority, i->msgQ );
+            TRACFCOMP(g_trac_initsvc, "notify priority=0x%x, queue=0x%x, "
+                "msgType=0x%x, componentID=0x%x", i->msgPriority, i->msgQ,
+                i->msgType, i->compID );
             l_msg->type = i->msgType;
             l_msg->data[0] = worst_status;
             (void)msg_sendrecv(i->msgQ,l_msg);
@@ -903,7 +917,8 @@ void doShutdownWithError ( uint64_t i_status, uint32_t i_error_info)
 }
 
 
-bool InitService::registerShutdownEvent(msg_q_t i_msgQ,
+bool InitService::registerShutdownEvent(compId_t i_compID,
+                                        msg_q_t i_msgQ,
                                         uint32_t i_msgType,
                                         EventPriority_t i_priority)
 {
@@ -928,8 +943,13 @@ bool InitService::registerShutdownEvent(msg_q_t i_msgQ,
 
         if(result)
         {
+            TRACFCOMP(g_trac_initsvc, "InitService::registerShutdownEvent: "
+                "componentID=0x%x, queue=0x%x, msgType=0x%x, priority=0x%x",
+                i_compID, i_msgQ, i_msgType, i_priority);
+
             // add it to the queue, we'll sort it before sending
-            iv_regMsgQ.push_back(regMsgQ_t(i_msgQ, i_msgType, i_priority));
+            iv_regMsgQ.push_back( regMsgQ_t(i_msgQ, i_msgType,
+                                            i_priority, i_compID) );
         }
     }
 
@@ -954,6 +974,11 @@ bool InitService::unregisterShutdownEvent(msg_q_t i_msgQ)
             // erase all instances
             if(r->msgQ == i_msgQ)
             {
+                TRACFCOMP(g_trac_initsvc,
+                    "InitService::unregisterShutdownEvent: "
+                    "componentID=0x%x, queue=0x%x, msgType=0x%x, priority=0x%x",
+                    r->compID, r->msgQ, r->msgType, r->msgPriority);
+
                 result = true;
                 iv_regMsgQ.erase(r);
             }
@@ -989,12 +1014,14 @@ void InitService::GetIstepData( uint8_t & o_step,
 /**
  * @see src/include/usr/initservice/initservicif.H
  */
-bool registerShutdownEvent(msg_q_t i_msgQ,
+bool registerShutdownEvent(compId_t i_compID,
+                           msg_q_t i_msgQ,
                            uint32_t i_msgType,
                            EventPriority_t i_priority)
 {
     return
-    Singleton<InitService>::instance().registerShutdownEvent(i_msgQ,
+    Singleton<InitService>::instance().registerShutdownEvent(i_compID,
+                                                             i_msgQ,
                                                              i_msgType,
                                                              i_priority);
 }

src/usr/initservice/baseinitsvc/initservice.H

@@ -95,15 +95,18 @@ public:
         msg_q_t msgQ;
         uint32_t msgType;
         uint32_t msgPriority;
+        compId_t compID;
 
         /**
          * @brief Constructor
          */
         regMsgQ_t(msg_q_t i_msgQ,
                   uint32_t i_msgType,
-                  EventPriority_t i_priority) :
+                  EventPriority_t i_priority,
+                  compId_t i_compId) :
             msgQ(i_msgQ), msgType(i_msgType),
-                  msgPriority((uint32_t)i_priority) {}
+                  msgPriority((uint32_t)i_priority),
+                  compID(i_compId) {}
 
         // allow us to sort the queue based on priority
         bool operator < (const regMsgQ_t &msg ) const
@@ -193,14 +196,16 @@ public:
     /**
      * @brief Register a service to be notified during shutdown
      *
+     * @param[in] i_compID, component registering event
      * @param[in] i_msgQ, A message queue to send a message to on shutdown
      * @param[in] i_msgType, The message type to send.
      * @param[in] i_priority, @See src/include/usr/initservice/initserviceif.H
      *
      * @return true  - i_msgQ registered
      *         false - i_msgQ already registered.- not registered again.
      */
-    bool registerShutdownEvent(msg_q_t i_msgQ,
+    bool registerShutdownEvent(compId_t i_compID,
+                               msg_q_t i_msgQ,
                                uint32_t i_msgType,
                                EventPriority_t i_priority);
 

src/usr/intr/intrrp.C

@@ -404,7 +404,7 @@ errlHndl_t IntrRp::_init()
         task_create(IntrRp::msg_handler, NULL);
 
         // Register event to be called on shutdown
-        INITSERVICE::registerShutdownEvent(iv_msgQ,
+        INITSERVICE::registerShutdownEvent(INTR_COMP_ID, iv_msgQ,
                                            MSG_INTR_SHUTDOWN,
                                            INITSERVICE::INTR_PRIORITY);
 

src/usr/ipmi/ipmirp.C

@@ -5,7 +5,7 @@
 /*                                                                        */
 /* OpenPOWER HostBoot Project                                             */
 /*                                                                        */
-/* Contributors Listed Below - COPYRIGHT 2012,2017                        */
+/* Contributors Listed Below - COPYRIGHT 2012,2018                        */
 /* [+] International Business Machines Corp.                              */
 /*                                                                        */
 /*                                                                        */
@@ -464,7 +464,7 @@ void IpmiRP::handlePowerMessage( IPMI::oemSEL* i_event )
         INITSERVICE::stopIpl();
 
         // register for the post memory flush callback
-        INITSERVICE::registerShutdownEvent(iv_msgQ,
+        INITSERVICE::registerShutdownEvent(IPMI_COMP_ID, iv_msgQ,
                         IPMI::MSG_STATE_GRACEFUL_SHUTDOWN,
                         INITSERVICE::POST_MEM_FLUSH_NOTIFY_LAST);
 
@@ -551,7 +551,8 @@ void IpmiRP::execute(void)
     //      as we don't want to accidentally get this message after
     //      interrupt processing has stopped in case we need intr to
     //      finish flushing the pipe.
-    INITSERVICE::registerShutdownEvent(iv_msgQ, IPMI::MSG_STATE_SHUTDOWN,
+    INITSERVICE::registerShutdownEvent(IPMI_COMP_ID, iv_msgQ,
+                                       IPMI::MSG_STATE_SHUTDOWN,
                                        INITSERVICE::MBOX_PRIORITY);
 
     // Start the thread that waits for timeouts
@@ -710,7 +711,7 @@ void IpmiRP::execute(void)
                 iv_chassis_power_mod = IPMI::CHASSIS_POWER_RESET;
 
                 // register for the post memory flush callback
-                INITSERVICE::registerShutdownEvent(iv_msgQ,
+                INITSERVICE::registerShutdownEvent(IPMI_COMP_ID, iv_msgQ,
                         IPMI::MSG_STATE_GRACEFUL_SHUTDOWN,
                         INITSERVICE::POST_MEM_FLUSH_NOTIFY_LAST);
 

src/usr/isteps/istep21/call_host_start_payload.C

@@ -206,9 +206,9 @@ void* call_host_start_payload (void *io_pArgs)
         msg_q_t l_msgQ = msg_q_create();
 
         // Register event to be called on shutdown
-        INITSERVICE::registerShutdownEvent(l_msgQ,
-                                           MSG_PRE_SHUTDOWN_INITS,
-                                           INITSERVICE::PRESHUTDOWN_INIT_PRIORITY);
+        INITSERVICE::registerShutdownEvent(ISTEP_COMP_ID, l_msgQ,
+                                       MSG_PRE_SHUTDOWN_INITS,
+                                       INITSERVICE::PRESHUTDOWN_INIT_PRIORITY);
 
         // Create a task to handle the messages
         task_create(ISTEP_21::msg_handler, l_msgQ);

src/usr/mbox/mailboxsp.C

@@ -209,7 +209,8 @@ errlHndl_t MailboxSp::_init()
         MBOX::send(FSP_MAILBOX_MSGQ,msg);
 
         // Register for shutdown
-        INITSERVICE::registerShutdownEvent(iv_msgQ,
+        INITSERVICE::registerShutdownEvent(MBOX_COMP_ID,
+                                           iv_msgQ,
                                            MSG_MBOX_SHUTDOWN,
                                            INITSERVICE::MBOX_PRIORITY);
 

src/usr/pnor/pnorrp.C

@@ -280,9 +280,10 @@ void PnorRP::initDaemon()
         // create a message queue
         iv_msgQ = msg_q_create();
 
-        INITSERVICE::registerShutdownEvent( iv_msgQ,
-                PNOR::MSG_SHUTDOWN,
-                INITSERVICE::PNOR_RP_PRIORITY);
+        INITSERVICE::registerShutdownEvent( PNOR_COMP_ID,
+                                            iv_msgQ,
+                                            PNOR::MSG_SHUTDOWN,
+                                            INITSERVICE::PNOR_RP_PRIORITY );
 
         // create a Block, passing in the message queue
         int rc = mm_alloc_block( iv_msgQ, (void*) BASE_VADDR, TOTAL_SIZE );

src/usr/secureboot/trusted/trustedboot.C

@@ -1275,7 +1275,8 @@ void* tpmDaemon(void* unused)
     // Register shutdown events with init service.
     //      Done at the "end" of shutdown processing.
     // This will flush any other messages (PCR extends) and terminate task
-    INITSERVICE::registerShutdownEvent(systemData.msgQ,
+    INITSERVICE::registerShutdownEvent(TRBOOT_COMP_ID,
+                                       systemData.msgQ,
                                        TRUSTEDBOOT::MSG_TYPE_SHUTDOWN);
 
     Message* tb_msg = nullptr;

src/usr/trace/daemon/daemon.C

@@ -114,10 +114,12 @@ namespace TRACEDAEMON
         //      The one at the end will only be useful in non-FSP environments
         //      for continuous trace, because the mailbox is already shutdown.
         //
-        INITSERVICE::registerShutdownEvent(iv_service->iv_daemon->iv_queue,
+        INITSERVICE::registerShutdownEvent(TRACE_COMP_ID,
+                                           iv_service->iv_daemon->iv_queue,
                                            DaemonIf::TRACE_DAEMON_SIGNAL,
                                            INITSERVICE::HIGHEST_PRIORITY);
-        INITSERVICE::registerShutdownEvent(iv_service->iv_daemon->iv_queue,
+        INITSERVICE::registerShutdownEvent(TRACE_COMP_ID,
+                                           iv_service->iv_daemon->iv_queue,
                                            DaemonIf::TRACE_DAEMON_SIGNAL,
                                            INITSERVICE::LOWEST_PRIORITY);