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