X-Git-Url: https://git.librecmc.org/?a=blobdiff_plain;f=src%2Fdinit-log.cc;h=43062f0f15a400ca938c7d188be6b9f9d5dcc28b;hb=100650949c81204d8d52002e028aa8858a406bce;hp=acead3b3502f00d4fea36a1d222dbb7fbbbacd40;hpb=1cc742bdf23abba7b5fea2d9de2db1ce57aa113d;p=oweals%2Fdinit.git diff --git a/src/dinit-log.cc b/src/dinit-log.cc index acead3b..43062f0 100644 --- a/src/dinit-log.cc +++ b/src/dinit-log.cc @@ -1,99 +1,167 @@ #include #include -#include #include #include +#include +#include + +#include "dasynq.h" #include "service.h" #include "dinit-log.h" #include "cpbuffer.h" -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 +extern EventLoop_t eventLoop; -static ServiceSet *service_set = nullptr; // Reference to service set +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 }; -// Buffer for current log line: -constexpr static int log_linebuf_len = 120; // TODO needed? -static char * lineBuf = new char[log_linebuf_len]; -static int lineBuf_idx = 0; +static ServiceSet *service_set = nullptr; // Reference to service set +namespace { +class BufferedLogStream : public EventLoop_t::FdWatcher +{ + private: -// Buffer of log lines: -// (One for main log, one for console) -static CPBuffer<4096> log_buffer[2]; + // 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 -// Each line is represented as a string of characters terminated by a -// newline. (If the newline is missing, the line is not complete). + // A "special message" is not stored in the circular buffer; instead + // it is delivered from an external buffer not managed by BufferedLogger. + bool special = false; // currently outputting special message? + char *special_buf; // buffer containing special message + int msg_index; // index into special message -constexpr static int DLOG_MAIN = 0; // main log facility -constexpr static int DLOG_CONS = 1; // console + CPBuffer<4096> log_buffer; + + public: + + // Incoming: + int current_index = 0; // current/next incoming message index -constexpr static char DLOG_MAIN_FLAG = 1 << DLOG_MAIN; -constexpr static char DLOG_CONS_FLAG = 1 << DLOG_CONS; + int fd = -1; -static int current_index[2] = { 0, 0 }; // current/next message slot for (main, console) + void init(int fd) + { + this->fd = fd; + release = false; + } + + Rearm gotEvent(EventLoop_t *loop, int fd, int flags) noexcept override; -static bool partway[2] = { false, false }; // part-way through writing log line? -static int msg_index[2] = { 0, 0 }; // index into the current message + // 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 && ! release) { + setEnabled(&eventLoop, true); + } + } + + void rollback_msg() + { + log_buffer.trim_to(current_index); + } + + int get_free() + { + return log_buffer.get_free(); + } + + void append(const char *s, size_t len) + { + log_buffer.append(s, len); + } +}; +} -static struct ev_io eviocb[2]; +// Two log streams: +// (One for main log, one for console) +static BufferedLogStream log_stream[2]; -static bool discarded[2] = { false, false }; // have discarded a log line? -static bool special[2] = { false, false }; // writing from a special buffer? -static char *special_buf[2] = { nullptr, nullptr }; // special buffer +constexpr static int DLOG_MAIN = 0; // main log facility +constexpr static int DLOG_CONS = 1; // console -static void release_console() +void BufferedLogStream::release_console() { - ev_io_stop(ev_default_loop(EVFLAG_AUTO), &eviocb[DLOG_CONS]); - if (! log_to_console) { + if (release) { int flags = fcntl(1, F_GETFL, 0); fcntl(1, F_SETFL, flags & ~O_NONBLOCK); service_set->pullConsoleQueue(); } } -static void log_conn_callback(struct ev_loop * loop, ev_io * w, int revents) noexcept +void BufferedLogStream::flushForRelease() { - if (special[DLOG_CONS]) { - char * start = special_buf[DLOG_CONS] + msg_index[DLOG_CONS]; - char * end = std::find(special_buf[DLOG_CONS] + msg_index[DLOG_CONS], (char *)nullptr, '\n'); - int r = write(1, start, end - start + 1); + 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) { + // Console has already been released at this point. + setEnabled(&eventLoop, false); + } + // gotEvent didn't want to disarm, so must be partway through a message; will + // release when it's finished. +} + +Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept +{ + 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'); + int r = write(fd, start, end - start + 1); if (r >= 0) { if (start + r > end) { // All written: go on to next message in queue - special[DLOG_CONS] = false; - partway[DLOG_CONS] = false; - msg_index[DLOG_CONS] = 0; + log_stream.special = false; + log_stream.partway = false; + log_stream.msg_index = 0; + + if (release) { + release_console(); + return Rearm::DISARM; + } } else { - msg_index[DLOG_CONS] += r; - return; + log_stream.msg_index += r; + return Rearm::REARM; } } - else { - // spurious readiness - EAGAIN or EWOULDBLOCK? - // other error? - // TODO + else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) { + return Rearm::REMOVE; } - return; + return Rearm::REARM; } else { // Writing from the regular circular buffer // TODO issue special message if we have discarded a log message - if (current_index[DLOG_CONS] == 0) { + if (current_index == 0) { release_console(); - return; + return Rearm::DISARM; } - char *ptr = log_buffer[DLOG_CONS].get_ptr(0); - int len = log_buffer[DLOG_CONS].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'); @@ -105,71 +173,90 @@ static void log_conn_callback(struct ev_loop * loop, ev_io * w, int revents) noe len = eptr - ptr; - int r = write(1, 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) { - // msg_index[DLOG_CONS] += r; bool complete = (r == len) && will_complete; - log_buffer[DLOG_CONS].consume(len); - partway[DLOG_CONS] = ! complete; + log_stream.log_buffer.consume(len); + log_stream.partway = ! complete; if (complete) { - current_index[DLOG_CONS] -= len; - if (current_index[DLOG_CONS] == 0 || !log_to_console) { + log_stream.current_index -= len; + 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; + else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) { + return Rearm::REMOVE; } } // We've written something by the time we get here. We could fall through to below, but // let's give other events a chance to be processed by returning now. - return; + 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 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; +} + // Enable or disable console logging. If disabled, console logging will be disabled on the // completion of output of the current message (if any), at which point the first service record // 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: int flags = fcntl(1, F_GETFL, 0); fcntl(1, F_SETFL, flags | O_NONBLOCK); // Activate watcher: - ev_io_init(&eviocb[DLOG_CONS], log_conn_callback, 1, EV_WRITE); - if (current_index[DLOG_CONS] > 0) { - ev_io_start(ev_default_loop(EVFLAG_AUTO), &eviocb[DLOG_CONS]); - } - log_to_console = true; + log_stream[DLOG_CONS].init(STDOUT_FILENO); + log_stream[DLOG_CONS].setEnabled(&eventLoop, true); } else if (! enable && log_to_console) { - log_to_console = false; - if (! partway[DLOG_CONS]) { - if (current_index[DLOG_CONS] > 0) { - // Try to flush any messages that are currently buffered. (Console is non-blocking - // so it will fail gracefully). - log_conn_callback(ev_default_loop(EVFLAG_AUTO), &eviocb[DLOG_CONS], EV_WRITE); - } - else { - release_console(); - } - } - // (if we're partway through logging a message, we release the console when - // finished). + log_stream[DLOG_CONS].flushForRelease(); } } @@ -180,35 +267,48 @@ 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...); } // Variadic method to append strings to a buffer: -static void append(CPBuffer<4096> &buf, const char *s) +static void append(BufferedLogStream &buf, const char *s) { buf.append(s, std::strlen(s)); } -template static void append(CPBuffer<4096> &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_buffer[DLOG_CONS].get_free() >= amount) { - append(log_buffer[DLOG_CONS], args...); - - bool was_first = (current_index[DLOG_CONS] == 0); - current_index[DLOG_CONS] += amount; - if (was_first && log_to_console) { - ev_io_start(ev_default_loop(EVFLAG_AUTO), & eviocb[DLOG_CONS]); - } + if (log_stream[idx].get_free() >= amount) { + append(log_stream[idx], args...); + log_stream[idx].commit_msg(); } else { // TODO mark a discarded message @@ -218,11 +318,36 @@ 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 @@ -230,51 +355,79 @@ void log(LogLevel lvl, const char *msg) noexcept do_log(lvl, "dinit: ", msg, "\n"); } +// 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(int idx, T arg) noexcept +{ + 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(int idx) noexcept +{ + 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) { - std::cout << "dinit: " << 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) { - std::cout << 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) { - std::cout << msg << std::endl; - } + 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"); }