src/dinit-log.cc

   1 #include <iostream>
   2 #include <algorithm>
   3
   4 #include <unistd.h>
   5 #include <fcntl.h>
   6
   7 #include "dasync.h"
   8
   9 #include "service.h"
  10 #include "dinit-log.h"
  11 #include "cpbuffer.h"
  12
  13 // TODO should disarm, not remove, the file descriptor watchers when they are not busy
  14 //      (and likewise re-arm instead of re-add them when new data arrives).
  15
  16 extern EventLoop_t eventLoop;
  17
  18 LogLevel log_level = LogLevel::WARN;
  19 LogLevel cons_log_level = LogLevel::WARN;
  20
  21 static bool log_to_console = false;   // whether we should output log messages to
  22                                      // console immediately
  23 static bool log_current_line;  // Whether the current line is being logged
  24
  25 static ServiceSet *service_set = nullptr;  // Reference to service set
  26
  27 namespace {
  28 class BufferedLogStream : public PosixFdWatcher<NullMutex>
  29 {
  30     private:
  31
  32     // Outgoing:
  33     bool partway = false;     // if we are partway throught output of a log message
  34     bool discarded = false;   // if we have discarded a message
  35
  36     // A "special message" is not stored in the circular buffer; instead
  37     // it is delivered from an external buffer not managed by BufferedLogger.
  38     bool special = false;      // currently outputting special message?
  39     char *special_buf; // buffer containing special message
  40     int msg_index;     // index into special message
  41
  42     public:
  43     CPBuffer<4096> log_buffer;
  44
  45     // Incoming:
  46     int current_index = 0;    // current/next incoming message index
  47        // ^^ TODO is this always just the length of log_buffer?
  48
  49     int fd;
  50
  51     void init(int fd)
  52     {
  53         this->fd = fd;
  54     }
  55
  56     Rearm gotEvent(EventLoop_t *loop, int fd, int flags) noexcept override;
  57
  58     // Check whether the console can be released.
  59     void flushForRelease();
  60 };
  61 }
  62
  63 // Two log streams:
  64 // (One for main log, one for console)
  65 static BufferedLogStream log_stream[2];
  66
  67 constexpr static int DLOG_MAIN = 0; // main log facility
  68 constexpr static int DLOG_CONS = 1; // console
  69
  70
  71 static void release_console()
  72 {
  73     if (! log_to_console) {
  74         int flags = fcntl(1, F_GETFL, 0);
  75         fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
  76         service_set->pullConsoleQueue();
  77     }
  78 }
  79
  80 void BufferedLogStream::flushForRelease()
  81 {
  82     // Try to flush any messages that are currently buffered. (Console is non-blocking
  83     // so it will fail gracefully).
  84     if (gotEvent(&eventLoop, fd, out_events) == Rearm::REMOVE) {
  85         // Console has already been released at this point.
  86         deregisterWatch(&eventLoop);
  87     }
  88     // gotEvent didn't want to disarm, so must be partway through a message; will
  89     // release when it's finished.
  90 }
  91
  92 Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept
  93 {
  94     // TODO correct for the case that this is *not* the console log stream.
  95
  96     auto &log_stream = *this;
  97
  98     if ((! partway) && log_stream.special) {
  99         char * start = log_stream.special_buf + log_stream.msg_index;
 100         char * end = std::find(log_stream.special_buf + log_stream.msg_index, (char *)nullptr, '\n');
 101         int r = write(fd, start, end - start + 1);
 102         if (r >= 0) {
 103             if (start + r > end) {
 104                 // All written: go on to next message in queue
 105                 log_stream.special = false;
 106                 log_stream.partway = false;
 107                 log_stream.msg_index = 0;
 108
 109                 if (!log_to_console) {
 110                     release_console();
 111                     return Rearm::REMOVE;
 112                 }
 113             }
 114             else {
 115                 log_stream.msg_index += r;
 116                 return Rearm::REARM;
 117             }
 118         }
 119         else {
 120             // spurious readiness - EAGAIN or EWOULDBLOCK?
 121             // other error?
 122             // TODO
 123         }
 124         return Rearm::REARM;
 125     }
 126     else {
 127         // Writing from the regular circular buffer
 128
 129         // TODO issue special message if we have discarded a log message
 130
 131         if (log_stream.current_index == 0) {
 132             release_console();
 133             return Rearm::REMOVE;
 134         }
 135
 136         char *ptr = log_stream.log_buffer.get_ptr(0);
 137         int len = log_stream.log_buffer.get_contiguous_length(ptr);
 138         char *creptr = ptr + len;  // contiguous region end
 139         char *eptr = std::find(ptr, creptr, '\n');
 140
 141         bool will_complete = false;  // will complete this message?
 142         if (eptr != creptr) {
 143             eptr++;  // include '\n'
 144             will_complete = true;
 145         }
 146
 147         len = eptr - ptr;
 148
 149         int r = write(fd, ptr, len);
 150
 151         if (r >= 0) {
 152             bool complete = (r == len) && will_complete;
 153             log_stream.log_buffer.consume(len);
 154             log_stream.partway = ! complete;
 155             if (complete) {
 156                 log_stream.current_index -= len;
 157                 if (log_stream.current_index == 0 || !log_to_console) {
 158                     // No more messages buffered / stop logging to console:
 159                     release_console();
 160                     return Rearm::REMOVE;
 161                 }
 162             }
 163         }
 164         else {
 165             // TODO
 166             // EAGAIN / EWOULDBLOCK?
 167             // error?
 168             return Rearm::REARM;
 169         }
 170     }
 171
 172     // We've written something by the time we get here. We could fall through to below, but
 173     // let's give other events a chance to be processed by returning now.
 174     return Rearm::REARM;
 175 }
 176
 177 void init_log(ServiceSet *sset) noexcept
 178 {
 179     service_set = sset;
 180     enable_console_log(true);
 181 }
 182
 183 bool is_log_flushed() noexcept
 184 {
 185     return log_stream[DLOG_CONS].current_index > 0;
 186 }
 187
 188 // Enable or disable console logging. If disabled, console logging will be disabled on the
 189 // completion of output of the current message (if any), at which point the first service record
 190 // queued in the service set will acquire the console.
 191 void enable_console_log(bool enable) noexcept
 192 {
 193     if (enable && ! log_to_console) {
 194         // Console is fd 1 - stdout
 195         // Set non-blocking IO:
 196         int flags = fcntl(1, F_GETFL, 0);
 197         fcntl(1, F_SETFL, flags | O_NONBLOCK);
 198         // Activate watcher:
 199         log_stream[DLOG_CONS].init(STDOUT_FILENO);
 200         if (log_stream[DLOG_CONS].current_index > 0) {
 201             log_stream[DLOG_CONS].registerWith(&eventLoop, log_stream[DLOG_CONS].fd, out_events);
 202         }
 203         log_to_console = true;
 204     }
 205     else if (! enable && log_to_console) {
 206         log_to_console = false;
 207         log_stream[DLOG_CONS].flushForRelease();
 208     }
 209 }
 210
 211
 212 // Variadic method to calculate the sum of string lengths:
 213 static int sum_length(const char *arg) noexcept
 214 {
 215     return std::strlen(arg);
 216 }
 217
 218 template <typename U, typename ... T> static int sum_length(U first, T ... args) noexcept
 219 {
 220     return sum_length(first) + sum_length(args...);
 221 }
 222
 223 // Variadic method to append strings to a buffer:
 224 static void append(CPBuffer<4096> &buf, const char *s)
 225 {
 226     buf.append(s, std::strlen(s));
 227 }
 228
 229 template <typename U, typename ... T> static void append(CPBuffer<4096> &buf, U u, T ... t)
 230 {
 231     append(buf, u);
 232     append(buf, t...);
 233 }
 234
 235 // Variadic method to log a sequence of strings as a single message:
 236 template <typename ... T> static void do_log(T ... args) noexcept
 237 {
 238     int amount = sum_length(args...);
 239     if (log_stream[DLOG_CONS].log_buffer.get_free() >= amount) {
 240         append(log_stream[DLOG_CONS].log_buffer, args...);
 241
 242         bool was_first = (log_stream[DLOG_CONS].current_index == 0);
 243         log_stream[DLOG_CONS].current_index += amount;
 244         if (was_first && log_to_console) {
 245             log_stream[DLOG_CONS].registerWith(&eventLoop, log_stream[DLOG_CONS].fd, out_events);
 246         }
 247     }
 248     else {
 249         // TODO mark a discarded message
 250     }
 251 }
 252
 253 // Variadic method to potentially log a sequence of strings as a single message with the given log level:
 254 template <typename ... T> static void do_log(LogLevel lvl, T ... args) noexcept
 255 {
 256     if (lvl >= cons_log_level) {
 257         do_log(args...);
 258     }
 259 }
 260
 261 // Log a message. A newline will be appended.
 262 void log(LogLevel lvl, const char *msg) noexcept
 263 {
 264     do_log(lvl, "dinit: ", msg, "\n");
 265 }
 266
 267 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
 268 template <typename T> static void do_log_part(T arg) noexcept
 269 {
 270     int amount = sum_length(arg);
 271     if (log_stream[DLOG_CONS].log_buffer.get_free() >= amount) {
 272         append(log_stream[DLOG_CONS].log_buffer, arg);
 273     }
 274     else {
 275         // reset
 276         log_stream[DLOG_CONS].log_buffer.trim_to(log_stream[DLOG_CONS].current_index);
 277         log_current_line = false;
 278         // TODO mark discarded message
 279     }
 280 }
 281
 282 // Commit a message that was issued as a series of parts (via do_log_part).
 283 static void do_log_commit() noexcept
 284 {
 285     if (log_current_line) {
 286         bool was_first = log_stream[DLOG_CONS].current_index == 0;
 287         log_stream[DLOG_CONS].current_index = log_stream[DLOG_CONS].log_buffer.get_length();
 288         if (was_first && log_to_console) {
 289             log_stream[DLOG_CONS].registerWith(&eventLoop, log_stream[DLOG_CONS].fd, out_events);
 290         }
 291     }
 292 }
 293
 294 // Log a multi-part message beginning
 295 void logMsgBegin(LogLevel lvl, const char *msg) noexcept
 296 {
 297     // TODO use buffer
 298     log_current_line = lvl >= log_level;
 299     if (log_current_line) {
 300         if (log_to_console) {
 301             do_log_part("dinit: ");
 302             do_log_part(msg);
 303         }
 304     }
 305 }
 306
 307 // Continue a multi-part log message
 308 void logMsgPart(const char *msg) noexcept
 309 {
 310     // TODO use buffer
 311     if (log_current_line) {
 312         if (log_to_console) {
 313             do_log_part(msg);
 314         }
 315     }
 316 }
 317
 318 // Complete a multi-part log message
 319 void logMsgEnd(const char *msg) noexcept
 320 {
 321     // TODO use buffer
 322     if (log_current_line) {
 323         if (log_to_console) {
 324             do_log_part(msg);
 325             do_log_part("\n");
 326             do_log_commit();
 327         }
 328     }
 329 }
 330
 331 void logServiceStarted(const char *service_name) noexcept
 332 {
 333     do_log("[  OK  ] ", service_name, "\n");
 334 }
 335
 336 void logServiceFailed(const char *service_name) noexcept
 337 {
 338     do_log("[FAILED] ", service_name, "\n");
 339 }
 340
 341 void logServiceStopped(const char *service_name) noexcept
 342 {
 343     do_log("[STOPPD] ", service_name, "\n");
 344 }