src/dinit-log.cc

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