src/libdlog/log.c

   1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: t -*-
   2  * DLOG
   3  * Copyright (c) 2005-2008, The Android Open Source Project
   4  * Copyright (c) 2012-2013 Samsung Electronics Co., Ltd.
   5  *
   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
   9  *
  10  *     http://www.apache.org/licenses/LICENSE-2.0
  11  *
  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.
  17  */
  18
  19 // C
  20 #include <assert.h>
  21 #include <stdbool.h>
  22 #include <stdio.h>
  23 #include <stdlib.h>
  24
  25 // POSIX
  26 #include <pthread.h>
  27 #include <unistd.h>
  28
  29 // DLog
  30 #include <dynamic_config.h>
  31 #include <libdlog.h>
  32 #include <logcommon.h>
  33 #include "logconfig.h"
  34 #include "loglimiter.h"
  35
  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
  40
  41 /**
  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
  50  */
  51 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
  52 void (*destroy_backend)();
  53
  54 pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
  55 static pthread_rwlock_t log_destruction_lock = PTHREAD_RWLOCK_INITIALIZER;
  56 static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
  57 static bool is_initialized = false;
  58
  59 extern void __dlog_init_pipe(const struct log_config *conf);
  60 extern void __dlog_init_android(const struct log_config *conf);
  61
  62 bool limiter;
  63 bool dynamic_config;
  64 bool plog[LOG_ID_MAX];
  65 bool plog_default_values[LOG_ID_MAX];
  66
  67 static int debugmode;
  68 static int fatal_assert;
  69 static int limiter_apply_to_all_buffers;
  70
  71 static void __configure_limiter(struct log_config *config)
  72 {
  73         assert(config);
  74
  75         if (!limiter)
  76                 return;
  77
  78         limiter = __log_limiter_create(config);
  79 }
  80
  81 static int __configure_backend(struct log_config *config)
  82 {
  83         assert(config);
  84
  85         const char *const backend = log_config_get(config, "backend");
  86         if (!backend)
  87                 return 0;
  88
  89         if (!strcmp(backend, "pipe"))
  90                 __dlog_init_pipe(config);
  91         else if (!strcmp(backend, "logger"))
  92                 __dlog_init_android(config);
  93         else
  94                 return 0;
  95
  96         return 1;
  97 }
  98
  99 static void __set_plog_default_values()
 100 {
 101         for (int i = 0; i < NELEMS(plog); ++i)
 102                 plog_default_values[i] = plog[i];
 103 }
 104
 105 static void __initialize_plog(const struct log_config *config)
 106 {
 107         assert(config);
 108
 109         const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
 110         for (int i = 0; i < NELEMS(plog); ++i)
 111                 plog[i] = plog_default;
 112         plog[LOG_ID_APPS] = true; // the default does not apply here for backward compatibility reasons.
 113         __set_plog_default_values();
 114 }
 115
 116 static void __configure_parameters(struct log_config *config)
 117 {
 118         assert(config);
 119
 120         __initialize_plog(config);
 121         __update_plog(config);
 122         __set_plog_default_values();
 123
 124         debugmode = log_config_get_int(config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
 125         fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
 126         limiter = log_config_get_boolean(config, "limiter", DEFAULT_CONFIG_LIMITER);
 127         limiter_apply_to_all_buffers = log_config_get_int(config,
 128                                                                         "limiter_apply_to_all_buffers",
 129                                                                         DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
 130 }
 131
 132 void __update_plog(const struct log_config *conf)
 133 {
 134         assert(conf);
 135
 136         for (int i = 0; i < NELEMS(plog); ++i) {
 137                 char key[MAX_CONF_KEY_LEN];
 138                 const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
 139                 if (r < 0)
 140                         continue;
 141                 plog[i] = log_config_get_boolean(conf, key, plog_default_values[i]);
 142         }
 143 }
 144
 145 /**
 146  * @brief Configure the library
 147  * @details Reads relevant config values
 148  * @remarks This is more or less a constructor, but there are some obstacles
 149  *          to using it as such (i.e. with attribute constructor):
 150  *
 151  *  - some important pieces of the system link to dlog, they start very early
 152  *    such that dlog can't properly initialize (which lasts for program lifetime)
 153  *    but don't actually log anything until later on and would be fine under lazy
 154  *    initialisation. The way to do it "properly" would be to expose this function
 155  *    into the API so that people can manually call it when they're ready, but
 156  *    one of the design goals of the current API is that it requires absolutely no
 157  *    other calls than `dlog_print`. Changing it would require somebody with a
 158  *    bird's eye view of the system to produce a design so I wouldn't count on it.
 159  *
 160  *  - the constructor would need to have as high of a priority as possible (so as
 161  *    to minimize the risk of another library's constructor using uninitialized data)
 162  *    but at the same time others might want some room to wrap functions before
 163  *    dlog uses them (think mprobe/mcheck). This would also require a design pass.
 164  */
 165 #ifndef UNIT_TEST
 166 static
 167 #endif
 168 void __configure(void)
 169 {
 170         struct log_config config;
 171
 172         if (log_config_read(&config) < 0)
 173                 goto out;
 174
 175         dynamic_config = __dynamic_config_create(&config);
 176
 177         __configure_parameters(&config);
 178
 179         if (!__configure_backend(&config))
 180                 goto out;
 181
 182         __configure_limiter(&config);
 183
 184 out:
 185         log_config_free(&config);
 186         return;
 187 }
 188
 189 static bool first = true;
 190 static void initialize()
 191 {
 192         if (is_initialized)
 193                 return;
 194
 195         /* The mutex acts as a barrier, but otherwise the C language's
 196          * machine abstraction is single-threaded. This means that the
 197          * compiler is free to rearrange calls inside the mutex according
 198          * to the as-if rule because it doesn't care if another thread can
 199          * access it in parallel. In particular, `is_initialized = true`
 200          * directly after `__configure()` could be rearranged to go in
 201          * front of it because it is not touched inside that function
 202          * if the compiler thinks it helps somehow (not unlikely: since
 203          * it is checked before the mutex, it is very probable for it to
 204          * still be in the CPU register or something like that). On top
 205          * of that, some architectures (in particular, armv7l) don't have
 206          * strict memory guarantees and can reorder actual memory stores
 207          * on their own, even if the compiler didn't do anything fancy
 208          * when creating machine code. For more info about the issue,
 209          * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
 210          *
 211          * Ultimately this means that there needs to be some sort of
 212          * barrier between `__configure` and `is_initialized = true`,
 213          * and the simplest way to achieve that is to just wait until
 214          * the second entry into the mutex. */
 215
 216         pthread_mutex_lock(&log_construction_lock);
 217                 if (first) {
 218                         __configure();
 219                         first = false; // pop this cherry
 220                 } else {
 221                         is_initialized = true;
 222                 }
 223         pthread_mutex_unlock(&log_construction_lock);
 224 }
 225
 226 /**
 227  * @brief Fatal assertion
 228  * @details Conditionally crash the sucka who sent the log
 229  * @param[in] prio Priority of the log
 230  */
 231 static void __dlog_fatal_assert(int prio)
 232 {
 233         assert(!fatal_assert || (prio != DLOG_FATAL));
 234 }
 235
 236 /**
 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
 244  */
 245 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
 246 {
 247         if (!tag)
 248                 return DLOG_ERROR_INVALID_PARAMETER;
 249
 250         if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
 251                 return DLOG_ERROR_INVALID_PARAMETER;
 252
 253         return DLOG_ERROR_NONE;
 254 }
 255
 256 /**
 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
 264  */
 265 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
 266 {
 267         if (!debugmode && prio <= DLOG_DEBUG)
 268                 return DLOG_ERROR_NOT_PERMITTED;
 269
 270         if (dynamic_config)
 271                 __dynamic_config_update();
 272
 273         if (limiter) {
 274                 pthread_rwlock_rdlock(&log_limiter_lock);
 275                 int should_log = __log_limiter_pass_log(tag, prio);
 276                 pthread_rwlock_unlock(&log_limiter_lock);
 277
 278                 if (!should_log) {
 279                         return DLOG_ERROR_NOT_PERMITTED;
 280                 } else if (should_log < 0) {
 281                         write_to_log(log_id, prio, tag,
 282                                         "Your log has been blocked due to limit of log lines per minute.");
 283                         return DLOG_ERROR_NOT_PERMITTED;
 284                 }
 285         }
 286
 287         /* This can change due to __dynamic_config_update(), but is atomic and its
 288          * value implies nothing else so does not need to be under a lock. */
 289         if (!plog[log_id])
 290                 return DLOG_ERROR_NOT_PERMITTED;
 291
 292         return DLOG_ERROR_NONE;
 293 }
 294
 295 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)
 296 {
 297         if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
 298                 return DLOG_ERROR_NONE;
 299
 300         char buf[LOG_MAX_PAYLOAD_SIZE];
 301         vsnprintf(buf, sizeof buf, fmt, ap);
 302         return write_to_log(log_id, prio, tag, buf);
 303 }
 304
 305 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)
 306 {
 307         int ret = dlog_check_validity(log_id, prio, tag);
 308         if (ret < 0)
 309                 return ret;
 310
 311         /* The only thing that needs to be protected here is `write_to_log` since
 312          * all other resources already have their own specific locks (and even the
 313          * pointer could be made to point at a null handler instead of a true NULL)
 314          * but giving this guarantee makes everything a lot simpler as it removes
 315          * the risk of something suddenly becoming NULL during processing. */
 316         pthread_rwlock_rdlock(&log_destruction_lock);
 317         initialize();
 318         ret = write_to_log ? __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log) : DLOG_ERROR_NOT_PERMITTED;
 319         pthread_rwlock_unlock(&log_destruction_lock);
 320
 321         return ret;
 322 }
 323
 324 /**
 325  * @brief Print log
 326  * @details Print a log line
 327  * @param[in] log_id The target buffer ID
 328  * @param[in] prio Priority
 329  * @param[in] tag tag
 330  * @param[in] fmt Format (same as printf)
 331  * @param[in] ap Argument list
 332  * @return Bytes written, or negative error
 333  */
 334 int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
 335 {
 336         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true);
 337         __dlog_fatal_assert(prio);
 338
 339         return ret;
 340 }
 341
 342 /**
 343  * @brief Print log
 344  * @details Print a log line
 345  * @param[in] log_id The target buffer ID
 346  * @param[in] prio Priority
 347  * @param[in] tag tag
 348  * @param[in] fmt Format (same as printf)
 349  * @return Bytes written, or negative error
 350  */
 351 int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
 352 {
 353         va_list ap;
 354
 355         va_start(ap, fmt);
 356         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
 357         va_end(ap);
 358
 359         return ret;
 360 }
 361
 362 int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
 363 {
 364         return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false);
 365 }
 366
 367 int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
 368 {
 369         va_list ap;
 370
 371         va_start(ap, fmt);
 372         int ret = dlog_vprint(prio, tag, fmt, ap);
 373         va_end(ap);
 374
 375         return ret;
 376 }
 377
 378 /**
 379  * @brief Finalize DLog
 380  * @details Finalizes and deallocates the library
 381  * @notes Used directly in tests; brings back the pre-init state
 382  */
 383 #ifndef UNIT_TEST
 384 static
 385 #endif
 386 void __dlog_fini(void)
 387 {
 388         if (destroy_backend) {
 389                 destroy_backend();
 390                 destroy_backend = NULL;
 391         }
 392         write_to_log = NULL;
 393         is_initialized = false;
 394         first = true;
 395
 396         __log_limiter_destroy();
 397         __dynamic_config_destroy();
 398 }
 399
 400 #ifdef UNIT_TEST
 401 void
 402 #else
 403 static void __attribute__((destructor))
 404 #endif
 405 __dlog_destroy(void)
 406 {
 407         pthread_rwlock_wrlock(&log_destruction_lock);
 408         __dlog_fini();
 409
 410         /* IMPORTANT! The lock is NEVER RELEASED. This is done ON PURPOSE.
 411          * The critical section can still be reached in some ways, NONE LEGAL.
 412          *
 413          * The first is that the program links the library dynamically and keeps
 414          * pointers to API functions past dlclose(). This is UNDEFINED BEHAVIOUR
 415          * and the implementation is NOT REQUIRED to keep the functions in memory
 416          * AT ALL and doing this COULD HAVE ALREADY CRASHED the program under a
 417          * different implementation.
 418          *
 419          * The second is when linking statically and FAILING TO JOIN threads before
 420          * exit(). These threads then typically keep running and can access the
 421          * library interface. However, they WILL DIE ANY MOMENT NOW ANYWAY so
 422          * getting deadlocked is of no consequence.
 423          *
 424          * In theory it would be possible to detect that destruction has already
 425          * taken place and reinitialize the library to salvage a logging attempt.
 426          * This is a HORRIBLE IDEA since without a destructor to rely on, either
 427          * those RESOURCES WOULD LEAK or we would have to MASSIVELY CONVOLUTE our
 428          * logic for manual destruction in such cases. */
 429 }
 430