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