src/dinit-log.cc

   1 #include <iostream>
   2 #include <algorithm>
   3
   4 #include <unistd.h>
   5 #include <fcntl.h>
   6
   7 #include "dasync.h"
   8
   9 #include "service.h"
  10 #include "dinit-log.h"
  11 #include "cpbuffer.h"
  12
  13 extern EventLoop_t eventLoop;
  14
  15 LogLevel log_level = LogLevel::WARN;
  16 LogLevel cons_log_level = LogLevel::WARN;
  17
  18 static bool log_to_console = false;   // whether we should output log messages to
  19                                      // console immediately
  20 static bool log_current_line;  // Whether the current line is being logged
  21
  22 static ServiceSet *service_set = nullptr;  // Reference to service set
  23
  24 namespace {
  25 class BufferedLogStream : public PosixFdWatcher<NullMutex>
  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
  33     // A "special message" is not stored in the circular buffer; instead
  34     // it is delivered from an external buffer not managed by BufferedLogger.
  35     bool special = false;      // currently outputting special message?
  36     char *special_buf; // buffer containing special message
  37     int msg_index;     // index into special message
  38
  39     CPBuffer<4096> log_buffer;
  40
  41     public:
  42
  43     // Incoming:
  44     int current_index = 0;    // current/next incoming message index
  45
  46     int fd;
  47
  48     void init(int fd)
  49     {
  50         this->fd = fd;
  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
  58     // Commit a log message
  59     void commit_msg()
  60     {
  61         bool was_first = current_index == 0;
  62         current_index = log_buffer.get_length();
  63         if (was_first && log_to_console) {
  64             setEnabled(&eventLoop, true);
  65         }
  66     }
  67
  68     void rollback_msg()
  69     {
  70         log_buffer.trim_to(current_index);
  71     }
  72
  73     int get_free()
  74     {
  75         return log_buffer.get_free();
  76     }
  77
  78     void append(const char *s, size_t len)
  79     {
  80         log_buffer.append(s, len);
  81     }
  82 };
  83 }
  84
  85 // Two log streams:
  86 // (One for main log, one for console)
  87 static BufferedLogStream log_stream[2];
  88
  89 constexpr static int DLOG_MAIN = 0; // main log facility
  90 constexpr static int DLOG_CONS = 1; // console
  91
  92
  93 static void release_console()
  94 {
  95     if (! log_to_console) {
  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     // Try to flush any messages that are currently buffered. (Console is non-blocking
 105     // so it will fail gracefully).
 106     if (gotEvent(&eventLoop, fd, out_events) == Rearm::DISARM) {
 107         // Console has already been released at this point.
 108         setEnabled(&eventLoop, false);
 109     }
 110     // gotEvent didn't want to disarm, so must be partway through a message; will
 111     // release when it's finished.
 112 }
 113
 114 Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept
 115 {
 116     // TODO correct for the case that this is *not* the console log stream.
 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 (!log_to_console) {
 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 {
 142             // spurious readiness - EAGAIN or EWOULDBLOCK?
 143             // other error?
 144             // TODO
 145         }
 146         return Rearm::REARM;
 147     }
 148     else {
 149         // Writing from the regular circular buffer
 150
 151         // TODO issue special message if we have discarded a log message
 152
 153         if (log_stream.current_index == 0) {
 154             release_console();
 155             return Rearm::DISARM;
 156         }
 157
 158         char *ptr = log_stream.log_buffer.get_ptr(0);
 159         int len = log_stream.log_buffer.get_contiguous_length(ptr);
 160         char *creptr = ptr + len;  // contiguous region end
 161         char *eptr = std::find(ptr, creptr, '\n');
 162
 163         bool will_complete = false;  // will complete this message?
 164         if (eptr != creptr) {
 165             eptr++;  // include '\n'
 166             will_complete = true;
 167         }
 168
 169         len = eptr - ptr;
 170
 171         int r = write(fd, ptr, len);
 172
 173         if (r >= 0) {
 174             bool complete = (r == len) && will_complete;
 175             log_stream.log_buffer.consume(len);
 176             log_stream.partway = ! complete;
 177             if (complete) {
 178                 log_stream.current_index -= len;
 179                 if (log_stream.current_index == 0 || !log_to_console) {
 180                     // No more messages buffered / stop logging to console:
 181                     release_console();
 182                     return Rearm::DISARM;
 183                 }
 184             }
 185         }
 186         else {
 187             // TODO
 188             // EAGAIN / EWOULDBLOCK?
 189             // error?
 190             return Rearm::REARM;
 191         }
 192     }
 193
 194     // We've written something by the time we get here. We could fall through to below, but
 195     // let's give other events a chance to be processed by returning now.
 196     return Rearm::REARM;
 197 }
 198
 199 void init_log(ServiceSet *sset) noexcept
 200 {
 201     service_set = sset;
 202     log_stream[DLOG_CONS].registerWith(&eventLoop, STDOUT_FILENO, out_events); // TODO register in disabled state
 203     enable_console_log(true);
 204 }
 205
 206 bool is_log_flushed() noexcept
 207 {
 208     return log_stream[DLOG_CONS].current_index == 0;
 209 }
 210
 211 // Enable or disable console logging. If disabled, console logging will be disabled on the
 212 // completion of output of the current message (if any), at which point the first service record
 213 // queued in the service set will acquire the console.
 214 void enable_console_log(bool enable) noexcept
 215 {
 216     if (enable && ! log_to_console) {
 217         // Console is fd 1 - stdout
 218         // Set non-blocking IO:
 219         int flags = fcntl(1, F_GETFL, 0);
 220         fcntl(1, F_SETFL, flags | O_NONBLOCK);
 221         // Activate watcher:
 222         log_stream[DLOG_CONS].init(STDOUT_FILENO);
 223         log_stream[DLOG_CONS].setEnabled(&eventLoop, true);
 224         log_to_console = true;
 225     }
 226     else if (! enable && log_to_console) {
 227         log_to_console = false;
 228         log_stream[DLOG_CONS].flushForRelease();
 229     }
 230 }
 231
 232
 233 // Variadic method to calculate the sum of string lengths:
 234 static int sum_length(const char *arg) noexcept
 235 {
 236     return std::strlen(arg);
 237 }
 238
 239 template <typename U, typename ... T> static int sum_length(U first, T ... args) noexcept
 240 {
 241     return sum_length(first) + sum_length(args...);
 242 }
 243
 244 // Variadic method to append strings to a buffer:
 245 static void append(BufferedLogStream &buf, const char *s)
 246 {
 247     buf.append(s, std::strlen(s));
 248 }
 249
 250 template <typename U, typename ... T> static void append(BufferedLogStream &buf, U u, T ... t)
 251 {
 252     append(buf, u);
 253     append(buf, t...);
 254 }
 255
 256 // Variadic method to log a sequence of strings as a single message:
 257 template <typename ... T> static void do_log(T ... args) noexcept
 258 {
 259     int amount = sum_length(args...);
 260     if (log_stream[DLOG_CONS].get_free() >= amount) {
 261         append(log_stream[DLOG_CONS], args...);
 262
 263         bool was_first = (log_stream[DLOG_CONS].current_index == 0);
 264         log_stream[DLOG_CONS].current_index += amount;
 265         if (was_first && log_to_console) {
 266             log_stream[DLOG_CONS].setEnabled(&eventLoop, true);
 267         }
 268     }
 269     else {
 270         // TODO mark a discarded message
 271     }
 272 }
 273
 274 // Variadic method to potentially log a sequence of strings as a single message with the given log level:
 275 template <typename ... T> static void do_log(LogLevel lvl, T ... args) noexcept
 276 {
 277     if (lvl >= cons_log_level) {
 278         do_log(args...);
 279     }
 280 }
 281
 282 // Log a message. A newline will be appended.
 283 void log(LogLevel lvl, const char *msg) noexcept
 284 {
 285     do_log(lvl, "dinit: ", msg, "\n");
 286 }
 287
 288 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
 289 template <typename T> static void do_log_part(T arg) noexcept
 290 {
 291     int amount = sum_length(arg);
 292     if (log_stream[DLOG_CONS].get_free() >= amount) {
 293         append(log_stream[DLOG_CONS], arg);
 294     }
 295     else {
 296         log_stream[DLOG_CONS].rollback_msg();
 297         log_current_line = false;
 298         // TODO mark discarded message
 299     }
 300 }
 301
 302 // Commit a message that was issued as a series of parts (via do_log_part).
 303 static void do_log_commit() noexcept
 304 {
 305     if (log_current_line) {
 306         log_stream[DLOG_CONS].commit_msg();
 307     }
 308 }
 309
 310 // Log a multi-part message beginning
 311 void logMsgBegin(LogLevel lvl, const char *msg) noexcept
 312 {
 313     // TODO use buffer
 314     log_current_line = lvl >= log_level;
 315     if (log_current_line) {
 316         if (log_to_console) {
 317             do_log_part("dinit: ");
 318             do_log_part(msg);
 319         }
 320     }
 321 }
 322
 323 // Continue a multi-part log message
 324 void logMsgPart(const char *msg) noexcept
 325 {
 326     // TODO use buffer
 327     if (log_current_line) {
 328         if (log_to_console) {
 329             do_log_part(msg);
 330         }
 331     }
 332 }
 333
 334 // Complete a multi-part log message
 335 void logMsgEnd(const char *msg) noexcept
 336 {
 337     // TODO use buffer
 338     if (log_current_line) {
 339         if (log_to_console) {
 340             do_log_part(msg);
 341             do_log_part("\n");
 342             do_log_commit();
 343         }
 344     }
 345 }
 346
 347 void logServiceStarted(const char *service_name) noexcept
 348 {
 349     do_log("[  OK  ] ", service_name, "\n");
 350 }
 351
 352 void logServiceFailed(const char *service_name) noexcept
 353 {
 354     do_log("[FAILED] ", service_name, "\n");
 355 }
 356
 357 void logServiceStopped(const char *service_name) noexcept
 358 {
 359     do_log("[STOPPD] ", service_name, "\n");
 360 }