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