-/*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: t -*-
- * DLOG
- * Copyright (c) 2005-2008, The Android Open Source Project
- * Copyright (c) 2012-2013 Samsung Electronics Co., Ltd.
+/* MIT License
*
- * Licensed under the Apache License, Version 2.0 (the License);
- * you may not use this file except in compliance with the License.
- * You may obtain a copy of the License at
+ * Copyright (c) 2012-2020 Samsung Electronics Co., Ltd
*
- * http://www.apache.org/licenses/LICENSE-2.0
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is furnished
+ * to do so, subject to the following conditions:
*
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the License for the specific language governing permissions and
- * limitations under the License.
- */
-
-#include <pthread.h>
-#include <stdlib.h>
+ * The above copyright notice and this permission notice shall be included in all
+ * copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+ * THE SOFTWARE. */
+
+// C
+#include <assert.h>
#include <stdbool.h>
#include <stdio.h>
+#include <stdlib.h>
+
+// POSIX
+#include <pthread.h>
+#include <sys/wait.h>
+#include <unistd.h>
+
+// Tizen
+#include <tizen.h>
+// DLog
+#include <buffer_traits.h>
+#include "deduplicate.h"
#include <dynamic_config.h>
-#include <logcommon.h>
-#include "loglimiter.h"
+#include "extra_sinks.h"
+#include <libdlog.h>
#include "logconfig.h"
-#include <assert.h>
-#include <unistd.h>
+#include "loglimiter.h"
#define DEFAULT_CONFIG_LIMITER false
#define DEFAULT_CONFIG_PLOG true
#define DEFAULT_CONFIG_DEBUGMODE 0
#define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
-static int __write_to_log_null(log_id_t, log_priority, const char *, const char *);
+
+/* 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
* @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) = __write_to_log_null;
-pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
+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;
+static bool is_initialized = false;
+
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;
-bool dynamic_config;
-bool plog[LOG_ID_MAX];
-bool plog_default_values[LOG_ID_MAX];
+struct limiter_data *limiter_data;
+static bool dynamic_config;
+static bool plog[SINKS_MAX];
+static bool plog_default_values[SINKS_MAX];
+static bool enable_secure_logs = true;
+static bool enable_critical = true;
-void __update_plog(const struct log_config *conf);
+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;
-/**
- * @brief Null handler
- * @details Ignores a log
- * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
- * @param[in] prio Priority of the message.
- * @param[in] tag The message tag, identifies the sender.
- * @param[in] msg The contents of the message.
- * @return DLOG_ERROR_NOT_PERMITTED
- */
-static int __write_to_log_null(log_id_t log_id, log_priority prio, const char *tag, const char *msg)// LCOV_EXCL_LINE
+/* 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()
{
- return DLOG_ERROR_NOT_PERMITTED; // LCOV_EXCL_LINE
+ return cached_pid;
}
-static void __configure_limiter(struct log_config *config)
+static inline int32_t get_cached_tid()
{
- assert(config);
+ 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 (int i = 0; i < NELEMS(plog); ++i)
+ 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 (int 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.
+ for (size_t i = 0; i < NELEMS(plog); ++i)
+ 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);
- 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)
{
assert(conf);
- for (int i = 0; i < NELEMS(plog); ++i) {
+ for (size_t i = 0; i < NELEMS(plog); ++i) {
char key[MAX_CONF_KEY_LEN];
const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
if (r < 0)
/**
* @brief Configure the library
* @details Reads relevant config values
+ * @remarks This is more or less a constructor, but there are some obstacles
+ * to using it as such (i.e. with attribute constructor):
+ *
+ * - some important pieces of the system link to dlog, they start very early
+ * such that dlog can't properly initialize (which lasts for program lifetime)
+ * but don't actually log anything until later on and would be fine under lazy
+ * initialisation. The way to do it "properly" would be to expose this function
+ * into the API so that people can manually call it when they're ready, but
+ * one of the design goals of the current API is that it requires absolutely no
+ * other calls than `dlog_print`. Changing it would require somebody with a
+ * bird's eye view of the system to produce a design so I wouldn't count on it.
+ *
+ * - the constructor would need to have as high of a priority as possible (so as
+ * to minimize the risk of another library's constructor using uninitialized data)
+ * but at the same time others might want some room to wrap functions before
+ * dlog uses them (think mprobe/mcheck). This would also require a design pass.
*/
-static void __configure(void)
+#ifndef UNIT_TEST
+static
+#endif
+bool __configure(void)
{
- struct log_config config;
+ __attribute__((cleanup(log_config_free))) struct log_config static_config = {};
+ __attribute__((cleanup(log_config_free))) struct log_config both_config = {};
- if (log_config_read(&config) < 0)
- goto failure;
+ cached_pid = getpid();
- dynamic_config = __dynamic_config_create(&config);
+ if (log_config_read(&static_config) < 0)
+ return false;
+ log_config_copy(&both_config, &static_config);
- __configure_parameters(&config);
+ dynamic_config = __dynamic_config_create(&both_config);
- if (!__configure_backend(&config))
- goto failure;
+ __configure_parameters(&static_config, &both_config);
- __configure_limiter(&config);
+ if (!__configure_backend(&both_config)) {
+ __dynamic_config_destroy();
+ dynamic_config = false;
+ return false;
+ }
+
+ __configure_deduplicate(&both_config);
+ __configure_limiter(&static_config, &both_config);
- log_config_free(&config);
- return;
+ pthread_atfork(NULL, NULL, update_cached_pid);
-failure:
- log_config_free(&config); // LCOV_EXCL_LINE
- return;
+ return true;
}
-/**
- * @brief DLog init
- * @details Initializes the library
- */
-static inline void __dlog_init(void)
+static void __attribute__((constructor(101))) __install_pipe_handler(void)
{
- static int is_initialized = 0;
-
- if (is_initialized)
- return;
-
- pthread_mutex_lock(&log_init_lock);
+ /* We mask SIGPIPE signal because most applications do not install their
+ * own SIGPIPE handler. Default behaviour in SIGPIPE case is to abort the
+ * process. SIGPIPE occurs when e.g. dlog daemon closes read pipe endpoint.
+ *
+ * We do this in the library constructor (at maximum priority) and not
+ * during regular (lazy) initialisation so as to prevent overwriting the
+ * program's actual signal handler, if it has one.
+ *
+ * In theory this is not required for the Android logger backend; however,
+ * this early we don't yet know the backend and also it is good to behave
+ * consistently in this regard anyway.
+ *
+ * We don't revert this in a destructor because Unix signals are bonkers
+ * and we have no way to do this cleanly. Most libdlog users don't use
+ * runtime linking so this would mostly done at program exit either way. */
+ signal(SIGPIPE, SIG_IGN);
+}
- if (!is_initialized) {
- __configure();
- is_initialized = 1;
- }
+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);
+}
- pthread_mutex_unlock(&log_init_lock);
+static bool first = true;
+static bool initialize(void)
+{
+ if (is_initialized)
+ return true;
+
+ /* The mutex acts as a barrier, but otherwise the C language's
+ * machine abstraction is single-threaded. This means that the
+ * compiler is free to rearrange calls inside the mutex according
+ * to the as-if rule because it doesn't care if another thread can
+ * access it in parallel. In particular, `is_initialized = true`
+ * directly after `__configure()` could be rearranged to go in
+ * front of it because it is not touched inside that function
+ * if the compiler thinks it helps somehow (not unlikely: since
+ * it is checked before the mutex, it is very probable for it to
+ * still be in the CPU register or something like that). On top
+ * of that, some architectures (in particular, armv7l) don't have
+ * strict memory guarantees and can reorder actual memory stores
+ * on their own, even if the compiler didn't do anything fancy
+ * when creating machine code. For more info about the issue,
+ * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
+ *
+ * Ultimately this means that there needs to be some sort of
+ * barrier between `__configure` and `is_initialized = true`,
+ * and the simplest way to achieve that is to just wait until
+ * the second entry into the mutex. */
+
+ bool ret;
+ pthread_mutex_lock(&log_construction_lock);
+ if (first)
+ first = !__configure();
+ else
+ is_initialized = true;
+ ret = !first;
+ pthread_mutex_unlock(&log_construction_lock);
+ return ret;
}
/**
* @param[in] log_id The target buffer ID
* @param[in] prio The log's priority
* @param[in] tag The log's tag
- * @return 0 on success, else an error code.
+ * @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
- * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
*/
-static int dlog_should_log(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)
{
- if (!debugmode && prio <= DLOG_DEBUG)
+ (void) prio;
+ if (!tag)
return DLOG_ERROR_INVALID_PARAMETER;
- if (!tag)
+ if (!is_buffer_valid(log_id))
return DLOG_ERROR_INVALID_PARAMETER;
- if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
+ /* 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;
+}
+
+/**
+ * @brief Check log against limiter rules
+ * @details Checks whether the log passes current limiter rules
+ * @param[in] log_id The target buffer ID
+ * @param[in] prio The log's priority
+ * @param[in] tag The log's tag
+ * @return DLOG_ERROR_NONE on success, else an error code.
+ * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
+ */
+static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
+{
+ if (!debugmode && prio <= DLOG_DEBUG)
+ return DLOG_ERROR_NOT_PERMITTED;
+
if (dynamic_config)
- __dynamic_config_update();
+ __dynamic_config_update(limiter_data);
- // LCOV_EXCL_START : disabled feature (limiter)
if (limiter) {
- pthread_mutex_lock(&log_init_lock);
- int should_log = __log_limiter_pass_log(tag, prio);
- pthread_mutex_unlock(&log_init_lock);
-
- if (!should_log) {
- return DLOG_ERROR_NOT_PERMITTED;
- } else if (should_log < 0) {
- write_to_log(log_id, prio, tag,
- "Your log has been blocked due to limit of log lines per minute.");
- return DLOG_ERROR_NOT_PERMITTED;
+ 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);
+ }
+
+ 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;
+ }
+
+ case DECISION_ALLOWED:
+ break;
}
}
- // LCOV_EXCL_STOP
+ /* This can change due to __dynamic_config_update(), but is atomic and its
+ * value implies nothing else so does not need to be under a lock. */
if (!plog[log_id])
return DLOG_ERROR_NOT_PERMITTED;
return DLOG_ERROR_NONE;
}
-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)
+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 || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
+ return DLOG_ERROR_NONE;
+
+ log_id = get_log_id_from_sink(log_id);
+
+
+ // 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)
{
+ /* 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;
- __dlog_init();
- /* if limiter_apply_to_all_buffers config variable is set to 1,
- * check_should_log value does not matter and the entry is always
- * tested against all conditions, i.e. limiter rules
- */
- int ret = (limiter_apply_to_all_buffers ? true : check_should_log) ? dlog_should_log(log_id, prio, tag) : 0;
+ int ret = dlog_check_validity(log_id, prio, tag, check_should_log);
if (ret < 0)
return ret;
- vsnprintf(buf, sizeof buf, fmt, ap);
+ 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 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
+ * runtime costs. The downside of disabling cancellation
+ * is not a problem in our case because it is temporary
+ * and very brief so we don't keep an obsolete thread
+ * for much longer than we otherwise would. */
+ int old_cancel_state;
+ 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, sizeof buf, buf, len, check_should_log);
+
+ if (should_disable_cancels)
+ pthread_setcancelstate(old_cancel_state, NULL);
+
+ return ret;
+}
+
+int __critical_log_append_timestamp(char *buf, size_t buflen)
+{
+ /* NB: the timestamp may slightly differ from the one that gets
+ * added onto the copy that goes into the regular buffer, and
+ * timestamp acquisition is duplicated. This would ideally be
+ * solved, but timestamps are currently added fairly deep in
+ * backend-specific functions so for now this will have to do.
+ * Also, since we're the sender, there is just this one set of
+ * timestamps, i.e. the send timestamp! The usual alternative
+ * set of receive timestamps will never have the opportunity
+ * to get added to the entry since this log is supposed to end
+ * up straight in the file (there's potentially the trusted
+ * writer binary but we're trying to keep the set of actions
+ * it needs to do to the minimum and those timestamps would
+ * in practice be the same anyway). */
+
+ struct timespec ts;
+ clock_gettime(CLOCK_REALTIME, &ts);
+ const time_t tt = ts.tv_sec;
+ const long int real_millisec = ts.tv_nsec / 1000000;
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ struct tm tmBuf;
+ struct tm *const ptm = localtime_r(&tt, &tmBuf);
+ assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
+
+ int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
+ assert(len != 0);
+
+ int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
+ assert(tmp_len > 0);
+ assert(tmp_len < buflen - len);
+ len += tmp_len;
+
+ tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
+ assert(tmp_len != 0);
+ len += tmp_len;
+
+ tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
+ assert(tmp_len > 0);
+ assert(tmp_len < buflen - len);
+ len += tmp_len;
+
+ return len;
+}
+
+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)
+{
+ int len = __critical_log_append_timestamp(buf, buflen);
+ const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
+ main_pid,
+ main_tid,
+ log_name_by_id(log_id),
+ filter_pri_to_char(prio),
+ tag ?: "CRITICAL_NO_TAG");
+ assert(metadata_len > 0);
+ if (metadata_len >= buflen - len)
+ return buflen - 1; // can genuinely happen with an exceedingly large tag
+ len += metadata_len;
+
+ const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
+ assert(content_len >= 0); // 0 is legit with format == ""
+ if (content_len >= buflen - len)
+ return buflen - 1;
+ len += content_len;
+
+ return len;
+}
+
+#ifndef UNIT_TEST
+__attribute__ ((noreturn))
+#endif
+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)
+{
+ char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
+ const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
+ buf[len] = '\n';
+ buf[len + 1] = '\0';
+
+ static const char *const path = "/usr/libexec/dlog-log-critical";
+ execl(path, path /* argv[0] convention */, buf, (char *) NULL);
+
+#ifndef UNIT_TEST
+ /* Compilers are sometimes smart enough to recognize _exit's
+ * noreturn attribute, even if we wrap it with something that
+ * returns. This causes it to behave in unexpected ways, for
+ * example it can blow up the program regardless or it can
+ * optimize some conditionals out (and incorrectly enter them
+ * after the exit call fails to actually exit). This makes it
+ * unsuitable for tests. */
+
+ _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
+#endif
+}
+
+#ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
+void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
+{
+ /* Critical log functionality is mostly done in a separate binary
+ * to handle security correctly (else every process would have to
+ * possess the necessary privilege to write onto that file, which
+ * would be opening a fairly nasty can of worms from the security
+ * point of view). Our use of exec() is why a simple thread would
+ * not suffice and we're resorting to a fork.
+ *
+ * The double fork, much like a double barreled 12 gauge shotgun,
+ * is an elegant solution designed to stop a zombie army. We'd be
+ * creating zombie processes if we didn't wait() for the children
+ * we spawn, but we don't really want to do that since it results
+ * in a needless delay. Instead, the writer process is actually a
+ * grandchild, with our direct child exiting immediately just for
+ * us to have something to wait on that is guaranteed not to take
+ * too long. The orphaned grandchild is adopted by init, who will
+ * take care to reap it when it dies. In addition to avoiding the
+ * delay, the client will not have any unexpected children (which
+ * could ruin logic in its own waits).
+ *
+ * Right after forks:
+ * ┌───────┐ ┌─────────┐ ┌─────────────┐ ┌────────┐
+ * │ pid 1 ├──>│ libdlog ├──>│ immediately ├──>│ execs │
+ * │ init │ │ client │ │ exits │ │ writer │
+ * └───────┘ └─────────┘ └─────────────┘ └────────┘
+ *
+ * Afterwards, libdlog has no children:
+ * ┌───────┐ ┌─────────┐ ┌────────┐
+ * │ pid 1 ├──>│ libdlog │ ┌─────────>│ writer │
+ * │ init ├─┐ │ client │ │ │ binary │
+ * └───────┘ │ └─────────┘ │ └────────┘
+ * └──────────────────────┘
+ */
+
+ initialize();
+
+ if (!enable_critical)
+ return;
+
+ const pid_t main_pid = getpid();
+ const pid_t main_tid = gettid();
+
+ const int temporary_exiter_pid = fork();
+ if (temporary_exiter_pid < 0)
+ return;
+ if (temporary_exiter_pid != 0) {
+ waitpid(temporary_exiter_pid, NULL, 0);
+ return;
+ }
+
+ const int child_pid = fork();
+ if (child_pid < 0)
+ _exit(1);
+ if (child_pid != 0)
+ _exit(0);
+
+ __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
+}
+
+// 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;
+
+ va_start(ap, fmt);
+ __critical_log(log_id, prio, tag, fmt, ap);
+ va_end(ap);
+
+ va_start(ap, fmt);
+ int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
+ va_end(ap);
+
+ return ret;
+}
+#endif
+
+EXPORT_API int dlog_set_minimum_priority(int priority)
+{
+ if (priority < DLOG_DEFAULT || priority > DLOG_PRIO_MAX)
+ return DLOG_ERROR_INVALID_PARAMETER;
- return write_to_log(log_id, prio, tag, buf);
+ priority_filter_level = priority;
+ return DLOG_ERROR_NONE;
}
/**
* @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);
+ int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, false);
__dlog_fatal_assert(prio);
return ret;
* @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;
return ret;
}
-int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
+/**
+ * @brief Print log
+ * @details Print a log line
+ * @param[in] log_id The target buffer ID
+ * @param[in] prio Priority
+ * @param[in] tag tag
+ * @param[in] fmt Format (same as printf)
+ * @return Bytes written, or negative error
+ */
+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;
+
+ va_list ap;
+
+ va_start(ap, fmt);
+ int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, true);
+ __dlog_fatal_assert(prio);
+ va_end(ap);
+
+ return ret;
+}
+
+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);
+ 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
- * @notes Assumes it has exclusive thread access,
- * i.e. no other library function can run in parallel
+ * @notes Used directly in tests; brings back the pre-init state
*/
-void __attribute__((destructor)) __dlog_fini(void)
+void __dlog_fini(void)
{
- __log_limiter_destroy();
+ if (destroy_backend) {
+ destroy_backend();
+ destroy_backend = 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(limiter_data);
+ limiter = false;
__dynamic_config_destroy();
+ should_disable_cancels = false;
}
+
+// LCOV_EXCL_STOP
projects / platform / core / system / dlog.git / blobdiff