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