Use bp_sys aliases to write from log
[oweals/dinit.git] / src / dinit-log.cc
index 8465520a01182bf77cd0f0bda3c3a2cc0976ab88..e0ee69a369e635ba374f05f05312a9d185db1b19 100644 (file)
@@ -1,4 +1,3 @@
-#include <iostream>
 #include <algorithm>
 
 #include <unistd.h>
 //
 // 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
 // message (if any) and then assigns the console to a waiting service.
 
 extern eventloop_t event_loop;
+extern bool external_log_open;
 
 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::WARN };
+static bool log_format_syslog[2] = { false, true };
 
 static service_set *services = nullptr;  // Reference to service set
 
+loglevel_t log_level[2] = { loglevel_t::INFO, loglevel_t::WARN };
+bool console_service_status = true;  // show service status messages to console?
+
+dasynq::time_val release_time; // time the log was released
+
 using rearm = dasynq::rearm;
 
 namespace {
@@ -42,7 +47,7 @@ class buffered_log_stream : public eventloop_t::fd_watcher_impl<buffered_log_str
     // Outgoing:
     bool partway = false;     // if we are partway throught output of a log message
     bool discarded = false;   // if we have discarded a message
-    bool release = true;      // if we should inhibit output and release console
+    bool release = true;      // if we should inhibit output and release console when possible
 
     // A "special message" is not stored in the circular buffer; instead
     // it is delivered from an external buffer not managed by BufferedLogger.
@@ -109,17 +114,15 @@ class buffered_log_stream : public eventloop_t::fd_watcher_impl<buffered_log_str
         discarded = true;
     }
 
+    void watch_removed() noexcept override;
+
     private:
     void release_console();
 };
-}
 
 // Two log streams:
 // (One for main log, one for console)
-static buffered_log_stream log_stream[2];
-
-constexpr static int DLOG_MAIN = 0; // main log facility
-constexpr static int DLOG_CONS = 1; // console
+buffered_log_stream log_stream[2];
 
 void buffered_log_stream::release_console()
 {
@@ -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);
+        }
     }
 }
 
@@ -136,10 +144,14 @@ void buffered_log_stream::flush_for_release()
     
     // Try to flush any messages that are currently buffered. (Console is non-blocking
     // so it will fail gracefully).
-    if (fd_event(event_loop, fd, dasynq::OUT_EVENTS) == rearm::DISARM) {
+    rearm rearm_val = fd_event(event_loop, fd, dasynq::OUT_EVENTS);
+    if (rearm_val == rearm::DISARM) {
         // Console has already been released at this point.
         set_enabled(event_loop, false);
     }
+    if (rearm_val == rearm::REMOVE) {
+        deregister(event_loop);
+    }
     // fd_event didn't want to disarm, so must be partway through a message; will
     // release when it's finished.
 }
@@ -148,18 +160,21 @@ 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;
     }
 
     if ((! partway) && special) {
         const char * start = special_buf + msg_index;
-        const char * end = std::find(special_buf + msg_index, (const char *)nullptr, '\n');
-        int r = write(fd, start, end - start + 1);
+        const char * end = start;
+        while (*end != '\n') end++;
+        int r = bp_sys::write(fd, start, end - start + 1);
         if (r >= 0) {
             if (start + r > end) {
                 // All written: go on to next message in queue
                 special = false;
-                partway = false;
+                discarded = false;
                 msg_index = 0;
                 
                 if (release) {
@@ -224,7 +239,7 @@ rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexce
             iovs_to_write = 2;
         }
         
-        ssize_t r = writev(fd, logiov, iovs_to_write);
+        ssize_t r = bp_sys::writev(fd, logiov, iovs_to_write);
 
         if (r >= 0) {
             bool complete = (r == len) && will_complete;
@@ -249,13 +264,32 @@ rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexce
     return rearm::REARM;
 }
 
+void buffered_log_stream::watch_removed() noexcept
+{
+    if (fd > STDERR_FILENO) {
+        close(fd);
+        fd = -1;
+    }
+    // Here we rely on there only being two logs, console and "main"; we can check if we are the
+    // main log via identity:
+    if (&log_stream[DLOG_MAIN] == this) {
+        external_log_open = false;
+    }
+}
+
+} // end namespace
+
 // 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.
@@ -268,7 +302,8 @@ void setup_main_log(int fd)
 
 bool is_log_flushed() noexcept
 {
-    return log_stream[DLOG_CONS].current_index == 0;
+    return log_stream[DLOG_CONS].current_index == 0 &&
+            (log_stream[DLOG_MAIN].fd == -1 || log_stream[DLOG_MAIN].current_index == 0);
 }
 
 // Enable or disable console logging. If disabled, console logging will be disabled on the
@@ -292,7 +327,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,18 +397,24 @@ 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...);
+        }
     }
 }
 
 template <typename ... T> static void do_log_cons(T ... args) noexcept
 {
-    log_current_line[DLOG_CONS] = true;
-    log_current_line[DLOG_MAIN] = false;
-    push_to_log(DLOG_CONS, args...);
+    if (console_service_status) {
+        log_current_line[DLOG_CONS] = true;
+        log_current_line[DLOG_MAIN] = false;
+        push_to_log(DLOG_CONS, args...);
+    }
 }
 
 // Log to the main facility at NOTICE level
@@ -377,10 +423,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.
@@ -395,7 +445,7 @@ void log(loglevel_t lvl, bool to_cons, const char *msg) noexcept
 }
 
 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
-template <typename T> static void do_log_part(int idx, T arg) noexcept
+static void do_log_part(int idx, const char *arg) noexcept
 {
     if (log_current_line[idx]) {
         int amount = sum_length(arg);
@@ -426,9 +476,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++) {