6 #include <sys/syslog.h>
12 #include "dinit-log.h"
15 // Dinit logging subsystem.
17 // Note that most actual functions for logging messages are found in the header, dinit-log.h.
19 // We have two separate log "streams": one for the console/stdout, one for the syslog facility. Both have a
20 // circular buffer. Log messages are appended to the circular buffer (for the syslog stream, the messages
21 // are prepended with a syslog priority indicator). Both streams start out inactive (release = true in
22 // buffered_log_stream), which means they will buffer messages but not write them.
24 // The console log stream needs to be able to release the console, if a service is waiting to acquire it.
25 // This is accomplished by calling flush_for_release() which then completes the output of the current
26 // message (if any) and then assigns the console to a waiting service.
28 extern eventloop_t event_loop;
30 static bool log_current_line[2]; // Whether the current line is being logged (for console, main log)
31 loglevel_t log_level[2] = { loglevel_t::WARN, loglevel_t::INFO };
32 static bool log_format_syslog[2] = { false, true };
34 static service_set *services = nullptr; // Reference to service set
36 using rearm = dasynq::rearm;
39 class buffered_log_stream : public eventloop_t::fd_watcher_impl<buffered_log_stream>
44 bool partway = false; // if we are partway throught output of a log message
45 bool discarded = false; // if we have discarded a message
46 bool release = true; // if we should inhibit output and release console
48 // A "special message" is not stored in the circular buffer; instead
49 // it is delivered from an external buffer not managed by BufferedLogger.
50 bool special = false; // currently outputting special message?
51 const char *special_buf; // buffer containing special message
52 int msg_index; // index into special message
54 cpbuffer<4096> log_buffer;
59 int current_index = 0; // current/next incoming message index
69 rearm fd_event(eventloop_t &loop, int fd, int flags) noexcept;
71 // Check whether the console can be released.
72 void flush_for_release();
73 bool is_release_set() { return release; }
75 // Commit a log message
78 bool was_first = current_index == 0;
79 current_index = log_buffer.get_length();
80 if (was_first && ! release) {
81 set_enabled(event_loop, true);
87 log_buffer.trim_to(current_index);
92 return log_buffer.get_free();
95 void append(const char *s, size_t len)
97 log_buffer.append(s, len);
100 // Discard buffer; call only when the stream isn't active.
104 log_buffer.trim_to(0);
107 // Mark that a message was discarded due to full buffer
108 void mark_discarded()
114 void release_console();
119 // (One for main log, one for console)
120 static buffered_log_stream log_stream[2];
122 constexpr static int DLOG_MAIN = 0; // main log facility
123 constexpr static int DLOG_CONS = 1; // console
125 void buffered_log_stream::release_console()
128 int flags = fcntl(1, F_GETFL, 0);
129 fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
130 services->pull_console_queue();
134 void buffered_log_stream::flush_for_release()
138 // Try to flush any messages that are currently buffered. (Console is non-blocking
139 // so it will fail gracefully).
140 if (fd_event(event_loop, fd, dasynq::OUT_EVENTS) == rearm::DISARM) {
141 // Console has already been released at this point.
142 set_enabled(event_loop, false);
144 // fd_event didn't want to disarm, so must be partway through a message; will
145 // release when it's finished.
148 rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexcept
150 if ((! partway) && (! special) && discarded) {
151 special_buf = "dinit: *** log message discarded due to full buffer ***\n";
155 if ((! partway) && special) {
156 const char * start = special_buf + msg_index;
157 const char * end = std::find(special_buf + msg_index, (const char *)nullptr, '\n');
158 int r = write(fd, start, end - start + 1);
160 if (start + r > end) {
161 // All written: go on to next message in queue
168 return rearm::DISARM;
176 else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
177 return rearm::REMOVE;
182 // Writing from the regular circular buffer
184 if (current_index == 0) {
186 return rearm::DISARM;
189 // We try to find a complete line (terminated by '\n') in the buffer, and write it
190 // out. Since it may span the circular buffer end, it may consist of two distinct spans,
191 // and so we use writev to write them atomically.
193 struct iovec logiov[2];
195 char *ptr = log_buffer.get_ptr(0);
196 int len = log_buffer.get_contiguous_length(ptr);
197 char *creptr = ptr + len; // contiguous region end
198 char *eptr = std::find(ptr, creptr, '\n');
200 bool will_complete = false; // will complete this message?
201 if (eptr != creptr) {
202 eptr++; // include '\n'
203 will_complete = true;
208 logiov[0].iov_base = ptr;
209 logiov[0].iov_len = len;
210 int iovs_to_write = 1;
212 // Do we need the second span?
213 if (! will_complete && len != log_buffer.get_length()) {
214 ptr = log_buffer.get_buf_base();
215 creptr = ptr + log_buffer.get_length() - len;
216 eptr = std::find(ptr, creptr, '\n');
217 if (eptr != creptr) {
218 eptr++; // include '\n'
219 // It should not ever be the case that we do not now have a complete message
220 will_complete = true;
222 logiov[1].iov_base = ptr;
223 logiov[1].iov_len = eptr - ptr;
224 len += logiov[1].iov_len;
228 ssize_t r = writev(fd, logiov, iovs_to_write);
231 bool complete = (r == len) && will_complete;
232 log_buffer.consume(len);
233 partway = ! complete;
235 current_index -= len;
236 if (current_index == 0 || release) {
237 // No more messages buffered / stop logging to console:
239 return rearm::DISARM;
243 else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
244 return rearm::REMOVE;
248 // We've written something by the time we get here. We could fall through to below, but
249 // let's give other events a chance to be processed by returning now.
253 // Initialise the logging subsystem
254 // Potentially throws std::bad_alloc or std::system_error
255 void init_log(service_set *sset)
258 log_stream[DLOG_CONS].add_watch(event_loop, STDOUT_FILENO, dasynq::OUT_EVENTS, false);
259 enable_console_log(true);
262 // Set up the main log to output to the given file descriptor.
263 // Potentially throws std::bad_alloc or std::system_error
264 void setup_main_log(int fd, bool syslog_format)
266 log_stream[DLOG_MAIN].init(fd);
267 log_stream[DLOG_MAIN].add_watch(event_loop, fd, dasynq::OUT_EVENTS);
268 log_format_syslog[DLOG_MAIN] = syslog_format;
271 bool is_log_flushed() noexcept
273 return log_stream[DLOG_CONS].current_index == 0;
276 // Enable or disable console logging. If disabled, console logging will be disabled on the
277 // completion of output of the current message (if any), at which point the first service record
278 // queued in the service set will acquire the console.
279 void enable_console_log(bool enable) noexcept
281 bool log_to_console = ! log_stream[DLOG_CONS].is_release_set();
282 if (enable && ! log_to_console) {
283 // Set non-blocking IO:
284 int flags = fcntl(STDOUT_FILENO, F_GETFL, 0);
285 fcntl(STDOUT_FILENO, F_SETFL, flags | O_NONBLOCK);
287 log_stream[DLOG_CONS].init(STDOUT_FILENO);
288 log_stream[DLOG_CONS].set_enabled(event_loop, true);
290 else if (! enable && log_to_console) {
291 log_stream[DLOG_CONS].flush_for_release();
295 void discard_console_log_buffer() noexcept
297 log_stream[DLOG_CONS].discard();
300 // Variadic method to calculate the sum of string lengths:
301 static int sum_length(const char *arg) noexcept
303 return std::strlen(arg);
306 template <typename ... T> static int sum_length(const char * first, T ... args) noexcept
308 return sum_length(first) + sum_length(args...);
311 // Variadic method to append strings to a buffer:
312 static void append(buffered_log_stream &buf, const char *s)
314 buf.append(s, std::strlen(s));
317 template <typename ... T> static void append(buffered_log_stream &buf, const char *u, T ... t)
323 static int log_level_to_syslog_level(loglevel_t l)
326 case loglevel_t::DEBUG:
328 case loglevel_t::INFO:
330 case loglevel_t::WARN:
332 case loglevel_t::ERROR:
340 // Variadic method to log a sequence of strings as a single message to a particular facility:
341 template <typename ... T> static void push_to_log(int idx, T ... args) noexcept
343 if (! log_current_line[idx]) return;
344 int amount = sum_length(args...);
345 if (log_stream[idx].get_free() >= amount) {
346 append(log_stream[idx], args...);
347 log_stream[idx].commit_msg();
350 log_stream[idx].mark_discarded();
354 // Variadic method to potentially log a sequence of strings as a single message with the given log level:
355 template <typename ... T> static void do_log(loglevel_t lvl, bool to_cons, T ... args) noexcept
357 log_current_line[DLOG_CONS] = (lvl >= log_level[DLOG_CONS]) && to_cons;
358 log_current_line[DLOG_MAIN] = (lvl >= log_level[DLOG_MAIN]);
359 push_to_log(DLOG_CONS, args...);
361 if (log_current_line[DLOG_MAIN]) {
362 if (log_format_syslog[DLOG_MAIN]) {
364 snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
365 push_to_log(DLOG_MAIN, svcbuf, args...);
368 push_to_log(DLOG_MAIN, args...);
373 template <typename ... T> static void do_log_cons(T ... args) noexcept
375 log_current_line[DLOG_CONS] = true;
376 log_current_line[DLOG_MAIN] = false;
377 push_to_log(DLOG_CONS, args...);
380 // Log to the main facility at NOTICE level
381 template <typename ... T> static void do_log_main(T ... args) noexcept
383 log_current_line[DLOG_CONS] = false;
384 log_current_line[DLOG_MAIN] = true;
386 if (log_format_syslog[DLOG_MAIN]) {
388 snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | LOG_NOTICE);
389 push_to_log(DLOG_MAIN, svcbuf, args...);
392 push_to_log(DLOG_MAIN, args...);
396 // Log a message. A newline will be appended.
397 void log(loglevel_t lvl, const char *msg) noexcept
399 do_log(lvl, true, "dinit: ", msg, "\n");
402 void log(loglevel_t lvl, bool to_cons, const char *msg) noexcept
404 do_log(lvl, to_cons, "dinit: ", msg, "\n");
407 // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
408 template <typename T> static void do_log_part(int idx, T arg) noexcept
410 if (log_current_line[idx]) {
411 int amount = sum_length(arg);
412 if (log_stream[idx].get_free() >= amount) {
413 append(log_stream[idx], arg);
416 log_stream[idx].rollback_msg();
417 log_current_line[idx] = false;
418 log_stream[idx].mark_discarded();
423 // Commit a message that was issued as a series of parts (via do_log_part).
424 static void do_log_commit(int idx) noexcept
426 if (log_current_line[idx]) {
427 log_stream[idx].commit_msg();
431 // Log a multi-part message beginning
432 void log_msg_begin(loglevel_t lvl, const char *msg) noexcept
434 log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
435 log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
437 // Prepend the syslog priority level string ("<N>") for the main log:
438 if (log_current_line[DLOG_MAIN]) {
439 if (log_format_syslog[DLOG_MAIN]) {
441 snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
442 do_log_part(DLOG_MAIN, svcbuf);
446 for (int i = 0; i < 2; i++) {
447 do_log_part(i, "dinit: ");
452 // Continue a multi-part log message
453 void log_msg_part(const char *msg) noexcept
455 do_log_part(DLOG_CONS, msg);
456 do_log_part(DLOG_MAIN, msg);
459 // Complete a multi-part log message
460 void log_msg_end(const char *msg) noexcept
462 for (int i = 0; i < 2; i++) {
464 do_log_part(i, "\n");
469 void log_service_started(const char *service_name) noexcept
471 do_log_cons("[ OK ] ", service_name, "\n");
472 do_log_main("dinit: service ", service_name, " started.\n");
475 void log_service_failed(const char *service_name) noexcept
477 do_log_cons("[FAILED] ", service_name, "\n");
478 do_log_main("dinit: service ", service_name, " failed to start.\n");
481 void log_service_stopped(const char *service_name) noexcept
483 do_log_cons("[STOPPD] ", service_name, "\n");
484 do_log_main("dinit: service ", service_name, " stopped.\n");