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