1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: t -*-
3 * Copyright (c) 2005-2008, The Android Open Source Project
4 * Copyright (c) 2012-2013 Samsung Electronics Co., Ltd.
6 * Licensed under the Apache License, Version 2.0 (the License);
7 * you may not use this file except in compliance with the License.
8 * You may obtain a copy of the License at
10 * http://www.apache.org/licenses/LICENSE-2.0
12 * Unless required by applicable law or agreed to in writing, software
13 * distributed under the License is distributed on an "AS IS" BASIS,
14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15 * See the License for the specific language governing permissions and
16 * limitations under the License.
30 #include <dynamic_config.h>
32 #include <logcommon.h>
33 #include "logconfig.h"
34 #include "loglimiter.h"
36 #define DEFAULT_CONFIG_LIMITER false
37 #define DEFAULT_CONFIG_PLOG true
38 #define DEFAULT_CONFIG_DEBUGMODE 0
39 #define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
42 * @brief Points to a function which writes a log message
43 * @details The function pointed to depends on the backend used
44 * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
45 * @param[in] prio Priority of the message.
46 * @param[in] tag The message tag, identifies the sender.
47 * @param[in] msg The contents of the message.
48 * @return Returns the number of bytes written on success and a negative error value on error.
49 * @see __dlog_init_backend
51 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
52 void (*destroy_backend)();
54 pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
55 static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
56 static bool is_initialized = false;
58 extern void __dlog_init_pipe(const struct log_config *conf);
59 extern void __dlog_init_android(const struct log_config *conf);
63 bool plog[LOG_ID_MAX];
64 bool plog_default_values[LOG_ID_MAX];
67 static int fatal_assert;
68 static int limiter_apply_to_all_buffers;
70 static void __configure_limiter(struct log_config *config)
77 limiter = __log_limiter_create(config);
80 static int __configure_backend(struct log_config *config)
84 const char *const backend = log_config_get(config, "backend");
88 if (!strcmp(backend, "pipe"))
89 __dlog_init_pipe(config);
90 else if (!strcmp(backend, "logger"))
91 __dlog_init_android(config);
98 static void __set_plog_default_values()
100 for (int i = 0; i < NELEMS(plog); ++i)
101 plog_default_values[i] = plog[i];
104 static void __initialize_plog(const struct log_config *config)
108 const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
109 for (int i = 0; i < NELEMS(plog); ++i)
110 plog[i] = plog_default;
111 plog[LOG_ID_APPS] = true; // the default does not apply here for backward compatibility reasons.
112 __set_plog_default_values();
115 static void __configure_parameters(struct log_config *config)
119 __initialize_plog(config);
120 __update_plog(config);
121 __set_plog_default_values();
123 debugmode = log_config_get_int(config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
124 fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
125 limiter = log_config_get_boolean(config, "limiter", DEFAULT_CONFIG_LIMITER);
126 limiter_apply_to_all_buffers = log_config_get_int(config,
127 "limiter_apply_to_all_buffers",
128 DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
131 void __update_plog(const struct log_config *conf)
135 for (int i = 0; i < NELEMS(plog); ++i) {
136 char key[MAX_CONF_KEY_LEN];
137 const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
140 plog[i] = log_config_get_boolean(conf, key, plog_default_values[i]);
145 * @brief Configure the library
146 * @details Reads relevant config values
147 * @remarks This is more or less a constructor, but there are some obstacles
148 * to using it as such (i.e. with attribute constructor):
150 * - some important pieces of the system link to dlog, they start very early
151 * such that dlog can't properly initialize (which lasts for program lifetime)
152 * but don't actually log anything until later on and would be fine under lazy
153 * initialisation. The way to do it "properly" would be to expose this function
154 * into the API so that people can manually call it when they're ready, but
155 * one of the design goals of the current API is that it requires absolutely no
156 * other calls than `dlog_print`. Changing it would require somebody with a
157 * bird's eye view of the system to produce a design so I wouldn't count on it.
159 * - the constructor would need to have as high of a priority as possible (so as
160 * to minimize the risk of another library's constructor using uninitialized data)
161 * but at the same time others might want some room to wrap functions before
162 * dlog uses them (think mprobe/mcheck). This would also require a design pass.
167 bool __configure(void)
169 __attribute__((cleanup(log_config_free))) struct log_config config;
171 if (log_config_read(&config) < 0)
174 dynamic_config = __dynamic_config_create(&config);
176 __configure_parameters(&config);
178 if (!__configure_backend(&config)) {
179 __dynamic_config_destroy();
180 dynamic_config = false;
184 __configure_limiter(&config);
188 static bool first = true;
189 static bool initialize()
194 /* The mutex acts as a barrier, but otherwise the C language's
195 * machine abstraction is single-threaded. This means that the
196 * compiler is free to rearrange calls inside the mutex according
197 * to the as-if rule because it doesn't care if another thread can
198 * access it in parallel. In particular, `is_initialized = true`
199 * directly after `__configure()` could be rearranged to go in
200 * front of it because it is not touched inside that function
201 * if the compiler thinks it helps somehow (not unlikely: since
202 * it is checked before the mutex, it is very probable for it to
203 * still be in the CPU register or something like that). On top
204 * of that, some architectures (in particular, armv7l) don't have
205 * strict memory guarantees and can reorder actual memory stores
206 * on their own, even if the compiler didn't do anything fancy
207 * when creating machine code. For more info about the issue,
208 * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
210 * Ultimately this means that there needs to be some sort of
211 * barrier between `__configure` and `is_initialized = true`,
212 * and the simplest way to achieve that is to just wait until
213 * the second entry into the mutex. */
216 pthread_mutex_lock(&log_construction_lock);
218 first = !__configure();
220 is_initialized = true;
222 pthread_mutex_unlock(&log_construction_lock);
227 * @brief Fatal assertion
228 * @details Conditionally crash the sucka who sent the log
229 * @param[in] prio Priority of the log
231 static void __dlog_fatal_assert(int prio)
233 assert(!fatal_assert || (prio != DLOG_FATAL));
237 * @brief Check log validity
238 * @details Checks whether the log is valid and eligible for printing
239 * @param[in] log_id The target buffer ID
240 * @param[in] prio The log's priority
241 * @param[in] tag The log's tag
242 * @return DLOG_ERROR_NONE on success, else an error code.
243 * @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
245 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
248 return DLOG_ERROR_INVALID_PARAMETER;
250 if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
251 return DLOG_ERROR_INVALID_PARAMETER;
253 return DLOG_ERROR_NONE;
257 * @brief Check log against limiter rules
258 * @details Checks whether the log passes current limiter rules
259 * @param[in] log_id The target buffer ID
260 * @param[in] prio The log's priority
261 * @param[in] tag The log's tag
262 * @return DLOG_ERROR_NONE on success, else an error code.
263 * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
265 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
267 if (!debugmode && prio <= DLOG_DEBUG)
268 return DLOG_ERROR_NOT_PERMITTED;
271 __dynamic_config_update();
275 if (!pthread_rwlock_rdlock(&log_limiter_lock)) {
276 should_log = __log_limiter_pass_log(tag, prio);
277 pthread_rwlock_unlock(&log_limiter_lock);
281 return DLOG_ERROR_NOT_PERMITTED;
282 } else if (should_log < 0) {
283 write_to_log(log_id, prio, tag,
284 "Your log has been blocked due to limit of log lines per minute.");
285 return DLOG_ERROR_NOT_PERMITTED;
289 /* This can change due to __dynamic_config_update(), but is atomic and its
290 * value implies nothing else so does not need to be under a lock. */
292 return DLOG_ERROR_NOT_PERMITTED;
294 return DLOG_ERROR_NONE;
297 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)
299 if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
300 return DLOG_ERROR_NONE;
302 char buf[LOG_MAX_PAYLOAD_SIZE];
303 vsnprintf(buf, sizeof buf, fmt, ap);
304 return write_to_log(log_id, prio, tag, buf);
307 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)
309 int ret = dlog_check_validity(log_id, prio, tag);
313 /* Threads can be cancelled before they give up a lock.
314 * Therefore cancellation is temporarily disabled.
315 * This solution is comparatively simple and cheap.
316 * The other solutions (cleanup handlers, robust mutexes)
317 * would be much more complicated and also inflict larger
318 * runtime costs. The downside of disabling cancellation
319 * is not a problem in our case because it is temporary
320 * and very brief so we don't keep an obsolete thread
321 * for much longer than we otherwise would. */
322 int old_cancel_state;
323 pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
325 /* The only thing that needs to be protected here is `write_to_log` since
326 * all other resources already have their own specific locks (and even the
327 * pointer could be made to point at a null handler instead of a true NULL)
328 * but giving this guarantee makes everything a lot simpler as it removes
329 * the risk of something suddenly becoming NULL during processing. */
330 ret = !initialize() || !write_to_log
331 ? DLOG_ERROR_NOT_PERMITTED
332 : __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log)
335 pthread_setcancelstate(old_cancel_state, NULL);
340 int __critical_log_append_timestamp(char *buf, size_t buflen)
342 /* NB: the timestamp may slightly differ from the one that gets
343 * added onto the copy that goes into the regular buffer, and
344 * timestamp acquisition is duplicated. This would ideally be
345 * solved, but timestamps are currently added fairly deep in
346 * backend-specific functions so for now this will have to do.
347 * Also, since we're the sender, there is just this one set of
348 * timestamps, i.e. the send timestamp! The usual alternative
349 * set of receive timestamps will never have the opportunity
350 * to get added to the entry since this log is supposed to end
351 * up straight in the file (there's potentially the trusted
352 * writer binary but we're trying to keep the set of actions
353 * it needs to do to the minimum and those timestamps would
354 * in practice be the same anyway). */
357 clock_gettime(CLOCK_REALTIME, &ts);
358 const time_t tt = ts.tv_sec;
359 const long int real_millisec = ts.tv_nsec / 1000000;
360 clock_gettime(CLOCK_MONOTONIC, &ts);
361 #ifdef HAVE_LOCALTIME_R
363 struct tm *const ptm = localtime_r(&tt, &tmBuf);
365 struct tm *const ptm = localtime(&tt);
367 assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
369 int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
372 int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
374 assert(tmp_len < buflen - len);
377 tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
378 assert(tmp_len != 0);
381 tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
383 assert(tmp_len < buflen - len);
389 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)
391 int len = __critical_log_append_timestamp(buf, buflen);
392 const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
395 log_name_by_id(log_id),
396 filter_pri_to_char(prio),
397 tag ?: "CRITICAL_NO_TAG");
398 assert(metadata_len > 0);
399 if (metadata_len >= buflen - len)
400 return buflen - 1; // can genuinely happen with an exceedingly large tag
403 const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
404 assert(content_len >= 0); // 0 is legit with format == ""
405 if (content_len >= buflen - len)
413 __attribute__ ((noreturn))
415 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)
417 char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
418 const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
422 static const char *const path = "/usr/libexec/dlog-log-critical";
423 execl(path, path /* argv[0] convention */, buf, (char *) NULL);
426 /* Compilers are sometimes smart enough to recognize _exit's
427 * noreturn attribute, even if we wrap it with something that
428 * returns. This causes it to behave in unexpected ways, for
429 * example it can blow up the program regardless or it can
430 * optimize some conditionals out (and incorrectly enter them
431 * after the exit call fails to actually exit). This makes it
432 * unsuitable for tests. */
434 _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
438 #ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
439 void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
441 /* Critical log functionality is mostly done in a separate binary
442 * to handle security correctly (else every process would have to
443 * possess the necessary privilege to write onto that file, which
444 * would be opening a fairly nasty can of worms from the security
445 * point of view). Our use of exec() is why a simple thread would
446 * not suffice and we're resorting to a fork. */
448 const pid_t main_pid = getpid();
449 const pid_t main_tid = gettid();
450 const int child_pid = fork();
456 __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
459 int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
464 __critical_log(log_id, prio, tag, fmt, ap);
468 int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
477 * @details Print a log line
478 * @param[in] log_id The target buffer ID
479 * @param[in] prio Priority
481 * @param[in] fmt Format (same as printf)
482 * @param[in] ap Argument list
483 * @return Bytes written, or negative error
485 int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
487 int ret = __write_to_log(log_id, prio, tag, fmt, ap, true);
488 __dlog_fatal_assert(prio);
495 * @details Print a log line
496 * @param[in] log_id The target buffer ID
497 * @param[in] prio Priority
499 * @param[in] fmt Format (same as printf)
500 * @return Bytes written, or negative error
502 int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
507 int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
515 * @details Print a log line
516 * @param[in] log_id The target buffer ID
517 * @param[in] prio Priority
519 * @param[in] fmt Format (same as printf)
520 * @return Bytes written, or negative error
522 int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
527 int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
533 int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
535 return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false);
538 int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
543 int ret = dlog_vprint(prio, tag, fmt, ap);
550 * @brief Finalize DLog
551 * @details Finalizes and deallocates the library
552 * @notes Used directly in tests; brings back the pre-init state
554 void __dlog_fini(void)
556 if (destroy_backend) {
558 destroy_backend = NULL;
561 is_initialized = false;
564 __log_limiter_destroy();
565 __dynamic_config_destroy();