Log format during shutdown (Issue 480)

hscmisc.c

@@ -1462,20 +1462,45 @@ static void cancel_wait_for_guest_quiesce()
 /*  completely exited beforehand.                                    */
 /*                                                                   */
 /*-------------------------------------------------------------------*/
+/*  Shutdown initialation steps:                                     */
+/*     1. set shutbegin=TRUE to notify logger to synchronize it's    */
+/*        shutdown steps and set system shutdown request             */
+/*     2. short spin-wait for logger to set system shutdown request  */
+/*     3  ensure system shutdown requested                           */
+/*-------------------------------------------------------------------*/
 
 static void do_shutdown_now()
 {
+    int     spincount = 16;           // spin-wait count for logger-thread
+    bool    loggersetshutdown = TRUE; // assume logger sets system shutdown
+
+    ASSERT( !sysblk.shutfini );   // (sanity check)
+    ASSERT( !sysblk.shutdown );   // (sanity check)
+    sysblk.shutfini = FALSE;      // (shutdown NOT finished yet)
+    sysblk.shutdown = FALSE;      // (system shutdown NOT initiated yet)
+    sysblk.shutbegin = TRUE;      // (begin system shutdown)
+
     // "Begin Hercules shutdown"
     WRMSG( HHC01420, "I" );
 
     // (hack to prevent minor message glitch during shutdown)
     fflush( stdout );
     fflush( stderr );
-    USLEEP( 10000 );
 
-    ASSERT( !sysblk.shutfini );   // (sanity check)
-    sysblk.shutfini = FALSE;      // (shutdown NOT finished yet)
-    sysblk.shutdown = TRUE;       // (system shutdown initiated)
+    // spin-wait for logger to initiate system shutdown
+    while ( !sysblk.shutdown && spincount-- )
+    {
+        log_wakeup( NULL );
+        USLEEP( 5000 );
+        //LOGMSG("hsmisc.c: shutdown spin-wait on logger: count: %d, shutdown: %d\n", spincount, (int) sysblk.shutdown);
+    }
+
+    // safety measure: ensure system shutdown requested
+    if ( !sysblk.shutdown )
+    {
+        sysblk.shutdown = TRUE;       // (system shutdown initiated)
+        loggersetshutdown = FALSE;    // logger didn't set system shutdown
+    }
 
     /* Wakeup I/O subsystem to start I/O subsystem shutdown */
     {
@@ -1495,10 +1520,16 @@ static void do_shutdown_now()
     fflush( stderr );
     USLEEP( 10000 );
 
+    // if logger didn't set shutdown, handle unredirect
+    if ( !loggersetshutdown )
+    {
+
 #if !defined( _MSVC_ )
-    logger_unredirect();
+                logger_unredirect();
 #endif
 
+    }
+
     hdl_atexit();
 
     // "All termination routines complete"

hstructs.h

@@ -990,6 +990,7 @@ atomic_update64( &sysblk.txf_stats[ contran ? 1 : 0 ].txf_ ## ctr, +1 )
                 insttrace:1,            /* 1 = Inst trace enabled    */
                 tfnostop:1,             /* 1 = tf continue tracing   */
                 instbreak:1,            /* 1 = Inst break enabled    */
+                shutbegin:1,            /* 1 = shutdown begin req    */
                 shutdown:1,             /* 1 = shutdown requested    */
                 shutfini:1,             /* 1 = shutdown complete     */
                 shutimmed:1,            /* 1 = shutdown req immed    */

logger.c

@@ -29,6 +29,7 @@
 
 static COND  logger_cond;
 static LOCK  logger_lock;
+static LOCK  stamp_lock;
 
 static int   logger_init_flg = FALSE;   /* reset by logger_init()    */
 
@@ -299,8 +300,19 @@ DLL_EXPORT void logger_timestamped_logfile_write( const void* pBuff, size_t nByt
     if (logger_hrdcpy)
     {
         if (STAMPLOG)
-            logger_logfile_timestamp();
-        logger_logfile_write( pBuff, nBytes );
+        {
+            /* during shutdown ensure that timestamp and message are one line */
+            obtain_lock( &stamp_lock );
+            {
+                logger_logfile_timestamp();
+                logger_logfile_write( pBuff, nBytes );
+            }
+            release_lock( &stamp_lock );
+        }
+        else
+        {
+            logger_logfile_write( pBuff, nBytes );
+        }
     }
 }
 
@@ -445,6 +457,27 @@ static void* logger_thread( void* arg )
         }
         release_lock( &logger_lock );
 
+        /* begin shutdown requested
+           - handle all logger pre-shutdown actions
+           - set system shutdown flag
+        */
+        if (sysblk.shutbegin)
+        {
+            obtain_lock( &logger_lock );
+            {
+                if ( !sysblk.shutdown )
+                {
+
+#if !defined( _MSVC_ )
+                    logger_unredirect();
+#endif
+
+                    sysblk.shutdown = TRUE;       // (system shutdown initiated)
+                }
+            }
+            release_lock( &logger_lock );
+        }
+
     } /* end while (...) */
 
     logger_active = 0;
@@ -482,6 +515,7 @@ DLL_EXPORT void logger_init( void )
 
     initialize_condition( &logger_cond );
     initialize_lock( &logger_lock );
+    initialize_lock( &stamp_lock );
     logger_init_flg = TRUE;
 
     obtain_lock( &logger_lock );