libdlog: Rewrite errnous comments about pthread_atfork() usage
[platform/core/system/dlog.git] / src / libdlog / log.c
1 /*  MIT License
2  *
3  * Copyright (c) 2012-2020 Samsung Electronics Co., Ltd
4  *
5  * Permission is hereby granted, free of charge, to any person obtaining a copy
6  * of this software and associated documentation files (the "Software"), to deal
7  * in the Software without restriction, including without limitation the rights
8  * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
9  * copies of the Software, and to permit persons to whom the Software is furnished
10  * to do so, subject to the following conditions:
11  *
12  * The above copyright notice and this permission notice shall be included in all
13  * copies or substantial portions of the Software.
14  *
15  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
16  * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
17  * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
18  * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
19  * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
20  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
21  * THE SOFTWARE. */
22
23 // C
24 #include <assert.h>
25 #include <stdbool.h>
26 #include <stdio.h>
27 #include <stdlib.h>
28
29 // POSIX
30 #include <pthread.h>
31 #include <sys/wait.h>
32 #include <unistd.h>
33
34 // Tizen
35 #include <tizen.h>
36
37 // DLog
38 #include <buffer_traits.h>
39 #include "deduplicate.h"
40 #include <dynamic_config.h>
41 #include "extra_sinks.h"
42 #include <libdlog.h>
43 #include "logconfig.h"
44 #include "loglimiter.h"
45
46 #define DEFAULT_CONFIG_LIMITER false
47 #define DEFAULT_CONFIG_PLOG true
48 #define DEFAULT_CONFIG_DEBUGMODE 0
49 #define DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS 0
50
51
52 /* A pseudo-backend that does nothing. Useful for removing the overhead of dlog
53  * for debugging and measurement purposes, also it simplifies some checking as
54  * the `write_to_log` pointer below never needs to be NULL. Note that features
55  * independent of the backend (such as limiter or dynamic config) are controlled
56  * separately if dlog is to be disabled completely and that minimal overhead is
57  * always present (e.g. building the message via vprintf). */
58 static int write_to_log_null (log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono, int32_t pid, int32_t tid)
59 {
60         return DLOG_ERROR_NONE;
61 }
62
63 /**
64  * @brief Points to a function which writes a log message
65  * @details The function pointed to depends on the backend used
66  * @param[in] log_id ID of the buffer to log to. Belongs to (LOG_ID_INVALID, LOG_ID_MAX) non-inclusive
67  * @param[in] prio Priority of the message.
68  * @param[in] tag The message tag, identifies the sender.
69  * @param[in] msg The contents of the message.
70  * @return Returns the number of bytes written on success and a negative error value on error.
71  * @see __dlog_init_backend
72  */
73 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg, struct timespec *tp_mono, int32_t pid, int32_t tid) = write_to_log_null;
74 void (*destroy_backend)(void);
75
76 int (*stash_failed_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
77 #ifndef UNIT_TEST
78 static int stash_critical(log_id_t log_id, log_priority prio, const char *tag, const char *msg);
79 #endif
80
81 pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
82 static pthread_mutex_t log_construction_lock = PTHREAD_MUTEX_INITIALIZER;
83 static bool is_initialized = false;
84
85 extern void __dlog_init_pipe(const struct log_config *conf);
86 extern void __dlog_init_android(const struct log_config *conf);
87 extern void __dlog_init_zero_copy();
88
89 extern void prepend_container_tag_if_in_container(size_t buf_size, char buf[static buf_size], int *len);
90
91 bool limiter;
92 struct limiter_data *limiter_data;
93 static bool dynamic_config;
94 static bool plog[SINKS_MAX];
95 static bool plog_default_values[SINKS_MAX];
96 static bool enable_secure_logs = true;
97 static bool enable_critical = true;
98
99 static bool should_disable_cancels;
100
101 static int debugmode;
102 static int fatal_assert;
103 static int limiter_apply_to_all_buffers;
104 static _Atomic log_priority priority_filter_level = DLOG_VERBOSE;
105
106 /* Cache pid and tid to avoid up to two syscalls per log.
107  * PID is reset at fork() via pthread_atfork().
108  * TID is reset by being a thread local var. */
109 static int32_t cached_pid = 0;
110 _Thread_local int32_t cached_tid = 0;
111
112 static inline int32_t get_cached_pid()
113 {
114         return (cached_pid = cached_pid ?: getpid());
115 }
116
117 static inline int32_t get_cached_tid()
118 {
119         return (cached_tid = cached_tid ?: gettid());
120 }
121
122 static void update_cached_pid()
123 {
124         cached_pid = getpid();
125         // tid is reset passively (to 0) by virtue of being thread-local
126 }
127
128 /* Here, static_config is the original config from /etc/dlog.conf{,.d} which can be overriden,
129  * but comes back if the override is removed. both_config additionally contains dynamic rules
130  * (by default from /run/dlog/filters.d) which can be changed in the runtime.
131  * The static_config has to be kept separately, so that we can go back to it when dynamic rules change.
132  * Note that most functions only use static_config, since the parameters can't be changed in runtime. */
133 static void __configure_limiter(struct log_config *static_config, struct log_config *both_config)
134 {
135         assert(static_config);
136         if (dynamic_config)
137                 assert(both_config);
138
139         if (!limiter)
140                 return;
141
142         limiter_data = __log_limiter_create(static_config);
143         if (limiter_data && dynamic_config)
144                 __log_limiter_update(limiter_data, both_config);
145         limiter = (bool)limiter_data;
146
147         should_disable_cancels |= limiter; // due to locks
148 }
149
150 static int __configure_backend(struct log_config *config)
151 {
152         assert(config);
153
154         const char *const backend = log_config_claim_backend(config);
155         if (!backend)
156                 return 0;
157
158         if (!strcmp(backend, "pipe")) {
159                 __dlog_init_pipe(config);
160                 should_disable_cancels = true;
161         } else if (!strcmp(backend, "logger"))
162                 __dlog_init_android(config);
163         else if (!strcmp(backend, "zero-copy"))
164                 __dlog_init_zero_copy(config);
165         else if (!strcmp(backend, "null"))
166                 ; // already the default
167         else
168                 return 0;
169
170         return 1;
171 }
172
173 static void __set_plog_default_values(void)
174 {
175         for (size_t i = 0; i < NELEMS(plog); ++i)
176                 plog_default_values[i] = plog[i];
177 }
178
179 static void __initialize_plog(const struct log_config *config)
180 {
181         assert(config);
182
183         /* plog stands for "platform logging", which is why
184          * non-platform (i.e. application) buffers ignore it */
185         const bool plog_default = log_config_get_boolean(config, "plog", DEFAULT_CONFIG_PLOG);
186         for (size_t i = 0; i < NELEMS(plog); ++i)
187                 plog[i] = is_platform_buffer(i) ? plog_default : true;
188
189         __set_plog_default_values();
190 }
191
192 static void __configure_parameters(struct log_config *static_config, struct log_config *both_config)
193 {
194         assert(static_config);
195         assert(both_config);
196
197         __initialize_plog(static_config);
198         __update_plog(static_config);
199         /* Like in __configure_limiter, we also check the dynamic rules. However, we make sure to
200      * set the default values to the ones generated by the static rules first. */
201         __set_plog_default_values();
202         __update_plog(both_config);
203
204         enable_secure_logs = log_config_get_boolean(both_config, "enable_secure_logs", enable_secure_logs);
205         enable_critical = log_config_get_boolean(both_config, "enable_critical", enable_critical);
206         debugmode = log_config_get_int(both_config, "debugmode", DEFAULT_CONFIG_DEBUGMODE);
207         fatal_assert = access(DEBUGMODE_FILE, F_OK) != -1;
208         limiter = log_config_get_boolean(both_config, "limiter", DEFAULT_CONFIG_LIMITER);
209         limiter_apply_to_all_buffers = log_config_get_int(both_config,
210                                                                         "limiter_apply_to_all_buffers",
211                                                                         DEFAULT_CONFIG_LIMITER_APPLY_TO_ALL_BUFFERS);
212
213         stash_failed_log = NULL;
214         const char *stash_failed_log_method = log_config_get(both_config, "stash_failed_log_method");
215         if (stash_failed_log_method) {
216 #ifndef UNIT_TEST
217                 if (strcmp(stash_failed_log_method, "critical") == 0)
218                         stash_failed_log = stash_critical;
219 #endif
220         }
221 }
222
223 void __update_plog(const struct log_config *conf)
224 {
225         assert(conf);
226
227         for (size_t i = 0; i < NELEMS(plog); ++i) {
228                 char key[MAX_CONF_KEY_LEN];
229                 const int r = snprintf(key, sizeof key, "enable_%s", log_name_by_id((log_id_t)i));
230                 if (r < 0)
231                         continue;
232                 plog[i] = log_config_get_boolean(conf, key, plog_default_values[i]);
233         }
234 }
235
236 /**
237  * @brief Configure the library
238  * @details Reads relevant config values
239  * @remarks This is more or less a constructor, but there are some obstacles
240  *          to using it as such (i.e. with attribute constructor):
241  *
242  *  - some important pieces of the system link to dlog, they start very early
243  *    such that dlog can't properly initialize (which lasts for program lifetime)
244  *    but don't actually log anything until later on and would be fine under lazy
245  *    initialisation. The way to do it "properly" would be to expose this function
246  *    into the API so that people can manually call it when they're ready, but
247  *    one of the design goals of the current API is that it requires absolutely no
248  *    other calls than `dlog_print`. Changing it would require somebody with a
249  *    bird's eye view of the system to produce a design so I wouldn't count on it.
250  *
251  *  - the constructor would need to have as high of a priority as possible (so as
252  *    to minimize the risk of another library's constructor using uninitialized data)
253  *    but at the same time others might want some room to wrap functions before
254  *    dlog uses them (think mprobe/mcheck). This would also require a design pass.
255  */
256 #ifndef UNIT_TEST
257 static
258 #endif
259 bool __configure(void)
260 {
261         __attribute__((cleanup(log_config_free))) struct log_config static_config = {};
262         __attribute__((cleanup(log_config_free))) struct log_config both_config = {};
263
264         if (log_config_read(&static_config) < 0)
265                 return false;
266         log_config_copy(&both_config, &static_config);
267
268         dynamic_config = __dynamic_config_create(&both_config);
269
270         __configure_parameters(&static_config, &both_config);
271
272         if (!__configure_backend(&both_config)) {
273                 __dynamic_config_destroy();
274                 dynamic_config = false;
275                 return false;
276         }
277
278         __configure_deduplicate(&both_config);
279         __configure_limiter(&static_config, &both_config);
280
281         pthread_atfork(NULL, NULL, update_cached_pid);
282
283         return true;
284 }
285
286 static void __attribute__((constructor(101))) __install_pipe_handler(void)
287 {
288         /* We mask SIGPIPE signal because most applications do not install their
289          * own SIGPIPE handler. Default behaviour in SIGPIPE case is to abort the
290          * process. SIGPIPE occurs when e.g. dlog daemon closes read pipe endpoint.
291          *
292          * We do this in the library constructor (at maximum priority) and not
293          * during regular (lazy) initialisation so as to prevent overwriting the
294          * program's actual signal handler, if it has one.
295          *
296          * In theory this is not required for the Android logger backend; however,
297          * this early we don't yet know the backend and also it is good to behave
298          * consistently in this regard anyway.
299          *
300          * We don't revert this in a destructor because Unix signals are bonkers
301          * and we have no way to do this cleanly. Most libdlog users don't use
302          * runtime linking so this would mostly done at program exit either way. */
303         signal(SIGPIPE, SIG_IGN);
304 }
305
306 static void __attribute__((constructor(102))) __set_output_buffering(void)
307 {
308         /* If stdout and/or stderr is redirected to dlog (service, driver)
309          * it is best if we buffer lines, otherwise the following can happen:
310          *  - no buffering: service/driver recives every single byte (precisely
311          *    every single write*(2) call), causing it to either buffer the data
312          *    anyway (service), or print logs at random places (driver)
313          *  - full buffering: service/driver receives several hundred lines,
314          *    which results in one giant entry being added (driver) or long delays
315          *    before logs appear (service) */
316         if (getenv(DLOG_ENV_STDOUT_LINE_BUFFERED))
317                 setlinebuf(stdout);
318
319         if (getenv(DLOG_ENV_STDERR_LINE_BUFFERED))
320                 setlinebuf(stderr);
321 }
322
323 static bool first = true;
324 static bool initialize(void)
325 {
326         if (is_initialized)
327                 return true;
328
329         /* The mutex acts as a barrier, but otherwise the C language's
330          * machine abstraction is single-threaded. This means that the
331          * compiler is free to rearrange calls inside the mutex according
332          * to the as-if rule because it doesn't care if another thread can
333          * access it in parallel. In particular, `is_initialized = true`
334          * directly after `__configure()` could be rearranged to go in
335          * front of it because it is not touched inside that function
336          * if the compiler thinks it helps somehow (not unlikely: since
337          * it is checked before the mutex, it is very probable for it to
338          * still be in the CPU register or something like that). On top
339          * of that, some architectures (in particular, armv7l) don't have
340          * strict memory guarantees and can reorder actual memory stores
341          * on their own, even if the compiler didn't do anything fancy
342          * when creating machine code. For more info about the issue,
343          * see https://www.aristeia.com/Papers/DDJ_Jul_Aug_2004_revised.pdf
344          *
345          * Ultimately this means that there needs to be some sort of
346          * barrier between `__configure` and `is_initialized = true`,
347          * and the simplest way to achieve that is to just wait until
348          * the second entry into the mutex. */
349
350         bool ret;
351         pthread_mutex_lock(&log_construction_lock);
352                 if (first)
353                         first = !__configure();
354                 else
355                         is_initialized = true;
356                 ret = !first;
357         pthread_mutex_unlock(&log_construction_lock);
358         return ret;
359 }
360
361 /**
362  * @brief Fatal assertion
363  * @details Conditionally crash the sucka who sent the log
364  * @param[in] prio Priority of the log
365  */
366 static void __dlog_fatal_assert(int prio)
367 {
368         assert(!fatal_assert || (prio != DLOG_FATAL));
369 }
370
371 /**
372  * @brief Check log validity
373  * @details Checks whether the log is valid and eligible for printing
374  * @param[in] log_id The target buffer ID
375  * @param[in] prio The log's priority
376  * @param[in] tag The log's tag
377  * @param[in] only_core Whether non-core buffers are rejected
378  * @return DLOG_ERROR_NONE on success, else an error code.
379  * @retval DLOG_ERROR_INVALID_PARAMETER Invalid parameter
380  */
381 static int dlog_check_validity(log_id_t log_id, int prio, const char *tag, bool only_core)
382 {
383         (void) prio;
384         if (!tag)
385                 return DLOG_ERROR_INVALID_PARAMETER;
386
387         if (!is_buffer_valid(log_id))
388                 return DLOG_ERROR_INVALID_PARAMETER;
389
390         /* The interface here is a bit confused. `__dlog_print` is nominally
391          * for platform logging and is not necessarily supposed to use the
392          * APPS buffer (which is a core buffer, but not a platform buffer),
393          * yet the internal interface (dlog-internal.h) exposes macros for
394          * platform programs to log into APPS. The design is probably too
395          * ossified to change at this point though. */
396         if (only_core && !is_core_buffer(log_id))
397                 return DLOG_ERROR_INVALID_PARAMETER;
398
399         return DLOG_ERROR_NONE;
400 }
401
402 /**
403  * @brief Check log against limiter rules
404  * @details Checks whether the log passes current limiter rules
405  * @param[in] log_id The target buffer ID
406  * @param[in] prio The log's priority
407  * @param[in] tag The log's tag
408  * @return DLOG_ERROR_NONE on success, else an error code.
409  * @retval DLOG_ERROR_NOT_PERMITTED Not permitted
410  */
411 static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
412 {
413         if (!debugmode && prio <= DLOG_DEBUG)
414                 return DLOG_ERROR_NOT_PERMITTED;
415
416         if (dynamic_config)
417                 __dynamic_config_update(limiter_data);
418
419         if (limiter) {
420                 struct pass_log_result should_log = { .decision = DECISION_DENIED };
421
422                 /* Since the only `wrlock` is done by the dynamic config, we can avoid
423                  * the `rdlock` entirely if the config is static. This sounds unsafe
424                  * but lets us save an entire syscall, which is a lot (both comparatively
425                  * and because it compounds). */
426                 if (!dynamic_config || !pthread_rwlock_rdlock(&log_limiter_lock)) {
427                         should_log = __log_limiter_pass_log_pid(limiter_data, tag, prio, get_cached_pid());
428                         if (dynamic_config)
429                                 pthread_rwlock_unlock(&log_limiter_lock);
430                 }
431
432                 switch (should_log.decision) {
433                         case DECISION_DENIED:
434                                 return DLOG_ERROR_NOT_PERMITTED;
435
436                         case DECISION_TAG_LIMIT_EXCEEDED_MESSAGE:
437                         case DECISION_PID_LIMIT_EXCEEDED_MESSAGE: {
438                                 struct timespec tp;
439                                 int result = clock_gettime(CLOCK_MONOTONIC, &tp);
440                                 if (result < 0)
441                                         return DLOG_ERROR_NOT_PERMITTED;
442                                 char buf[100] = {};
443                                 snprintf(buf, sizeof(buf),
444                                                 "Your log has been blocked due to per-%s limit of %d logs per %d seconds.",
445                                                 should_log.decision == DECISION_TAG_LIMIT_EXCEEDED_MESSAGE ? "tag" : "PID",
446                                                 should_log.logs_per_period, should_log.period_s);
447                                 write_to_log(log_id, prio, tag, buf, &tp, get_cached_pid(), get_cached_tid());
448                                 return DLOG_ERROR_NOT_PERMITTED;
449                         }
450
451                         case DECISION_ALLOWED:
452                                 break;
453                 }
454         }
455
456         /* This can change due to __dynamic_config_update(), but is atomic and its
457          * value implies nothing else so does not need to be under a lock. */
458         if (!plog[log_id])
459                 return DLOG_ERROR_NOT_PERMITTED;
460
461         return DLOG_ERROR_NONE;
462 }
463
464 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)
465 {
466         if ((check_should_log || limiter_apply_to_all_buffers) && (dlog_check_limiter(log_id, prio, tag) < 0))
467                 return DLOG_ERROR_NONE;
468
469         log_id = get_log_id_from_sink(log_id);
470
471         char buf[LOG_MAX_PAYLOAD_SIZE];
472         int len = vsnprintf(buf, sizeof buf, fmt, ap);
473         if (len < 0)
474                 return DLOG_ERROR_NONE;
475         else if (len >= sizeof buf)
476                 len = sizeof buf - 1;
477
478         // Temporary workaround, see temporary.c
479         prepend_container_tag_if_in_container(sizeof buf, buf, &len);
480
481         struct timespec tp;
482         int r;
483         if (deduplicate_func && !clock_gettime(CLOCK_MONOTONIC, &tp)) {
484                 dlog_deduplicate_e ret = deduplicate_func(buf, len, &tp);
485                 if (ret == DLOG_DEDUPLICATE)
486                         return DLOG_ERROR_NONE;
487                 else if (ret == DLOG_DO_NOT_DEDUPLICATE_BUT_WARN)
488                         deduplicate_warn(buf, sizeof buf, len);
489                 r = write_to_log(log_id, prio, tag, buf, &tp, get_cached_pid(), get_cached_tid());
490         } else
491                 r = write_to_log(log_id, prio, tag, buf, NULL, get_cached_pid(), get_cached_tid());
492
493         if (r < 0 && stash_failed_log)
494                 r = stash_failed_log(log_id, prio, tag, buf);
495
496         return r;
497 }
498
499 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)
500 {
501         int ret = dlog_check_validity(log_id, prio, tag, check_should_log);
502         if (ret < 0)
503                 return ret;
504
505         if (check_should_log && prio < priority_filter_level)
506                 return DLOG_ERROR_NONE;
507
508         /* Threads can be cancelled before they give up a lock.
509          * Therefore cancellation is temporarily disabled as
510          * long as the current set of features uses a lock.
511          *
512          * This solution is comparatively simple and cheap.
513          * The other solutions (cleanup handlers, robust mutexes)
514          * would be much more complicated and also inflict larger
515          * runtime costs. The downside of disabling cancellation
516          * is not a problem in our case because it is temporary
517          * and very brief so we don't keep an obsolete thread
518          * for much longer than we otherwise would. */
519         int old_cancel_state;
520         if (should_disable_cancels)
521                 pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &old_cancel_state);
522
523         if (!initialize())
524                 // TODO: We could consider stashing the failed log here
525                 ret = DLOG_ERROR_NOT_PERMITTED;
526         else if (secure_log && !enable_secure_logs)
527                 ret = 0;
528         else
529                 ret = __write_to_log_critical_section(log_id, prio, tag, fmt, ap, check_should_log);
530
531         if (should_disable_cancels)
532                 pthread_setcancelstate(old_cancel_state, NULL);
533
534         return ret;
535 }
536
537 int __critical_log_append_timestamp(char *buf, size_t buflen)
538 {
539         /* NB: the timestamp may slightly differ from the one that gets
540          * added onto the copy that goes into the regular buffer, and
541          * timestamp acquisition is duplicated. This would ideally be
542          * solved, but timestamps are currently added fairly deep in
543          * backend-specific functions so for now this will have to do.
544          * Also, since we're the sender, there is just this one set of
545          * timestamps, i.e. the send timestamp! The usual alternative
546          * set of receive timestamps will never have the opportunity
547          * to get added to the entry since this log is supposed to end
548          * up straight in the file (there's potentially the trusted
549          * writer binary but we're trying to keep the set of actions
550          * it needs to do to the minimum and those timestamps would
551          * in practice be the same anyway). */
552
553         struct timespec ts;
554         clock_gettime(CLOCK_REALTIME, &ts);
555         const time_t tt = ts.tv_sec;
556         const long int real_millisec = ts.tv_nsec / 1000000;
557         clock_gettime(CLOCK_MONOTONIC, &ts);
558         struct tm tmBuf;
559         struct tm *const ptm = localtime_r(&tt, &tmBuf);
560         assert(ptm); // we're in a short lived fork so asserts are fine and make things simple
561
562         int len = strftime(buf, buflen, "%m-%d %H:%M:%S", ptm);
563         assert(len != 0);
564
565         int tmp_len = snprintf(buf + len, buflen - len, ".%03ld", real_millisec);
566         assert(tmp_len > 0);
567         assert(tmp_len < buflen - len);
568         len += tmp_len;
569
570         tmp_len = strftime(buf + len, buflen - len, "%z ", ptm);
571         assert(tmp_len != 0);
572         len += tmp_len;
573
574         tmp_len = snprintf(buf + len, buflen - len, "%5lu.%03ld", ts.tv_sec, ts.tv_nsec / 1000000);
575         assert(tmp_len > 0);
576         assert(tmp_len < buflen - len);
577         len += tmp_len;
578
579         return len;
580 }
581
582 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)
583 {
584         int len = __critical_log_append_timestamp(buf, buflen);
585         const int metadata_len = snprintf(buf + len, buflen - len, " P%5d T%5d B%-6s %c/%-8s: ",
586                 main_pid,
587                 main_tid,
588                 log_name_by_id(log_id),
589                 filter_pri_to_char(prio),
590                 tag ?: "CRITICAL_NO_TAG");
591         assert(metadata_len > 0);
592         if (metadata_len >= buflen - len)
593                 return buflen - 1; // can genuinely happen with an exceedingly large tag
594         len += metadata_len;
595
596         const int content_len = vsnprintf(buf + len, buflen - len, fmt, ap);
597         assert(content_len >= 0); // 0 is legit with format == ""
598         if (content_len >= buflen - len)
599                 return buflen - 1;
600         len += content_len;
601
602         return len;
603 }
604
605 #ifndef UNIT_TEST
606 __attribute__ ((noreturn))
607 #endif
608 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)
609 {
610         char buf[LOG_MAX_PAYLOAD_SIZE + 128]; // extra space for some metadata
611         const int len = __critical_log_build_msg(buf, sizeof buf - 1, main_pid, main_tid, log_id, prio, tag, fmt, ap);
612         buf[len] = '\n';
613         buf[len + 1] = '\0';
614
615         static const char *const path = "/usr/libexec/dlog-log-critical";
616         execl(path, path /* argv[0] convention */, buf, (char *) NULL);
617
618 #ifndef UNIT_TEST
619         /* Compilers are sometimes smart enough to recognize _exit's
620          * noreturn attribute, even if we wrap it with something that
621          * returns. This causes it to behave in unexpected ways, for
622          * example it can blow up the program regardless or it can
623          * optimize some conditionals out (and incorrectly enter them
624          * after the exit call fails to actually exit). This makes it
625          * unsuitable for tests. */
626
627         _exit(1); // not the regular `exit` so as not to trigger any `atexit` handlers prematurely
628 #endif
629 }
630
631 #ifndef UNIT_TEST // contains forks and exits, these don't work well with wrapping (see above)
632 void __critical_log(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
633 {
634         /* Critical log functionality is mostly done in a separate binary
635          * to handle security correctly (else every process would have to
636          * possess the necessary privilege to write onto that file, which
637          * would be opening a fairly nasty can of worms from the security
638          * point of view). Our use of exec() is why a simple thread would
639          * not suffice and we're resorting to a fork.
640          *
641          * The double fork, much like a double barreled 12 gauge shotgun,
642          * is an elegant solution designed to stop a zombie army. We'd be
643          * creating zombie processes if we didn't wait() for the children
644          * we spawn, but we don't really want to do that since it results
645          * in a needless delay. Instead, the writer process is actually a
646          * grandchild, with our direct child exiting immediately just for
647          * us to have something to wait on that is guaranteed not to take
648          * too long. The orphaned grandchild is adopted by init, who will
649          * take care to reap it when it dies. In addition to avoiding the
650          * delay, the client will not have any unexpected children (which
651          * could ruin logic in its own waits).
652          *
653          * Right after forks:
654          * ┌───────┐   ┌─────────┐   ┌─────────────┐   ┌────────┐
655          * │ pid 1 ├──>│ libdlog ├──>│ immediately ├──>│ execs  │
656          * │ init  │   │ client  │   │    exits    │   │ writer │
657          * └───────┘   └─────────┘   └─────────────┘   └────────┘
658          *
659          * Afterwards, libdlog has no children:
660          * ┌───────┐   ┌─────────┐                     ┌────────┐
661          * │ pid 1 ├──>│ libdlog │          ┌─────────>│ writer │
662          * │ init  ├─┐ │ client  │          │          │ binary │
663          * └───────┘ │ └─────────┘          │          └────────┘
664          *           └──────────────────────┘
665          */
666
667         initialize();
668
669         if (!enable_critical)
670                 return;
671
672         const pid_t main_pid = getpid();
673         const pid_t main_tid = gettid();
674
675         const int temporary_exiter_pid = fork();
676         if (temporary_exiter_pid < 0)
677                 return;
678         if (temporary_exiter_pid != 0) {
679                 waitpid(temporary_exiter_pid, NULL, 0);
680                 return;
681         }
682
683         const int child_pid = fork();
684         if (child_pid < 0)
685                 _exit(1);
686         if (child_pid != 0)
687                 _exit(0);
688
689         __critical_log_child(main_pid, main_tid, log_id, prio, tag, fmt, ap);
690 }
691
692 // LCOV_EXCL_START : stashing is essentially error handling.
693 static void stash_critical_inner(log_id_t log_id, log_priority prio, const char *tag, const char *fmt, ...)
694 {
695         va_list ap;
696
697         va_start(ap, fmt);
698         __critical_log(log_id, prio, tag, fmt, ap);
699         va_end(ap);
700 }
701
702 static int stash_critical(log_id_t log_id, log_priority prio, const char *tag, const char *msg)
703 {
704         stash_critical_inner(log_id, prio, tag, "FAILED TO LOG: %s", msg);
705         return 0;
706 }
707 // LCOV_EXCL_STOP
708
709 EXPORT_API int __dlog_critical_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
710 {
711         va_list ap;
712
713         va_start(ap, fmt);
714         __critical_log(log_id, prio, tag, fmt, ap);
715         va_end(ap);
716
717         va_start(ap, fmt);
718         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
719         va_end(ap);
720
721         return ret;
722 }
723 #endif
724
725 EXPORT_API int dlog_set_minimum_priority(int priority)
726 {
727         if (priority < DLOG_DEFAULT || priority > DLOG_PRIO_MAX)
728                 return DLOG_ERROR_INVALID_PARAMETER;
729
730         priority_filter_level = priority;
731         return DLOG_ERROR_NONE;
732 }
733
734 /**
735  * @brief Print log
736  * @details Print a log line
737  * @param[in] log_id The target buffer ID
738  * @param[in] prio Priority
739  * @param[in] tag tag
740  * @param[in] fmt Format (same as printf)
741  * @param[in] ap Argument list
742  * @return Bytes written, or negative error
743  */
744 EXPORT_API int __dlog_vprint(log_id_t log_id, int prio, const char *tag, const char *fmt, va_list ap)
745 {
746         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, false);
747         __dlog_fatal_assert(prio);
748
749         return ret;
750 }
751
752 /**
753  * @brief Print log
754  * @details Print a log line
755  * @param[in] log_id The target buffer ID
756  * @param[in] prio Priority
757  * @param[in] tag tag
758  * @param[in] fmt Format (same as printf)
759  * @return Bytes written, or negative error
760  */
761 EXPORT_API int __dlog_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
762 {
763         va_list ap;
764
765         va_start(ap, fmt);
766         int ret = __dlog_vprint(log_id, prio, tag, fmt, ap);
767         va_end(ap);
768
769         return ret;
770 }
771
772 /**
773  * @brief Print log
774  * @details Print a log line
775  * @param[in] log_id The target buffer ID
776  * @param[in] prio Priority
777  * @param[in] tag tag
778  * @param[in] fmt Format (same as printf)
779  * @return Bytes written, or negative error
780  */
781 EXPORT_API int __dlog_sec_print(log_id_t log_id, int prio, const char *tag, const char *fmt, ...)
782 {
783         if (!enable_secure_logs)
784                 return 0;
785
786         va_list ap;
787
788         va_start(ap, fmt);
789         int ret = __write_to_log(log_id, prio, tag, fmt, ap, true, true);
790         __dlog_fatal_assert(prio);
791         va_end(ap);
792
793         return ret;
794 }
795
796 EXPORT_API int dlog_vprint(log_priority prio, const char *tag, const char *fmt, va_list ap)
797 {
798         return __write_to_log(LOG_ID_APPS, prio, tag, fmt, ap, false, false);
799 }
800
801 EXPORT_API int dlog_print(log_priority prio, const char *tag, const char *fmt, ...)
802 {
803         va_list ap;
804
805         va_start(ap, fmt);
806         int ret = dlog_vprint(prio, tag, fmt, ap);
807         va_end(ap);
808
809         return ret;
810 }
811
812 EXPORT_API int dlog_vprint_dotnet(log_priority prio, const char *tag, const char *fmt, va_list ap)
813 {
814         return __write_to_log(SINK_DOTNET, prio, tag, fmt, ap, false, false);
815 }
816
817 EXPORT_API int dlog_print_dotnet(log_priority prio, const char *tag, const char *fmt, ...)
818 {
819         va_list ap;
820
821         va_start(ap, fmt);
822         int ret = dlog_vprint_dotnet(prio, tag, fmt, ap);
823         va_end(ap);
824
825         return ret;
826 }
827
828 EXPORT_API int dlog_vprint_native(log_priority prio, const char *tag, const char *fmt, va_list ap)
829 {
830         return __write_to_log(SINK_NATIVE, prio, tag, fmt, ap, false, false);
831 }
832
833 EXPORT_API int dlog_print_native(log_priority prio, const char *tag, const char *fmt, ...)
834 {
835         va_list ap;
836
837         va_start(ap, fmt);
838         int ret = dlog_vprint_native(prio, tag, fmt, ap);
839         va_end(ap);
840
841         return ret;
842 }
843
844 // LCOV_EXCL_START : for internal use only, not accessible via public API
845
846 /**
847  * @brief Finalize DLog
848  * @details Finalizes and deallocates the library
849  * @notes Used directly in tests; brings back the pre-init state
850  */
851 void __dlog_fini(void)
852 {
853         if (destroy_backend) {
854                 destroy_backend();
855                 destroy_backend = NULL;
856         }
857         write_to_log = write_to_log_null;
858         stash_failed_log = NULL;
859         is_initialized = false;
860         first = true;
861
862         enable_secure_logs = true;
863         enable_critical = false;
864         __deduplicate_destroy();
865         __log_limiter_destroy(limiter_data);
866         limiter = false;
867         __dynamic_config_destroy();
868         should_disable_cancels = false;
869 }
870
871 // LCOV_EXCL_STOP