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