dinit-log.cc 16 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540
  1. #include <algorithm>
  2. #include <unistd.h>
  3. #include <fcntl.h>
  4. #include <sys/syslog.h>
  5. #include <sys/uio.h>
  6. #include "dasynq.h"
  7. #include "service.h"
  8. #include "dinit-log.h"
  9. #include "cpbuffer.h"
  10. // Dinit logging subsystem.
  11. //
  12. // Note that most actual functions for logging messages are found in the header, dinit-log.h.
  13. // See documentation there also.
  14. extern eventloop_t event_loop;
  15. extern bool external_log_open;
  16. static bool log_current_line[DLOG_NUM]; // Whether the current line is being logged (for console, main log)
  17. static bool log_format_syslog[DLOG_NUM] = { true, false };
  18. static_assert(DLOG_NUM == 2, "number of log streams has changed");
  19. static_assert(DLOG_MAIN == 0, "main log index has changed");
  20. static service_set *services = nullptr; // Reference to service set
  21. loglevel_t log_level[DLOG_NUM] = { loglevel_t::NOTICE, loglevel_t::WARN };
  22. static_assert(DLOG_NUM == 2, "number of log streams has changed");
  23. bool console_service_status = true; // show service status messages to console?
  24. dasynq::time_val release_time; // time the log was released
  25. using rearm = dasynq::rearm;
  26. namespace {
  27. class buffered_log_stream : public eventloop_t::fd_watcher_impl<buffered_log_stream>
  28. {
  29. private:
  30. // Outgoing:
  31. bool partway = false; // if we are partway throught output of a log message
  32. bool discarded = false; // if we have discarded a message
  33. bool release = true; // if we should inhibit output and release console when possible
  34. // A "special message" is not stored in the circular buffer; instead
  35. // it is delivered from an external buffer not managed by BufferedLogger.
  36. bool special = false; // currently outputting special message?
  37. const char *special_buf; // buffer containing special message
  38. int msg_index; // index into special message
  39. cpbuffer<4096> log_buffer;
  40. public:
  41. // Incoming:
  42. int current_index = 0; // current/next incoming message index
  43. int fd = -1;
  44. void init(int fd)
  45. {
  46. this->fd = fd;
  47. release = false;
  48. }
  49. rearm fd_event(eventloop_t &loop, int fd, int flags) noexcept;
  50. // Check whether the console can be released.
  51. void flush_for_release();
  52. bool is_release_set() { return release; }
  53. // Commit a log message
  54. void commit_msg()
  55. {
  56. bool was_first = current_index == 0;
  57. current_index = log_buffer.get_length();
  58. if (was_first && ! release) {
  59. set_enabled(event_loop, true);
  60. }
  61. }
  62. void rollback_msg()
  63. {
  64. log_buffer.trim_to(current_index);
  65. }
  66. int get_free()
  67. {
  68. return log_buffer.get_free();
  69. }
  70. void append(const char *s, size_t len)
  71. {
  72. log_buffer.append(s, len);
  73. }
  74. // Discard buffer; call only when the stream isn't active.
  75. void discard()
  76. {
  77. current_index = 0;
  78. log_buffer.trim_to(0);
  79. }
  80. // Mark that a message was discarded due to full buffer
  81. void mark_discarded()
  82. {
  83. discarded = true;
  84. }
  85. void watch_removed() noexcept override;
  86. private:
  87. void release_console();
  88. };
  89. // Two log streams:
  90. // (One for main log, one for console)
  91. buffered_log_stream log_stream[DLOG_NUM];
  92. void buffered_log_stream::release_console()
  93. {
  94. if (release) {
  95. int flags = fcntl(1, F_GETFL, 0);
  96. fcntl(1, F_SETFL, flags & ~O_NONBLOCK);
  97. if (services != nullptr) {
  98. services->pull_console_queue();
  99. }
  100. if (release) {
  101. // release still set, we didn't immediately get the console back; record the
  102. // time at which we released:
  103. event_loop.get_time(release_time, clock_type::MONOTONIC);
  104. }
  105. }
  106. }
  107. void buffered_log_stream::flush_for_release()
  108. {
  109. if (release) return;
  110. release = true;
  111. // Try to flush any messages that are currently buffered. (Console is non-blocking
  112. // so it will fail gracefully).
  113. rearm rearm_val = fd_event(event_loop, fd, dasynq::OUT_EVENTS);
  114. if (rearm_val == rearm::DISARM) {
  115. // Console has already been released at this point.
  116. set_enabled(event_loop, false);
  117. }
  118. if (rearm_val == rearm::REMOVE) {
  119. deregister(event_loop);
  120. }
  121. // fd_event didn't want to disarm, so must be partway through a message; will
  122. // release when it's finished.
  123. }
  124. rearm buffered_log_stream::fd_event(eventloop_t &loop, int fd, int flags) noexcept
  125. {
  126. if ((! partway) && (! special) && discarded) {
  127. special_buf = "dinit: *** log message discarded due to full buffer ***\n";
  128. special = true;
  129. discarded = false;
  130. msg_index = 0;
  131. }
  132. if ((! partway) && special) {
  133. const char * start = special_buf + msg_index;
  134. const char * end = start;
  135. while (*end != '\n') end++;
  136. int r = bp_sys::write(fd, start, end - start + 1);
  137. if (r >= 0) {
  138. if (start + r > end) {
  139. // All written: go on to next message in queue
  140. special = false;
  141. discarded = false;
  142. msg_index = 0;
  143. if (release) {
  144. release_console();
  145. return rearm::DISARM;
  146. }
  147. }
  148. else {
  149. msg_index += r;
  150. return rearm::REARM;
  151. }
  152. }
  153. else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
  154. return rearm::REMOVE;
  155. }
  156. return rearm::REARM;
  157. }
  158. else {
  159. // Writing from the regular circular buffer
  160. if (current_index == 0) {
  161. release_console();
  162. return rearm::DISARM;
  163. }
  164. // We try to find a complete line (terminated by '\n') in the buffer, and write it
  165. // out. Since it may span the circular buffer end, it may consist of two distinct spans,
  166. // and so we use writev to write them atomically.
  167. struct iovec logiov[2];
  168. char *ptr = log_buffer.get_ptr(0);
  169. unsigned len = log_buffer.get_contiguous_length(ptr);
  170. char *creptr = ptr + len; // contiguous region end
  171. char *eptr = std::find(ptr, creptr, '\n');
  172. bool will_complete = false; // will complete this message?
  173. if (eptr != creptr) {
  174. eptr++; // include '\n'
  175. will_complete = true;
  176. }
  177. len = eptr - ptr;
  178. logiov[0].iov_base = ptr;
  179. logiov[0].iov_len = len;
  180. int iovs_to_write = 1;
  181. // Do we need the second span?
  182. if (!will_complete && len != log_buffer.get_length()) {
  183. ptr = log_buffer.get_buf_base();
  184. creptr = ptr + log_buffer.get_length() - len;
  185. eptr = std::find(ptr, creptr, '\n');
  186. if (eptr != creptr) {
  187. eptr++; // include '\n'
  188. // It should not ever be the case that we do not now have a complete message
  189. will_complete = true;
  190. }
  191. logiov[1].iov_base = ptr;
  192. logiov[1].iov_len = eptr - ptr;
  193. len += logiov[1].iov_len;
  194. iovs_to_write = 2;
  195. }
  196. ssize_t r = bp_sys::writev(fd, logiov, iovs_to_write);
  197. if (r >= 0) {
  198. bool complete = (r == len) && will_complete;
  199. log_buffer.consume(len);
  200. partway = ! complete;
  201. if (complete) {
  202. current_index -= len;
  203. if (current_index == 0 || release) {
  204. // No more messages buffered / stop logging to console:
  205. release_console();
  206. return rearm::DISARM;
  207. }
  208. }
  209. }
  210. else if (errno != EAGAIN && errno != EINTR && errno != EWOULDBLOCK) {
  211. return rearm::REMOVE;
  212. }
  213. }
  214. // We've written something by the time we get here. We could fall through to below, but
  215. // let's give other events a chance to be processed by returning now.
  216. return rearm::REARM;
  217. }
  218. void buffered_log_stream::watch_removed() noexcept
  219. {
  220. if (fd > STDERR_FILENO) {
  221. bp_sys::close(fd);
  222. }
  223. fd = -1;
  224. release = true; // prevent attempt to enable watch
  225. // Here we rely on there only being two logs, console and "main"; we can check if we are the
  226. // main log via identity:
  227. if (&log_stream[DLOG_MAIN] == this) {
  228. external_log_open = false;
  229. }
  230. }
  231. } // end namespace
  232. // Initialise the logging subsystem
  233. // Potentially throws std::bad_alloc or std::system_error
  234. void init_log(bool syslog_format)
  235. {
  236. log_stream[DLOG_CONS].add_watch(event_loop, STDOUT_FILENO, dasynq::OUT_EVENTS, false);
  237. enable_console_log(true);
  238. // The main (non-console) log won't be active yet, but we set the format here so that we
  239. // buffer messages in the correct format:
  240. log_format_syslog[DLOG_MAIN] = syslog_format;
  241. }
  242. void setup_log_console_handoff(service_set *sset)
  243. {
  244. services = sset;
  245. }
  246. // Close logging subsystem
  247. void close_log()
  248. {
  249. if (log_stream[DLOG_CONS].fd != -1) log_stream[DLOG_CONS].deregister(event_loop);
  250. if (log_stream[DLOG_MAIN].fd != -1) log_stream[DLOG_MAIN].deregister(event_loop);
  251. }
  252. // Set up the main log to output to the given file descriptor.
  253. // Potentially throws std::bad_alloc or std::system_error
  254. void setup_main_log(int fd)
  255. {
  256. log_stream[DLOG_MAIN].init(fd);
  257. log_stream[DLOG_MAIN].add_watch(event_loop, fd, dasynq::OUT_EVENTS);
  258. }
  259. bool is_log_flushed() noexcept
  260. {
  261. return log_stream[DLOG_CONS].current_index == 0 &&
  262. (log_stream[DLOG_MAIN].fd == -1 || log_stream[DLOG_MAIN].current_index == 0);
  263. }
  264. // Enable or disable console logging. If disabled, console logging will be disabled on the
  265. // completion of output of the current message (if any), at which point the first service record
  266. // queued in the service set will acquire the console.
  267. void enable_console_log(bool enable) noexcept
  268. {
  269. bool log_to_console = ! log_stream[DLOG_CONS].is_release_set();
  270. if (enable && ! log_to_console) {
  271. // Set non-blocking IO:
  272. int flags = fcntl(STDOUT_FILENO, F_GETFL, 0);
  273. fcntl(STDOUT_FILENO, F_SETFL, flags | O_NONBLOCK);
  274. // Activate watcher:
  275. log_stream[DLOG_CONS].init(STDOUT_FILENO);
  276. log_stream[DLOG_CONS].set_enabled(event_loop, true);
  277. }
  278. else if (! enable && log_to_console) {
  279. log_stream[DLOG_CONS].flush_for_release();
  280. }
  281. }
  282. void discard_console_log_buffer() noexcept
  283. {
  284. // Only discard if more than a second has passed since we released the console.
  285. dasynq::time_val current_time;
  286. event_loop.get_time(current_time, clock_type::MONOTONIC);
  287. if (current_time - release_time >= dasynq::time_val(1, 0)) {
  288. log_stream[DLOG_CONS].discard();
  289. }
  290. }
  291. // Variadic method to calculate the sum of string lengths:
  292. static int sum_length(const char *arg) noexcept
  293. {
  294. return std::strlen(arg);
  295. }
  296. template <typename ... T> static int sum_length(const char * first, T ... args) noexcept
  297. {
  298. return sum_length(first) + sum_length(args...);
  299. }
  300. // Variadic method to append strings to a buffer:
  301. static void append(buffered_log_stream &buf, const char *s)
  302. {
  303. buf.append(s, std::strlen(s));
  304. }
  305. template <typename ... T> static void append(buffered_log_stream &buf, const char *u, T ... t)
  306. {
  307. append(buf, u);
  308. append(buf, t...);
  309. }
  310. static int log_level_to_syslog_level(loglevel_t l)
  311. {
  312. switch (l) {
  313. case loglevel_t::DEBUG:
  314. return LOG_DEBUG;
  315. case loglevel_t::NOTICE:
  316. return LOG_NOTICE;
  317. case loglevel_t::WARN:
  318. return LOG_WARNING;
  319. case loglevel_t::ERROR:
  320. return LOG_ERR;
  321. default: ;
  322. }
  323. return LOG_CRIT;
  324. }
  325. // Variadic method to log a sequence of strings as a single message to a particular facility:
  326. template <typename ... T> static void push_to_log(int idx, T ... args) noexcept
  327. {
  328. if (! log_current_line[idx]) return;
  329. int amount = sum_length(args...);
  330. if (log_stream[idx].get_free() >= amount) {
  331. append(log_stream[idx], args...);
  332. log_stream[idx].commit_msg();
  333. }
  334. else {
  335. log_stream[idx].mark_discarded();
  336. }
  337. }
  338. // Variadic method to potentially log a sequence of strings as a single message with the given log level:
  339. template <typename ... T> static void do_log(loglevel_t lvl, bool to_cons, T ... args) noexcept
  340. {
  341. log_current_line[DLOG_CONS] = (lvl >= log_level[DLOG_CONS]) && to_cons;
  342. log_current_line[DLOG_MAIN] = (lvl >= log_level[DLOG_MAIN]);
  343. push_to_log(DLOG_CONS, args...);
  344. if (log_current_line[DLOG_MAIN]) {
  345. if (log_format_syslog[DLOG_MAIN]) {
  346. char svcbuf[10];
  347. snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
  348. push_to_log(DLOG_MAIN, svcbuf, args...);
  349. }
  350. else {
  351. push_to_log(DLOG_MAIN, args...);
  352. }
  353. }
  354. }
  355. template <typename ... T> static void do_log_cons(T ... args) noexcept
  356. {
  357. if (console_service_status) {
  358. log_current_line[DLOG_CONS] = true;
  359. log_current_line[DLOG_MAIN] = false;
  360. push_to_log(DLOG_CONS, args...);
  361. }
  362. }
  363. // Log to the main facility at NOTICE level
  364. template <typename ... T> static void do_log_main(T ... args) noexcept
  365. {
  366. log_current_line[DLOG_CONS] = false;
  367. log_current_line[DLOG_MAIN] = true;
  368. if (log_format_syslog[DLOG_MAIN]) {
  369. char svcbuf[10];
  370. snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | LOG_NOTICE);
  371. push_to_log(DLOG_MAIN, svcbuf, args...);
  372. }
  373. else {
  374. push_to_log(DLOG_MAIN, args...);
  375. }
  376. }
  377. // Log a message. A newline will be appended.
  378. void log(loglevel_t lvl, const char *msg) noexcept
  379. {
  380. do_log(lvl, true, "dinit: ", msg, "\n");
  381. }
  382. void log(loglevel_t lvl, bool to_cons, const char *msg) noexcept
  383. {
  384. do_log(lvl, to_cons, "dinit: ", msg, "\n");
  385. }
  386. // Log part of a message. A series of calls to do_log_part must be followed by a call to do_log_commit.
  387. static void do_log_part(int idx, const char *arg) noexcept
  388. {
  389. if (log_current_line[idx]) {
  390. int amount = sum_length(arg);
  391. if (log_stream[idx].get_free() >= amount) {
  392. append(log_stream[idx], arg);
  393. }
  394. else {
  395. // we have to discard the message
  396. log_stream[idx].rollback_msg();
  397. log_current_line[idx] = false;
  398. log_stream[idx].mark_discarded();
  399. }
  400. }
  401. }
  402. // Commit a message that was issued as a series of parts (via do_log_part).
  403. static void do_log_commit(int idx) noexcept
  404. {
  405. if (log_current_line[idx]) {
  406. log_stream[idx].commit_msg();
  407. }
  408. }
  409. // Log a multi-part message beginning
  410. void log_msg_begin(loglevel_t lvl, const char *msg) noexcept
  411. {
  412. log_current_line[DLOG_CONS] = lvl >= log_level[DLOG_CONS];
  413. log_current_line[DLOG_MAIN] = lvl >= log_level[DLOG_MAIN];
  414. // Prepend the syslog priority level string ("<N>") for the main log:
  415. if (log_current_line[DLOG_MAIN]) {
  416. if (log_format_syslog[DLOG_MAIN]) {
  417. char svcbuf[10];
  418. snprintf(svcbuf, 10, "<%d>", LOG_DAEMON | log_level_to_syslog_level(lvl));
  419. do_log_part(DLOG_MAIN, svcbuf);
  420. }
  421. }
  422. for (int i = 0; i < DLOG_NUM; i++) {
  423. do_log_part(i, "dinit: ");
  424. do_log_part(i, msg);
  425. }
  426. }
  427. // Continue a multi-part log message
  428. void log_msg_part(const char *msg) noexcept
  429. {
  430. do_log_part(DLOG_CONS, msg);
  431. do_log_part(DLOG_MAIN, msg);
  432. }
  433. // Complete a multi-part log message
  434. void log_msg_end(const char *msg) noexcept
  435. {
  436. for (int i = 0; i < DLOG_NUM; i++) {
  437. do_log_part(i, msg);
  438. do_log_part(i, "\n");
  439. do_log_commit(i);
  440. }
  441. }
  442. void log_service_started(const char *service_name) noexcept
  443. {
  444. do_log_cons("[ OK ] ", service_name, "\n");
  445. do_log_main("dinit: service ", service_name, " started.\n");
  446. }
  447. void log_service_failed(const char *service_name) noexcept
  448. {
  449. do_log_cons("[FAILED] ", service_name, "\n");
  450. do_log_main("dinit: service ", service_name, " failed to start.\n");
  451. }
  452. void log_service_stopped(const char *service_name) noexcept
  453. {
  454. do_log_cons("[STOPPD] ", service_name, "\n");
  455. do_log_main("dinit: service ", service_name, " stopped.\n");
  456. }