#include <sys/wait.h>
#include <unistd.h>
+// Tizen
+#include <tizen.h>
+
// DLog
+#include <buffer_traits.h>
#include "deduplicate.h"
#include <dynamic_config.h>
+#include "extra_sinks.h"
#include <libdlog.h>
-#include <logcommon.h>
#include "logconfig.h"
#include "loglimiter.h"
#define DEFAULT_CONFIG_DEBUGMODE 0
#define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
+
+/* A pseudo-backend that does nothing. Useful for removing the overhead of dlog
+ * for debugging and measurement purposes, also it simplifies some checking as
+ * the `write_to_log` pointer below never needs to be NULL. Note that features
+ * independent of the backend (such as limiter or dynamic config) are controlled
+ * separately if dlog is to be disabled completely and that minimal overhead is
+ * always present (e.g. building the message via vprintf). */
+static int write_to_log_null (log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono, int32_t pid, int32_t tid)
+{
+ return DLOG_ERROR_NONE;
+}
+
/**
* @brief Points to a function which writes a log message
* @details The function pointed to depends on the backend used
* @return Returns the number of bytes written on success and a negative error value on error.
* @see __dlog_init_backend
*/
-int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono) = NULL;
-void (*destroy_backend)();
+int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono, int32_t pid, int32_t tid) = write_to_log_null;
+void (*destroy_backend)(void);
+
+int (*stash_failed_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
+#ifndef UNIT_TEST
+static int stash_critical(log_id_t log_id, log_priority prio, const char *tag, const char *msg);
+#endif
pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
extern void __dlog_init_pipe(const struct log_config *conf);
extern void __dlog_init_android(const struct log_config *conf);
+extern void __dlog_init_zero_copy();
+
+extern void prepend_container_tag_if_in_container(size_t buf_size, char buf[static buf_size], int *len);
bool limiter;
+struct limiter_data *limiter_data;
static bool dynamic_config;
-static bool plog[LOG_ID_MAX];
-static bool plog_default_values[LOG_ID_MAX];
+static bool plog[SINKS_MAX];
+static bool plog_default_values[SINKS_MAX];
static bool enable_secure_logs = true;
+static bool enable_critical = true;
+
+static bool should_disable_cancels;
static int debugmode;
static int fatal_assert;
static int limiter_apply_to_all_buffers;
static _Atomic log_priority priority_filter_level = DLOG_VERBOSE;
-static void __configure_limiter(struct log_config *config)
+/* Cache pid and tid to avoid up to two syscalls per log.
+ * PID is reset at fork() via pthread_atfork().
+ * TID is reset by being a thread local var. */
+static int32_t cached_pid = 0;
+_Thread_local int32_t cached_tid = 0;
+
+static inline int32_t get_cached_pid()
{
- assert(config);
+ return cached_pid;
+}
+
+static inline int32_t get_cached_tid()
+{
+ return (cached_tid = cached_tid ?: gettid());
+}
+
+static void update_cached_pid()
+{
+ cached_pid = getpid();
+ // tid is reset passively (to 0) by virtue of being thread-local
+}
+
+/* Here, static_config is the original config from /etc/dlog.conf{,.d} which can be overriden,
+ * but comes back if the override is removed. both_config additionally contains dynamic rules
+ * (by default from /run/dlog/filters.d) which can be changed in the runtime.
+ * The static_config has to be kept separately, so that we can go back to it when dynamic rules change.
+ * Note that most functions only use static_config, since the parameters can't be changed in runtime. */
+static void __configure_limiter(struct log_config *static_config, struct log_config *both_config)
+{
+ assert(static_config);
+ if (dynamic_config)
+ assert(both_config);
if (!limiter)
return;
- limiter = __log_limiter_create(config);
+ limiter_data = __log_limiter_create(static_config);
+ if (limiter_data && dynamic_config)
+ __log_limiter_update(limiter_data, both_config);
+ limiter = (bool)limiter_data;
+
+ should_disable_cancels |= limiter; // due to locks
}
static int __configure_backend(struct log_config *config)
{
assert(config);
- const char *const backend = log_config_get(config, "backend");
+ const char *const backend = log_config_claim_backend(config);
if (!backend)
return 0;
- if (!strcmp(backend, "pipe"))
+ if (!strcmp(backend, "pipe")) {
__dlog_init_pipe(config);
- else if (!strcmp(backend, "logger"))
+ should_disable_cancels = true;
+ } else if (!strcmp(backend, "logger"))
__dlog_init_android(config);
+ else if (!strcmp(backend, "zero-copy"))
+ __dlog_init_zero_copy(config);
+ else if (!strcmp(backend, "null"))
+ ; // already the default
else
return 0;
return 1;
}
-static void __set_plog_default_values()
+static void __set_plog_default_values(void)
{
for (size_t i = 0; i < NELEMS(plog); ++i)
plog_default_values[i] = plog[i];
{
assert(config);
+ /* plog stands for "platform logging", which is why
+ * non-platform (i.e. application) buffers ignore it */
const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
for (size_t i = 0; i < NELEMS(plog); ++i)
- plog[i] = plog_default;
- plog[LOG_ID_APPS] = true; // the default does not apply here for backward compatibility reasons.
+ plog[i] = is_platform_buffer(i) ? plog_default : true;
+
__set_plog_default_values();
}
-static void __configure_parameters(struct log_config *config)
+static void __configure_parameters(struct log_config *static_config, struct log_config *both_config)
{
- assert(config);
+ assert(static_config);
+ assert(both_config);
- __initialize_plog(config);
- __update_plog(config);
+ __initialize_plog(static_config);
+ __update_plog(static_config);
+ /* Like in __configure_limiter, we also check the dynamic rules. However, we make sure to
+ * set the default values to the ones generated by the static rules first. */
__set_plog_default_values();
+ __update_plog(both_config);
- enable_secure_logs = log_config_get_boolean(config, "enable_secure_logs", enable_secure_logs);
- debugmode = log_config_get_int(config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
+ enable_secure_logs = log_config_get_boolean(both_config, "enable_secure_logs", enable_secure_logs);
+ enable_critical = log_config_get_boolean(both_config, "enable_critical", enable_critical);
+ debugmode = log_config_get_int(both_config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
- limiter = log_config_get_boolean(config, "limiter", DEFAULT_CONFIG_LIMITER);
- limiter_apply_to_all_buffers = log_config_get_int(config,
+ limiter = log_config_get_boolean(both_config, "limiter", DEFAULT_CONFIG_LIMITER);
+ limiter_apply_to_all_buffers = log_config_get_int(both_config,
"limiter_apply_to_all_buffers",
DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
+
+ stash_failed_log = NULL;
+ const char *stash_failed_log_method = log_config_get(both_config, "stash_failed_log_method");
+ if (stash_failed_log_method) {
+#ifndef UNIT_TEST
+ if (strcmp(stash_failed_log_method, "critical") == 0)
+ stash_failed_log = stash_critical;
+#endif
+ }
}
void __update_plog(const struct log_config *conf)
#endif
bool __configure(void)
{
- __attribute__((cleanup(log_config_free))) struct log_config config;
+ __attribute__((cleanup(log_config_free))) struct log_config static_config = {};
+ __attribute__((cleanup(log_config_free))) struct log_config both_config = {};
+
+ cached_pid = getpid();
- if (log_config_read(&config) < 0)
+ if (log_config_read(&static_config) < 0)
return false;
+ log_config_copy(&both_config, &static_config);
- dynamic_config = __dynamic_config_create(&config);
+ dynamic_config = __dynamic_config_create(&both_config);
- __configure_parameters(&config);
+ __configure_parameters(&static_config, &both_config);
- if (!__configure_backend(&config)) {
+ if (!__configure_backend(&both_config)) {
__dynamic_config_destroy();
dynamic_config = false;
return false;
}
- __configure_deduplicate(&config);
- __configure_limiter(&config);
+ __configure_deduplicate(&both_config);
+ __configure_limiter(&static_config, &both_config);
+
+ pthread_atfork(NULL, NULL, update_cached_pid);
+
return true;
}
signal(SIGPIPE, SIG_IGN);
}
+static void __attribute__((constructor(102))) __set_output_buffering(void)
+{
+ /* If stdout and/or stderr is redirected to dlog (service, driver)
+ * it is best if we buffer lines, otherwise the following can happen:
+ * - no buffering: service/driver recives every single byte (precisely
+ * every single write*(2) call), causing it to either buffer the data
+ * anyway (service), or print logs at random places (driver)
+ * - full buffering: service/driver receives several hundred lines,
+ * which results in one giant entry being added (driver) or long delays
+ * before logs appear (service) */
+ if (getenv(DLOG_ENV_STDOUT_LINE_BUFFERED))
+ setlinebuf(stdout);
+
+ if (getenv(DLOG_ENV_STDERR_LINE_BUFFERED))
+ setlinebuf(stderr);
+}
+
static bool first = true;
-static bool initialize()
+static bool initialize(void)
{
if (is_initialized)
return true;
* @param[in] log_id The target buffer ID
* @param[in] prio The log's priority
* @param[in] tag The log's tag
+ * @param[in] only_core Whether non-core buffers are rejected
* @return DLOG_ERROR_NONE on success, else an error code.
* @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
*/
-static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
+static int dlog_check_validity(log_id_t log_id, int prio, const char *tag, bool only_core)
{
(void) prio;
if (!tag)
return DLOG_ERROR_INVALID_PARAMETER;
- if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
+ if (!is_buffer_valid(log_id))
+ return DLOG_ERROR_INVALID_PARAMETER;
+
+ /* The interface here is a bit confused. `__dlog_print` is nominally
+ * for platform logging and is not necessarily supposed to use the
+ * APPS buffer (which is a core buffer, but not a platform buffer),
+ * yet the internal interface (dlog-internal.h) exposes macros for
+ * platform programs to log into APPS. The design is probably too
+ * ossified to change at this point though. */
+ if (only_core && !is_core_buffer(log_id))
return DLOG_ERROR_INVALID_PARAMETER;
return DLOG_ERROR_NONE;
return DLOG_ERROR_NOT_PERMITTED;
if (dynamic_config)
- __dynamic_config_update();
+ __dynamic_config_update(limiter_data);
if (limiter) {
- int should_log = 0;
- if (!pthread_rwlock_rdlock(&log_limiter_lock)) {
- should_log = __log_limiter_pass_log(tag, prio);
- pthread_rwlock_unlock(&log_limiter_lock);
+ struct pass_log_result should_log = { .decision = DECISION_DENIED };
+
+ /* Since the only `wrlock` is done by the dynamic config, we can avoid
+ * the `rdlock` entirely if the config is static. This sounds unsafe
+ * but lets us save an entire syscall, which is a lot (both comparatively
+ * and because it compounds). */
+ if (!dynamic_config || !pthread_rwlock_rdlock(&log_limiter_lock)) {
+ should_log = __log_limiter_pass_log_pid(limiter_data, tag, prio, get_cached_pid());
+ if (dynamic_config)
+ pthread_rwlock_unlock(&log_limiter_lock);
}
- if (!should_log) {
- return DLOG_ERROR_NOT_PERMITTED;
- } else if (should_log < 0) {
- struct timespec tp;
- int result = clock_gettime(CLOCK_MONOTONIC, &tp);
- if (result < 0)
+ switch (should_log.decision) {
+ case DECISION_DENIED:
+ return DLOG_ERROR_NOT_PERMITTED;
+
+ case DECISION_TAG_LIMIT_EXCEEDED_MESSAGE:
+ case DECISION_PID_LIMIT_EXCEEDED_MESSAGE: {
+ struct timespec tp;
+ int result = clock_gettime(CLOCK_MONOTONIC, &tp);
+ if (result < 0)
+ return DLOG_ERROR_NOT_PERMITTED;
+ char buf[100] = {};
+ snprintf(buf, sizeof(buf),
+ "Your log has been blocked due to per-%s limit of %d logs per %d seconds.",
+ should_log.decision == DECISION_TAG_LIMIT_EXCEEDED_MESSAGE ? "tag" : "PID",
+ should_log.logs_per_period, should_log.period_s);
+ write_to_log(log_id, prio, tag, buf, &tp, get_cached_pid(), get_cached_tid());
return DLOG_ERROR_NOT_PERMITTED;
- write_to_log(log_id, prio, tag,
- "Your log has been blocked due to limit of log lines per minute.", &tp);
- return DLOG_ERROR_NOT_PERMITTED;
+ }
+
+ case DECISION_ALLOWED:
+ break;
}
}
return DLOG_ERROR_NONE;
}
-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)
+static int __write_to_log_critical_section(log_id_t log_id, int prio, const char *tag, size_t buf_size, char buf[static buf_size], int buf_len, bool check_should_log)
{
- if (check_should_log && prio < priority_filter_level)
- return DLOG_ERROR_NONE;
-
if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
return DLOG_ERROR_NONE;
- char buf[LOG_MAX_PAYLOAD_SIZE];
- size_t len = vsnprintf(buf, sizeof buf, fmt, ap);
- if (len < 0)
- return DLOG_ERROR_NONE;
- else if (len >= sizeof buf)
- len = sizeof buf - 1;
+ log_id = get_log_id_from_sink(log_id);
- struct timespec tp;
- int result = clock_gettime(CLOCK_MONOTONIC, &tp);
- if (result < 0)
- return DLOG_ERROR_NONE;
- if (deduplicate(buf, len, &tp))
- return 0;
- return write_to_log(log_id, prio, tag, buf, &tp);
+ // Temporary workaround, see temporary.c
+ prepend_container_tag_if_in_container(buf_size, buf, &buf_len);
+
+ struct timespec tp;
+ int r;
+ if (deduplicate_func && !clock_gettime(CLOCK_MONOTONIC, &tp)) {
+ dlog_deduplicate_e ret = deduplicate_func(buf, buf_len, &tp);
+ if (ret == DLOG_DEDUPLICATE)
+ return DLOG_ERROR_NONE;
+ else if (ret == DLOG_DO_NOT_DEDUPLICATE_BUT_WARN)
+ deduplicate_warn(buf, buf_size, buf_len);
+ r = write_to_log(log_id, prio, tag, buf, &tp, get_cached_pid(), get_cached_tid());
+ } else
+ r = write_to_log(log_id, prio, tag, buf, NULL, get_cached_pid(), get_cached_tid());
+
+ if (r < 0 && stash_failed_log)
+ r = stash_failed_log(log_id, prio, tag, buf);
+
+ return r;
}
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)
{
- int ret = dlog_check_validity(log_id, prio, tag);
+ /* Write down the log first, before all other checks. This
+ * is because validity checks may involve syscalls, which
+ * could overwrite `errno` and ruin the `%m` specifier if
+ * the client specifies it in format. */
+ char buf[LOG_MAX_PAYLOAD_SIZE];
+ int len = vsnprintf(buf, sizeof buf, fmt, ap);
+ if (len < 0)
+ return DLOG_ERROR_NONE; // not really, but no better choice and not too realistic
+ else if (len >= sizeof buf)
+ len = sizeof buf - 1;
+
+
+ int ret = dlog_check_validity(log_id, prio, tag, check_should_log);
if (ret < 0)
return ret;
+ if (check_should_log && prio < priority_filter_level)
+ return DLOG_ERROR_NONE;
+
/* Threads can be cancelled before they give up a lock.
- * Therefore cancellation is temporarily disabled.
+ * Therefore cancellation is temporarily disabled as
+ * long as the current set of features uses a lock.
+ *
* This solution is comparatively simple and cheap.
* The other solutions (cleanup handlers, robust mutexes)
* would be much more complicated and also inflict larger
* and very brief so we don't keep an obsolete thread
* for much longer than we otherwise would. */
int old_cancel_state;
- pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
-
- /* The only thing that needs to be protected here is `write_to_log` since
- * all other resources already have their own specific locks (and even the
- * pointer could be made to point at a null handler instead of a true NULL)
- * but giving this guarantee makes everything a lot simpler as it removes
- * the risk of something suddenly becoming NULL during processing. */
- if (!initialize() || !write_to_log)
+ if (should_disable_cancels)
+ pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
+
+ if (!initialize())
+ // TODO: We could consider stashing the failed log here
ret = DLOG_ERROR_NOT_PERMITTED;
else if (secure_log && !enable_secure_logs)
ret = 0;
else
- ret = __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log);
+ ret = __write_to_log_critical_section(log_id, prio, tag, sizeof buf, buf, len, check_should_log);
- pthread_setcancelstate(old_cancel_state, NULL);
+ if (should_disable_cancels)
+ pthread_setcancelstate(old_cancel_state, NULL);
return ret;
}
* └──────────────────────┘
*/
+ initialize();
+
+ if (!enable_critical)
+ return;
+
const pid_t main_pid = getpid();
const pid_t main_tid = gettid();
__critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
}
-int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
+// LCOV_EXCL_START : stashing is essentially error handling.
+static void stash_critical_inner(log_id_t log_id, log_priority prio, const char *tag, const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ __critical_log(log_id, prio, tag, fmt, ap);
+ va_end(ap);
+}
+
+static int stash_critical(log_id_t log_id, log_priority prio, const char *tag, const char *msg)
+{
+ stash_critical_inner(log_id, prio, tag, "FAILED TO LOG: %s", msg);
+ return 0;
+}
+// LCOV_EXCL_STOP
+
+EXPORT_API int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
{
va_list ap;
}
#endif
-int dlog_set_minimum_priority(int priority)
+EXPORT_API int dlog_set_minimum_priority(int priority)
{
if (priority < DLOG_DEFAULT || priority > DLOG_PRIO_MAX)
return DLOG_ERROR_INVALID_PARAMETER;
* @param[in] ap Argument list
* @return Bytes written, or negative error
*/
-int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
+EXPORT_API int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
{
int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, false);
__dlog_fatal_assert(prio);
* @param[in] fmt Format (same as printf)
* @return Bytes written, or negative error
*/
-int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
+EXPORT_API int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
{
va_list ap;
* @param[in] fmt Format (same as printf)
* @return Bytes written, or negative error
*/
-int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
+EXPORT_API int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
{
if (!enable_secure_logs)
return 0;
return ret;
}
-int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
+EXPORT_API int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
{
return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false, false);
}
-int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
+EXPORT_API int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
{
va_list ap;
return ret;
}
+EXPORT_API int dlog_vprint_dotnet(log_priority prio, const char *tag, const char *fmt, va_list ap)
+{
+ return __write_to_log(SINK_DOTNET, prio, tag, fmt, ap, false, false);
+}
+
+EXPORT_API int dlog_print_dotnet(log_priority prio, const char *tag, const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ int ret = dlog_vprint_dotnet(prio, tag, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+
+EXPORT_API int dlog_vprint_native(log_priority prio, const char *tag, const char *fmt, va_list ap)
+{
+ return __write_to_log(SINK_NATIVE, prio, tag, fmt, ap, false, false);
+}
+
+EXPORT_API int dlog_print_native(log_priority prio, const char *tag, const char *fmt, ...)
+{
+ va_list ap;
+
+ va_start(ap, fmt);
+ int ret = dlog_vprint_native(prio, tag, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+
+// LCOV_EXCL_START : for internal use only, not accessible via public API
+
/**
* @brief Finalize DLog
* @details Finalizes and deallocates the library
destroy_backend();
destroy_backend = NULL;
}
- write_to_log = NULL;
+ write_to_log = write_to_log_null;
+ stash_failed_log = NULL;
is_initialized = false;
first = true;
+ enable_secure_logs = true;
+ enable_critical = false;
__deduplicate_destroy();
- __log_limiter_destroy();
+ __log_limiter_destroy(limiter_data);
+ limiter = false;
__dynamic_config_destroy();
+ should_disable_cancels = false;
}
+
+// LCOV_EXCL_STOP