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