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