]> code.delx.au - pulseaudio/blob - src/pulsecore/log.c
protocol-native: Early request bandaid for high latency sink/source
[pulseaudio] / src / pulsecore / log.c
1 /***
2 This file is part of PulseAudio.
3
4 Copyright 2004-2006 Lennart Poettering
5 Copyright 2006 Pierre Ossman <ossman@cendio.se> for Cendio AB
6
7 PulseAudio is free software; you can redistribute it and/or modify
8 it under the terms of the GNU Lesser General Public License as
9 published by the Free Software Foundation; either version 2.1 of the
10 License, or (at your option) any later version.
11
12 PulseAudio is distributed in the hope that it will be useful, but
13 WITHOUT ANY WARRANTY; without even the implied warranty of
14 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
15 General Public License for more details.
16
17 You should have received a copy of the GNU Lesser General Public
18 License along with PulseAudio; if not, write to the Free Software
19 Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307
20 USA.
21 ***/
22
23 #ifdef HAVE_CONFIG_H
24 #include <config.h>
25 #endif
26
27 #include <stdarg.h>
28 #include <stdio.h>
29 #include <unistd.h>
30 #include <string.h>
31 #include <errno.h>
32 #include <fcntl.h>
33 #include <sys/stat.h>
34
35 #ifdef HAVE_EXECINFO_H
36 #include <execinfo.h>
37 #endif
38
39 #ifdef HAVE_SYSLOG_H
40 #include <syslog.h>
41 #endif
42
43 #ifdef HAVE_JOURNAL
44 #include <systemd/sd-journal.h>
45 #endif
46
47 #include <pulse/gccmacro.h>
48 #include <pulse/rtclock.h>
49 #include <pulse/utf8.h>
50 #include <pulse/xmalloc.h>
51 #include <pulse/util.h>
52 #include <pulse/timeval.h>
53
54 #include <pulsecore/macro.h>
55 #include <pulsecore/core-util.h>
56 #include <pulsecore/core-error.h>
57 #include <pulsecore/once.h>
58 #include <pulsecore/ratelimit.h>
59 #include <pulsecore/thread.h>
60 #include <pulsecore/i18n.h>
61
62 #include "log.h"
63
64 #define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG"
65 #define ENV_LOG_LEVEL "PULSE_LOG"
66 #define ENV_LOG_COLORS "PULSE_LOG_COLORS"
67 #define ENV_LOG_PRINT_TIME "PULSE_LOG_TIME"
68 #define ENV_LOG_PRINT_FILE "PULSE_LOG_FILE"
69 #define ENV_LOG_PRINT_META "PULSE_LOG_META"
70 #define ENV_LOG_PRINT_LEVEL "PULSE_LOG_LEVEL"
71 #define ENV_LOG_BACKTRACE "PULSE_LOG_BACKTRACE"
72 #define ENV_LOG_BACKTRACE_SKIP "PULSE_LOG_BACKTRACE_SKIP"
73 #define ENV_LOG_NO_RATELIMIT "PULSE_LOG_NO_RATE_LIMIT"
74 #define LOG_MAX_SUFFIX_NUMBER 99
75
76 static char *ident = NULL; /* in local charset format */
77 static pa_log_target target = { PA_LOG_STDERR, NULL };
78 static pa_log_target_type_t target_override;
79 static bool target_override_set = false;
80 static pa_log_level_t maximum_level = PA_LOG_ERROR, maximum_level_override = PA_LOG_ERROR;
81 static unsigned show_backtrace = 0, show_backtrace_override = 0, skip_backtrace = 0;
82 static pa_log_flags_t flags = 0, flags_override = 0;
83 static bool no_rate_limit = false;
84 static int log_fd = -1;
85 static int write_type = 0;
86
87 #ifdef HAVE_SYSLOG_H
88 static const int level_to_syslog[] = {
89 [PA_LOG_ERROR] = LOG_ERR,
90 [PA_LOG_WARN] = LOG_WARNING,
91 [PA_LOG_NOTICE] = LOG_NOTICE,
92 [PA_LOG_INFO] = LOG_INFO,
93 [PA_LOG_DEBUG] = LOG_DEBUG
94 };
95 #endif
96
97 /* These are actually equivalent to the syslog ones
98 * but we don't want to depend on syslog.h */
99 #ifdef HAVE_JOURNAL
100 static const int level_to_journal[] = {
101 [PA_LOG_ERROR] = 3,
102 [PA_LOG_WARN] = 4,
103 [PA_LOG_NOTICE] = 5,
104 [PA_LOG_INFO] = 6,
105 [PA_LOG_DEBUG] = 7
106 };
107 #endif
108
109 static const char level_to_char[] = {
110 [PA_LOG_ERROR] = 'E',
111 [PA_LOG_WARN] = 'W',
112 [PA_LOG_NOTICE] = 'N',
113 [PA_LOG_INFO] = 'I',
114 [PA_LOG_DEBUG] = 'D'
115 };
116
117 void pa_log_set_ident(const char *p) {
118 pa_xfree(ident);
119
120 if (!(ident = pa_utf8_to_locale(p)))
121 ident = pa_ascii_filter(p);
122 }
123
124 /* To make valgrind shut up. */
125 static void ident_destructor(void) PA_GCC_DESTRUCTOR;
126 static void ident_destructor(void) {
127 if (!pa_in_valgrind())
128 return;
129
130 pa_xfree(ident);
131 }
132
133 void pa_log_set_level(pa_log_level_t l) {
134 pa_assert(l < PA_LOG_LEVEL_MAX);
135
136 maximum_level = l;
137 }
138
139 int pa_log_set_target(pa_log_target *t) {
140 int fd = -1;
141 int old_fd;
142
143 pa_assert(t);
144
145 switch (t->type) {
146 case PA_LOG_STDERR:
147 case PA_LOG_SYSLOG:
148 #ifdef HAVE_JOURNAL
149 case PA_LOG_JOURNAL:
150 #endif
151 case PA_LOG_NULL:
152 break;
153 case PA_LOG_FILE:
154 if ((fd = pa_open_cloexec(t->file, O_WRONLY | O_TRUNC | O_CREAT, S_IRUSR | S_IWUSR)) < 0) {
155 pa_log(_("Failed to open target file '%s'."), t->file);
156 return -1;
157 }
158 break;
159 case PA_LOG_NEWFILE: {
160 char *file_path;
161 char *p;
162 unsigned version;
163
164 file_path = pa_sprintf_malloc("%s.xx", t->file);
165 p = file_path + strlen(t->file);
166
167 for (version = 0; version <= LOG_MAX_SUFFIX_NUMBER; version++) {
168 memset(p, 0, 3); /* Overwrite the ".xx" part in file_path with zero bytes. */
169
170 if (version > 0)
171 pa_snprintf(p, 4, ".%u", version); /* Why 4? ".xx" + termitating zero byte. */
172
173 if ((fd = pa_open_cloexec(file_path, O_WRONLY | O_TRUNC | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR)) >= 0)
174 break;
175 }
176
177 if (version > LOG_MAX_SUFFIX_NUMBER) {
178 pa_log(_("Tried to open target file '%s', '%s.1', '%s.2' ... '%s.%d', but all failed."),
179 t->file, t->file, t->file, t->file, LOG_MAX_SUFFIX_NUMBER);
180 pa_xfree(file_path);
181 return -1;
182 } else
183 pa_log_debug("Opened target file %s\n", file_path);
184
185 pa_xfree(file_path);
186 break;
187 }
188 }
189
190 target.type = t->type;
191 pa_xfree(target.file);
192 target.file = pa_xstrdup(t->file);
193
194 old_fd = log_fd;
195 log_fd = fd;
196
197 if (old_fd >= 0)
198 pa_close(old_fd);
199
200 return 0;
201 }
202
203 void pa_log_set_flags(pa_log_flags_t _flags, pa_log_merge_t merge) {
204 pa_assert(!(_flags & ~(PA_LOG_COLORS|PA_LOG_PRINT_TIME|PA_LOG_PRINT_FILE|PA_LOG_PRINT_META|PA_LOG_PRINT_LEVEL)));
205
206 if (merge == PA_LOG_SET)
207 flags |= _flags;
208 else if (merge == PA_LOG_UNSET)
209 flags &= ~_flags;
210 else
211 flags = _flags;
212 }
213
214 void pa_log_set_show_backtrace(unsigned nlevels) {
215 show_backtrace = nlevels;
216 }
217
218 void pa_log_set_skip_backtrace(unsigned nlevels) {
219 skip_backtrace = nlevels;
220 }
221
222 #ifdef HAVE_EXECINFO_H
223
224 static char* get_backtrace(unsigned show_nframes) {
225 void* trace[32];
226 int n_frames;
227 char **symbols, *e, *r;
228 unsigned j, n, s;
229 size_t a;
230
231 pa_assert(show_nframes > 0);
232
233 n_frames = backtrace(trace, PA_ELEMENTSOF(trace));
234
235 if (n_frames <= 0)
236 return NULL;
237
238 symbols = backtrace_symbols(trace, n_frames);
239
240 if (!symbols)
241 return NULL;
242
243 s = skip_backtrace;
244 n = PA_MIN((unsigned) n_frames, s + show_nframes);
245
246 a = 4;
247
248 for (j = s; j < n; j++) {
249 if (j > s)
250 a += 2;
251 a += strlen(pa_path_get_filename(symbols[j]));
252 }
253
254 r = pa_xnew(char, a);
255
256 strcpy(r, " (");
257 e = r + 2;
258
259 for (j = s; j < n; j++) {
260 const char *sym;
261
262 if (j > s) {
263 strcpy(e, "<<");
264 e += 2;
265 }
266
267 sym = pa_path_get_filename(symbols[j]);
268
269 strcpy(e, sym);
270 e += strlen(sym);
271 }
272
273 strcpy(e, ")");
274
275 free(symbols);
276
277 return r;
278 }
279
280 #endif
281
282 static void init_defaults(void) {
283 PA_ONCE_BEGIN {
284
285 const char *e;
286
287 if (!ident) {
288 char binary[256];
289 if (pa_get_binary_name(binary, sizeof(binary)))
290 pa_log_set_ident(binary);
291 }
292
293 if (getenv(ENV_LOG_SYSLOG)) {
294 target_override = PA_LOG_SYSLOG;
295 target_override_set = true;
296 }
297
298 if ((e = getenv(ENV_LOG_LEVEL))) {
299 maximum_level_override = (pa_log_level_t) atoi(e);
300
301 if (maximum_level_override >= PA_LOG_LEVEL_MAX)
302 maximum_level_override = PA_LOG_LEVEL_MAX-1;
303 }
304
305 if (getenv(ENV_LOG_COLORS))
306 flags_override |= PA_LOG_COLORS;
307
308 if (getenv(ENV_LOG_PRINT_TIME))
309 flags_override |= PA_LOG_PRINT_TIME;
310
311 if (getenv(ENV_LOG_PRINT_FILE))
312 flags_override |= PA_LOG_PRINT_FILE;
313
314 if (getenv(ENV_LOG_PRINT_META))
315 flags_override |= PA_LOG_PRINT_META;
316
317 if (getenv(ENV_LOG_PRINT_LEVEL))
318 flags_override |= PA_LOG_PRINT_LEVEL;
319
320 if ((e = getenv(ENV_LOG_BACKTRACE))) {
321 show_backtrace_override = (unsigned) atoi(e);
322
323 if (show_backtrace_override <= 0)
324 show_backtrace_override = 0;
325 }
326
327 if ((e = getenv(ENV_LOG_BACKTRACE_SKIP))) {
328 skip_backtrace = (unsigned) atoi(e);
329
330 if (skip_backtrace <= 0)
331 skip_backtrace = 0;
332 }
333
334 if (getenv(ENV_LOG_NO_RATELIMIT))
335 no_rate_limit = true;
336
337 } PA_ONCE_END;
338 }
339
340 #ifdef HAVE_SYSLOG_H
341 static void log_syslog(pa_log_level_t level, char *t, char *timestamp, char *location, char *bt) {
342 char *local_t;
343
344 openlog(ident, LOG_PID, LOG_USER);
345
346 if ((local_t = pa_utf8_to_locale(t)))
347 t = local_t;
348
349 syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
350 pa_xfree(local_t);
351 }
352 #endif
353
354 void pa_log_levelv_meta(
355 pa_log_level_t level,
356 const char*file,
357 int line,
358 const char *func,
359 const char *format,
360 va_list ap) {
361
362 char *t, *n;
363 int saved_errno = errno;
364 char *bt = NULL;
365 pa_log_target_type_t _target;
366 pa_log_level_t _maximum_level;
367 unsigned _show_backtrace;
368 pa_log_flags_t _flags;
369
370 /* We don't use dynamic memory allocation here to minimize the hit
371 * in RT threads */
372 char text[16*1024], location[128], timestamp[32];
373
374 pa_assert(level < PA_LOG_LEVEL_MAX);
375 pa_assert(format);
376
377 init_defaults();
378
379 _target = target_override_set ? target_override : target.type;
380 _maximum_level = PA_MAX(maximum_level, maximum_level_override);
381 _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override);
382 _flags = flags | flags_override;
383
384 if (PA_LIKELY(level > _maximum_level)) {
385 errno = saved_errno;
386 return;
387 }
388
389 pa_vsnprintf(text, sizeof(text), format, ap);
390
391 if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func)
392 pa_snprintf(location, sizeof(location), "[%s][%s:%i %s()] ",
393 pa_strnull(pa_thread_get_name(pa_thread_self())), file, line, func);
394 else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file)
395 pa_snprintf(location, sizeof(location), "[%s] %s: ",
396 pa_strnull(pa_thread_get_name(pa_thread_self())), pa_path_get_filename(file));
397 else
398 location[0] = 0;
399
400 if (_flags & PA_LOG_PRINT_TIME) {
401 static pa_usec_t start, last;
402 pa_usec_t u, a, r;
403
404 u = pa_rtclock_now();
405
406 PA_ONCE_BEGIN {
407 start = u;
408 last = u;
409 } PA_ONCE_END;
410
411 r = u - last;
412 a = u - start;
413
414 /* This is not thread safe, but this is a debugging tool only
415 * anyway. */
416 last = u;
417
418 pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ",
419 (unsigned long long) (a / PA_USEC_PER_SEC),
420 (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000),
421 (unsigned long long) (r / PA_USEC_PER_SEC),
422 (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000));
423
424 } else
425 timestamp[0] = 0;
426
427 #ifdef HAVE_EXECINFO_H
428 if (_show_backtrace > 0)
429 bt = get_backtrace(_show_backtrace);
430 #endif
431
432 if (!pa_utf8_valid(text))
433 pa_logl(level, "Invalid UTF-8 string following below:");
434
435 for (t = text; t; t = n) {
436 if ((n = strchr(t, '\n'))) {
437 *n = 0;
438 n++;
439 }
440
441 /* We ignore strings only made out of whitespace */
442 if (t[strspn(t, "\t ")] == 0)
443 continue;
444
445 switch (_target) {
446
447 case PA_LOG_STDERR: {
448 const char *prefix = "", *suffix = "", *grey = "";
449 char *local_t;
450
451 #ifndef OS_IS_WIN32
452 /* Yes indeed. Useless, but fun! */
453 if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) {
454 if (level <= PA_LOG_ERROR)
455 prefix = "\x1B[1;31m";
456 else if (level <= PA_LOG_WARN)
457 prefix = "\x1B[1m";
458
459 if (bt)
460 grey = "\x1B[2m";
461
462 if (grey[0] || prefix[0])
463 suffix = "\x1B[0m";
464 }
465 #endif
466
467 /* We shouldn't be using dynamic allocation here to
468 * minimize the hit in RT threads */
469 if ((local_t = pa_utf8_to_locale(t)))
470 t = local_t;
471
472 if (_flags & PA_LOG_PRINT_LEVEL)
473 fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
474 else
475 fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
476 #ifdef OS_IS_WIN32
477 fflush(stderr);
478 #endif
479
480 pa_xfree(local_t);
481
482 break;
483 }
484
485 #ifdef HAVE_SYSLOG_H
486 case PA_LOG_SYSLOG:
487 log_syslog(level, t, timestamp, location, bt);
488 break;
489 #endif
490
491 #ifdef HAVE_JOURNAL
492 case PA_LOG_JOURNAL:
493 if (sd_journal_send("MESSAGE=%s", t,
494 "PRIORITY=%i", level_to_journal[level],
495 "CODE_FILE=%s", file,
496 "CODE_FUNC=%s", func,
497 "CODE_LINE=%d", line,
498 NULL) < 0) {
499 #ifdef HAVE_SYSLOG_H
500 pa_log_target new_target = { .type = PA_LOG_SYSLOG, .file = NULL };
501
502 syslog(level_to_syslog[PA_LOG_ERROR], "%s%s%s", timestamp, __FILE__,
503 "Error writing logs to the journal. Redirect log messages to syslog.");
504 log_syslog(level, t, timestamp, location, bt);
505 #else
506 pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
507
508 saved_errno = errno;
509 fprintf(stderr, "%s\n", "Error writing logs to the journal. Redirect log messages to console.");
510 fprintf(stderr, "%s %s\n", metadata, t);
511 #endif
512 pa_log_set_target(&new_target);
513 }
514 break;
515 #endif
516
517 case PA_LOG_FILE:
518 case PA_LOG_NEWFILE: {
519 char *local_t;
520
521 if ((local_t = pa_utf8_to_locale(t)))
522 t = local_t;
523
524 if (log_fd >= 0) {
525 char metadata[256];
526
527 if (_flags & PA_LOG_PRINT_LEVEL)
528 pa_snprintf(metadata, sizeof(metadata), "%s%c: %s", timestamp, level_to_char[level], location);
529 else
530 pa_snprintf(metadata, sizeof(metadata), "%s%s", timestamp, location);
531
532 if ((pa_write(log_fd, metadata, strlen(metadata), &write_type) < 0)
533 || (pa_write(log_fd, t, strlen(t), &write_type) < 0)
534 || (bt && pa_write(log_fd, bt, strlen(bt), &write_type) < 0)
535 || (pa_write(log_fd, "\n", 1, &write_type) < 0)) {
536 pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
537 saved_errno = errno;
538 fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console.");
539 fprintf(stderr, "%s %s\n", metadata, t);
540 pa_log_set_target(&new_target);
541 }
542 }
543
544 pa_xfree(local_t);
545
546 break;
547 }
548 case PA_LOG_NULL:
549 default:
550 break;
551 }
552 }
553
554 pa_xfree(bt);
555 errno = saved_errno;
556 }
557
558 void pa_log_level_meta(
559 pa_log_level_t level,
560 const char*file,
561 int line,
562 const char *func,
563 const char *format, ...) {
564
565 va_list ap;
566 va_start(ap, format);
567 pa_log_levelv_meta(level, file, line, func, format, ap);
568 va_end(ap);
569 }
570
571 void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) {
572 pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
573 }
574
575 void pa_log_level(pa_log_level_t level, const char *format, ...) {
576 va_list ap;
577
578 va_start(ap, format);
579 pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
580 va_end(ap);
581 }
582
583 bool pa_log_ratelimit(pa_log_level_t level) {
584 /* Not more than 10 messages every 5s */
585 static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10);
586
587 init_defaults();
588
589 if (no_rate_limit)
590 return true;
591
592 return pa_ratelimit_test(&ratelimit, level);
593 }
594
595 pa_log_target *pa_log_target_new(pa_log_target_type_t type, const char *file) {
596 pa_log_target *t = NULL;
597
598 t = pa_xnew(pa_log_target, 1);
599
600 t->type = type;
601 t->file = pa_xstrdup(file);
602
603 return t;
604 }
605
606 void pa_log_target_free(pa_log_target *t) {
607 pa_assert(t);
608
609 pa_xfree(t->file);
610 pa_xfree(t);
611 }
612
613 pa_log_target *pa_log_parse_target(const char *string) {
614 pa_log_target *t = NULL;
615
616 pa_assert(string);
617
618 if (pa_streq(string, "stderr"))
619 t = pa_log_target_new(PA_LOG_STDERR, NULL);
620 else if (pa_streq(string, "syslog"))
621 t = pa_log_target_new(PA_LOG_SYSLOG, NULL);
622 #ifdef HAVE_JOURNAL
623 else if (pa_streq(string, "journal"))
624 t = pa_log_target_new(PA_LOG_JOURNAL, NULL);
625 #endif
626 else if (pa_streq(string, "null"))
627 t = pa_log_target_new(PA_LOG_NULL, NULL);
628 else if (pa_startswith(string, "file:"))
629 t = pa_log_target_new(PA_LOG_FILE, string + 5);
630 else if (pa_startswith(string, "newfile:"))
631 t = pa_log_target_new(PA_LOG_NEWFILE, string + 8);
632 else
633 pa_log(_("Invalid log target."));
634
635 return t;
636 }
637
638 char *pa_log_target_to_string(const pa_log_target *t) {
639 char *string = NULL;
640
641 pa_assert(t);
642
643 switch (t->type) {
644 case PA_LOG_STDERR:
645 string = pa_xstrdup("stderr");
646 break;
647 case PA_LOG_SYSLOG:
648 string = pa_xstrdup("syslog");
649 break;
650 #ifdef HAVE_JOURNAL
651 case PA_LOG_JOURNAL:
652 string = pa_xstrdup("journal");
653 break;
654 #endif
655 case PA_LOG_NULL:
656 string = pa_xstrdup("null");
657 break;
658 case PA_LOG_FILE:
659 string = pa_sprintf_malloc("file:%s", t->file);
660 break;
661 case PA_LOG_NEWFILE:
662 string = pa_sprintf_malloc("newfile:%s", t->file);
663 break;
664 }
665
666 return string;
667 }