X-Git-Url: https://git.librecmc.org/?a=blobdiff_plain;f=src%2Fdinit-log.cc;h=43062f0f15a400ca938c7d188be6b9f9d5dcc28b;hb=100650949c81204d8d52002e028aa8858a406bce;hp=50baaaa2feec3e7fc40d66b25f2848939d40949f;hpb=e047bb6dfc62942f31f07a335d76631b32c6b1f4;p=oweals%2Fdinit.git diff --git a/src/dinit-log.cc b/src/dinit-log.cc index 50baaaa..43062f0 100644 --- a/src/dinit-log.cc +++ b/src/dinit-log.cc @@ -3,8 +3,10 @@ #include #include +#include +#include -#include "dasync.h" +#include "dasynq.h" #include "service.h" #include "dinit-log.h" @@ -12,23 +14,20 @@ extern EventLoop_t eventLoop; -LogLevel log_level = LogLevel::WARN; -LogLevel cons_log_level = LogLevel::WARN; - -static bool log_to_console = false; // whether we should output log messages to - // console immediately -static bool log_current_line; // Whether the current line is being logged +static bool log_current_line[2]; // Whether the current line is being logged (for console, main log) +LogLevel log_level[2] = { LogLevel::WARN, LogLevel::WARN }; static ServiceSet *service_set = nullptr; // Reference to service set namespace { -class BufferedLogStream : public PosixFdWatcher +class BufferedLogStream : public EventLoop_t::FdWatcher { private: // 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 // A "special message" is not stored in the circular buffer; instead // it is delivered from an external buffer not managed by BufferedLogger. @@ -43,31 +42,34 @@ class BufferedLogStream : public PosixFdWatcher // Incoming: int current_index = 0; // current/next incoming message index - int fd; + int fd = -1; void init(int fd) { this->fd = fd; + release = false; } Rearm gotEvent(EventLoop_t *loop, int fd, int flags) noexcept override; // Check whether the console can be released. void flushForRelease(); + void release_console(); + bool is_release_set() { return release; } // Commit a log message void commit_msg() { bool was_first = current_index == 0; current_index = log_buffer.get_length(); - if (was_first && log_to_console) { + if (was_first && ! release) { setEnabled(&eventLoop, true); - } + } } void rollback_msg() { - log_buffer.trim_to(current_index); + log_buffer.trim_to(current_index); } int get_free() @@ -89,10 +91,9 @@ static BufferedLogStream log_stream[2]; constexpr static int DLOG_MAIN = 0; // main log facility constexpr static int DLOG_CONS = 1; // console - -static void release_console() +void BufferedLogStream::release_console() { - if (! log_to_console) { + if (release) { int flags = fcntl(1, F_GETFL, 0); fcntl(1, F_SETFL, flags & ~O_NONBLOCK); service_set->pullConsoleQueue(); @@ -101,9 +102,11 @@ static void release_console() void BufferedLogStream::flushForRelease() { + release = true; + // Try to flush any messages that are currently buffered. (Console is non-blocking // so it will fail gracefully). - if (gotEvent(&eventLoop, fd, out_events) == Rearm::DISARM) { + if (gotEvent(&eventLoop, fd, OUT_EVENTS) == Rearm::DISARM) { // Console has already been released at this point. setEnabled(&eventLoop, false); } @@ -113,10 +116,8 @@ void BufferedLogStream::flushForRelease() Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept { - // TODO correct for the case that this is *not* the console log stream. - auto &log_stream = *this; - + if ((! partway) && log_stream.special) { char * start = log_stream.special_buf + log_stream.msg_index; char * end = std::find(log_stream.special_buf + log_stream.msg_index, (char *)nullptr, '\n'); @@ -128,7 +129,7 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept log_stream.partway = false; log_stream.msg_index = 0; - if (!log_to_console) { + if (release) { release_console(); return Rearm::DISARM; } @@ -138,10 +139,8 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept return Rearm::REARM; } } - else { - // spurious readiness - EAGAIN or EWOULDBLOCK? - // other error? - // TODO + else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) { + return Rearm::REMOVE; } return Rearm::REARM; } @@ -150,13 +149,19 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept // TODO issue special message if we have discarded a log message - if (log_stream.current_index == 0) { + if (current_index == 0) { release_console(); return Rearm::DISARM; } - char *ptr = log_stream.log_buffer.get_ptr(0); - int len = log_stream.log_buffer.get_contiguous_length(ptr); + // We try to find a complete line (terminated by '\n') in the buffer, and write it + // out. Since it may span the circular buffer end, it may consist of two distinct spans, + // and so we use writev to write them atomically. + + struct iovec logiov[2]; + + char *ptr = log_buffer.get_ptr(0); + int len = log_buffer.get_contiguous_length(ptr); char *creptr = ptr + len; // contiguous region end char *eptr = std::find(ptr, creptr, '\n'); @@ -168,7 +173,27 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept len = eptr - ptr; - int r = write(fd, ptr, len); + logiov[0].iov_base = ptr; + logiov[0].iov_len = len; + int iovs_to_write = 1; + + // Do we need the second span? + if (! will_complete && len != log_buffer.get_length()) { + ptr = log_buffer.get_buf_base(); + creptr = static_cast(logiov[1].iov_base) + log_buffer.get_length() - len; + eptr = std::find(ptr, creptr, '\n'); + if (eptr != creptr) { + eptr++; // include '\n' + // It should not ever be the case that we do not now have a complete message + will_complete = true; + } + logiov[1].iov_base = ptr; + logiov[1].iov_len = eptr - ptr; + len += logiov[1].iov_len; + iovs_to_write = 2; + } + + ssize_t r = writev(fd, logiov, iovs_to_write); if (r >= 0) { bool complete = (r == len) && will_complete; @@ -176,18 +201,15 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept log_stream.partway = ! complete; if (complete) { log_stream.current_index -= len; - if (log_stream.current_index == 0 || !log_to_console) { + if (log_stream.current_index == 0 || release) { // No more messages buffered / stop logging to console: release_console(); return Rearm::DISARM; } } } - else { - // TODO - // EAGAIN / EWOULDBLOCK? - // error? - return Rearm::REARM; + else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) { + return Rearm::REMOVE; } } @@ -196,13 +218,23 @@ Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept return Rearm::REARM; } -void init_log(ServiceSet *sset) noexcept +// Initialise the logging subsystem +// Potentially throws std::bad_alloc or std::system_error +void init_log(ServiceSet *sset) { service_set = sset; - log_stream[DLOG_CONS].registerWith(&eventLoop, STDOUT_FILENO, out_events); // TODO register in disabled state + log_stream[DLOG_CONS].registerWith(&eventLoop, STDOUT_FILENO, OUT_EVENTS); // TODO register in disabled state enable_console_log(true); } +// Set up the main log to output to the given file descriptor. +// Potentially throws std::bad_alloc or std::system_error +void setup_main_log(int fd) +{ + log_stream[DLOG_MAIN].init(fd); + log_stream[DLOG_MAIN].registerWith(&eventLoop, fd, OUT_EVENTS); +} + bool is_log_flushed() noexcept { return log_stream[DLOG_CONS].current_index == 0; @@ -213,6 +245,7 @@ bool is_log_flushed() noexcept // queued in the service set will acquire the console. void enable_console_log(bool enable) noexcept { + bool log_to_console = ! log_stream[DLOG_CONS].is_release_set(); if (enable && ! log_to_console) { // Console is fd 1 - stdout // Set non-blocking IO: @@ -221,10 +254,8 @@ void enable_console_log(bool enable) noexcept // Activate watcher: log_stream[DLOG_CONS].init(STDOUT_FILENO); log_stream[DLOG_CONS].setEnabled(&eventLoop, true); - log_to_console = true; } else if (! enable && log_to_console) { - log_to_console = false; log_stream[DLOG_CONS].flushForRelease(); } } @@ -236,7 +267,7 @@ static int sum_length(const char *arg) noexcept return std::strlen(arg); } -template static int sum_length(U first, T ... args) noexcept +template static int sum_length(const char * first, T ... args) noexcept { return sum_length(first) + sum_length(args...); } @@ -247,24 +278,37 @@ static void append(BufferedLogStream &buf, const char *s) buf.append(s, std::strlen(s)); } -template static void append(BufferedLogStream &buf, U u, T ... t) +template static void append(BufferedLogStream &buf, const char *u, T ... t) { append(buf, u); append(buf, t...); } -// Variadic method to log a sequence of strings as a single message: -template static void do_log(T ... args) noexcept +static int log_level_to_syslog_level(LogLevel l) { + switch (l) { + case LogLevel::DEBUG: + return LOG_DEBUG; + case LogLevel::INFO: + return LOG_INFO; + case LogLevel::WARN: + return LOG_WARNING; + case LogLevel::ERROR: + return LOG_ERR; + default: ; + } + + return LOG_CRIT; +} + +// Variadic method to log a sequence of strings as a single message to a particular facility: +template static void push_to_log(int idx, T ... args) noexcept +{ + if (! log_current_line[idx]) return; int amount = sum_length(args...); - if (log_stream[DLOG_CONS].get_free() >= amount) { - append(log_stream[DLOG_CONS], args...); - - bool was_first = (log_stream[DLOG_CONS].current_index == 0); - log_stream[DLOG_CONS].current_index += amount; - if (was_first && log_to_console) { - log_stream[DLOG_CONS].setEnabled(&eventLoop, true); - } + if (log_stream[idx].get_free() >= amount) { + append(log_stream[idx], args...); + log_stream[idx].commit_msg(); } else { // TODO mark a discarded message @@ -274,11 +318,37 @@ template static void do_log(T ... args) noexcept // Variadic method to potentially log a sequence of strings as a single message with the given log level: template static void do_log(LogLevel lvl, T ... args) noexcept { - if (lvl >= cons_log_level) { - do_log(args...); + log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS]; + log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN]; + 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...); } } +template 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...); +} + +// Log to the main facility at NOTICE level +template 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...); +} + // Log a message. A newline will be appended. void log(LogLevel lvl, const char *msg) noexcept { @@ -286,75 +356,78 @@ void log(LogLevel lvl, 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 static void do_log_part(T arg) noexcept +template static void do_log_part(int idx, T arg) noexcept { - int amount = sum_length(arg); - if (log_stream[DLOG_CONS].get_free() >= amount) { - append(log_stream[DLOG_CONS], arg); - } - else { - log_stream[DLOG_CONS].rollback_msg(); - log_current_line = false; - // TODO mark discarded message + if (log_current_line[idx]) { + int amount = sum_length(arg); + if (log_stream[idx].get_free() >= amount) { + append(log_stream[idx], arg); + } + else { + log_stream[idx].rollback_msg(); + log_current_line[idx] = false; + // TODO mark discarded message + } } } // Commit a message that was issued as a series of parts (via do_log_part). -static void do_log_commit() noexcept +static void do_log_commit(int idx) noexcept { - if (log_current_line) { - log_stream[DLOG_CONS].commit_msg(); + if (log_current_line[idx]) { + log_stream[idx].commit_msg(); } } // Log a multi-part message beginning void logMsgBegin(LogLevel lvl, const char *msg) noexcept { - // TODO use buffer - log_current_line = lvl >= log_level; - if (log_current_line) { - if (log_to_console) { - do_log_part("dinit: "); - do_log_part(msg); - } + log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS]; + log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN]; + + 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); + } + + for (int i = 0; i < 2; i++) { + do_log_part(i, "dinit: "); + do_log_part(i, msg); } } // Continue a multi-part log message void logMsgPart(const char *msg) noexcept { - // TODO use buffer - if (log_current_line) { - if (log_to_console) { - do_log_part(msg); - } - } + do_log_part(DLOG_CONS, msg); + do_log_part(DLOG_MAIN, msg); } // Complete a multi-part log message void logMsgEnd(const char *msg) noexcept { - // TODO use buffer - if (log_current_line) { - if (log_to_console) { - do_log_part(msg); - do_log_part("\n"); - do_log_commit(); - } + for (int i = 0; i < 2; i++) { + do_log_part(i, msg); + do_log_part(i, "\n"); + do_log_commit(i); } } void logServiceStarted(const char *service_name) noexcept { - do_log("[ OK ] ", service_name, "\n"); + do_log_cons("[ OK ] ", service_name, "\n"); + do_log_main("dinit: service ", service_name, " started.\n"); } void logServiceFailed(const char *service_name) noexcept { - do_log("[FAILED] ", service_name, "\n"); + do_log_cons("[FAILED] ", service_name, "\n"); + do_log_main("dinit: service ", service_name, " failed to start.\n"); } void logServiceStopped(const char *service_name) noexcept { - do_log("[STOPPD] ", service_name, "\n"); + do_log_cons("[STOPPD] ", service_name, "\n"); + do_log_main("dinit: service ", service_name, " stopped.\n"); }