Fix log flushing and clean up output in boot failure handling.

[oweals/dinit.git] / src / dinit-log.cc

diff --git a/src/dinit-log.cc b/src/dinit-log.cc
index 723fd676075c68bab6132ad41738d81a8d3df130..dbdf868760c34a99e41348292263b81a279a189f 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
@@ -28,10 +28,13 @@
 extern eventloop_t event_loop;
 
 static bool log_current_line[2];  // Whether the current line is being logged (for console, main log)
-loglevel_t log_level[2] = { loglevel_t::WARN, loglevel_t::INFO };
+loglevel_t log_level[2] = { loglevel_t::INFO, loglevel_t::WARN };
+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 {
@@ -127,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);
+        }
     }
 }
 
@@ -148,6 +156,8 @@ rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexce
 {
     if ((! partway) && (! special) && discarded) {
         special_buf = "dinit: *** log message discarded due to full buffer ***\n";
+        special = true;
+        discarded = false;
         msg_index = 0;
     }
 
@@ -159,7 +169,7 @@ rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexce
             if (start + r > end) {
                 // All written: go on to next message in queue
                 special = false;
-                partway = false;
+                discarded = false;
                 msg_index = 0;
                 
                 if (release) {
@@ -251,11 +261,15 @@ rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexce
 
 // Initialise the logging subsystem
 // Potentially throws std::bad_alloc or std::system_error
-void init_log(service_set *sset)
+void init_log(service_set *sset, bool syslog_format)
 {
     services = sset;
     log_stream[DLOG_CONS].add_watch(event_loop, STDOUT_FILENO, dasynq::OUT_EVENTS, false);
     enable_console_log(true);
+
+    // The main (non-console) log won't be active yet, but we set the format here so that we
+    // buffer messages in the correct format:
+    log_format_syslog[DLOG_MAIN] = syslog_format;
 }
 
 // Set up the main log to output to the given file descriptor.
@@ -292,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:
@@ -357,10 +376,14 @@ template <typename ... T> static void do_log(loglevel_t lvl, bool to_cons, T ...
     push_to_log(DLOG_CONS, args...);
     
     if (log_current_line[DLOG_MAIN]) {
-        char svcbuf[10];
-        snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
-        
-        push_to_log(DLOG_MAIN, svcbuf, args...);
+        if (log_format_syslog[DLOG_MAIN]) {
+            char svcbuf[10];
+            snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
+            push_to_log(DLOG_MAIN, svcbuf, args...);
+        }
+        else {
+            push_to_log(DLOG_MAIN, args...);
+        }
     }
 }
 
@@ -377,10 +400,14 @@ template <typename ... T> static void do_log_main(T ... args) noexcept
     log_current_line[DLOG_CONS] = false;
     log_current_line[DLOG_MAIN] = true;
     
-    char svcbuf[10];
-    snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | LOG_NOTICE);
-    
-    push_to_log(DLOG_MAIN, svcbuf, args...);
+    if (log_format_syslog[DLOG_MAIN]) {
+        char svcbuf[10];
+        snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | LOG_NOTICE);
+        push_to_log(DLOG_MAIN, svcbuf, args...);
+    }
+    else {
+        push_to_log(DLOG_MAIN, args...);
+    }
 }
 
 // Log a message. A newline will be appended.
@@ -426,9 +453,11 @@ void log_msg_begin(loglevel_t lvl, const char *msg) noexcept
 
     // Prepend the syslog priority level string ("<N>") for the main log:
     if (log_current_line[DLOG_MAIN]) {
-        char svcbuf[10];
-        snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
-        do_log_part(DLOG_MAIN, svcbuf);
+        if (log_format_syslog[DLOG_MAIN]) {
+            char svcbuf[10];
+            snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
+            do_log_part(DLOG_MAIN, svcbuf);
+        }
     }
 
     for (int i = 0; i < 2; i++) {