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