#include <iostream>
#include <algorithm>
-#include <ev.h>
#include <unistd.h>
#include <fcntl.h>
+#include <sys/syslog.h>
+#include <sys/uio.h>
+
+#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
+// Dinit logging subsystem.
+//
+// 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 (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.
-static ServiceSet *service_set = nullptr; // Reference to service set
+extern eventloop_t event_loop;
-// 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 bool log_current_line[2]; // Whether the current line is being logged (for console, main log)
+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
-// Buffer of log lines:
-// (One for main log, one for console)
-static CPBuffer<4096> log_buffer[2];
+dasynq::time_val release_time; // time the log was released
-// Each line is represented as a string of characters terminated by a
-// newline. (If the newline is missing, the line is not complete).
+using rearm = dasynq::rearm;
-constexpr static int DLOG_MAIN = 0; // main log facility
-constexpr static int DLOG_CONS = 1; // console
+namespace {
+class buffered_log_stream : public eventloop_t::fd_watcher_impl<buffered_log_stream>
+{
+ 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.
+ bool special = false; // currently outputting special message?
+ const char *special_buf; // buffer containing special message
+ int msg_index; // index into special message
+
+ cpbuffer<4096> log_buffer;
+
+ public:
+
+ // Incoming:
+ int current_index = 0; // current/next incoming message index
+
+ int fd = -1;
+
+ void init(int fd)
+ {
+ this->fd = fd;
+ release = false;
+ }
+
+ rearm fd_event(eventloop_t &loop, int fd, int flags) noexcept;
-constexpr static char DLOG_MAIN_FLAG = 1 << DLOG_MAIN;
-constexpr static char DLOG_CONS_FLAG = 1 << DLOG_CONS;
+ // Check whether the console can be released.
+ void flush_for_release();
+ 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) {
+ set_enabled(event_loop, 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);
+ }
+
+ // Discard buffer; call only when the stream isn't active.
+ void discard()
+ {
+ current_index = 0;
+ log_buffer.trim_to(0);
+ }
-static int current_index[2] = { 0, 0 }; // current/next message slot for (main, console)
+ // Mark that a message was discarded due to full buffer
+ void mark_discarded()
+ {
+ discarded = true;
+ }
-static bool partway[2] = { false, false }; // part-way through writing log line?
-static int msg_index[2] = { 0, 0 }; // index into the current message
+ private:
+ void release_console();
+};
+}
-static struct ev_io eviocb[2];
+// Two log streams:
+// (One for main log, one for console)
+static buffered_log_stream 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 buffered_log_stream::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();
+ 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);
+ }
}
}
-static void log_conn_callback(struct ev_loop * loop, ev_io * w, int revents) noexcept
+void buffered_log_stream::flush_for_release()
{
- 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 (fd_event(event_loop, fd, dasynq::OUT_EVENTS) == rearm::DISARM) {
+ // Console has already been released at this point.
+ set_enabled(event_loop, false);
+ }
+ // fd_event didn't want to disarm, so must be partway through a message; will
+ // release when it's finished.
+}
+
+rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexcept
+{
+ 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);
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;
+ special = false;
+ discarded = false;
+ msg_index = 0;
+
+ if (release) {
+ release_console();
+ return rearm::DISARM;
+ }
}
else {
- msg_index[DLOG_CONS] += r;
- return;
+ 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');
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 = ptr + 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_buffer.consume(len);
+ partway = ! complete;
if (complete) {
- current_index[DLOG_CONS] -= len;
- if (current_index[DLOG_CONS] == 0 || !log_to_console) {
+ current_index -= len;
+ if (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(service_set *sset, bool syslog_format)
{
- service_set = sset;
+ 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.
+// 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].add_watch(event_loop, fd, dasynq::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
// 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);
+ int flags = fcntl(STDOUT_FILENO, F_GETFL, 0);
+ fcntl(STDOUT_FILENO, 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].set_enabled(event_loop, 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].flush_for_release();
}
}
+void discard_console_log_buffer() noexcept
+{
+ // 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:
static int sum_length(const char *arg) noexcept
return std::strlen(arg);
}
-template <typename U, typename ... T> static int sum_length(U first, T ... args) noexcept
+template <typename ... T> 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(buffered_log_stream &buf, const char *s)
{
buf.append(s, std::strlen(s));
}
-template <typename U, typename ... T> static void append(CPBuffer<4096> &buf, U u, T ... t)
+template <typename ... T> static void append(buffered_log_stream &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 <typename ... T> static void do_log(T ... args) noexcept
+static int log_level_to_syslog_level(loglevel_t l)
{
+ switch (l) {
+ case loglevel_t::DEBUG:
+ return LOG_DEBUG;
+ case loglevel_t::INFO:
+ return LOG_INFO;
+ case loglevel_t::WARN:
+ return LOG_WARNING;
+ case loglevel_t::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 <typename ... T> 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
+ log_stream[idx].mark_discarded();
}
}
// Variadic method to potentially log a sequence of strings as a single message with the given log level:
-template <typename ... T> static void do_log(LogLevel lvl, T ... args) noexcept
+template <typename ... T> static void do_log(loglevel_t lvl, bool to_cons, T ... args) noexcept
{
- if (lvl >= cons_log_level) {
- do_log(args...);
+ log_current_line[DLOG_CONS] = (lvl >= log_level[DLOG_CONS]) && to_cons;
+ log_current_line[DLOG_MAIN] = (lvl >= log_level[DLOG_MAIN]);
+ push_to_log(DLOG_CONS, args...);
+
+ if (log_current_line[DLOG_MAIN]) {
+ 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...);
+}
+
+// Log to the main facility at NOTICE level
+template <typename ... T> static void do_log_main(T ... args) noexcept
+{
+ log_current_line[DLOG_CONS] = false;
+ log_current_line[DLOG_MAIN] = true;
+
+ 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.
-void log(LogLevel lvl, const char *msg) noexcept
+void log(loglevel_t lvl, const char *msg) noexcept
{
- do_log(lvl, "dinit: ", msg, "\n");
+ do_log(lvl, true, "dinit: ", msg, "\n");
}
-// Log a multi-part message beginning
-void logMsgBegin(LogLevel lvl, const char *msg) noexcept
+void log(loglevel_t lvl, bool to_cons, const char *msg) noexcept
+{
+ do_log(lvl, to_cons, "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 <typename T> static void do_log_part(int idx, T arg) noexcept
{
- // TODO use buffer
- log_current_line = lvl >= log_level;
- if (log_current_line) {
- if (log_to_console) {
- std::cout << "dinit: " << msg;
+ 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;
+ log_stream[idx].mark_discarded();
}
}
}
-// Continue a multi-part log message
-void logMsgPart(const char *msg) noexcept
+// Commit a message that was issued as a series of parts (via do_log_part).
+static void do_log_commit(int idx) noexcept
{
- // TODO use buffer
- if (log_current_line) {
- if (log_to_console) {
- std::cout << msg;
+ if (log_current_line[idx]) {
+ log_stream[idx].commit_msg();
+ }
+}
+
+// Log a multi-part message beginning
+void log_msg_begin(loglevel_t lvl, const char *msg) noexcept
+{
+ log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
+ log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
+
+ // Prepend the syslog priority level string ("<N>") for the main log:
+ if (log_current_line[DLOG_MAIN]) {
+ 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++) {
+ do_log_part(i, "dinit: ");
+ do_log_part(i, msg);
+ }
+}
+
+// Continue a multi-part log message
+void log_msg_part(const char *msg) noexcept
+{
+ do_log_part(DLOG_CONS, msg);
+ do_log_part(DLOG_MAIN, msg);
}
// Complete a multi-part log message
-void logMsgEnd(const char *msg) noexcept
+void log_msg_end(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
+void log_service_started(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
+void log_service_failed(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
+void log_service_stopped(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");
}
projects / oweals / dinit.git / blobdiff