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 static bool log_current_line[2];  // Whether the current line is being logged (for console, main log)
  16 LogLevel log_level[2] = { LogLevel::WARN, LogLevel::WARN };
  17
  18 static ServiceSet *service_set = nullptr;  // Reference to service set
  19
  20 namespace {
  21 class BufferedLogStream : public PosixFdWatcher<NullMutex>
  22 {
  23     private:
  24
  25     // Outgoing:
  26     bool partway = false;     // if we are partway throught output of a log message
  27     bool discarded = false;   // if we have discarded a message
  28     bool release = true;      // if we should inhibit output and release console
  29
  30     // A "special message" is not stored in the circular buffer; instead
  31     // it is delivered from an external buffer not managed by BufferedLogger.
  32     bool special = false;      // currently outputting special message?
  33     char *special_buf; // buffer containing special message
  34     int msg_index;     // index into special message
  35
  36     CPBuffer<4096> log_buffer;
  37
  38     public:
  39
  40     // Incoming:
  41     int current_index = 0;    // current/next incoming message index
  42
  43     int fd = -1;
  44
  45     void init(int fd)
  46     {
  47         this->fd = fd;
  48         release = false;
  49     }
  50
  51     Rearm gotEvent(EventLoop_t *loop, int fd, int flags) noexcept override;
  52
  53     // Check whether the console can be released.
  54     void flushForRelease();
  55     void release_console();
  56     bool is_release_set() { return release; }
  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 && ! release) {
  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 void BufferedLogStream::release_console()
  93 {
  94     if (release) {
  95         int flags = fcntl(1, F_GETFL, 0);
  96         fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
  97         service_set->pullConsoleQueue();
  98     }
  99 }
 100
 101 void BufferedLogStream::flushForRelease()
 102 {
 103     release = true;
 104
 105     // Try to flush any messages that are currently buffered. (Console is non-blocking
 106     // so it will fail gracefully).
 107     if (gotEvent(&eventLoop, fd, out_events) == Rearm::DISARM) {
 108         // Console has already been released at this point.
 109         setEnabled(&eventLoop, false);
 110     }
 111     // gotEvent didn't want to disarm, so must be partway through a message; will
 112     // release when it's finished.
 113 }
 114
 115 Rearm BufferedLogStream::gotEvent(EventLoop_t *loop, int fd, int flags) noexcept
 116 {
 117     auto &log_stream = *this;
 118
 119     if ((! partway) && log_stream.special) {
 120         char * start = log_stream.special_buf + log_stream.msg_index;
 121         char * end = std::find(log_stream.special_buf + log_stream.msg_index, (char *)nullptr, '\n');
 122         int r = write(fd, start, end - start + 1);
 123         if (r >= 0) {
 124             if (start + r > end) {
 125                 // All written: go on to next message in queue
 126                 log_stream.special = false;
 127                 log_stream.partway = false;
 128                 log_stream.msg_index = 0;
 129
 130                 if (release) {
 131                     release_console();
 132                     return Rearm::DISARM;
 133                 }
 134             }
 135             else {
 136                 log_stream.msg_index += r;
 137                 return Rearm::REARM;
 138             }
 139         }
 140         else {
 141             // spurious readiness, or EAGAIN/EWOULDBLOCK/EINTR
 142             // There's not much we can do for other errors anyway.
 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 (log_stream.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     }
 185
 186     // We've written something by the time we get here. We could fall through to below, but
 187     // let's give other events a chance to be processed by returning now.
 188     return Rearm::REARM;
 189 }
 190
 191 // Initialise the logging subsystem
 192 // Potentially throws std::bad_alloc or std::system_error
 193 void init_log(ServiceSet *sset)
 194 {
 195     service_set = sset;
 196     log_stream[DLOG_CONS].registerWith(&eventLoop, STDOUT_FILENO, out_events); // TODO register in disabled state
 197     enable_console_log(true);
 198 }
 199
 200 // Set up the main log to output to the given file descriptor.
 201 // Potentially throws std::bad_alloc or std::system_error
 202 void setup_main_log(int fd)
 203 {
 204     log_stream[DLOG_MAIN].init(STDERR_FILENO);
 205     log_stream[DLOG_MAIN].registerWith(&eventLoop, STDERR_FILENO, out_events);
 206 }
 207
 208 bool is_log_flushed() noexcept
 209 {
 210     return log_stream[DLOG_CONS].current_index == 0;
 211 }
 212
 213 // Enable or disable console logging. If disabled, console logging will be disabled on the
 214 // completion of output of the current message (if any), at which point the first service record
 215 // queued in the service set will acquire the console.
 216 void enable_console_log(bool enable) noexcept
 217 {
 218     bool log_to_console = ! log_stream[DLOG_CONS].is_release_set();
 219     if (enable && ! log_to_console) {
 220         // Console is fd 1 - stdout
 221         // Set non-blocking IO:
 222         int flags = fcntl(1, F_GETFL, 0);
 223         fcntl(1, F_SETFL, flags | O_NONBLOCK);
 224         // Activate watcher:
 225         log_stream[DLOG_CONS].init(STDOUT_FILENO);
 226         log_stream[DLOG_CONS].setEnabled(&eventLoop, true);
 227     }
 228     else if (! enable && log_to_console) {
 229         log_stream[DLOG_CONS].flushForRelease();
 230     }
 231 }
 232
 233
 234 // Variadic method to calculate the sum of string lengths:
 235 static int sum_length(const char *arg) noexcept
 236 {
 237     return std::strlen(arg);
 238 }
 239
 240 template <typename U, typename ... T> static int sum_length(U first, T ... args) noexcept
 241 {
 242     return sum_length(first) + sum_length(args...);
 243 }
 244
 245 // Variadic method to append strings to a buffer:
 246 static void append(BufferedLogStream &buf, const char *s)
 247 {
 248     buf.append(s, std::strlen(s));
 249 }
 250
 251 template <typename U, typename ... T> static void append(BufferedLogStream &buf, U u, T ... t)
 252 {
 253     append(buf, u);
 254     append(buf, t...);
 255 }
 256
 257 // Variadic method to log a sequence of strings as a single message:
 258 template <typename ... T> static void push_to_log(T ... args) noexcept
 259 {
 260     int amount = sum_length(args...);
 261     for (int i = 0; i < 2; i++) {
 262         if (! log_current_line[i]) continue;
 263         if (log_stream[i].get_free() >= amount) {
 264             append(log_stream[i], args...);
 265             log_stream[i].commit_msg();
 266         }
 267         else {
 268             // TODO mark a discarded message
 269         }
 270     }
 271 }
 272
 273 // Variadic method to potentially log a sequence of strings as a single message with the given log level:
 274 template <typename ... T> static void do_log(LogLevel lvl, T ... args) noexcept
 275 {
 276     log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
 277     log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
 278     push_to_log(args...);
 279 }
 280
 281 template <typename ... T> static void do_log_cons(T ... args) noexcept
 282 {
 283     log_current_line[DLOG_CONS] = true;
 284     log_current_line[DLOG_MAIN] = false;
 285     push_to_log(args...);
 286 }
 287
 288 template <typename ... T> static void do_log_main(T ... args) noexcept
 289 {
 290     log_current_line[DLOG_CONS] = false;
 291     log_current_line[DLOG_MAIN] = true;
 292     push_to_log(args...);
 293 }
 294
 295 // Log a message. A newline will be appended.
 296 void log(LogLevel lvl, const char *msg) noexcept
 297 {
 298     do_log(lvl, "dinit: ", msg, "\n");
 299 }
 300
 301 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
 302 template <typename T> static void do_log_part(int idx, T arg) noexcept
 303 {
 304     if (log_current_line[idx]) {
 305         int amount = sum_length(arg);
 306         if (log_stream[idx].get_free() >= amount) {
 307             append(log_stream[idx], arg);
 308         }
 309         else {
 310             log_stream[idx].rollback_msg();
 311             log_current_line[idx] = false;
 312             // TODO mark discarded message
 313         }
 314     }
 315 }
 316
 317 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
 318 template <typename T> static void do_log_part(T arg) noexcept
 319 {
 320     do_log_part(DLOG_CONS, arg);
 321 }
 322
 323 // Commit a message that was issued as a series of parts (via do_log_part).
 324 static void do_log_commit(int idx) noexcept
 325 {
 326     if (log_current_line[idx]) {
 327         log_stream[idx].commit_msg();
 328     }
 329 }
 330
 331 // Log a multi-part message beginning
 332 void logMsgBegin(LogLevel lvl, const char *msg) noexcept
 333 {
 334     log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
 335     log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
 336     for (int i = 0; i < 2; i++) {
 337         do_log_part(i, "dinit: ");
 338         do_log_part(i, msg);
 339     }
 340 }
 341
 342 // Continue a multi-part log message
 343 void logMsgPart(const char *msg) noexcept
 344 {
 345     do_log_part(DLOG_CONS, msg);
 346     do_log_part(DLOG_MAIN, msg);
 347 }
 348
 349 // Complete a multi-part log message
 350 void logMsgEnd(const char *msg) noexcept
 351 {
 352     for (int i = 0; i < 2; i++) {
 353         do_log_part(i, msg);
 354         do_log_part(i, "\n");
 355         do_log_commit(i);
 356     }
 357 }
 358
 359 void logServiceStarted(const char *service_name) noexcept
 360 {
 361     do_log_cons("[  OK  ] ", service_name, "\n");
 362     do_log_main("dinit: service ", service_name, " started.\n");
 363 }
 364
 365 void logServiceFailed(const char *service_name) noexcept
 366 {
 367     do_log_cons("[FAILED] ", service_name, "\n");
 368     do_log_main("dinit: service ", service_name, " failed to start.\n");
 369 }
 370
 371 void logServiceStopped(const char *service_name) noexcept
 372 {
 373     do_log_cons("[STOPPD] ", service_name, "\n");
 374     do_log_main("dinit: service ", service_name, " stopped.\n");
 375 }