Line data Source code
1 : /*
2 : * Copyright (c) 2015-19 David Lamparter, for NetDEF, Inc.
3 : *
4 : * Permission to use, copy, modify, and distribute this software for any
5 : * purpose with or without fee is hereby granted, provided that the above
6 : * copyright notice and this permission notice appear in all copies.
7 : *
8 : * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
9 : * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
10 : * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
11 : * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
12 : * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
13 : * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
14 : * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
15 : */
16 :
17 : #include "zebra.h"
18 :
19 : #include <unistd.h>
20 : #include <sys/time.h>
21 : #include <sys/mman.h>
22 : #include <sys/types.h>
23 : #include <time.h>
24 : #include <stdlib.h>
25 : #include <stdio.h>
26 : #include <string.h>
27 : #include <stdarg.h>
28 : #include <pthread.h>
29 :
30 : /* gettid() & co. */
31 : #ifdef HAVE_PTHREAD_NP_H
32 : #include <pthread_np.h>
33 : #endif
34 : #ifdef linux
35 : #include <sys/syscall.h>
36 : #endif
37 : #ifdef __FreeBSD__
38 : #include <sys/thr.h>
39 : #endif
40 : #ifdef __NetBSD__
41 : #include <lwp.h>
42 : #endif
43 : #ifdef __DragonFly__
44 : #include <sys/lwp.h>
45 : #endif
46 : #ifdef __APPLE__
47 : #include <mach/mach_traps.h>
48 : #endif
49 :
50 : #ifdef HAVE_LIBUNWIND
51 : #define UNW_LOCAL_ONLY
52 : #include <libunwind.h>
53 : #include <dlfcn.h>
54 : #endif
55 :
56 : #include "memory.h"
57 : #include "atomlist.h"
58 : #include "printfrr.h"
59 : #include "frrcu.h"
60 : #include "zlog.h"
61 : #include "libfrr_trace.h"
62 : #include "thread.h"
63 :
64 18 : DEFINE_MTYPE_STATIC(LIB, LOG_MESSAGE, "log message");
65 18 : DEFINE_MTYPE_STATIC(LIB, LOG_TLSBUF, "log thread-local buffer");
66 :
67 18 : DEFINE_HOOK(zlog_init, (const char *progname, const char *protoname,
68 : unsigned short instance, uid_t uid, gid_t gid),
69 : (progname, protoname, instance, uid, gid));
70 12 : DEFINE_KOOH(zlog_fini, (), ());
71 0 : DEFINE_HOOK(zlog_aux_init, (const char *prefix, int prio_min),
72 : (prefix, prio_min));
73 :
74 : char zlog_prefix[128];
75 : size_t zlog_prefixsz;
76 : int zlog_tmpdirfd = -1;
77 : int zlog_instance = -1;
78 :
79 : static atomic_bool zlog_ec = true, zlog_xid = true;
80 :
81 : /* these are kept around because logging is initialized (and directories
82 : * & files created) before zprivs code switches to the FRR user; therefore
83 : * we need to chown() things so we don't get permission errors later when
84 : * trying to delete things on shutdown
85 : */
86 : static uid_t zlog_uid = -1;
87 : static gid_t zlog_gid = -1;
88 :
89 468 : DECLARE_ATOMLIST(zlog_targets, struct zlog_target, head);
90 : static struct zlog_targets_head zlog_targets;
91 :
92 : /* Global setting for buffered vs immediate output. The default is
93 : * per-pthread buffering.
94 : */
95 : static bool default_immediate;
96 :
97 : /* cf. zlog.h for additional comments on this struct.
98 : *
99 : * Note: you MUST NOT pass the format string + va_list to non-FRR format
100 : * string functions (e.g. vsyslog, sd_journal_printv, ...) since FRR uses an
101 : * extended prinf() with additional formats (%pI4 and the like).
102 : *
103 : * Also remember to use va_copy() on args.
104 : */
105 :
106 : struct zlog_msg {
107 : struct timespec ts;
108 : int prio;
109 :
110 : const char *fmt;
111 : va_list args;
112 : const struct xref_logmsg *xref;
113 :
114 : char *stackbuf;
115 : size_t stackbufsz;
116 : char *text;
117 : size_t textlen;
118 : size_t hdrlen;
119 :
120 : /* This is always ISO8601 with sub-second precision 9 here, it's
121 : * converted for callers as needed. ts_dot points to the "."
122 : * separating sub-seconds. ts_zonetail is "Z" or "+00:00" for the
123 : * local time offset.
124 : *
125 : * Valid if ZLOG_TS_ISO8601 is set.
126 : * (0 if timestamp has not been formatted yet)
127 : */
128 : char ts_str[32], *ts_dot, ts_zonetail[8];
129 : uint32_t ts_flags;
130 :
131 : /* "mmm dd hh:mm:ss" for 3164 legacy syslog - too dissimilar from
132 : * the above, so just kept separately here.
133 : */
134 : uint32_t ts_3164_flags;
135 : char ts_3164_str[16];
136 :
137 : /* at the time of writing, 16 args was the actual maximum of arguments
138 : * to a single zlog call. Particularly printing flag bitmasks seems
139 : * to drive this. That said, the overhead of dynamically sizing this
140 : * probably outweighs the value. If anything, a printfrr extension
141 : * for printing flag bitmasks might be a good idea.
142 : */
143 : struct fmt_outpos argpos[24];
144 : size_t n_argpos;
145 : };
146 :
147 : /* thread-local log message buffering
148 : *
149 : * This is strictly optional and set up by calling zlog_tls_buffer_init()
150 : * on a particular thread.
151 : *
152 : * If in use, this will create a temporary file in /var/tmp which is used as
153 : * memory-mapped MAP_SHARED log message buffer. The idea there is that buffer
154 : * access doesn't require any syscalls, but in case of a crash the kernel
155 : * knows to sync the memory back to disk. This way the user can still get the
156 : * last log messages if there were any left unwritten in the buffer.
157 : *
158 : * Sizing this dynamically isn't particularly useful, so here's an 8k buffer
159 : * with a message limit of 64 messages. Message metadata (e.g. priority,
160 : * timestamp) aren't in the mmap region, so they're lost on crash, but we can
161 : * live with that.
162 : */
163 :
164 : #if defined(HAVE_OPENAT) && defined(HAVE_UNLINKAT)
165 : #define CAN_DO_TLS 1
166 : #endif
167 :
168 : #define TLS_LOG_BUF_SIZE 8192
169 : #define TLS_LOG_MAXMSG 64
170 :
171 : struct zlog_tls {
172 : char *mmbuf;
173 : size_t bufpos;
174 : bool do_unlink;
175 :
176 : size_t nmsgs;
177 : struct zlog_msg msgs[TLS_LOG_MAXMSG];
178 : struct zlog_msg *msgp[TLS_LOG_MAXMSG];
179 : };
180 :
181 : static inline void zlog_tls_free(void *arg);
182 :
183 : /* proper ELF TLS is a bit faster than pthread_[gs]etspecific, so if it's
184 : * available we'll use it here
185 : */
186 :
187 : #ifdef __OpenBSD__
188 : static pthread_key_t zlog_tls_key;
189 :
190 : static void zlog_tls_key_init(void) __attribute__((_CONSTRUCTOR(500)));
191 : static void zlog_tls_key_init(void)
192 : {
193 : pthread_key_create(&zlog_tls_key, zlog_tls_free);
194 : }
195 :
196 : static void zlog_tls_key_fini(void) __attribute__((_DESTRUCTOR(500)));
197 : static void zlog_tls_key_fini(void)
198 : {
199 : pthread_key_delete(zlog_tls_key);
200 : }
201 :
202 : static inline struct zlog_tls *zlog_tls_get(void)
203 : {
204 : return pthread_getspecific(zlog_tls_key);
205 : }
206 :
207 : static inline void zlog_tls_set(struct zlog_tls *val)
208 : {
209 : pthread_setspecific(zlog_tls_key, val);
210 : }
211 : #else
212 : # ifndef thread_local
213 : # define thread_local __thread
214 : # endif
215 :
216 : static thread_local struct zlog_tls *zlog_tls_var
217 : __attribute__((tls_model("initial-exec")));
218 :
219 13292 : static inline struct zlog_tls *zlog_tls_get(void)
220 : {
221 13292 : return zlog_tls_var;
222 : }
223 :
224 42 : static inline void zlog_tls_set(struct zlog_tls *val)
225 : {
226 42 : zlog_tls_var = val;
227 21 : }
228 : #endif
229 :
230 : #ifdef CAN_DO_TLS
231 204 : static intmax_t zlog_gettid(void)
232 : {
233 : #ifndef __OpenBSD__
234 : /* accessing a TLS variable is much faster than a syscall */
235 204 : static thread_local intmax_t cached_tid = -1;
236 204 : if (cached_tid != -1)
237 : return cached_tid;
238 : #endif
239 :
240 21 : long rv = -1;
241 : #ifdef HAVE_PTHREAD_GETTHREADID_NP
242 : rv = pthread_getthreadid_np();
243 : #elif defined(linux)
244 21 : rv = syscall(__NR_gettid);
245 : #elif defined(__NetBSD__)
246 : rv = _lwp_self();
247 : #elif defined(__FreeBSD__)
248 : thr_self(&rv);
249 : #elif defined(__DragonFly__)
250 : rv = lwp_gettid();
251 : #elif defined(__OpenBSD__)
252 : rv = getthrid();
253 : #elif defined(__sun)
254 : rv = pthread_self();
255 : #elif defined(__APPLE__)
256 : rv = mach_thread_self();
257 : mach_port_deallocate(mach_task_self(), rv);
258 : #endif
259 :
260 : #ifndef __OpenBSD__
261 21 : cached_tid = rv;
262 : #endif
263 21 : return rv;
264 : }
265 :
266 21 : void zlog_tls_buffer_init(void)
267 : {
268 21 : struct zlog_tls *zlog_tls;
269 21 : char mmpath[MAXPATHLEN];
270 21 : int mmfd;
271 21 : size_t i;
272 :
273 21 : zlog_tls = zlog_tls_get();
274 :
275 21 : if (zlog_tls || zlog_tmpdirfd < 0)
276 21 : return;
277 :
278 21 : zlog_tls = XCALLOC(MTYPE_LOG_TLSBUF, sizeof(*zlog_tls));
279 1386 : for (i = 0; i < array_size(zlog_tls->msgp); i++)
280 1344 : zlog_tls->msgp[i] = &zlog_tls->msgs[i];
281 :
282 21 : snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid());
283 :
284 21 : mmfd = openat(zlog_tmpdirfd, mmpath,
285 : O_RDWR | O_CREAT | O_EXCL | O_CLOEXEC, 0600);
286 21 : if (mmfd < 0) {
287 0 : zlog_err("failed to open thread log buffer \"%s\": %s",
288 : mmpath, strerror(errno));
289 0 : goto out_anon;
290 : }
291 21 : fchown(mmfd, zlog_uid, zlog_gid);
292 :
293 : #ifdef HAVE_POSIX_FALLOCATE
294 21 : if (posix_fallocate(mmfd, 0, TLS_LOG_BUF_SIZE) != 0)
295 : /* note next statement is under above if() */
296 : #endif
297 0 : if (ftruncate(mmfd, TLS_LOG_BUF_SIZE) < 0) {
298 0 : zlog_err("failed to allocate thread log buffer \"%s\": %s",
299 : mmpath, strerror(errno));
300 0 : goto out_anon_unlink;
301 : }
302 :
303 21 : zlog_tls->mmbuf = mmap(NULL, TLS_LOG_BUF_SIZE, PROT_READ | PROT_WRITE,
304 : MAP_SHARED, mmfd, 0);
305 21 : if (zlog_tls->mmbuf == MAP_FAILED) {
306 0 : zlog_err("failed to mmap thread log buffer \"%s\": %s",
307 : mmpath, strerror(errno));
308 0 : goto out_anon_unlink;
309 : }
310 21 : zlog_tls->do_unlink = true;
311 :
312 21 : close(mmfd);
313 21 : zlog_tls_set(zlog_tls);
314 : return;
315 :
316 0 : out_anon_unlink:
317 0 : unlinkat(zlog_tmpdirfd, mmpath, 0);
318 0 : close(mmfd);
319 0 : out_anon:
320 :
321 : #ifndef MAP_ANONYMOUS
322 : #define MAP_ANONYMOUS MAP_ANON
323 : #endif
324 0 : zlog_tls->mmbuf = mmap(NULL, TLS_LOG_BUF_SIZE, PROT_READ | PROT_WRITE,
325 : MAP_ANONYMOUS | MAP_PRIVATE, -1, 0);
326 :
327 0 : if (!zlog_tls->mmbuf) {
328 0 : zlog_err("failed to anonymous-mmap thread log buffer: %s",
329 : strerror(errno));
330 0 : XFREE(MTYPE_LOG_TLSBUF, zlog_tls);
331 0 : zlog_tls_set(NULL);
332 0 : return;
333 : }
334 :
335 0 : zlog_tls_set(zlog_tls);
336 : }
337 :
338 21 : void zlog_tls_buffer_fini(void)
339 : {
340 21 : char mmpath[MAXPATHLEN];
341 21 : struct zlog_tls *zlog_tls = zlog_tls_get();
342 21 : bool do_unlink = zlog_tls ? zlog_tls->do_unlink : false;
343 :
344 21 : zlog_tls_buffer_flush();
345 :
346 21 : zlog_tls_free(zlog_tls);
347 21 : zlog_tls_set(NULL);
348 :
349 21 : snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid());
350 21 : if (do_unlink && unlinkat(zlog_tmpdirfd, mmpath, 0))
351 0 : zlog_err("unlink logbuf: %s (%d)", strerror(errno), errno);
352 21 : }
353 :
354 : #else /* !CAN_DO_TLS */
355 : void zlog_tls_buffer_init(void)
356 : {
357 : }
358 :
359 : void zlog_tls_buffer_fini(void)
360 : {
361 : }
362 : #endif
363 :
364 162 : void zlog_msg_pid(struct zlog_msg *msg, intmax_t *pid, intmax_t *tid)
365 : {
366 : #ifndef __OpenBSD__
367 162 : static thread_local intmax_t cached_pid = -1;
368 162 : if (cached_pid != -1)
369 147 : *pid = cached_pid;
370 : else
371 15 : cached_pid = *pid = (intmax_t)getpid();
372 : #else
373 : *pid = (intmax_t)getpid();
374 : #endif
375 : #ifdef CAN_DO_TLS
376 162 : *tid = zlog_gettid();
377 : #else
378 : *tid = *pid;
379 : #endif
380 162 : }
381 :
382 21 : static inline void zlog_tls_free(void *arg)
383 : {
384 21 : struct zlog_tls *zlog_tls = arg;
385 :
386 21 : if (!zlog_tls)
387 : return;
388 :
389 21 : munmap(zlog_tls->mmbuf, TLS_LOG_BUF_SIZE);
390 21 : XFREE(MTYPE_LOG_TLSBUF, zlog_tls);
391 : }
392 :
393 13088 : void zlog_tls_buffer_flush(void)
394 : {
395 13088 : struct zlog_target *zt;
396 13088 : struct zlog_tls *zlog_tls = zlog_tls_get();
397 :
398 13088 : if (!zlog_tls)
399 : return;
400 13088 : if (!zlog_tls->nmsgs)
401 : return;
402 :
403 75 : rcu_read_lock();
404 600 : frr_each_safe (zlog_targets, &zlog_targets, zt) {
405 225 : if (!zt->logfn)
406 0 : continue;
407 :
408 225 : zt->logfn(zt, zlog_tls->msgp, zlog_tls->nmsgs);
409 : }
410 75 : rcu_read_unlock();
411 :
412 75 : zlog_tls->bufpos = 0;
413 75 : zlog_tls->nmsgs = 0;
414 : }
415 :
416 :
417 81 : static void vzlog_notls(const struct xref_logmsg *xref, int prio,
418 : const char *fmt, va_list ap)
419 : {
420 81 : struct zlog_target *zt;
421 81 : struct zlog_msg stackmsg = {
422 81 : .prio = prio & LOG_PRIMASK,
423 : .fmt = fmt,
424 : .xref = xref,
425 81 : }, *msg = &stackmsg;
426 81 : char stackbuf[512];
427 :
428 81 : clock_gettime(CLOCK_REALTIME, &msg->ts);
429 81 : va_copy(msg->args, ap);
430 81 : msg->stackbuf = stackbuf;
431 81 : msg->stackbufsz = sizeof(stackbuf);
432 :
433 81 : rcu_read_lock();
434 648 : frr_each_safe (zlog_targets, &zlog_targets, zt) {
435 243 : if (prio > zt->prio_min)
436 78 : continue;
437 165 : if (!zt->logfn)
438 0 : continue;
439 :
440 165 : zt->logfn(zt, &msg, 1);
441 : }
442 81 : rcu_read_unlock();
443 :
444 81 : va_end(msg->args);
445 81 : if (msg->text && msg->text != stackbuf)
446 0 : XFREE(MTYPE_LOG_MESSAGE, msg->text);
447 81 : }
448 :
449 81 : static void vzlog_tls(struct zlog_tls *zlog_tls, const struct xref_logmsg *xref,
450 : int prio, const char *fmt, va_list ap)
451 : {
452 81 : struct zlog_target *zt;
453 81 : struct zlog_msg *msg;
454 81 : char *buf;
455 81 : bool ignoremsg = true;
456 81 : bool immediate = default_immediate;
457 :
458 : /* avoid further processing cost if no target wants this message */
459 81 : rcu_read_lock();
460 87 : frr_each (zlog_targets, &zlog_targets, zt) {
461 87 : if (prio > zt->prio_min)
462 6 : continue;
463 : ignoremsg = false;
464 : break;
465 : }
466 81 : rcu_read_unlock();
467 :
468 81 : if (ignoremsg)
469 : return;
470 :
471 81 : msg = &zlog_tls->msgs[zlog_tls->nmsgs];
472 81 : zlog_tls->nmsgs++;
473 81 : if (zlog_tls->nmsgs == array_size(zlog_tls->msgs))
474 0 : immediate = true;
475 :
476 81 : memset(msg, 0, sizeof(*msg));
477 81 : clock_gettime(CLOCK_REALTIME, &msg->ts);
478 81 : va_copy(msg->args, ap);
479 81 : msg->stackbuf = buf = zlog_tls->mmbuf + zlog_tls->bufpos;
480 81 : msg->stackbufsz = TLS_LOG_BUF_SIZE - zlog_tls->bufpos - 1;
481 81 : msg->fmt = fmt;
482 81 : msg->prio = prio & LOG_PRIMASK;
483 81 : msg->xref = xref;
484 81 : if (msg->prio < LOG_INFO)
485 : immediate = true;
486 :
487 13 : if (!immediate) {
488 : /* messages written later need to take the formatting cost
489 : * immediately since we can't hold a reference on varargs
490 : */
491 13 : zlog_msg_text(msg, NULL);
492 :
493 13 : if (msg->text != buf)
494 : /* zlog_msg_text called malloc() on us :( */
495 : immediate = true;
496 : else {
497 13 : zlog_tls->bufpos += msg->textlen + 1;
498 : /* write a second \0 to mark current end position
499 : * (in case of crash this signals end of unwritten log
500 : * messages in mmap'd logbuf file)
501 : */
502 13 : zlog_tls->mmbuf[zlog_tls->bufpos] = '\0';
503 :
504 : /* avoid malloc() for next message */
505 13 : if (TLS_LOG_BUF_SIZE - zlog_tls->bufpos < 256)
506 : immediate = true;
507 : }
508 : }
509 :
510 81 : if (immediate)
511 68 : zlog_tls_buffer_flush();
512 :
513 81 : va_end(msg->args);
514 81 : if (msg->text && msg->text != buf)
515 0 : XFREE(MTYPE_LOG_MESSAGE, msg->text);
516 : }
517 :
518 0 : static void zlog_backtrace_msg(const struct xref_logmsg *xref, int prio)
519 : {
520 0 : struct thread *tc = pthread_getspecific(thread_current);
521 0 : const char *uid = xref->xref.xrefdata->uid;
522 0 : bool found_thread = false;
523 :
524 0 : zlog(prio, "| (%s) message in thread %jd, at %s(), %s:%d", uid,
525 0 : zlog_gettid(), xref->xref.func, xref->xref.file, xref->xref.line);
526 :
527 : #ifdef HAVE_LIBUNWIND
528 0 : const char *threadfunc = tc ? tc->xref->funcname : NULL;
529 0 : bool found_caller = false;
530 0 : unw_cursor_t cursor;
531 0 : unw_context_t uc;
532 0 : unw_word_t ip, off, sp;
533 0 : Dl_info dlinfo;
534 :
535 0 : unw_getcontext(&uc);
536 :
537 0 : unw_init_local(&cursor, &uc);
538 0 : while (unw_step(&cursor) > 0) {
539 0 : char buf[96], name[128] = "?";
540 0 : bool is_thread = false;
541 :
542 0 : unw_get_reg(&cursor, UNW_REG_IP, &ip);
543 0 : unw_get_reg(&cursor, UNW_REG_SP, &sp);
544 :
545 0 : if (unw_is_signal_frame(&cursor))
546 0 : zlog(prio, "| (%s) ---- signal ----", uid);
547 :
548 0 : if (!unw_get_proc_name(&cursor, buf, sizeof(buf), &off)) {
549 0 : if (!strcmp(buf, xref->xref.func))
550 0 : found_caller = true;
551 0 : if (threadfunc && !strcmp(buf, threadfunc))
552 0 : found_thread = is_thread = true;
553 :
554 0 : snprintf(name, sizeof(name), "%s+%#lx", buf, (long)off);
555 : }
556 :
557 0 : if (!found_caller)
558 0 : continue;
559 :
560 0 : if (dladdr((void *)ip, &dlinfo))
561 0 : zlog(prio, "| (%s) %-36s %16lx+%08lx %16lx %s", uid,
562 : name, (long)dlinfo.dli_fbase,
563 0 : (long)ip - (long)dlinfo.dli_fbase, (long)sp,
564 : dlinfo.dli_fname);
565 : else
566 0 : zlog(prio, "| (%s) %-36s %16lx %16lx", uid, name,
567 : (long)ip, (long)sp);
568 :
569 0 : if (is_thread)
570 0 : zlog(prio, "| (%s) ^- scheduled from %s(), %s:%u", uid,
571 0 : tc->xref->xref.func, tc->xref->xref.file,
572 0 : tc->xref->xref.line);
573 : }
574 : #elif defined(HAVE_GLIBC_BACKTRACE)
575 : void *frames[64];
576 : char **names = NULL;
577 : int n_frames, i;
578 :
579 : n_frames = backtrace(frames, array_size(frames));
580 : if (n_frames < 0)
581 : n_frames = 0;
582 : if (n_frames)
583 : names = backtrace_symbols(frames, n_frames);
584 :
585 : for (i = 0; i < n_frames; i++) {
586 : void *retaddr = frames[i];
587 : char *loc = names[i];
588 :
589 : zlog(prio, "| (%s) %16lx %-36s", uid, (long)retaddr, loc);
590 : }
591 : free(names);
592 : #endif
593 0 : if (!found_thread && tc)
594 0 : zlog(prio, "| (%s) scheduled from %s(), %s:%u", uid,
595 0 : tc->xref->xref.func, tc->xref->xref.file,
596 0 : tc->xref->xref.line);
597 0 : }
598 :
599 162 : void vzlogx(const struct xref_logmsg *xref, int prio,
600 : const char *fmt, va_list ap)
601 : {
602 162 : struct zlog_tls *zlog_tls = zlog_tls_get();
603 :
604 : #ifdef HAVE_LTTNG
605 : va_list copy;
606 : va_copy(copy, ap);
607 : char *msg = vasprintfrr(MTYPE_LOG_MESSAGE, fmt, copy);
608 :
609 : switch (prio) {
610 : case LOG_ERR:
611 : frrtracelog(TRACE_ERR, msg);
612 : break;
613 : case LOG_WARNING:
614 : frrtracelog(TRACE_WARNING, msg);
615 : break;
616 : case LOG_DEBUG:
617 : frrtracelog(TRACE_DEBUG, msg);
618 : break;
619 : case LOG_NOTICE:
620 : frrtracelog(TRACE_DEBUG, msg);
621 : break;
622 : case LOG_INFO:
623 : default:
624 : frrtracelog(TRACE_INFO, msg);
625 : break;
626 : }
627 :
628 : va_end(copy);
629 : XFREE(MTYPE_LOG_MESSAGE, msg);
630 : #endif
631 :
632 162 : if (zlog_tls)
633 81 : vzlog_tls(zlog_tls, xref, prio, fmt, ap);
634 : else
635 81 : vzlog_notls(xref, prio, fmt, ap);
636 :
637 162 : if (xref) {
638 162 : struct xrefdata_logmsg *xrdl;
639 :
640 162 : xrdl = container_of(xref->xref.xrefdata, struct xrefdata_logmsg,
641 : xrefdata);
642 162 : if (xrdl->fl_print_bt)
643 0 : zlog_backtrace_msg(xref, prio);
644 : }
645 162 : }
646 :
647 0 : void zlog_sigsafe(const char *text, size_t len)
648 : {
649 0 : struct zlog_target *zt;
650 0 : const char *end = text + len, *nlpos;
651 :
652 0 : while (text < end) {
653 0 : nlpos = memchr(text, '\n', end - text);
654 0 : if (!nlpos)
655 0 : nlpos = end;
656 :
657 0 : frr_each (zlog_targets, &zlog_targets, zt) {
658 0 : if (LOG_CRIT > zt->prio_min)
659 0 : continue;
660 0 : if (!zt->logfn_sigsafe)
661 0 : continue;
662 :
663 0 : zt->logfn_sigsafe(zt, text, nlpos - text);
664 : }
665 :
666 0 : if (nlpos == end)
667 : break;
668 0 : text = nlpos + 1;
669 : }
670 0 : }
671 :
672 0 : void _zlog_assert_failed(const struct xref_assert *xref, const char *extra, ...)
673 : {
674 0 : va_list ap;
675 0 : static bool assert_in_assert; /* "global-ish" variable, init to 0 */
676 :
677 0 : if (assert_in_assert)
678 0 : abort();
679 0 : assert_in_assert = true;
680 :
681 0 : if (extra) {
682 0 : struct va_format vaf;
683 :
684 0 : va_start(ap, extra);
685 0 : vaf.fmt = extra;
686 0 : vaf.va = ≈
687 :
688 0 : zlog(LOG_CRIT,
689 : "%s:%d: %s(): assertion (%s) failed, extra info: %pVA",
690 0 : xref->xref.file, xref->xref.line, xref->xref.func,
691 0 : xref->expr, &vaf);
692 :
693 0 : va_end(ap);
694 : } else
695 0 : zlog(LOG_CRIT, "%s:%d: %s(): assertion (%s) failed",
696 0 : xref->xref.file, xref->xref.line, xref->xref.func,
697 0 : xref->expr);
698 :
699 : /* abort() prints backtrace & memstats in SIGABRT handler */
700 0 : abort();
701 : }
702 :
703 408 : int zlog_msg_prio(struct zlog_msg *msg)
704 : {
705 408 : return msg->prio;
706 : }
707 :
708 162 : const struct xref_logmsg *zlog_msg_xref(struct zlog_msg *msg)
709 : {
710 162 : return msg->xref;
711 : }
712 :
713 450 : const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen)
714 : {
715 450 : if (!msg->text) {
716 162 : va_list args;
717 162 : bool do_xid, do_ec;
718 162 : size_t need = 0, hdrlen;
719 162 : struct fbuf fb = {
720 162 : .buf = msg->stackbuf,
721 : .pos = msg->stackbuf,
722 162 : .len = msg->stackbufsz,
723 : };
724 :
725 162 : do_ec = atomic_load_explicit(&zlog_ec, memory_order_relaxed);
726 162 : do_xid = atomic_load_explicit(&zlog_xid, memory_order_relaxed);
727 :
728 162 : if (msg->xref && do_xid && msg->xref->xref.xrefdata->uid[0]) {
729 162 : need += bputch(&fb, '[');
730 162 : need += bputs(&fb, msg->xref->xref.xrefdata->uid);
731 324 : need += bputch(&fb, ']');
732 : }
733 162 : if (msg->xref && do_ec && msg->xref->ec)
734 31 : need += bprintfrr(&fb, "[EC %u]", msg->xref->ec);
735 162 : if (need)
736 324 : need += bputch(&fb, ' ');
737 :
738 162 : msg->hdrlen = hdrlen = need;
739 162 : assert(hdrlen < msg->stackbufsz);
740 :
741 162 : fb.outpos = msg->argpos;
742 162 : fb.outpos_n = array_size(msg->argpos);
743 162 : fb.outpos_i = 0;
744 :
745 162 : va_copy(args, msg->args);
746 : #pragma GCC diagnostic push
747 : #pragma GCC diagnostic ignored "-Wformat-nonliteral"
748 : /* format-string checking is done further up the chain */
749 162 : need += vbprintfrr(&fb, msg->fmt, args);
750 : #pragma GCC diagnostic pop
751 162 : va_end(args);
752 :
753 162 : msg->textlen = need;
754 162 : need += bputch(&fb, '\n');
755 :
756 162 : if (need <= msg->stackbufsz)
757 162 : msg->text = msg->stackbuf;
758 : else {
759 0 : msg->text = XMALLOC(MTYPE_LOG_MESSAGE, need);
760 :
761 0 : memcpy(msg->text, msg->stackbuf, hdrlen);
762 :
763 0 : fb.buf = msg->text;
764 0 : fb.len = need;
765 0 : fb.pos = msg->text + hdrlen;
766 0 : fb.outpos_i = 0;
767 :
768 0 : va_copy(args, msg->args);
769 : #pragma GCC diagnostic push
770 : #pragma GCC diagnostic ignored "-Wformat-nonliteral"
771 : /* same as above */
772 0 : vbprintfrr(&fb, msg->fmt, args);
773 : #pragma GCC diagnostic pop
774 0 : va_end(args);
775 :
776 0 : bputch(&fb, '\n');
777 : }
778 :
779 162 : msg->n_argpos = fb.outpos_i;
780 : }
781 450 : if (textlen)
782 327 : *textlen = msg->textlen;
783 450 : return msg->text;
784 : }
785 :
786 162 : void zlog_msg_args(struct zlog_msg *msg, size_t *hdrlen, size_t *n_argpos,
787 : const struct fmt_outpos **argpos)
788 : {
789 162 : if (!msg->text)
790 110 : zlog_msg_text(msg, NULL);
791 :
792 162 : if (hdrlen)
793 162 : *hdrlen = msg->hdrlen;
794 162 : if (n_argpos)
795 162 : *n_argpos = msg->n_argpos;
796 162 : if (argpos)
797 162 : *argpos = msg->argpos;
798 162 : }
799 :
800 : #define ZLOG_TS_FORMAT (ZLOG_TS_ISO8601 | ZLOG_TS_LEGACY)
801 : #define ZLOG_TS_FLAGS ~ZLOG_TS_PREC
802 :
803 165 : size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags)
804 : {
805 165 : size_t outsz = out ? (out->buf + out->len - out->pos) : 0;
806 165 : size_t len1;
807 :
808 165 : if (!(flags & ZLOG_TS_FORMAT))
809 : return 0;
810 :
811 165 : if (!(msg->ts_flags & ZLOG_TS_FORMAT) ||
812 3 : ((msg->ts_flags ^ flags) & ZLOG_TS_UTC)) {
813 162 : struct tm tm;
814 :
815 162 : if (flags & ZLOG_TS_UTC)
816 0 : gmtime_r(&msg->ts.tv_sec, &tm);
817 : else
818 162 : localtime_r(&msg->ts.tv_sec, &tm);
819 :
820 162 : strftime(msg->ts_str, sizeof(msg->ts_str),
821 : "%Y-%m-%dT%H:%M:%S", &tm);
822 :
823 162 : if (flags & ZLOG_TS_UTC) {
824 0 : msg->ts_zonetail[0] = 'Z';
825 0 : msg->ts_zonetail[1] = '\0';
826 : } else
827 162 : snprintfrr(msg->ts_zonetail, sizeof(msg->ts_zonetail),
828 : "%+03d:%02d",
829 162 : (int)(tm.tm_gmtoff / 3600),
830 162 : (int)(labs(tm.tm_gmtoff) / 60) % 60);
831 :
832 162 : msg->ts_dot = msg->ts_str + strlen(msg->ts_str);
833 162 : snprintfrr(msg->ts_dot,
834 162 : msg->ts_str + sizeof(msg->ts_str) - msg->ts_dot,
835 162 : ".%09lu", (unsigned long)msg->ts.tv_nsec);
836 :
837 162 : msg->ts_flags = ZLOG_TS_ISO8601 | (flags & ZLOG_TS_UTC);
838 : }
839 :
840 165 : len1 = flags & ZLOG_TS_PREC;
841 165 : len1 = (msg->ts_dot - msg->ts_str) + (len1 ? len1 + 1 : 0);
842 :
843 165 : if (len1 > strlen(msg->ts_str))
844 : len1 = strlen(msg->ts_str);
845 :
846 165 : if (flags & ZLOG_TS_LEGACY) {
847 165 : if (!out)
848 : return len1;
849 :
850 165 : if (len1 > outsz) {
851 0 : memset(out->pos, 0, outsz);
852 0 : out->pos += outsz;
853 0 : return len1;
854 : }
855 :
856 : /* just swap out the formatting, faster than redoing it */
857 3867 : for (char *p = msg->ts_str; p < msg->ts_str + len1; p++) {
858 3702 : switch (*p) {
859 330 : case '-':
860 330 : *out->pos++ = '/';
861 330 : break;
862 165 : case 'T':
863 165 : *out->pos++ = ' ';
864 165 : break;
865 3207 : default:
866 3207 : *out->pos++ = *p;
867 : }
868 : }
869 : return len1;
870 : } else {
871 0 : size_t len2 = strlen(msg->ts_zonetail);
872 :
873 0 : if (!out)
874 0 : return len1 + len2;
875 :
876 0 : if (len1 + len2 > outsz) {
877 0 : memset(out->pos, 0, outsz);
878 0 : out->pos += outsz;
879 0 : return len1 + len2;
880 : }
881 :
882 0 : memcpy(out->pos, msg->ts_str, len1);
883 0 : out->pos += len1;
884 0 : memcpy(out->pos, msg->ts_zonetail, len2);
885 0 : out->pos += len2;
886 0 : return len1 + len2;
887 : }
888 : }
889 :
890 0 : size_t zlog_msg_ts_3164(struct zlog_msg *msg, struct fbuf *out, uint32_t flags)
891 : {
892 0 : flags &= ZLOG_TS_UTC;
893 :
894 0 : if (!msg->ts_3164_str[0] || flags != msg->ts_3164_flags) {
895 : /* these are "hardcoded" in RFC3164, so they're here too... */
896 0 : static const char *const months[12] = {
897 : "Jan", "Feb", "Mar", "Apr", "May", "Jun",
898 : "Jul", "Aug", "Sep", "Oct", "Nov", "Dec",
899 : };
900 0 : struct tm tm;
901 :
902 : /* RFC3164 explicitly asks for local time, but common usage
903 : * also includes UTC.
904 : */
905 0 : if (flags & ZLOG_TS_UTC)
906 0 : gmtime_r(&msg->ts.tv_sec, &tm);
907 : else
908 0 : localtime_r(&msg->ts.tv_sec, &tm);
909 :
910 0 : snprintfrr(msg->ts_3164_str, sizeof(msg->ts_3164_str),
911 0 : "%3s %2d %02d:%02d:%02d", months[tm.tm_mon],
912 : tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec);
913 :
914 0 : msg->ts_3164_flags = flags;
915 : }
916 0 : return bputs(out, msg->ts_3164_str);
917 : }
918 :
919 162 : void zlog_msg_tsraw(struct zlog_msg *msg, struct timespec *ts)
920 : {
921 162 : memcpy(ts, &msg->ts, sizeof(*ts));
922 162 : }
923 :
924 6 : void zlog_set_prefix_ec(bool enable)
925 : {
926 6 : atomic_store_explicit(&zlog_ec, enable, memory_order_relaxed);
927 6 : }
928 :
929 0 : bool zlog_get_prefix_ec(void)
930 : {
931 0 : return atomic_load_explicit(&zlog_ec, memory_order_relaxed);
932 : }
933 :
934 6 : void zlog_set_prefix_xid(bool enable)
935 : {
936 6 : atomic_store_explicit(&zlog_xid, enable, memory_order_relaxed);
937 6 : }
938 :
939 0 : bool zlog_get_prefix_xid(void)
940 : {
941 0 : return atomic_load_explicit(&zlog_xid, memory_order_relaxed);
942 : }
943 :
944 : /* setup functions */
945 :
946 18 : struct zlog_target *zlog_target_clone(struct memtype *mt,
947 : struct zlog_target *oldzt, size_t size)
948 : {
949 18 : struct zlog_target *newzt;
950 :
951 18 : newzt = XCALLOC(mt, size);
952 18 : if (oldzt) {
953 0 : newzt->prio_min = oldzt->prio_min;
954 0 : newzt->logfn = oldzt->logfn;
955 0 : newzt->logfn_sigsafe = oldzt->logfn_sigsafe;
956 : }
957 :
958 18 : return newzt;
959 : }
960 :
961 72 : struct zlog_target *zlog_target_replace(struct zlog_target *oldzt,
962 : struct zlog_target *newzt)
963 : {
964 72 : if (newzt)
965 30 : zlog_targets_add_tail(&zlog_targets, newzt);
966 72 : if (oldzt)
967 12 : zlog_targets_del(&zlog_targets, oldzt);
968 72 : return oldzt;
969 : }
970 :
971 : /*
972 : * Enable or disable 'immediate' output - default is to buffer
973 : * each pthread's messages.
974 : */
975 0 : void zlog_set_immediate(bool set_p)
976 : {
977 0 : default_immediate = set_p;
978 0 : }
979 :
980 : /* common init */
981 :
982 : #define TMPBASEDIR "/var/tmp/frr"
983 :
984 : static char zlog_tmpdir[MAXPATHLEN];
985 :
986 0 : void zlog_aux_init(const char *prefix, int prio_min)
987 : {
988 0 : if (prefix)
989 0 : strlcpy(zlog_prefix, prefix, sizeof(zlog_prefix));
990 :
991 0 : hook_call(zlog_aux_init, prefix, prio_min);
992 0 : }
993 :
994 6 : void zlog_init(const char *progname, const char *protoname,
995 : unsigned short instance, uid_t uid, gid_t gid)
996 : {
997 6 : zlog_uid = uid;
998 6 : zlog_gid = gid;
999 6 : zlog_instance = instance;
1000 :
1001 6 : if (instance) {
1002 0 : snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s-%d.%ld",
1003 0 : TMPBASEDIR, progname, instance, (long)getpid());
1004 :
1005 0 : zlog_prefixsz = snprintfrr(zlog_prefix, sizeof(zlog_prefix),
1006 : "%s[%d]: ", protoname, instance);
1007 : } else {
1008 6 : snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s.%ld",
1009 6 : TMPBASEDIR, progname, (long)getpid());
1010 :
1011 6 : zlog_prefixsz = snprintfrr(zlog_prefix, sizeof(zlog_prefix),
1012 : "%s: ", protoname);
1013 : }
1014 :
1015 6 : if (mkdir(TMPBASEDIR, 0700) != 0) {
1016 6 : if (errno != EEXIST) {
1017 0 : zlog_err("failed to mkdir \"%s\": %s",
1018 : TMPBASEDIR, strerror(errno));
1019 0 : goto out_warn;
1020 : }
1021 : }
1022 6 : chown(TMPBASEDIR, zlog_uid, zlog_gid);
1023 :
1024 6 : if (mkdir(zlog_tmpdir, 0700) != 0) {
1025 0 : zlog_err("failed to mkdir \"%s\": %s",
1026 : zlog_tmpdir, strerror(errno));
1027 0 : goto out_warn;
1028 : }
1029 :
1030 : #ifdef O_PATH
1031 6 : zlog_tmpdirfd = open(zlog_tmpdir,
1032 : O_PATH | O_RDONLY | O_CLOEXEC);
1033 : #else
1034 : zlog_tmpdirfd = open(zlog_tmpdir,
1035 : O_DIRECTORY | O_RDONLY | O_CLOEXEC);
1036 : #endif
1037 6 : if (zlog_tmpdirfd < 0) {
1038 0 : zlog_err("failed to open \"%s\": %s",
1039 : zlog_tmpdir, strerror(errno));
1040 0 : goto out_warn;
1041 : }
1042 :
1043 : #ifdef AT_EMPTY_PATH
1044 6 : fchownat(zlog_tmpdirfd, "", zlog_uid, zlog_gid, AT_EMPTY_PATH);
1045 : #else
1046 : chown(zlog_tmpdir, zlog_uid, zlog_gid);
1047 : #endif
1048 :
1049 6 : hook_call(zlog_init, progname, protoname, instance, uid, gid);
1050 6 : return;
1051 :
1052 0 : out_warn:
1053 0 : zlog_err("crashlog and per-thread log buffering unavailable!");
1054 0 : hook_call(zlog_init, progname, protoname, instance, uid, gid);
1055 : }
1056 :
1057 6 : void zlog_fini(void)
1058 : {
1059 6 : hook_call(zlog_fini);
1060 :
1061 6 : if (zlog_tmpdirfd >= 0) {
1062 6 : close(zlog_tmpdirfd);
1063 6 : zlog_tmpdirfd = -1;
1064 :
1065 6 : if (rmdir(zlog_tmpdir))
1066 0 : zlog_err("failed to rmdir \"%s\": %s",
1067 : zlog_tmpdir, strerror(errno));
1068 : }
1069 6 : }
|
