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 <sys/wait.h>
  28 #include <unistd.h>
  29
  30 // DLog
  31 #include <dynamic_config.h>
  32 #include <libdlog.h>
  33 #include <logcommon.h>
  34 #include "logconfig.h"
  35 #include "loglimiter.h"
  36
  37 #define DEFAULT_CONFIG_LIMITER false
  38 #define DEFAULT_CONFIG_PLOG true
  39 #define DEFAULT_CONFIG_DEBUGMODE 0
  40 #define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
  41
  42 /**
  43  * @brief Points to a function which writes a log message
  44  * @details The function pointed to depends on the backend used
  45  * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
  46  * @param[in] prio Priority of the message.
  47  * @param[in] tag The message tag, identifies the sender.
  48  * @param[in] msg The contents of the message.
  49  * @return Returns the number of bytes written on success and a negative error value on error.
  50  * @see __dlog_init_backend
  51  */
  52 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
  53 void (*destroy_backend)();
  54
  55 pthread_rwlock_t log_limiter_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 static bool dynamic_config;
  64 static bool plog[LOG_ID_MAX];
  65 static 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 (size_t 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 (size_t 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 (size_t 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 bool __configure(void)
 169 {
 170         __attribute__((cleanup(log_config_free))) struct log_config config;
 171
 172         if (log_config_read(&config) < 0)
 173                 return false;
 174
 175         dynamic_config = __dynamic_config_create(&config);
 176
 177         __configure_parameters(&config);
 178
 179         if (!__configure_backend(&config)) {
 180                 __dynamic_config_destroy();
 181                 dynamic_config = false;
 182                 return false;
 183         }
 184
 185         __configure_limiter(&config);
 186         return true;
 187 }
 188
 189 static bool first = true;
 190 static bool initialize()
 191 {
 192         if (is_initialized)
 193                 return true;
 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         bool ret;
 217         pthread_mutex_lock(&log_construction_lock);
 218                 if (first)
 219                         first = !__configure();
 220                 else
 221                         is_initialized = true;
 222                 ret = !first;
 223         pthread_mutex_unlock(&log_construction_lock);
 224         return ret;
 225 }
 226
 227 /**
 228  * @brief Fatal assertion
 229  * @details Conditionally crash the sucka who sent the log
 230  * @param[in] prio Priority of the log
 231  */
 232 static void __dlog_fatal_assert(int prio)
 233 {
 234         assert(!fatal_assert || (prio != DLOG_FATAL));
 235 }
 236
 237 /**
 238  * @brief Check log validity
 239  * @details Checks whether the log is valid and eligible for printing
 240  * @param[in] log_id The target buffer ID
 241  * @param[in] prio The log's priority
 242  * @param[in] tag The log's tag
 243  * @return DLOG_ERROR_NONE on success, else an error code.
 244  * @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
 245  */
 246 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
 247 {
 248         (void) prio;
 249         if (!tag)
 250                 return DLOG_ERROR_INVALID_PARAMETER;
 251
 252         if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
 253                 return DLOG_ERROR_INVALID_PARAMETER;
 254
 255         return DLOG_ERROR_NONE;
 256 }
 257
 258 /**
 259  * @brief Check log against limiter rules
 260  * @details Checks whether the log passes current limiter rules
 261  * @param[in] log_id The target buffer ID
 262  * @param[in] prio The log's priority
 263  * @param[in] tag The log's tag
 264  * @return DLOG_ERROR_NONE on success, else an error code.
 265  * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
 266  */
 267 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
 268 {
 269         if (!debugmode && prio <= DLOG_DEBUG)
 270                 return DLOG_ERROR_NOT_PERMITTED;
 271
 272         if (dynamic_config)
 273                 __dynamic_config_update();
 274
 275         if (limiter) {
 276                 int should_log = 0;
 277                 if (!pthread_rwlock_rdlock(&log_limiter_lock)) {
 278                         should_log = __log_limiter_pass_log(tag, prio);
 279                         pthread_rwlock_unlock(&log_limiter_lock);
 280                 }
 281
 282                 if (!should_log) {
 283                         return DLOG_ERROR_NOT_PERMITTED;
 284                 } else if (should_log < 0) {
 285                         write_to_log(log_id, prio, tag,
 286                                         "Your log has been blocked due to limit of log lines per minute.");
 287                         return DLOG_ERROR_NOT_PERMITTED;
 288                 }
 289         }
 290
 291         /* This can change due to __dynamic_config_update(), but is atomic and its
 292          * value implies nothing else so does not need to be under a lock. */
 293         if (!plog[log_id])
 294                 return DLOG_ERROR_NOT_PERMITTED;
 295
 296         return DLOG_ERROR_NONE;
 297 }
 298
 299 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)
 300 {
 301         if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
 302                 return DLOG_ERROR_NONE;
 303
 304         char buf[LOG_MAX_PAYLOAD_SIZE];
 305         vsnprintf(buf, sizeof buf, fmt, ap);
 306         return write_to_log(log_id, prio, tag, buf);
 307 }
 308
 309 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)
 310 {
 311         int ret = dlog_check_validity(log_id, prio, tag);
 312         if (ret < 0)
 313                 return ret;
 314
 315         /* Threads can be cancelled before they give up a lock.
 316          * Therefore cancellation is temporarily disabled.
 317          * This solution is comparatively simple and cheap.
 318          * The other solutions (cleanup handlers, robust mutexes)
 319          * would be much more complicated and also inflict larger
 320          * runtime costs. The downside of disabling cancellation
 321          * is not a problem in our case because it is temporary
 322          * and very brief so we don't keep an obsolete thread
 323          * for much longer than we otherwise would. */
 324         int old_cancel_state;
 325         pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
 326
 327         /* The only thing that needs to be protected here is `write_to_log` since
 328          * all other resources already have their own specific locks (and even the
 329          * pointer could be made to point at a null handler instead of a true NULL)
 330          * but giving this guarantee makes everything a lot simpler as it removes
 331          * the risk of something suddenly becoming NULL during processing. */
 332         ret = !initialize() || !write_to_log
 333                 ? DLOG_ERROR_NOT_PERMITTED
 334                 : __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log)
 335                 ;
 336
 337         pthread_setcancelstate(old_cancel_state, NULL);
 338
 339         return ret;
 340 }
 341
 342 int __critical_log_append_timestamp(char *buf, size_t buflen)
 343 {
 344         /* NB: the timestamp may slightly differ from the one that gets
 345          * added onto the copy that goes into the regular buffer, and
 346          * timestamp acquisition is duplicated. This would ideally be
 347          * solved, but timestamps are currently added fairly deep in
 348          * backend-specific functions so for now this will have to do.
 349          * Also, since we're the sender, there is just this one set of
 350          * timestamps, i.e. the send timestamp! The usual alternative
 351          * set of receive timestamps will never have the opportunity
 352          * to get added to the entry since this log is supposed to end
 353          * up straight in the file (there's potentially the trusted
 354          * writer binary but we're trying to keep the set of actions
 355          * it needs to do to the minimum and those timestamps would
 356          * in practice be the same anyway). */
 357
 358         struct timespec ts;
 359         clock_gettime(CLOCK_REALTIME, &ts);
 360         const time_t tt = ts.tv_sec;
 361         const long int real_millisec = ts.tv_nsec / 1000000;
 362         clock_gettime(CLOCK_MONOTONIC, &ts);
 363 #ifdef HAVE_LOCALTIME_R
 364         struct tm tmBuf;
 365         struct tm *const ptm = localtime_r(&tt, &tmBuf);
 366 #else
 367         struct tm *const ptm = localtime(&tt);
 368 #endif
 369         assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
 370
 371         int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
 372         assert(len != 0);
 373
 374         int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
 375         assert(tmp_len > 0);
 376         assert(tmp_len < buflen - len);
 377         len += tmp_len;
 378
 379         tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
 380         assert(tmp_len != 0);
 381         len += tmp_len;
 382
 383         tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
 384         assert(tmp_len > 0);
 385         assert(tmp_len < buflen - len);
 386         len += tmp_len;
 387
 388         return len;
 389 }
 390
 391 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)
 392 {
 393         int len = __critical_log_append_timestamp(buf, buflen);
 394         const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
 395                 main_pid,
 396                 main_tid,
 397                 log_name_by_id(log_id),
 398                 filter_pri_to_char(prio),
 399                 tag ?: "CRITICAL_NO_TAG");
 400         assert(metadata_len > 0);
 401         if (metadata_len >= buflen - len)
 402                 return buflen - 1; // can genuinely happen with an exceedingly large tag
 403         len += metadata_len;
 404
 405         const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
 406         assert(content_len >= 0); // 0 is legit with format == ""
 407         if (content_len >= buflen - len)
 408                 return buflen - 1;
 409         len += content_len;
 410
 411         return len;
 412 }
 413
 414 #ifndef UNIT_TEST
 415 __attribute__ ((noreturn))
 416 #endif
 417 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)
 418 {
 419         char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
 420         const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
 421         buf[len] = '\n';
 422         buf[len + 1] = '\0';
 423
 424         static const char *const path = "/usr/libexec/dlog-log-critical";
 425         execl(path, path /* argv[0] convention */, buf, (char *) NULL);
 426
 427 #ifndef UNIT_TEST
 428         /* Compilers are sometimes smart enough to recognize _exit's
 429          * noreturn attribute, even if we wrap it with something that
 430          * returns. This causes it to behave in unexpected ways, for
 431          * example it can blow up the program regardless or it can
 432          * optimize some conditionals out (and incorrectly enter them
 433          * after the exit call fails to actually exit). This makes it
 434          * unsuitable for tests. */
 435
 436         _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
 437 #endif
 438 }
 439
 440 #ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
 441 void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
 442 {
 443         /* Critical log functionality is mostly done in a separate binary
 444          * to handle security correctly (else every process would have to
 445          * possess the necessary privilege to write onto that file, which
 446          * would be opening a fairly nasty can of worms from the security
 447          * point of view). Our use of exec() is why a simple thread would
 448          * not suffice and we're resorting to a fork.
 449          *
 450          * The double fork, much like a double barreled 12 gauge shotgun,
 451          * is an elegant solution designed to stop a zombie army. We'd be
 452          * creating zombie processes if we didn't wait() for the children
 453          * we spawn, but we don't really want to do that since it results
 454          * in a needless delay. Instead, the writer process is actually a
 455          * grandchild, with our direct child exiting immediately just for
 456          * us to have something to wait on that is guaranteed not to take
 457          * too long. The orphaned grandchild is adopted by init, who will
 458          * take care to reap it when it dies. In addition to avoiding the
 459          * delay, the client will not have any unexpected children (which
 460          * could ruin logic in its own waits).
 461          *
 462          * Right after forks:
 463          * ┌───────┐   ┌─────────┐   ┌─────────────┐   ┌────────┐
 464          * │ pid 1 ├──>│ libdlog ├──>│ immediately ├──>│ execs  │
 465          * │ init  │   │ client  │   │    exits    │   │ writer │
 466          * └───────┘   └─────────┘   └─────────────┘   └────────┘
 467          *
 468          * Afterwards, libdlog has no children:
 469          * ┌───────┐   ┌─────────┐                     ┌────────┐
 470          * │ pid 1 ├──>│ libdlog │          ┌─────────>│ writer │
 471          * │ init  ├─┐ │ client  │          │          │ binary │
 472          * └───────┘ │ └─────────┘          │          └────────┘
 473          *           └──────────────────────┘
 474          */
 475
 476         const pid_t main_pid = getpid();
 477         const pid_t main_tid = gettid();
 478
 479         const int temporary_exiter_pid = fork();
 480         if (temporary_exiter_pid < 0)
 481                 return;
 482         if (temporary_exiter_pid != 0) {
 483                 waitpid(temporary_exiter_pid, NULL, 0);
 484                 return;
 485         }
 486
 487         const int child_pid = fork();
 488         if (child_pid < 0)
 489                 _exit(1);
 490         if (child_pid != 0)
 491                 _exit(0);
 492
 493         __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
 494 }
 495
 496 int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
 497 {
 498         va_list ap;
 499
 500         va_start(ap, fmt);
 501         __critical_log(log_id, prio, tag, fmt, ap);
 502         va_end(ap);
 503
 504         va_start(ap, fmt);
 505         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
 506         va_end(ap);
 507
 508         return ret;
 509 }
 510 #endif
 511
 512 /**
 513  * @brief Print log
 514  * @details Print a log line
 515  * @param[in] log_id The target buffer ID
 516  * @param[in] prio Priority
 517  * @param[in] tag tag
 518  * @param[in] fmt Format (same as printf)
 519  * @param[in] ap Argument list
 520  * @return Bytes written, or negative error
 521  */
 522 int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
 523 {
 524         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true);
 525         __dlog_fatal_assert(prio);
 526
 527         return ret;
 528 }
 529
 530 /**
 531  * @brief Print log
 532  * @details Print a log line
 533  * @param[in] log_id The target buffer ID
 534  * @param[in] prio Priority
 535  * @param[in] tag tag
 536  * @param[in] fmt Format (same as printf)
 537  * @return Bytes written, or negative error
 538  */
 539 int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
 540 {
 541         va_list ap;
 542
 543         va_start(ap, fmt);
 544         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
 545         va_end(ap);
 546
 547         return ret;
 548 }
 549
 550 /**
 551  * @brief Print log
 552  * @details Print a log line
 553  * @param[in] log_id The target buffer ID
 554  * @param[in] prio Priority
 555  * @param[in] tag tag
 556  * @param[in] fmt Format (same as printf)
 557  * @return Bytes written, or negative error
 558  */
 559 int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
 560 {
 561         va_list ap;
 562
 563         va_start(ap, fmt);
 564         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
 565         va_end(ap);
 566
 567         return ret;
 568 }
 569
 570 int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
 571 {
 572         return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false);
 573 }
 574
 575 int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
 576 {
 577         va_list ap;
 578
 579         va_start(ap, fmt);
 580         int ret = dlog_vprint(prio, tag, fmt, ap);
 581         va_end(ap);
 582
 583         return ret;
 584 }
 585
 586 /**
 587  * @brief Finalize DLog
 588  * @details Finalizes and deallocates the library
 589  * @notes Used directly in tests; brings back the pre-init state
 590  */
 591 void __dlog_fini(void)
 592 {
 593         if (destroy_backend) {
 594                 destroy_backend();
 595                 destroy_backend = NULL;
 596         }
 597         write_to_log = NULL;
 598         is_initialized = false;
 599         first = true;
 600
 601         __log_limiter_destroy();
 602         __dynamic_config_destroy();
 603 }