src/dinit-log.cc

   1 #include <iostream>
   2 #include <algorithm>
   3
   4 #include <unistd.h>
   5 #include <fcntl.h>
   6 #include <sys/syslog.h>
   7 #include <sys/uio.h>
   8
   9 #include "dasynq.h"
  10
  11 #include "service.h"
  12 #include "dinit-log.h"
  13 #include "cpbuffer.h"
  14
  15 extern EventLoop_t eventLoop;
  16
  17 static bool log_current_line[2];  // Whether the current line is being logged (for console, main log)
  18 LogLevel log_level[2] = { LogLevel::WARN, LogLevel::WARN };
  19
  20 static ServiceSet *service_set = nullptr;  // Reference to service set
  21
  22 namespace {
  23 class BufferedLogStream : public EventLoop_t::fd_watcher
  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     const 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 = -1;
  46
  47     void init(int fd)
  48     {
  49         this->fd = fd;
  50         release = false;
  51     }
  52
  53     rearm fd_event(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             set_enabled(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     // Discard buffer; call only when the stream isn't active.
  86     void discard()
  87     {
  88         current_index = 0;
  89         log_buffer.trim_to(0);
  90     }
  91
  92     // Mark that a message was discarded due to full buffer
  93     void mark_discarded()
  94     {
  95         discarded = true;
  96     }
  97 };
  98 }
  99
 100 // Two log streams:
 101 // (One for main log, one for console)
 102 static BufferedLogStream log_stream[2];
 103
 104 constexpr static int DLOG_MAIN = 0; // main log facility
 105 constexpr static int DLOG_CONS = 1; // console
 106
 107 void BufferedLogStream::release_console()
 108 {
 109     if (release) {
 110         int flags = fcntl(1, F_GETFL, 0);
 111         fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
 112         service_set->pullConsoleQueue();
 113     }
 114 }
 115
 116 void BufferedLogStream::flushForRelease()
 117 {
 118     release = true;
 119
 120     // Try to flush any messages that are currently buffered. (Console is non-blocking
 121     // so it will fail gracefully).
 122     if (fd_event(eventLoop, fd, OUT_EVENTS) == rearm::DISARM) {
 123         // Console has already been released at this point.
 124         set_enabled(eventLoop, false);
 125     }
 126     // fd_event didn't want to disarm, so must be partway through a message; will
 127     // release when it's finished.
 128 }
 129
 130 rearm BufferedLogStream::fd_event(EventLoop_t &loop, int fd, int flags) noexcept
 131 {
 132     if ((! partway) && (! special) && discarded) {
 133         special_buf = "dinit: *** message discarded due to full buffer ****\n";
 134         msg_index = 0;
 135     }
 136
 137     if ((! partway) && special) {
 138         const char * start = special_buf + msg_index;
 139         const char * end = std::find(special_buf + msg_index, (const char *)nullptr, '\n');
 140         int r = write(fd, start, end - start + 1);
 141         if (r >= 0) {
 142             if (start + r > end) {
 143                 // All written: go on to next message in queue
 144                 special = false;
 145                 partway = false;
 146                 msg_index = 0;
 147
 148                 if (release) {
 149                     release_console();
 150                     return rearm::DISARM;
 151                 }
 152             }
 153             else {
 154                 msg_index += r;
 155                 return rearm::REARM;
 156             }
 157         }
 158         else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
 159             return rearm::REMOVE;
 160         }
 161         return rearm::REARM;
 162     }
 163     else {
 164         // Writing from the regular circular buffer
 165
 166         if (current_index == 0) {
 167             release_console();
 168             return rearm::DISARM;
 169         }
 170
 171         // We try to find a complete line (terminated by '\n') in the buffer, and write it
 172         // out. Since it may span the circular buffer end, it may consist of two distinct spans,
 173         // and so we use writev to write them atomically.
 174
 175         struct iovec logiov[2];
 176
 177         char *ptr = log_buffer.get_ptr(0);
 178         int len = log_buffer.get_contiguous_length(ptr);
 179         char *creptr = ptr + len;  // contiguous region end
 180         char *eptr = std::find(ptr, creptr, '\n');
 181
 182         bool will_complete = false;  // will complete this message?
 183         if (eptr != creptr) {
 184             eptr++;  // include '\n'
 185             will_complete = true;
 186         }
 187
 188         len = eptr - ptr;
 189
 190         logiov[0].iov_base = ptr;
 191         logiov[0].iov_len = len;
 192         int iovs_to_write = 1;
 193
 194         // Do we need the second span?
 195         if (! will_complete && len != log_buffer.get_length()) {
 196             ptr = log_buffer.get_buf_base();
 197             creptr = static_cast<char *>(logiov[1].iov_base) + log_buffer.get_length() - len;
 198             eptr = std::find(ptr, creptr, '\n');
 199             if (eptr != creptr) {
 200                 eptr++; // include '\n'
 201                 // It should not ever be the case that we do not now have a complete message
 202                 will_complete = true;
 203             }
 204             logiov[1].iov_base = ptr;
 205             logiov[1].iov_len = eptr - ptr;
 206             len += logiov[1].iov_len;
 207             iovs_to_write = 2;
 208         }
 209
 210         ssize_t r = writev(fd, logiov, iovs_to_write);
 211
 212         if (r >= 0) {
 213             bool complete = (r == len) && will_complete;
 214             log_buffer.consume(len);
 215             partway = ! complete;
 216             if (complete) {
 217                 current_index -= len;
 218                 if (current_index == 0 || release) {
 219                     // No more messages buffered / stop logging to console:
 220                     release_console();
 221                     return rearm::DISARM;
 222                 }
 223             }
 224         }
 225         else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
 226             return rearm::REMOVE;
 227         }
 228     }
 229
 230     // We've written something by the time we get here. We could fall through to below, but
 231     // let's give other events a chance to be processed by returning now.
 232     return rearm::REARM;
 233 }
 234
 235 // Initialise the logging subsystem
 236 // Potentially throws std::bad_alloc or std::system_error
 237 void init_log(ServiceSet *sset)
 238 {
 239     service_set = sset;
 240     log_stream[DLOG_CONS].add_watch(eventLoop, STDOUT_FILENO, OUT_EVENTS, false);
 241     enable_console_log(true);
 242 }
 243
 244 // Set up the main log to output to the given file descriptor.
 245 // Potentially throws std::bad_alloc or std::system_error
 246 void setup_main_log(int fd)
 247 {
 248     log_stream[DLOG_MAIN].init(fd);
 249     log_stream[DLOG_MAIN].add_watch(eventLoop, fd, OUT_EVENTS);
 250 }
 251
 252 bool is_log_flushed() noexcept
 253 {
 254     return log_stream[DLOG_CONS].current_index == 0;
 255 }
 256
 257 // Enable or disable console logging. If disabled, console logging will be disabled on the
 258 // completion of output of the current message (if any), at which point the first service record
 259 // queued in the service set will acquire the console.
 260 void enable_console_log(bool enable) noexcept
 261 {
 262     bool log_to_console = ! log_stream[DLOG_CONS].is_release_set();
 263     if (enable && ! log_to_console) {
 264         // Console is fd 1 - stdout
 265         // Set non-blocking IO:
 266         int flags = fcntl(1, F_GETFL, 0);
 267         fcntl(1, F_SETFL, flags | O_NONBLOCK);
 268         // Activate watcher:
 269         log_stream[DLOG_CONS].init(STDOUT_FILENO);
 270         log_stream[DLOG_CONS].set_enabled(eventLoop, true);
 271     }
 272     else if (! enable && log_to_console) {
 273         log_stream[DLOG_CONS].flushForRelease();
 274     }
 275 }
 276
 277 void discard_console_log_buffer() noexcept
 278 {
 279     log_stream[DLOG_CONS].discard();
 280 }
 281
 282 // Variadic method to calculate the sum of string lengths:
 283 static int sum_length(const char *arg) noexcept
 284 {
 285     return std::strlen(arg);
 286 }
 287
 288 template <typename ... T> static int sum_length(const char * first, T ... args) noexcept
 289 {
 290     return sum_length(first) + sum_length(args...);
 291 }
 292
 293 // Variadic method to append strings to a buffer:
 294 static void append(BufferedLogStream &buf, const char *s)
 295 {
 296     buf.append(s, std::strlen(s));
 297 }
 298
 299 template <typename ... T> static void append(BufferedLogStream &buf, const char *u, T ... t)
 300 {
 301     append(buf, u);
 302     append(buf, t...);
 303 }
 304
 305 static int log_level_to_syslog_level(LogLevel l)
 306 {
 307     switch (l) {
 308     case LogLevel::DEBUG:
 309         return LOG_DEBUG;
 310     case LogLevel::INFO:
 311         return LOG_INFO;
 312     case LogLevel::WARN:
 313         return LOG_WARNING;
 314     case LogLevel::ERROR:
 315         return LOG_ERR;
 316     default: ;
 317     }
 318
 319     return LOG_CRIT;
 320 }
 321
 322 // Variadic method to log a sequence of strings as a single message to a particular facility:
 323 template <typename ... T> static void push_to_log(int idx, T ... args) noexcept
 324 {
 325     if (! log_current_line[idx]) return;
 326     int amount = sum_length(args...);
 327     if (log_stream[idx].get_free() >= amount) {
 328         append(log_stream[idx], args...);
 329         log_stream[idx].commit_msg();
 330     }
 331     else {
 332         log_stream[idx].mark_discarded();
 333     }
 334 }
 335
 336 // Variadic method to potentially log a sequence of strings as a single message with the given log level:
 337 template <typename ... T> static void do_log(LogLevel lvl, T ... args) noexcept
 338 {
 339     log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
 340     log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
 341     push_to_log(DLOG_CONS, args...);
 342
 343     if (log_current_line[DLOG_MAIN]) {
 344         char svcbuf[10];
 345         snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
 346
 347         push_to_log(DLOG_MAIN, svcbuf, args...);
 348     }
 349 }
 350
 351 template <typename ... T> static void do_log_cons(T ... args) noexcept
 352 {
 353     log_current_line[DLOG_CONS] = true;
 354     log_current_line[DLOG_MAIN] = false;
 355     push_to_log(DLOG_CONS, args...);
 356 }
 357
 358 // Log to the main facility at NOTICE level
 359 template <typename ... T> static void do_log_main(T ... args) noexcept
 360 {
 361     log_current_line[DLOG_CONS] = false;
 362     log_current_line[DLOG_MAIN] = true;
 363
 364     char svcbuf[10];
 365     snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | LOG_NOTICE);
 366
 367     push_to_log(DLOG_MAIN, svcbuf, args...);
 368 }
 369
 370 // Log a message. A newline will be appended.
 371 void log(LogLevel lvl, const char *msg) noexcept
 372 {
 373     do_log(lvl, "dinit: ", msg, "\n");
 374 }
 375
 376 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
 377 template <typename T> static void do_log_part(int idx, T arg) noexcept
 378 {
 379     if (log_current_line[idx]) {
 380         int amount = sum_length(arg);
 381         if (log_stream[idx].get_free() >= amount) {
 382             append(log_stream[idx], arg);
 383         }
 384         else {
 385             log_stream[idx].rollback_msg();
 386             log_current_line[idx] = false;
 387             log_stream[idx].mark_discarded();
 388         }
 389     }
 390 }
 391
 392 // Commit a message that was issued as a series of parts (via do_log_part).
 393 static void do_log_commit(int idx) noexcept
 394 {
 395     if (log_current_line[idx]) {
 396         log_stream[idx].commit_msg();
 397     }
 398 }
 399
 400 // Log a multi-part message beginning
 401 void logMsgBegin(LogLevel lvl, const char *msg) noexcept
 402 {
 403     log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
 404     log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
 405
 406     if (log_current_line[DLOG_MAIN]) {
 407         char svcbuf[10];
 408         snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
 409         do_log_part(DLOG_MAIN, svcbuf);
 410     }
 411
 412     for (int i = 0; i < 2; i++) {
 413         do_log_part(i, "dinit: ");
 414         do_log_part(i, msg);
 415     }
 416 }
 417
 418 // Continue a multi-part log message
 419 void logMsgPart(const char *msg) noexcept
 420 {
 421     do_log_part(DLOG_CONS, msg);
 422     do_log_part(DLOG_MAIN, msg);
 423 }
 424
 425 // Complete a multi-part log message
 426 void logMsgEnd(const char *msg) noexcept
 427 {
 428     for (int i = 0; i < 2; i++) {
 429         do_log_part(i, msg);
 430         do_log_part(i, "\n");
 431         do_log_commit(i);
 432     }
 433 }
 434
 435 void logServiceStarted(const char *service_name) noexcept
 436 {
 437     do_log_cons("[  OK  ] ", service_name, "\n");
 438     do_log_main("dinit: service ", service_name, " started.\n");
 439 }
 440
 441 void logServiceFailed(const char *service_name) noexcept
 442 {
 443     do_log_cons("[FAILED] ", service_name, "\n");
 444     do_log_main("dinit: service ", service_name, " failed to start.\n");
 445 }
 446
 447 void logServiceStopped(const char *service_name) noexcept
 448 {
 449     do_log_cons("[STOPPD] ", service_name, "\n");
 450     do_log_main("dinit: service ", service_name, " stopped.\n");
 451 }