libdlog: pass timestamp from a higher layer
[platform/core/system/dlog.git] / src / libdlog / log.c
1 /*-*- Mode: C; c-basic-offset: 8; indent-tabs-mode: t -*-
2  * DLOG
3  * Copyright (c) 2012-2013 Samsung Electronics Co., Ltd.
4  *
5  */
6
7 // C
8 #include <assert.h>
9 #include <stdbool.h>
10 #include <stdio.h>
11 #include <stdlib.h>
12
13 // POSIX
14 #include <pthread.h>
15 #include <sys/wait.h>
16 #include <unistd.h>
17
18 // DLog
19 #include <dynamic_config.h>
20 #include <libdlog.h>
21 #include <logcommon.h>
22 #include "logconfig.h"
23 #include "loglimiter.h"
24
25 #define DEFAULT_CONFIG_LIMITER false
26 #define DEFAULT_CONFIG_PLOG true
27 #define DEFAULT_CONFIG_DEBUGMODE 0
28 #define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
29
30 /**
31  * @brief Points to a function which writes a log message
32  * @details The function pointed to depends on the backend used
33  * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
34  * @param[in] prio Priority of the message.
35  * @param[in] tag The message tag, identifies the sender.
36  * @param[in] msg The contents of the message.
37  * @return Returns the number of bytes written on success and a negative error value on error.
38  * @see __dlog_init_backend
39  */
40 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono) = NULL;
41 void (*destroy_backend)();
42
43 pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
44 static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
45 static bool is_initialized = false;
46
47 extern void __dlog_init_pipe(const struct log_config *conf);
48 extern void __dlog_init_android(const struct log_config *conf);
49
50 bool limiter;
51 static bool dynamic_config;
52 static bool plog[LOG_ID_MAX];
53 static bool plog_default_values[LOG_ID_MAX];
54 static bool enable_secure_logs = true;
55
56 static int debugmode;
57 static int fatal_assert;
58 static int limiter_apply_to_all_buffers;
59 static _Atomic log_priority priority_filter_level = DLOG_VERBOSE;
60
61 static void __configure_limiter(struct log_config *config)
62 {
63         assert(config);
64
65         if (!limiter)
66                 return;
67
68         limiter = __log_limiter_create(config);
69 }
70
71 static int __configure_backend(struct log_config *config)
72 {
73         assert(config);
74
75         const char *const backend = log_config_get(config, "backend");
76         if (!backend)
77                 return 0;
78
79         if (!strcmp(backend, "pipe"))
80                 __dlog_init_pipe(config);
81         else if (!strcmp(backend, "logger"))
82                 __dlog_init_android(config);
83         else
84                 return 0;
85
86         return 1;
87 }
88
89 static void __set_plog_default_values()
90 {
91         for (size_t i = 0; i < NELEMS(plog); ++i)
92                 plog_default_values[i] = plog[i];
93 }
94
95 static void __initialize_plog(const struct log_config *config)
96 {
97         assert(config);
98
99         const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
100         for (size_t i = 0; i < NELEMS(plog); ++i)
101                 plog[i] = plog_default;
102         plog[LOG_ID_APPS] = true; // the default does not apply here for backward compatibility reasons.
103         __set_plog_default_values();
104 }
105
106 static void __configure_parameters(struct log_config *config)
107 {
108         assert(config);
109
110         __initialize_plog(config);
111         __update_plog(config);
112         __set_plog_default_values();
113
114         enable_secure_logs = log_config_get_boolean(config, "enable_secure_logs", enable_secure_logs);
115         debugmode = log_config_get_int(config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
116         fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
117         limiter = log_config_get_boolean(config, "limiter", DEFAULT_CONFIG_LIMITER);
118         limiter_apply_to_all_buffers = log_config_get_int(config,
119                                                                         "limiter_apply_to_all_buffers",
120                                                                         DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
121 }
122
123 void __update_plog(const struct log_config *conf)
124 {
125         assert(conf);
126
127         for (size_t i = 0; i < NELEMS(plog); ++i) {
128                 char key[MAX_CONF_KEY_LEN];
129                 const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
130                 if (r < 0)
131                         continue;
132                 plog[i] = log_config_get_boolean(conf, key, plog_default_values[i]);
133         }
134 }
135
136 /**
137  * @brief Configure the library
138  * @details Reads relevant config values
139  * @remarks This is more or less a constructor, but there are some obstacles
140  *          to using it as such (i.e. with attribute constructor):
141  *
142  *  - some important pieces of the system link to dlog, they start very early
143  *    such that dlog can't properly initialize (which lasts for program lifetime)
144  *    but don't actually log anything until later on and would be fine under lazy
145  *    initialisation. The way to do it "properly" would be to expose this function
146  *    into the API so that people can manually call it when they're ready, but
147  *    one of the design goals of the current API is that it requires absolutely no
148  *    other calls than `dlog_print`. Changing it would require somebody with a
149  *    bird's eye view of the system to produce a design so I wouldn't count on it.
150  *
151  *  - the constructor would need to have as high of a priority as possible (so as
152  *    to minimize the risk of another library's constructor using uninitialized data)
153  *    but at the same time others might want some room to wrap functions before
154  *    dlog uses them (think mprobe/mcheck). This would also require a design pass.
155  */
156 #ifndef UNIT_TEST
157 static
158 #endif
159 bool __configure(void)
160 {
161         __attribute__((cleanup(log_config_free))) struct log_config config;
162
163         if (log_config_read(&config) < 0)
164                 return false;
165
166         dynamic_config = __dynamic_config_create(&config);
167
168         __configure_parameters(&config);
169
170         if (!__configure_backend(&config)) {
171                 __dynamic_config_destroy();
172                 dynamic_config = false;
173                 return false;
174         }
175
176         __configure_limiter(&config);
177         return true;
178 }
179
180 static void __attribute__((constructor(101))) __install_pipe_handler(void)
181 {
182         /* We mask SIGPIPE signal because most applications do not install their
183          * own SIGPIPE handler. Default behaviour in SIGPIPE case is to abort the
184          * process. SIGPIPE occurs when e.g. dlog daemon closes read pipe endpoint.
185          *
186          * We do this in the library constructor (at maximum priority) and not
187          * during regular (lazy) initialisation so as to prevent overwriting the
188          * program's actual signal handler, if it has one.
189          *
190          * In theory this is not required for the Android logger backend; however,
191          * this early we don't yet know the backend and also it is good to behave
192          * consistently in this regard anyway.
193          *
194          * We don't revert this in a destructor because Unix signals are bonkers
195          * and we have no way to do this cleanly. Most libdlog users don't use
196          * runtime linking so this would mostly done at program exit either way. */
197         signal(SIGPIPE, SIG_IGN);
198 }
199
200 static bool first = true;
201 static bool initialize()
202 {
203         if (is_initialized)
204                 return true;
205
206         /* The mutex acts as a barrier, but otherwise the C language's
207          * machine abstraction is single-threaded. This means that the
208          * compiler is free to rearrange calls inside the mutex according
209          * to the as-if rule because it doesn't care if another thread can
210          * access it in parallel. In particular, `is_initialized = true`
211          * directly after `__configure()` could be rearranged to go in
212          * front of it because it is not touched inside that function
213          * if the compiler thinks it helps somehow (not unlikely: since
214          * it is checked before the mutex, it is very probable for it to
215          * still be in the CPU register or something like that). On top
216          * of that, some architectures (in particular, armv7l) don't have
217          * strict memory guarantees and can reorder actual memory stores
218          * on their own, even if the compiler didn't do anything fancy
219          * when creating machine code. For more info about the issue,
220          * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
221          *
222          * Ultimately this means that there needs to be some sort of
223          * barrier between `__configure` and `is_initialized = true`,
224          * and the simplest way to achieve that is to just wait until
225          * the second entry into the mutex. */
226
227         bool ret;
228         pthread_mutex_lock(&log_construction_lock);
229                 if (first)
230                         first = !__configure();
231                 else
232                         is_initialized = true;
233                 ret = !first;
234         pthread_mutex_unlock(&log_construction_lock);
235         return ret;
236 }
237
238 /**
239  * @brief Fatal assertion
240  * @details Conditionally crash the sucka who sent the log
241  * @param[in] prio Priority of the log
242  */
243 static void __dlog_fatal_assert(int prio)
244 {
245         assert(!fatal_assert || (prio != DLOG_FATAL));
246 }
247
248 /**
249  * @brief Check log validity
250  * @details Checks whether the log is valid and eligible for printing
251  * @param[in] log_id The target buffer ID
252  * @param[in] prio The log's priority
253  * @param[in] tag The log's tag
254  * @return DLOG_ERROR_NONE on success, else an error code.
255  * @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
256  */
257 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag)
258 {
259         (void) prio;
260         if (!tag)
261                 return DLOG_ERROR_INVALID_PARAMETER;
262
263         if (log_id <= LOG_ID_INVALID || LOG_ID_MAX <= log_id)
264                 return DLOG_ERROR_INVALID_PARAMETER;
265
266         return DLOG_ERROR_NONE;
267 }
268
269 /**
270  * @brief Check log against limiter rules
271  * @details Checks whether the log passes current limiter rules
272  * @param[in] log_id The target buffer ID
273  * @param[in] prio The log's priority
274  * @param[in] tag The log's tag
275  * @return DLOG_ERROR_NONE on success, else an error code.
276  * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
277  */
278 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
279 {
280         if (!debugmode && prio <= DLOG_DEBUG)
281                 return DLOG_ERROR_NOT_PERMITTED;
282
283         if (dynamic_config)
284                 __dynamic_config_update();
285
286         if (limiter) {
287                 int should_log = 0;
288                 if (!pthread_rwlock_rdlock(&log_limiter_lock)) {
289                         should_log = __log_limiter_pass_log(tag, prio);
290                         pthread_rwlock_unlock(&log_limiter_lock);
291                 }
292
293                 if (!should_log) {
294                         return DLOG_ERROR_NOT_PERMITTED;
295                 } else if (should_log < 0) {
296                         struct timespec tp;
297                         int result = clock_gettime(CLOCK_MONOTONIC, &tp);
298                         if (result < 0)
299                                 return DLOG_ERROR_NOT_PERMITTED;
300                         write_to_log(log_id, prio, tag,
301                                         "Your log has been blocked due to limit of log lines per minute.", &tp);
302                         return DLOG_ERROR_NOT_PERMITTED;
303                 }
304         }
305
306         /* This can change due to __dynamic_config_update(), but is atomic and its
307          * value implies nothing else so does not need to be under a lock. */
308         if (!plog[log_id])
309                 return DLOG_ERROR_NOT_PERMITTED;
310
311         return DLOG_ERROR_NONE;
312 }
313
314 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)
315 {
316         if (check_should_log && prio < priority_filter_level)
317                 return DLOG_ERROR_NONE;
318
319         if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
320                 return DLOG_ERROR_NONE;
321
322         char buf[LOG_MAX_PAYLOAD_SIZE];
323         vsnprintf(buf, sizeof buf, fmt, ap);
324
325         struct timespec tp;
326         int result = clock_gettime(CLOCK_MONOTONIC, &tp);
327         if (result < 0)
328                 return DLOG_ERROR_NONE;
329
330         return write_to_log(log_id, prio, tag, buf, &tp);
331 }
332
333 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)
334 {
335         int ret = dlog_check_validity(log_id, prio, tag);
336         if (ret < 0)
337                 return ret;
338
339         /* Threads can be cancelled before they give up a lock.
340          * Therefore cancellation is temporarily disabled.
341          * This solution is comparatively simple and cheap.
342          * The other solutions (cleanup handlers, robust mutexes)
343          * would be much more complicated and also inflict larger
344          * runtime costs. The downside of disabling cancellation
345          * is not a problem in our case because it is temporary
346          * and very brief so we don't keep an obsolete thread
347          * for much longer than we otherwise would. */
348         int old_cancel_state;
349         pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
350
351         /* The only thing that needs to be protected here is `write_to_log` since
352          * all other resources already have their own specific locks (and even the
353          * pointer could be made to point at a null handler instead of a true NULL)
354          * but giving this guarantee makes everything a lot simpler as it removes
355          * the risk of something suddenly becoming NULL during processing. */
356         if (!initialize() || !write_to_log)
357                 ret = DLOG_ERROR_NOT_PERMITTED;
358         else if (secure_log && !enable_secure_logs)
359                 ret = 0;
360         else
361                 ret = __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log);
362
363         pthread_setcancelstate(old_cancel_state, NULL);
364
365         return ret;
366 }
367
368 int __critical_log_append_timestamp(char *buf, size_t buflen)
369 {
370         /* NB: the timestamp may slightly differ from the one that gets
371          * added onto the copy that goes into the regular buffer, and
372          * timestamp acquisition is duplicated. This would ideally be
373          * solved, but timestamps are currently added fairly deep in
374          * backend-specific functions so for now this will have to do.
375          * Also, since we're the sender, there is just this one set of
376          * timestamps, i.e. the send timestamp! The usual alternative
377          * set of receive timestamps will never have the opportunity
378          * to get added to the entry since this log is supposed to end
379          * up straight in the file (there's potentially the trusted
380          * writer binary but we're trying to keep the set of actions
381          * it needs to do to the minimum and those timestamps would
382          * in practice be the same anyway). */
383
384         struct timespec ts;
385         clock_gettime(CLOCK_REALTIME, &ts);
386         const time_t tt = ts.tv_sec;
387         const long int real_millisec = ts.tv_nsec / 1000000;
388         clock_gettime(CLOCK_MONOTONIC, &ts);
389         struct tm tmBuf;
390         struct tm *const ptm = localtime_r(&tt, &tmBuf);
391         assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
392
393         int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
394         assert(len != 0);
395
396         int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
397         assert(tmp_len > 0);
398         assert(tmp_len < buflen - len);
399         len += tmp_len;
400
401         tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
402         assert(tmp_len != 0);
403         len += tmp_len;
404
405         tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
406         assert(tmp_len > 0);
407         assert(tmp_len < buflen - len);
408         len += tmp_len;
409
410         return len;
411 }
412
413 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)
414 {
415         int len = __critical_log_append_timestamp(buf, buflen);
416         const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
417                 main_pid,
418                 main_tid,
419                 log_name_by_id(log_id),
420                 filter_pri_to_char(prio),
421                 tag ?: "CRITICAL_NO_TAG");
422         assert(metadata_len > 0);
423         if (metadata_len >= buflen - len)
424                 return buflen - 1; // can genuinely happen with an exceedingly large tag
425         len += metadata_len;
426
427         const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
428         assert(content_len >= 0); // 0 is legit with format == ""
429         if (content_len >= buflen - len)
430                 return buflen - 1;
431         len += content_len;
432
433         return len;
434 }
435
436 #ifndef UNIT_TEST
437 __attribute__ ((noreturn))
438 #endif
439 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)
440 {
441         char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
442         const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
443         buf[len] = '\n';
444         buf[len + 1] = '\0';
445
446         static const char *const path = "/usr/libexec/dlog-log-critical";
447         execl(path, path /* argv[0] convention */, buf, (char *) NULL);
448
449 #ifndef UNIT_TEST
450         /* Compilers are sometimes smart enough to recognize _exit's
451          * noreturn attribute, even if we wrap it with something that
452          * returns. This causes it to behave in unexpected ways, for
453          * example it can blow up the program regardless or it can
454          * optimize some conditionals out (and incorrectly enter them
455          * after the exit call fails to actually exit). This makes it
456          * unsuitable for tests. */
457
458         _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
459 #endif
460 }
461
462 #ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
463 void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
464 {
465         /* Critical log functionality is mostly done in a separate binary
466          * to handle security correctly (else every process would have to
467          * possess the necessary privilege to write onto that file, which
468          * would be opening a fairly nasty can of worms from the security
469          * point of view). Our use of exec() is why a simple thread would
470          * not suffice and we're resorting to a fork.
471          *
472          * The double fork, much like a double barreled 12 gauge shotgun,
473          * is an elegant solution designed to stop a zombie army. We'd be
474          * creating zombie processes if we didn't wait() for the children
475          * we spawn, but we don't really want to do that since it results
476          * in a needless delay. Instead, the writer process is actually a
477          * grandchild, with our direct child exiting immediately just for
478          * us to have something to wait on that is guaranteed not to take
479          * too long. The orphaned grandchild is adopted by init, who will
480          * take care to reap it when it dies. In addition to avoiding the
481          * delay, the client will not have any unexpected children (which
482          * could ruin logic in its own waits).
483          *
484          * Right after forks:
485          * ┌───────┐   ┌─────────┐   ┌─────────────┐   ┌────────┐
486          * │ pid 1 ├──>│ libdlog ├──>│ immediately ├──>│ execs  │
487          * │ init  │   │ client  │   │    exits    │   │ writer │
488          * └───────┘   └─────────┘   └─────────────┘   └────────┘
489          *
490          * Afterwards, libdlog has no children:
491          * ┌───────┐   ┌─────────┐                     ┌────────┐
492          * │ pid 1 ├──>│ libdlog │          ┌─────────>│ writer │
493          * │ init  ├─┐ │ client  │          │          │ binary │
494          * └───────┘ │ └─────────┘          │          └────────┘
495          *           └──────────────────────┘
496          */
497
498         const pid_t main_pid = getpid();
499         const pid_t main_tid = gettid();
500
501         const int temporary_exiter_pid = fork();
502         if (temporary_exiter_pid < 0)
503                 return;
504         if (temporary_exiter_pid != 0) {
505                 waitpid(temporary_exiter_pid, NULL, 0);
506                 return;
507         }
508
509         const int child_pid = fork();
510         if (child_pid < 0)
511                 _exit(1);
512         if (child_pid != 0)
513                 _exit(0);
514
515         __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
516 }
517
518 int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
519 {
520         va_list ap;
521
522         va_start(ap, fmt);
523         __critical_log(log_id, prio, tag, fmt, ap);
524         va_end(ap);
525
526         va_start(ap, fmt);
527         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
528         va_end(ap);
529
530         return ret;
531 }
532 #endif
533
534 int dlog_set_minimum_priority(int priority)
535 {
536         if (priority < DLOG_DEFAULT || priority > DLOG_PRIO_MAX)
537                 return DLOG_ERROR_INVALID_PARAMETER;
538
539         priority_filter_level = priority;
540         return DLOG_ERROR_NONE;
541 }
542
543 /**
544  * @brief Print log
545  * @details Print a log line
546  * @param[in] log_id The target buffer ID
547  * @param[in] prio Priority
548  * @param[in] tag tag
549  * @param[in] fmt Format (same as printf)
550  * @param[in] ap Argument list
551  * @return Bytes written, or negative error
552  */
553 int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
554 {
555         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, false);
556         __dlog_fatal_assert(prio);
557
558         return ret;
559 }
560
561 /**
562  * @brief Print log
563  * @details Print a log line
564  * @param[in] log_id The target buffer ID
565  * @param[in] prio Priority
566  * @param[in] tag tag
567  * @param[in] fmt Format (same as printf)
568  * @return Bytes written, or negative error
569  */
570 int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
571 {
572         va_list ap;
573
574         va_start(ap, fmt);
575         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
576         va_end(ap);
577
578         return ret;
579 }
580
581 /**
582  * @brief Print log
583  * @details Print a log line
584  * @param[in] log_id The target buffer ID
585  * @param[in] prio Priority
586  * @param[in] tag tag
587  * @param[in] fmt Format (same as printf)
588  * @return Bytes written, or negative error
589  */
590 int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
591 {
592         if (!enable_secure_logs)
593                 return 0;
594
595         va_list ap;
596
597         va_start(ap, fmt);
598         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, true);
599         __dlog_fatal_assert(prio);
600         va_end(ap);
601
602         return ret;
603 }
604
605 int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
606 {
607         return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false, false);
608 }
609
610 int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
611 {
612         va_list ap;
613
614         va_start(ap, fmt);
615         int ret = dlog_vprint(prio, tag, fmt, ap);
616         va_end(ap);
617
618         return ret;
619 }
620
621 /**
622  * @brief Finalize DLog
623  * @details Finalizes and deallocates the library
624  * @notes Used directly in tests; brings back the pre-init state
625  */
626 void __dlog_fini(void)
627 {
628         if (destroy_backend) {
629                 destroy_backend();
630                 destroy_backend = NULL;
631         }
632         write_to_log = NULL;
633         is_initialized = false;
634         first = true;
635
636         __log_limiter_destroy();
637         __dynamic_config_destroy();
638 }