Don't discard buffer unless >1 second has elapse since console release.

If the log subsystem releases the console, the log buffer is normally
discarded when it is re-acquired (so that stale messages are not then
displayed). This change allows for a 1 second window, so that
short-running foreground jobs don't prevent log messages being seen.

diff --git a/src/dinit-log.cc b/src/dinit-log.cc
index fe5dd73187425a5fc4ae0bd15b08b47671fd4a70..cad22103d49cf60af9db34868fcb4827bd41b6ad 100644 (file)
--- a/src/dinit-log.cc
+++ b/src/dinit-log.cc
@@ -16,10 +16,10 @@
 //
 // Note that most actual functions for logging messages are found in the header, dinit-log.h.
 //
-// We have two separate log "streams": one for the console/stdout, one for the syslog facility. Both have a
-// circular buffer. Log messages are appended to the circular buffer (for the syslog stream, the messages
-// are prepended with a syslog priority indicator). Both streams start out inactive (release = true in
-// buffered_log_stream), which means they will buffer messages but not write them.
+// We have two separate log "streams": one for the console/stdout, one for the syslog facility (or log
+// file). Both have a circular buffer. Log messages are appended to the circular buffer (for a syslog
+// stream, the messages are prepended with a syslog priority indicator). Both streams start out inactive
+// (release = true in buffered_log_stream), which means they will buffer messages but not write them.
 //
 // The console log stream needs to be able to release the console, if a service is waiting to acquire it.
 // This is accomplished by calling flush_for_release() which then completes the output of the current
@@ -33,6 +33,8 @@ static bool log_format_syslog[2] = { false, true };
 
 static service_set *services = nullptr;  // Reference to service set
 
+dasynq::time_val release_time; // time the log was released
+
 using rearm = dasynq::rearm;
 
 namespace {
@@ -128,6 +130,11 @@ void buffered_log_stream::release_console()
         int flags = fcntl(1, F_GETFL, 0);
         fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
         services->pull_console_queue();
+        if (release) {
+            // release still set, we didn't immediately get the console back; record the
+            // time at which we released:
+            event_loop.get_time(release_time, clock_type::MONOTONIC);
+        }
     }
 }
 
@@ -299,7 +306,12 @@ void enable_console_log(bool enable) noexcept
 
 void discard_console_log_buffer() noexcept
 {
-    log_stream[DLOG_CONS].discard();
+    // Only discard if more than a second has passed since we released the console.
+    dasynq::time_val current_time;
+    event_loop.get_time(current_time, clock_type::MONOTONIC);
+    if (current_time - release_time >= dasynq::time_val(1, 0)) {
+        log_stream[DLOG_CONS].discard();
+    }
 }
 
 // Variadic method to calculate the sum of string lengths:

diff --git a/src/includes/service.h b/src/includes/service.h
index 89592068bd13e475ffe8d73f6f786f0959fc3c1b..c532d97ac2e9113d8d7d6b4392015067f34a2914 100644 (file)
--- a/src/includes/service.h
+++ b/src/includes/service.h
@@ -859,6 +859,10 @@ class service_set
     void pull_console_queue() noexcept
     {
         if (console_queue.is_empty()) {
+            // Discard the log buffer now, because we've potentially blocked output for a while
+            // and allowed it to fill with stale messages. (If not much time has passed, the
+            // request to discard will be ignored anyway).
+            discard_console_log_buffer();
             enable_console_log(true);
         }
         else {

diff --git a/src/service.cc b/src/service.cc
index aa00cee8f18925435ea6fc07acbbbc9be7fcd086..2fc07b3504a92fa7719ac59423966534a45c900e 100644 (file)
--- a/src/service.cc
+++ b/src/service.cc
@@ -54,7 +54,6 @@ void service_record::stopped() noexcept
 {
     if (have_console) {
         bp_sys::tcsetpgrp(0, bp_sys::getpgrp());
-        discard_console_log_buffer();
         release_console();
     }