1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: t -*-
3 * Copyright (c) 2012-2013 Samsung Electronics Co., Ltd.
19 #include "deduplicate.h"
20 #include <dynamic_config.h>
22 #include <logcommon.h>
23 #include "logconfig.h"
24 #include "loglimiter.h"
26 #define DEFAULT_CONFIG_LIMITER false
27 #define DEFAULT_CONFIG_PLOG true
28 #define DEFAULT_CONFIG_DEBUGMODE 0
29 #define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
32 * @brief Points to a function which writes a log message
33 * @details The function pointed to depends on the backend used
34 * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
35 * @param[in] prio Priority of the message.
36 * @param[in] tag The message tag, identifies the sender.
37 * @param[in] msg The contents of the message.
38 * @return Returns the number of bytes written on success and a negative error value on error.
39 * @see __dlog_init_backend
41 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono) = NULL;
42 void (*destroy_backend)();
44 pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
45 static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
46 static bool is_initialized = false;
48 extern void __dlog_init_pipe(const struct log_config *conf);
49 extern void __dlog_init_android(const struct log_config *conf);
52 static bool dynamic_config;
53 static bool plog[LOG_ID_MAX];
54 static bool plog_default_values[LOG_ID_MAX];
55 static bool enable_secure_logs = true;
58 static int fatal_assert;
59 static int limiter_apply_to_all_buffers;
60 static _Atomic log_priority priority_filter_level = DLOG_VERBOSE;
62 static void __configure_limiter(struct log_config *config)
69 limiter = __log_limiter_create(config);
72 static int __configure_backend(struct log_config *config)
76 const char *const backend = log_config_get(config, "backend");
80 if (!strcmp(backend, "pipe"))
81 __dlog_init_pipe(config);
82 else if (!strcmp(backend, "logger"))
83 __dlog_init_android(config);
90 static void __set_plog_default_values()
92 for (size_t i = 0; i < NELEMS(plog); ++i)
93 plog_default_values[i] = plog[i];
96 static void __initialize_plog(const struct log_config *config)
100 const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
101 for (size_t i = 0; i < NELEMS(plog); ++i)
102 plog[i] = plog_default;
103 plog[LOG_ID_APPS] = true; // the default does not apply here for backward compatibility reasons.
104 __set_plog_default_values();
107 static void __configure_parameters(struct log_config *config)
111 __initialize_plog(config);
112 __update_plog(config);
113 __set_plog_default_values();
115 enable_secure_logs = log_config_get_boolean(config, "enable_secure_logs", enable_secure_logs);
116 debugmode = log_config_get_int(config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
117 fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
118 limiter = log_config_get_boolean(config, "limiter", DEFAULT_CONFIG_LIMITER);
119 limiter_apply_to_all_buffers = log_config_get_int(config,
120 "limiter_apply_to_all_buffers",
121 DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
124 void __update_plog(const struct log_config *conf)
128 for (size_t i = 0; i < NELEMS(plog); ++i) {
129 char key[MAX_CONF_KEY_LEN];
130 const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
133 plog[i] = log_config_get_boolean(conf, key, plog_default_values[i]);
138 * @brief Configure the library
139 * @details Reads relevant config values
140 * @remarks This is more or less a constructor, but there are some obstacles
141 * to using it as such (i.e. with attribute constructor):
143 * - some important pieces of the system link to dlog, they start very early
144 * such that dlog can't properly initialize (which lasts for program lifetime)
145 * but don't actually log anything until later on and would be fine under lazy
146 * initialisation. The way to do it "properly" would be to expose this function
147 * into the API so that people can manually call it when they're ready, but
148 * one of the design goals of the current API is that it requires absolutely no
149 * other calls than `dlog_print`. Changing it would require somebody with a
150 * bird's eye view of the system to produce a design so I wouldn't count on it.
152 * - the constructor would need to have as high of a priority as possible (so as
153 * to minimize the risk of another library's constructor using uninitialized data)
154 * but at the same time others might want some room to wrap functions before
155 * dlog uses them (think mprobe/mcheck). This would also require a design pass.
160 bool __configure(void)
162 __attribute__((cleanup(log_config_free))) struct log_config config;
164 if (log_config_read(&config) < 0)
167 dynamic_config = __dynamic_config_create(&config);
169 __configure_parameters(&config);
171 if (!__configure_backend(&config)) {
172 __dynamic_config_destroy();
173 dynamic_config = false;
177 __configure_deduplicate(&config);
178 __configure_limiter(&config);
182 static void __attribute__((constructor(101))) __install_pipe_handler(void)
184 /* We mask SIGPIPE signal because most applications do not install their
185 * own SIGPIPE handler. Default behaviour in SIGPIPE case is to abort the
186 * process. SIGPIPE occurs when e.g. dlog daemon closes read pipe endpoint.
188 * We do this in the library constructor (at maximum priority) and not
189 * during regular (lazy) initialisation so as to prevent overwriting the
190 * program's actual signal handler, if it has one.
192 * In theory this is not required for the Android logger backend; however,
193 * this early we don't yet know the backend and also it is good to behave
194 * consistently in this regard anyway.
196 * We don't revert this in a destructor because Unix signals are bonkers
197 * and we have no way to do this cleanly. Most libdlog users don't use
198 * runtime linking so this would mostly done at program exit either way. */
199 signal(SIGPIPE, SIG_IGN);
202 static bool first = true;
203 static bool initialize()
208 /* The mutex acts as a barrier, but otherwise the C language's
209 * machine abstraction is single-threaded. This means that the
210 * compiler is free to rearrange calls inside the mutex according
211 * to the as-if rule because it doesn't care if another thread can
212 * access it in parallel. In particular, `is_initialized = true`
213 * directly after `__configure()` could be rearranged to go in
214 * front of it because it is not touched inside that function
215 * if the compiler thinks it helps somehow (not unlikely: since
216 * it is checked before the mutex, it is very probable for it to
217 * still be in the CPU register or something like that). On top
218 * of that, some architectures (in particular, armv7l) don't have
219 * strict memory guarantees and can reorder actual memory stores
220 * on their own, even if the compiler didn't do anything fancy
221 * when creating machine code. For more info about the issue,
222 * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
224 * Ultimately this means that there needs to be some sort of
225 * barrier between `__configure` and `is_initialized = true`,
226 * and the simplest way to achieve that is to just wait until
227 * the second entry into the mutex. */
230 pthread_mutex_lock(&log_construction_lock);
232 first = !__configure();
234 is_initialized = true;
236 pthread_mutex_unlock(&log_construction_lock);
241 * @brief Fatal assertion
242 * @details Conditionally crash the sucka who sent the log
243 * @param[in] prio Priority of the log
245 static void __dlog_fatal_assert(int prio)
247 assert(!fatal_assert || (prio != DLOG_FATAL));
251 * @brief Check log validity
252 * @details Checks whether the log is valid and eligible for printing
253 * @param[in] log_id The target buffer ID
254 * @param[in] prio The log's priority
255 * @param[in] tag The log's tag
256 * @return DLOG_ERROR_NONE on success, else an error code.
257 * @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
259 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
263 return DLOG_ERROR_INVALID_PARAMETER;
265 if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
266 return DLOG_ERROR_INVALID_PARAMETER;
268 return DLOG_ERROR_NONE;
272 * @brief Check log against limiter rules
273 * @details Checks whether the log passes current limiter rules
274 * @param[in] log_id The target buffer ID
275 * @param[in] prio The log's priority
276 * @param[in] tag The log's tag
277 * @return DLOG_ERROR_NONE on success, else an error code.
278 * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
280 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
282 if (!debugmode && prio <= DLOG_DEBUG)
283 return DLOG_ERROR_NOT_PERMITTED;
286 __dynamic_config_update();
290 if (!pthread_rwlock_rdlock(&log_limiter_lock)) {
291 should_log = __log_limiter_pass_log(tag, prio);
292 pthread_rwlock_unlock(&log_limiter_lock);
296 return DLOG_ERROR_NOT_PERMITTED;
297 } else if (should_log < 0) {
299 int result = clock_gettime(CLOCK_MONOTONIC, &tp);
301 return DLOG_ERROR_NOT_PERMITTED;
302 write_to_log(log_id, prio, tag,
303 "Your log has been blocked due to limit of log lines per minute.", &tp);
304 return DLOG_ERROR_NOT_PERMITTED;
308 /* This can change due to __dynamic_config_update(), but is atomic and its
309 * value implies nothing else so does not need to be under a lock. */
311 return DLOG_ERROR_NOT_PERMITTED;
313 return DLOG_ERROR_NONE;
316 static int __write_to_log_critical_section(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap, bool check_should_log)
318 if (check_should_log && prio < priority_filter_level)
319 return DLOG_ERROR_NONE;
321 if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
322 return DLOG_ERROR_NONE;
324 char buf[LOG_MAX_PAYLOAD_SIZE];
325 size_t len = vsnprintf(buf, sizeof buf, fmt, ap);
327 return DLOG_ERROR_NONE;
328 else if (len >= sizeof buf)
329 len = sizeof buf - 1;
332 int result = clock_gettime(CLOCK_MONOTONIC, &tp);
334 return DLOG_ERROR_NONE;
336 if (deduplicate(buf, len, &tp))
338 return write_to_log(log_id, prio, tag, buf, &tp);
341 static int __write_to_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap, bool check_should_log, bool secure_log)
343 int ret = dlog_check_validity(log_id, prio, tag);
347 /* Threads can be cancelled before they give up a lock.
348 * Therefore cancellation is temporarily disabled.
349 * This solution is comparatively simple and cheap.
350 * The other solutions (cleanup handlers, robust mutexes)
351 * would be much more complicated and also inflict larger
352 * runtime costs. The downside of disabling cancellation
353 * is not a problem in our case because it is temporary
354 * and very brief so we don't keep an obsolete thread
355 * for much longer than we otherwise would. */
356 int old_cancel_state;
357 pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
359 /* The only thing that needs to be protected here is `write_to_log` since
360 * all other resources already have their own specific locks (and even the
361 * pointer could be made to point at a null handler instead of a true NULL)
362 * but giving this guarantee makes everything a lot simpler as it removes
363 * the risk of something suddenly becoming NULL during processing. */
364 if (!initialize() || !write_to_log)
365 ret = DLOG_ERROR_NOT_PERMITTED;
366 else if (secure_log && !enable_secure_logs)
369 ret = __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log);
371 pthread_setcancelstate(old_cancel_state, NULL);
376 int __critical_log_append_timestamp(char *buf, size_t buflen)
378 /* NB: the timestamp may slightly differ from the one that gets
379 * added onto the copy that goes into the regular buffer, and
380 * timestamp acquisition is duplicated. This would ideally be
381 * solved, but timestamps are currently added fairly deep in
382 * backend-specific functions so for now this will have to do.
383 * Also, since we're the sender, there is just this one set of
384 * timestamps, i.e. the send timestamp! The usual alternative
385 * set of receive timestamps will never have the opportunity
386 * to get added to the entry since this log is supposed to end
387 * up straight in the file (there's potentially the trusted
388 * writer binary but we're trying to keep the set of actions
389 * it needs to do to the minimum and those timestamps would
390 * in practice be the same anyway). */
393 clock_gettime(CLOCK_REALTIME, &ts);
394 const time_t tt = ts.tv_sec;
395 const long int real_millisec = ts.tv_nsec / 1000000;
396 clock_gettime(CLOCK_MONOTONIC, &ts);
398 struct tm *const ptm = localtime_r(&tt, &tmBuf);
399 assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
401 int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
404 int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
406 assert(tmp_len < buflen - len);
409 tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
410 assert(tmp_len != 0);
413 tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
415 assert(tmp_len < buflen - len);
421 int __critical_log_build_msg(char *buf, size_t buflen, pid_t main_pid, pid_t main_tid, log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
423 int len = __critical_log_append_timestamp(buf, buflen);
424 const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
427 log_name_by_id(log_id),
428 filter_pri_to_char(prio),
429 tag ?: "CRITICAL_NO_TAG");
430 assert(metadata_len > 0);
431 if (metadata_len >= buflen - len)
432 return buflen - 1; // can genuinely happen with an exceedingly large tag
435 const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
436 assert(content_len >= 0); // 0 is legit with format == ""
437 if (content_len >= buflen - len)
445 __attribute__ ((noreturn))
447 void __critical_log_child(pid_t main_pid, pid_t main_tid, log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
449 char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
450 const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
454 static const char *const path = "/usr/libexec/dlog-log-critical";
455 execl(path, path /* argv[0] convention */, buf, (char *) NULL);
458 /* Compilers are sometimes smart enough to recognize _exit's
459 * noreturn attribute, even if we wrap it with something that
460 * returns. This causes it to behave in unexpected ways, for
461 * example it can blow up the program regardless or it can
462 * optimize some conditionals out (and incorrectly enter them
463 * after the exit call fails to actually exit). This makes it
464 * unsuitable for tests. */
466 _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
470 #ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
471 void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
473 /* Critical log functionality is mostly done in a separate binary
474 * to handle security correctly (else every process would have to
475 * possess the necessary privilege to write onto that file, which
476 * would be opening a fairly nasty can of worms from the security
477 * point of view). Our use of exec() is why a simple thread would
478 * not suffice and we're resorting to a fork.
480 * The double fork, much like a double barreled 12 gauge shotgun,
481 * is an elegant solution designed to stop a zombie army. We'd be
482 * creating zombie processes if we didn't wait() for the children
483 * we spawn, but we don't really want to do that since it results
484 * in a needless delay. Instead, the writer process is actually a
485 * grandchild, with our direct child exiting immediately just for
486 * us to have something to wait on that is guaranteed not to take
487 * too long. The orphaned grandchild is adopted by init, who will
488 * take care to reap it when it dies. In addition to avoiding the
489 * delay, the client will not have any unexpected children (which
490 * could ruin logic in its own waits).
493 * ┌───────┐ ┌─────────┐ ┌─────────────┐ ┌────────┐
494 * │ pid 1 ├──>│ libdlog ├──>│ immediately ├──>│ execs │
495 * │ init │ │ client │ │ exits │ │ writer │
496 * └───────┘ └─────────┘ └─────────────┘ └────────┘
498 * Afterwards, libdlog has no children:
499 * ┌───────┐ ┌─────────┐ ┌────────┐
500 * │ pid 1 ├──>│ libdlog │ ┌─────────>│ writer │
501 * │ init ├─┐ │ client │ │ │ binary │
502 * └───────┘ │ └─────────┘ │ └────────┘
503 * └──────────────────────┘
506 const pid_t main_pid = getpid();
507 const pid_t main_tid = gettid();
509 const int temporary_exiter_pid = fork();
510 if (temporary_exiter_pid < 0)
512 if (temporary_exiter_pid != 0) {
513 waitpid(temporary_exiter_pid, NULL, 0);
517 const int child_pid = fork();
523 __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
526 int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
531 __critical_log(log_id, prio, tag, fmt, ap);
535 int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
542 int dlog_set_minimum_priority(int priority)
544 if (priority < DLOG_DEFAULT || priority > DLOG_PRIO_MAX)
545 return DLOG_ERROR_INVALID_PARAMETER;
547 priority_filter_level = priority;
548 return DLOG_ERROR_NONE;
553 * @details Print a log line
554 * @param[in] log_id The target buffer ID
555 * @param[in] prio Priority
557 * @param[in] fmt Format (same as printf)
558 * @param[in] ap Argument list
559 * @return Bytes written, or negative error
561 int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
563 int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, false);
564 __dlog_fatal_assert(prio);
571 * @details Print a log line
572 * @param[in] log_id The target buffer ID
573 * @param[in] prio Priority
575 * @param[in] fmt Format (same as printf)
576 * @return Bytes written, or negative error
578 int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
583 int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
591 * @details Print a log line
592 * @param[in] log_id The target buffer ID
593 * @param[in] prio Priority
595 * @param[in] fmt Format (same as printf)
596 * @return Bytes written, or negative error
598 int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
600 if (!enable_secure_logs)
606 int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, true);
607 __dlog_fatal_assert(prio);
613 int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
615 return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false, false);
618 int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
623 int ret = dlog_vprint(prio, tag, fmt, ap);
630 * @brief Finalize DLog
631 * @details Finalizes and deallocates the library
632 * @notes Used directly in tests; brings back the pre-init state
634 void __dlog_fini(void)
636 if (destroy_backend) {
638 destroy_backend = NULL;
641 is_initialized = false;
644 __deduplicate_destroy();
645 __log_limiter_destroy();
646 __dynamic_config_destroy();