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