]>
Commit | Line | Data |
---|---|---|
0bdeb5e5 DL |
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 | ||
ef990bd9 DL |
50 | #ifdef HAVE_LIBUNWIND |
51 | #define UNW_LOCAL_ONLY | |
52 | #include <libunwind.h> | |
53 | #include <dlfcn.h> | |
54 | #endif | |
55 | ||
0bdeb5e5 DL |
56 | #include "memory.h" |
57 | #include "atomlist.h" | |
58 | #include "printfrr.h" | |
59 | #include "frrcu.h" | |
60 | #include "zlog.h" | |
912d45a1 | 61 | #include "libfrr_trace.h" |
ef990bd9 | 62 | #include "thread.h" |
0bdeb5e5 | 63 | |
bf8d3d6a DL |
64 | DEFINE_MTYPE_STATIC(LIB, LOG_MESSAGE, "log message"); |
65 | DEFINE_MTYPE_STATIC(LIB, LOG_TLSBUF, "log thread-local buffer"); | |
0bdeb5e5 DL |
66 | |
67 | DEFINE_HOOK(zlog_init, (const char *progname, const char *protoname, | |
68 | unsigned short instance, uid_t uid, gid_t gid), | |
8451921b DL |
69 | (progname, protoname, instance, uid, gid)); |
70 | DEFINE_KOOH(zlog_fini, (), ()); | |
0bdeb5e5 | 71 | DEFINE_HOOK(zlog_aux_init, (const char *prefix, int prio_min), |
8451921b | 72 | (prefix, prio_min)); |
0bdeb5e5 DL |
73 | |
74 | char zlog_prefix[128]; | |
75 | size_t zlog_prefixsz; | |
76 | int zlog_tmpdirfd = -1; | |
5c58f5d3 | 77 | int zlog_instance = -1; |
0bdeb5e5 | 78 | |
a3c67498 DL |
79 | static atomic_bool zlog_ec = true, zlog_xid = true; |
80 | ||
0bdeb5e5 DL |
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 | DECLARE_ATOMLIST(zlog_targets, struct zlog_target, head); | |
90 | static struct zlog_targets_head zlog_targets; | |
91 | ||
42ddefe8 MS |
92 | /* Global setting for buffered vs immediate output. The default is |
93 | * per-pthread buffering. | |
94 | */ | |
95 | static bool default_immediate; | |
96 | ||
0bdeb5e5 DL |
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; | |
131879fb | 112 | const struct xref_logmsg *xref; |
0bdeb5e5 DL |
113 | |
114 | char *stackbuf; | |
115 | size_t stackbufsz; | |
116 | char *text; | |
117 | size_t textlen; | |
e3daa82c | 118 | size_t hdrlen; |
0bdeb5e5 DL |
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 | */ | |
0bdeb5e5 | 128 | char ts_str[32], *ts_dot, ts_zonetail[8]; |
243ff228 DL |
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]; | |
e3daa82c DL |
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; | |
0bdeb5e5 DL |
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; | |
4b4935bb | 174 | bool do_unlink; |
0bdeb5e5 DL |
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 | static inline struct zlog_tls *zlog_tls_get(void) | |
220 | { | |
221 | return zlog_tls_var; | |
222 | } | |
223 | ||
224 | static inline void zlog_tls_set(struct zlog_tls *val) | |
225 | { | |
226 | zlog_tls_var = val; | |
227 | } | |
228 | #endif | |
229 | ||
230 | #ifdef CAN_DO_TLS | |
78598fd0 | 231 | static intmax_t zlog_gettid(void) |
0bdeb5e5 | 232 | { |
78598fd0 DL |
233 | #ifndef __OpenBSD__ |
234 | /* accessing a TLS variable is much faster than a syscall */ | |
235 | static thread_local intmax_t cached_tid = -1; | |
236 | if (cached_tid != -1) | |
237 | return cached_tid; | |
238 | #endif | |
239 | ||
0bdeb5e5 DL |
240 | long rv = -1; |
241 | #ifdef HAVE_PTHREAD_GETTHREADID_NP | |
242 | rv = pthread_getthreadid_np(); | |
243 | #elif defined(linux) | |
244 | 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 | |
78598fd0 DL |
259 | |
260 | #ifndef __OpenBSD__ | |
261 | cached_tid = rv; | |
262 | #endif | |
0bdeb5e5 DL |
263 | return rv; |
264 | } | |
265 | ||
266 | void zlog_tls_buffer_init(void) | |
267 | { | |
268 | struct zlog_tls *zlog_tls; | |
269 | char mmpath[MAXPATHLEN]; | |
270 | int mmfd; | |
271 | size_t i; | |
272 | ||
273 | zlog_tls = zlog_tls_get(); | |
274 | ||
275 | if (zlog_tls || zlog_tmpdirfd < 0) | |
276 | return; | |
277 | ||
278 | zlog_tls = XCALLOC(MTYPE_LOG_TLSBUF, sizeof(*zlog_tls)); | |
279 | for (i = 0; i < array_size(zlog_tls->msgp); i++) | |
280 | zlog_tls->msgp[i] = &zlog_tls->msgs[i]; | |
281 | ||
78598fd0 | 282 | snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid()); |
0bdeb5e5 DL |
283 | |
284 | mmfd = openat(zlog_tmpdirfd, mmpath, | |
285 | O_RDWR | O_CREAT | O_EXCL | O_CLOEXEC, 0600); | |
0bdeb5e5 DL |
286 | if (mmfd < 0) { |
287 | zlog_err("failed to open thread log buffer \"%s\": %s", | |
288 | mmpath, strerror(errno)); | |
289 | goto out_anon; | |
290 | } | |
41051697 | 291 | fchown(mmfd, zlog_uid, zlog_gid); |
0bdeb5e5 DL |
292 | |
293 | #ifdef HAVE_POSIX_FALLOCATE | |
6a3b431b DL |
294 | if (posix_fallocate(mmfd, 0, TLS_LOG_BUF_SIZE) != 0) |
295 | /* note next statement is under above if() */ | |
0bdeb5e5 | 296 | #endif |
6a3b431b | 297 | if (ftruncate(mmfd, TLS_LOG_BUF_SIZE) < 0) { |
0bdeb5e5 DL |
298 | zlog_err("failed to allocate thread log buffer \"%s\": %s", |
299 | mmpath, strerror(errno)); | |
300 | goto out_anon_unlink; | |
301 | } | |
302 | ||
303 | zlog_tls->mmbuf = mmap(NULL, TLS_LOG_BUF_SIZE, PROT_READ | PROT_WRITE, | |
304 | MAP_SHARED, mmfd, 0); | |
305 | if (zlog_tls->mmbuf == MAP_FAILED) { | |
306 | zlog_err("failed to mmap thread log buffer \"%s\": %s", | |
307 | mmpath, strerror(errno)); | |
308 | goto out_anon_unlink; | |
309 | } | |
4b4935bb | 310 | zlog_tls->do_unlink = true; |
0bdeb5e5 DL |
311 | |
312 | close(mmfd); | |
313 | zlog_tls_set(zlog_tls); | |
314 | return; | |
315 | ||
316 | out_anon_unlink: | |
4b4935bb | 317 | unlinkat(zlog_tmpdirfd, mmpath, 0); |
0bdeb5e5 DL |
318 | close(mmfd); |
319 | out_anon: | |
320 | ||
321 | #ifndef MAP_ANONYMOUS | |
322 | #define MAP_ANONYMOUS MAP_ANON | |
323 | #endif | |
324 | zlog_tls->mmbuf = mmap(NULL, TLS_LOG_BUF_SIZE, PROT_READ | PROT_WRITE, | |
325 | MAP_ANONYMOUS | MAP_PRIVATE, -1, 0); | |
326 | ||
327 | if (!zlog_tls->mmbuf) { | |
328 | zlog_err("failed to anonymous-mmap thread log buffer: %s", | |
329 | strerror(errno)); | |
330 | XFREE(MTYPE_LOG_TLSBUF, zlog_tls); | |
331 | zlog_tls_set(NULL); | |
332 | return; | |
333 | } | |
334 | ||
335 | zlog_tls_set(zlog_tls); | |
336 | } | |
337 | ||
338 | void zlog_tls_buffer_fini(void) | |
339 | { | |
340 | char mmpath[MAXPATHLEN]; | |
4b4935bb DL |
341 | struct zlog_tls *zlog_tls = zlog_tls_get(); |
342 | bool do_unlink = zlog_tls ? zlog_tls->do_unlink : false; | |
0bdeb5e5 DL |
343 | |
344 | zlog_tls_buffer_flush(); | |
345 | ||
4b4935bb | 346 | zlog_tls_free(zlog_tls); |
0bdeb5e5 DL |
347 | zlog_tls_set(NULL); |
348 | ||
78598fd0 | 349 | snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid()); |
4b4935bb | 350 | if (do_unlink && unlinkat(zlog_tmpdirfd, mmpath, 0)) |
0bdeb5e5 DL |
351 | zlog_err("unlink logbuf: %s (%d)", strerror(errno), errno); |
352 | } | |
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 | ||
78598fd0 DL |
364 | void zlog_msg_pid(struct zlog_msg *msg, intmax_t *pid, intmax_t *tid) |
365 | { | |
366 | #ifndef __OpenBSD__ | |
367 | static thread_local intmax_t cached_pid = -1; | |
368 | if (cached_pid != -1) | |
369 | *pid = cached_pid; | |
370 | else | |
371 | cached_pid = *pid = (intmax_t)getpid(); | |
372 | #else | |
373 | *pid = (intmax_t)getpid(); | |
374 | #endif | |
375 | #ifdef CAN_DO_TLS | |
376 | *tid = zlog_gettid(); | |
377 | #else | |
378 | *tid = *pid; | |
379 | #endif | |
380 | } | |
381 | ||
0bdeb5e5 DL |
382 | static inline void zlog_tls_free(void *arg) |
383 | { | |
384 | struct zlog_tls *zlog_tls = arg; | |
385 | ||
386 | if (!zlog_tls) | |
387 | return; | |
388 | ||
389 | munmap(zlog_tls->mmbuf, TLS_LOG_BUF_SIZE); | |
390 | XFREE(MTYPE_LOG_TLSBUF, zlog_tls); | |
391 | } | |
392 | ||
393 | void zlog_tls_buffer_flush(void) | |
394 | { | |
395 | struct zlog_target *zt; | |
396 | struct zlog_tls *zlog_tls = zlog_tls_get(); | |
397 | ||
398 | if (!zlog_tls) | |
399 | return; | |
400 | if (!zlog_tls->nmsgs) | |
401 | return; | |
402 | ||
403 | rcu_read_lock(); | |
d03440ca | 404 | frr_each_safe (zlog_targets, &zlog_targets, zt) { |
0bdeb5e5 DL |
405 | if (!zt->logfn) |
406 | continue; | |
407 | ||
408 | zt->logfn(zt, zlog_tls->msgp, zlog_tls->nmsgs); | |
409 | } | |
410 | rcu_read_unlock(); | |
411 | ||
412 | zlog_tls->bufpos = 0; | |
413 | zlog_tls->nmsgs = 0; | |
414 | } | |
415 | ||
416 | ||
131879fb DL |
417 | static void vzlog_notls(const struct xref_logmsg *xref, int prio, |
418 | const char *fmt, va_list ap) | |
0bdeb5e5 DL |
419 | { |
420 | struct zlog_target *zt; | |
421 | struct zlog_msg stackmsg = { | |
422 | .prio = prio & LOG_PRIMASK, | |
423 | .fmt = fmt, | |
131879fb | 424 | .xref = xref, |
0bdeb5e5 DL |
425 | }, *msg = &stackmsg; |
426 | char stackbuf[512]; | |
427 | ||
428 | clock_gettime(CLOCK_REALTIME, &msg->ts); | |
429 | va_copy(msg->args, ap); | |
430 | msg->stackbuf = stackbuf; | |
431 | msg->stackbufsz = sizeof(stackbuf); | |
432 | ||
433 | rcu_read_lock(); | |
d03440ca | 434 | frr_each_safe (zlog_targets, &zlog_targets, zt) { |
0bdeb5e5 DL |
435 | if (prio > zt->prio_min) |
436 | continue; | |
437 | if (!zt->logfn) | |
438 | continue; | |
439 | ||
440 | zt->logfn(zt, &msg, 1); | |
441 | } | |
442 | rcu_read_unlock(); | |
443 | ||
444 | va_end(msg->args); | |
445 | if (msg->text && msg->text != stackbuf) | |
446 | XFREE(MTYPE_LOG_MESSAGE, msg->text); | |
447 | } | |
448 | ||
131879fb DL |
449 | static void vzlog_tls(struct zlog_tls *zlog_tls, const struct xref_logmsg *xref, |
450 | int prio, const char *fmt, va_list ap) | |
0bdeb5e5 DL |
451 | { |
452 | struct zlog_target *zt; | |
453 | struct zlog_msg *msg; | |
454 | char *buf; | |
455 | bool ignoremsg = true; | |
42ddefe8 | 456 | bool immediate = default_immediate; |
0bdeb5e5 DL |
457 | |
458 | /* avoid further processing cost if no target wants this message */ | |
459 | rcu_read_lock(); | |
460 | frr_each (zlog_targets, &zlog_targets, zt) { | |
461 | if (prio > zt->prio_min) | |
462 | continue; | |
463 | ignoremsg = false; | |
464 | break; | |
465 | } | |
466 | rcu_read_unlock(); | |
467 | ||
468 | if (ignoremsg) | |
469 | return; | |
470 | ||
471 | msg = &zlog_tls->msgs[zlog_tls->nmsgs]; | |
472 | zlog_tls->nmsgs++; | |
473 | if (zlog_tls->nmsgs == array_size(zlog_tls->msgs)) | |
474 | immediate = true; | |
475 | ||
476 | memset(msg, 0, sizeof(*msg)); | |
477 | clock_gettime(CLOCK_REALTIME, &msg->ts); | |
478 | va_copy(msg->args, ap); | |
479 | msg->stackbuf = buf = zlog_tls->mmbuf + zlog_tls->bufpos; | |
480 | msg->stackbufsz = TLS_LOG_BUF_SIZE - zlog_tls->bufpos - 1; | |
481 | msg->fmt = fmt; | |
482 | msg->prio = prio & LOG_PRIMASK; | |
131879fb | 483 | msg->xref = xref; |
0bdeb5e5 DL |
484 | if (msg->prio < LOG_INFO) |
485 | immediate = true; | |
486 | ||
487 | 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 | zlog_msg_text(msg, NULL); | |
492 | ||
493 | if (msg->text != buf) | |
494 | /* zlog_msg_text called malloc() on us :( */ | |
495 | immediate = true; | |
496 | else { | |
497 | 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 | zlog_tls->mmbuf[zlog_tls->bufpos] = '\0'; | |
503 | ||
504 | /* avoid malloc() for next message */ | |
505 | if (TLS_LOG_BUF_SIZE - zlog_tls->bufpos < 256) | |
506 | immediate = true; | |
507 | } | |
508 | } | |
509 | ||
510 | if (immediate) | |
511 | zlog_tls_buffer_flush(); | |
512 | ||
513 | va_end(msg->args); | |
514 | if (msg->text && msg->text != buf) | |
515 | XFREE(MTYPE_LOG_MESSAGE, msg->text); | |
516 | } | |
517 | ||
ef990bd9 DL |
518 | static void zlog_backtrace_msg(const struct xref_logmsg *xref, int prio) |
519 | { | |
520 | struct thread *tc = pthread_getspecific(thread_current); | |
521 | const char *uid = xref->xref.xrefdata->uid; | |
522 | bool found_thread = false; | |
523 | ||
524 | zlog(prio, "| (%s) message in thread %jd, at %s(), %s:%d", uid, | |
525 | zlog_gettid(), xref->xref.func, xref->xref.file, xref->xref.line); | |
526 | ||
527 | #ifdef HAVE_LIBUNWIND | |
528 | const char *threadfunc = tc ? tc->xref->funcname : NULL; | |
529 | bool found_caller = false; | |
530 | unw_cursor_t cursor; | |
531 | unw_context_t uc; | |
532 | unw_word_t ip, off, sp; | |
533 | Dl_info dlinfo; | |
534 | ||
535 | unw_getcontext(&uc); | |
536 | ||
537 | unw_init_local(&cursor, &uc); | |
538 | while (unw_step(&cursor) > 0) { | |
539 | char buf[96], name[128] = "?"; | |
540 | bool is_thread = false; | |
541 | ||
542 | unw_get_reg(&cursor, UNW_REG_IP, &ip); | |
543 | unw_get_reg(&cursor, UNW_REG_SP, &sp); | |
544 | ||
545 | if (unw_is_signal_frame(&cursor)) | |
546 | zlog(prio, "| (%s) ---- signal ----", uid); | |
547 | ||
548 | if (!unw_get_proc_name(&cursor, buf, sizeof(buf), &off)) { | |
549 | if (!strcmp(buf, xref->xref.func)) | |
550 | found_caller = true; | |
551 | if (threadfunc && !strcmp(buf, threadfunc)) | |
552 | found_thread = is_thread = true; | |
553 | ||
554 | snprintf(name, sizeof(name), "%s+%#lx", buf, (long)off); | |
555 | } | |
556 | ||
557 | if (!found_caller) | |
558 | continue; | |
559 | ||
560 | if (dladdr((void *)ip, &dlinfo)) | |
561 | zlog(prio, "| (%s) %-36s %16lx+%08lx %16lx %s", uid, | |
562 | name, (long)dlinfo.dli_fbase, | |
563 | (long)ip - (long)dlinfo.dli_fbase, (long)sp, | |
564 | dlinfo.dli_fname); | |
565 | else | |
566 | zlog(prio, "| (%s) %-36s %16lx %16lx", uid, name, | |
567 | (long)ip, (long)sp); | |
568 | ||
569 | if (is_thread) | |
570 | zlog(prio, "| (%s) ^- scheduled from %s(), %s:%u", uid, | |
571 | tc->xref->xref.func, tc->xref->xref.file, | |
572 | 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 | if (!found_thread && tc) | |
594 | zlog(prio, "| (%s) scheduled from %s(), %s:%u", uid, | |
595 | tc->xref->xref.func, tc->xref->xref.file, | |
596 | tc->xref->xref.line); | |
597 | } | |
598 | ||
131879fb DL |
599 | void vzlogx(const struct xref_logmsg *xref, int prio, |
600 | const char *fmt, va_list ap) | |
0bdeb5e5 DL |
601 | { |
602 | struct zlog_tls *zlog_tls = zlog_tls_get(); | |
603 | ||
1bd1ebaa QY |
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: | |
c7bb4f00 | 611 | frrtracelog(TRACE_ERR, msg); |
1bd1ebaa QY |
612 | break; |
613 | case LOG_WARNING: | |
c7bb4f00 | 614 | frrtracelog(TRACE_WARNING, msg); |
1bd1ebaa QY |
615 | break; |
616 | case LOG_DEBUG: | |
c7bb4f00 | 617 | frrtracelog(TRACE_DEBUG, msg); |
1bd1ebaa QY |
618 | break; |
619 | case LOG_NOTICE: | |
c7bb4f00 | 620 | frrtracelog(TRACE_DEBUG, msg); |
1bd1ebaa QY |
621 | break; |
622 | case LOG_INFO: | |
623 | default: | |
c7bb4f00 | 624 | frrtracelog(TRACE_INFO, msg); |
1bd1ebaa QY |
625 | break; |
626 | } | |
627 | ||
628 | va_end(copy); | |
629 | XFREE(MTYPE_LOG_MESSAGE, msg); | |
630 | #endif | |
631 | ||
0bdeb5e5 | 632 | if (zlog_tls) |
131879fb | 633 | vzlog_tls(zlog_tls, xref, prio, fmt, ap); |
0bdeb5e5 | 634 | else |
131879fb | 635 | vzlog_notls(xref, prio, fmt, ap); |
ef990bd9 DL |
636 | |
637 | if (xref) { | |
638 | struct xrefdata_logmsg *xrdl; | |
639 | ||
640 | xrdl = container_of(xref->xref.xrefdata, struct xrefdata_logmsg, | |
641 | xrefdata); | |
642 | if (xrdl->fl_print_bt) | |
643 | zlog_backtrace_msg(xref, prio); | |
644 | } | |
0bdeb5e5 DL |
645 | } |
646 | ||
647 | void zlog_sigsafe(const char *text, size_t len) | |
648 | { | |
649 | struct zlog_target *zt; | |
650 | const char *end = text + len, *nlpos; | |
651 | ||
652 | while (text < end) { | |
653 | nlpos = memchr(text, '\n', end - text); | |
654 | if (!nlpos) | |
655 | nlpos = end; | |
656 | ||
657 | frr_each (zlog_targets, &zlog_targets, zt) { | |
658 | if (LOG_CRIT > zt->prio_min) | |
659 | continue; | |
660 | if (!zt->logfn_sigsafe) | |
661 | continue; | |
662 | ||
663 | zt->logfn_sigsafe(zt, text, nlpos - text); | |
664 | } | |
665 | ||
666 | if (nlpos == end) | |
667 | break; | |
668 | text = nlpos + 1; | |
669 | } | |
670 | } | |
671 | ||
64dd7736 DL |
672 | void _zlog_assert_failed(const struct xref_assert *xref, const char *extra, ...) |
673 | { | |
674 | va_list ap; | |
675 | static bool assert_in_assert; /* "global-ish" variable, init to 0 */ | |
676 | ||
677 | if (assert_in_assert) | |
678 | abort(); | |
679 | assert_in_assert = true; | |
680 | ||
681 | if (extra) { | |
682 | struct va_format vaf; | |
683 | ||
684 | va_start(ap, extra); | |
685 | vaf.fmt = extra; | |
686 | vaf.va = ≈ | |
687 | ||
688 | zlog(LOG_CRIT, | |
689 | "%s:%d: %s(): assertion (%s) failed, extra info: %pVA", | |
690 | xref->xref.file, xref->xref.line, xref->xref.func, | |
691 | xref->expr, &vaf); | |
692 | ||
693 | va_end(ap); | |
694 | } else | |
695 | zlog(LOG_CRIT, "%s:%d: %s(): assertion (%s) failed", | |
696 | xref->xref.file, xref->xref.line, xref->xref.func, | |
697 | xref->expr); | |
698 | ||
699 | /* abort() prints backtrace & memstats in SIGABRT handler */ | |
700 | abort(); | |
701 | } | |
0bdeb5e5 DL |
702 | |
703 | int zlog_msg_prio(struct zlog_msg *msg) | |
704 | { | |
705 | return msg->prio; | |
706 | } | |
707 | ||
131879fb DL |
708 | const struct xref_logmsg *zlog_msg_xref(struct zlog_msg *msg) |
709 | { | |
710 | return msg->xref; | |
711 | } | |
712 | ||
0bdeb5e5 DL |
713 | const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen) |
714 | { | |
715 | if (!msg->text) { | |
716 | va_list args; | |
a3c67498 DL |
717 | bool do_xid, do_ec; |
718 | size_t need = 0, hdrlen; | |
719 | struct fbuf fb = { | |
720 | .buf = msg->stackbuf, | |
721 | .pos = msg->stackbuf, | |
722 | .len = msg->stackbufsz, | |
723 | }; | |
724 | ||
725 | do_ec = atomic_load_explicit(&zlog_ec, memory_order_relaxed); | |
726 | do_xid = atomic_load_explicit(&zlog_xid, memory_order_relaxed); | |
727 | ||
728 | if (msg->xref && do_xid && msg->xref->xref.xrefdata->uid[0]) { | |
729 | need += bputch(&fb, '['); | |
730 | need += bputs(&fb, msg->xref->xref.xrefdata->uid); | |
731 | need += bputch(&fb, ']'); | |
732 | } | |
733 | if (msg->xref && do_ec && msg->xref->ec) | |
734 | need += bprintfrr(&fb, "[EC %u]", msg->xref->ec); | |
735 | if (need) | |
736 | need += bputch(&fb, ' '); | |
737 | ||
e3daa82c | 738 | msg->hdrlen = hdrlen = need; |
a3c67498 | 739 | assert(hdrlen < msg->stackbufsz); |
0bdeb5e5 | 740 | |
e3daa82c DL |
741 | fb.outpos = msg->argpos; |
742 | fb.outpos_n = array_size(msg->argpos); | |
743 | fb.outpos_i = 0; | |
744 | ||
0bdeb5e5 | 745 | va_copy(args, msg->args); |
a3c67498 | 746 | need += vbprintfrr(&fb, msg->fmt, args); |
0bdeb5e5 | 747 | va_end(args); |
a3c67498 DL |
748 | |
749 | msg->textlen = need; | |
8b94cb43 | 750 | need += bputch(&fb, '\n'); |
a3c67498 DL |
751 | |
752 | if (need <= msg->stackbufsz) | |
753 | msg->text = msg->stackbuf; | |
754 | else { | |
755 | msg->text = XMALLOC(MTYPE_LOG_MESSAGE, need); | |
756 | ||
757 | memcpy(msg->text, msg->stackbuf, hdrlen); | |
758 | ||
759 | fb.buf = msg->text; | |
760 | fb.len = need; | |
761 | fb.pos = msg->text + hdrlen; | |
e3daa82c | 762 | fb.outpos_i = 0; |
a3c67498 DL |
763 | |
764 | va_copy(args, msg->args); | |
765 | vbprintfrr(&fb, msg->fmt, args); | |
766 | va_end(args); | |
767 | ||
8b94cb43 | 768 | bputch(&fb, '\n'); |
a3c67498 | 769 | } |
e3daa82c DL |
770 | |
771 | msg->n_argpos = fb.outpos_i; | |
0bdeb5e5 DL |
772 | } |
773 | if (textlen) | |
774 | *textlen = msg->textlen; | |
775 | return msg->text; | |
776 | } | |
777 | ||
e3daa82c DL |
778 | void zlog_msg_args(struct zlog_msg *msg, size_t *hdrlen, size_t *n_argpos, |
779 | const struct fmt_outpos **argpos) | |
780 | { | |
781 | if (!msg->text) | |
782 | zlog_msg_text(msg, NULL); | |
783 | ||
784 | if (hdrlen) | |
785 | *hdrlen = msg->hdrlen; | |
786 | if (n_argpos) | |
787 | *n_argpos = msg->n_argpos; | |
788 | if (argpos) | |
789 | *argpos = msg->argpos; | |
790 | } | |
791 | ||
0bdeb5e5 DL |
792 | #define ZLOG_TS_FORMAT (ZLOG_TS_ISO8601 | ZLOG_TS_LEGACY) |
793 | #define ZLOG_TS_FLAGS ~ZLOG_TS_PREC | |
794 | ||
f6caaa65 | 795 | size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags) |
0bdeb5e5 | 796 | { |
f6caaa65 | 797 | size_t outsz = out ? (out->buf + out->len - out->pos) : 0; |
0bdeb5e5 DL |
798 | size_t len1; |
799 | ||
800 | if (!(flags & ZLOG_TS_FORMAT)) | |
801 | return 0; | |
802 | ||
803 | if (!(msg->ts_flags & ZLOG_TS_FORMAT) || | |
804 | ((msg->ts_flags ^ flags) & ZLOG_TS_UTC)) { | |
805 | struct tm tm; | |
806 | ||
807 | if (flags & ZLOG_TS_UTC) | |
808 | gmtime_r(&msg->ts.tv_sec, &tm); | |
809 | else | |
810 | localtime_r(&msg->ts.tv_sec, &tm); | |
811 | ||
812 | strftime(msg->ts_str, sizeof(msg->ts_str), | |
813 | "%Y-%m-%dT%H:%M:%S", &tm); | |
814 | ||
815 | if (flags & ZLOG_TS_UTC) { | |
816 | msg->ts_zonetail[0] = 'Z'; | |
817 | msg->ts_zonetail[1] = '\0'; | |
818 | } else | |
819 | snprintfrr(msg->ts_zonetail, sizeof(msg->ts_zonetail), | |
820 | "%+03d:%02d", | |
821 | (int)(tm.tm_gmtoff / 3600), | |
822 | (int)(labs(tm.tm_gmtoff) / 60) % 60); | |
823 | ||
824 | msg->ts_dot = msg->ts_str + strlen(msg->ts_str); | |
825 | snprintfrr(msg->ts_dot, | |
826 | msg->ts_str + sizeof(msg->ts_str) - msg->ts_dot, | |
827 | ".%09lu", (unsigned long)msg->ts.tv_nsec); | |
828 | ||
829 | msg->ts_flags = ZLOG_TS_ISO8601 | (flags & ZLOG_TS_UTC); | |
830 | } | |
831 | ||
832 | len1 = flags & ZLOG_TS_PREC; | |
833 | len1 = (msg->ts_dot - msg->ts_str) + (len1 ? len1 + 1 : 0); | |
834 | ||
835 | if (len1 > strlen(msg->ts_str)) | |
836 | len1 = strlen(msg->ts_str); | |
837 | ||
838 | if (flags & ZLOG_TS_LEGACY) { | |
f6caaa65 DL |
839 | if (!out) |
840 | return len1; | |
841 | ||
842 | if (len1 > outsz) { | |
843 | memset(out->pos, 0, outsz); | |
844 | out->pos += outsz; | |
845 | return len1; | |
846 | } | |
0bdeb5e5 DL |
847 | |
848 | /* just swap out the formatting, faster than redoing it */ | |
849 | for (char *p = msg->ts_str; p < msg->ts_str + len1; p++) { | |
850 | switch (*p) { | |
851 | case '-': | |
f6caaa65 | 852 | *out->pos++ = '/'; |
0bdeb5e5 DL |
853 | break; |
854 | case 'T': | |
f6caaa65 | 855 | *out->pos++ = ' '; |
0bdeb5e5 DL |
856 | break; |
857 | default: | |
f6caaa65 | 858 | *out->pos++ = *p; |
0bdeb5e5 DL |
859 | } |
860 | } | |
0bdeb5e5 DL |
861 | return len1; |
862 | } else { | |
863 | size_t len2 = strlen(msg->ts_zonetail); | |
864 | ||
f6caaa65 DL |
865 | if (!out) |
866 | return len1 + len2; | |
867 | ||
868 | if (len1 + len2 > outsz) { | |
869 | memset(out->pos, 0, outsz); | |
870 | out->pos += outsz; | |
871 | return len1 + len2; | |
872 | } | |
873 | ||
874 | memcpy(out->pos, msg->ts_str, len1); | |
875 | out->pos += len1; | |
876 | memcpy(out->pos, msg->ts_zonetail, len2); | |
877 | out->pos += len2; | |
0bdeb5e5 DL |
878 | return len1 + len2; |
879 | } | |
880 | } | |
881 | ||
243ff228 DL |
882 | size_t zlog_msg_ts_3164(struct zlog_msg *msg, struct fbuf *out, uint32_t flags) |
883 | { | |
884 | flags &= ZLOG_TS_UTC; | |
885 | ||
886 | if (!msg->ts_3164_str[0] || flags != msg->ts_3164_flags) { | |
887 | /* these are "hardcoded" in RFC3164, so they're here too... */ | |
888 | static const char *const months[12] = { | |
889 | "Jan", "Feb", "Mar", "Apr", "May", "Jun", | |
890 | "Jul", "Aug", "Sep", "Oct", "Nov", "Dec", | |
891 | }; | |
892 | struct tm tm; | |
893 | ||
894 | /* RFC3164 explicitly asks for local time, but common usage | |
895 | * also includes UTC. | |
896 | */ | |
897 | if (flags & ZLOG_TS_UTC) | |
898 | gmtime_r(&msg->ts.tv_sec, &tm); | |
899 | else | |
900 | localtime_r(&msg->ts.tv_sec, &tm); | |
901 | ||
902 | snprintfrr(msg->ts_3164_str, sizeof(msg->ts_3164_str), | |
903 | "%3s %2d %02d:%02d:%02d", months[tm.tm_mon], | |
904 | tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec); | |
905 | ||
906 | msg->ts_3164_flags = flags; | |
907 | } | |
908 | return bputs(out, msg->ts_3164_str); | |
909 | } | |
910 | ||
df45017f DL |
911 | void zlog_msg_tsraw(struct zlog_msg *msg, struct timespec *ts) |
912 | { | |
913 | memcpy(ts, &msg->ts, sizeof(*ts)); | |
914 | } | |
915 | ||
a3c67498 DL |
916 | void zlog_set_prefix_ec(bool enable) |
917 | { | |
918 | atomic_store_explicit(&zlog_ec, enable, memory_order_relaxed); | |
919 | } | |
920 | ||
921 | bool zlog_get_prefix_ec(void) | |
922 | { | |
923 | return atomic_load_explicit(&zlog_ec, memory_order_relaxed); | |
924 | } | |
925 | ||
926 | void zlog_set_prefix_xid(bool enable) | |
927 | { | |
928 | atomic_store_explicit(&zlog_xid, enable, memory_order_relaxed); | |
929 | } | |
930 | ||
931 | bool zlog_get_prefix_xid(void) | |
932 | { | |
933 | return atomic_load_explicit(&zlog_xid, memory_order_relaxed); | |
934 | } | |
935 | ||
0bdeb5e5 DL |
936 | /* setup functions */ |
937 | ||
938 | struct zlog_target *zlog_target_clone(struct memtype *mt, | |
939 | struct zlog_target *oldzt, size_t size) | |
940 | { | |
941 | struct zlog_target *newzt; | |
942 | ||
943 | newzt = XCALLOC(mt, size); | |
944 | if (oldzt) { | |
945 | newzt->prio_min = oldzt->prio_min; | |
946 | newzt->logfn = oldzt->logfn; | |
947 | newzt->logfn_sigsafe = oldzt->logfn_sigsafe; | |
948 | } | |
949 | ||
950 | return newzt; | |
951 | } | |
952 | ||
953 | struct zlog_target *zlog_target_replace(struct zlog_target *oldzt, | |
954 | struct zlog_target *newzt) | |
955 | { | |
956 | if (newzt) | |
957 | zlog_targets_add_tail(&zlog_targets, newzt); | |
958 | if (oldzt) | |
959 | zlog_targets_del(&zlog_targets, oldzt); | |
960 | return oldzt; | |
961 | } | |
962 | ||
42ddefe8 MS |
963 | /* |
964 | * Enable or disable 'immediate' output - default is to buffer | |
965 | * each pthread's messages. | |
966 | */ | |
967 | void zlog_set_immediate(bool set_p) | |
968 | { | |
969 | default_immediate = set_p; | |
970 | } | |
0bdeb5e5 DL |
971 | |
972 | /* common init */ | |
973 | ||
974 | #define TMPBASEDIR "/var/tmp/frr" | |
975 | ||
976 | static char zlog_tmpdir[MAXPATHLEN]; | |
977 | ||
978 | void zlog_aux_init(const char *prefix, int prio_min) | |
979 | { | |
980 | if (prefix) | |
981 | strlcpy(zlog_prefix, prefix, sizeof(zlog_prefix)); | |
982 | ||
983 | hook_call(zlog_aux_init, prefix, prio_min); | |
984 | } | |
985 | ||
986 | void zlog_init(const char *progname, const char *protoname, | |
987 | unsigned short instance, uid_t uid, gid_t gid) | |
988 | { | |
989 | zlog_uid = uid; | |
990 | zlog_gid = gid; | |
5c58f5d3 | 991 | zlog_instance = instance; |
0bdeb5e5 DL |
992 | |
993 | if (instance) { | |
b5d1433e | 994 | snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s-%d.%ld", |
995 | TMPBASEDIR, progname, instance, (long)getpid()); | |
0bdeb5e5 DL |
996 | |
997 | zlog_prefixsz = snprintfrr(zlog_prefix, sizeof(zlog_prefix), | |
998 | "%s[%d]: ", protoname, instance); | |
999 | } else { | |
b5d1433e | 1000 | snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s.%ld", |
1001 | TMPBASEDIR, progname, (long)getpid()); | |
0bdeb5e5 DL |
1002 | |
1003 | zlog_prefixsz = snprintfrr(zlog_prefix, sizeof(zlog_prefix), | |
1004 | "%s: ", protoname); | |
1005 | } | |
1006 | ||
1007 | if (mkdir(TMPBASEDIR, 0700) != 0) { | |
1008 | if (errno != EEXIST) { | |
1009 | zlog_err("failed to mkdir \"%s\": %s", | |
1010 | TMPBASEDIR, strerror(errno)); | |
1011 | goto out_warn; | |
1012 | } | |
1013 | } | |
1014 | chown(TMPBASEDIR, zlog_uid, zlog_gid); | |
1015 | ||
1016 | if (mkdir(zlog_tmpdir, 0700) != 0) { | |
1017 | zlog_err("failed to mkdir \"%s\": %s", | |
1018 | zlog_tmpdir, strerror(errno)); | |
1019 | goto out_warn; | |
1020 | } | |
1021 | ||
1022 | #ifdef O_PATH | |
1023 | zlog_tmpdirfd = open(zlog_tmpdir, | |
1024 | O_PATH | O_RDONLY | O_CLOEXEC); | |
1025 | #else | |
1026 | zlog_tmpdirfd = open(zlog_tmpdir, | |
1027 | O_DIRECTORY | O_RDONLY | O_CLOEXEC); | |
1028 | #endif | |
1029 | if (zlog_tmpdirfd < 0) { | |
1030 | zlog_err("failed to open \"%s\": %s", | |
1031 | zlog_tmpdir, strerror(errno)); | |
1032 | goto out_warn; | |
1033 | } | |
1034 | ||
1035 | #ifdef AT_EMPTY_PATH | |
1036 | fchownat(zlog_tmpdirfd, "", zlog_uid, zlog_gid, AT_EMPTY_PATH); | |
1037 | #else | |
1038 | chown(zlog_tmpdir, zlog_uid, zlog_gid); | |
1039 | #endif | |
1040 | ||
1041 | hook_call(zlog_init, progname, protoname, instance, uid, gid); | |
1042 | return; | |
1043 | ||
1044 | out_warn: | |
1045 | zlog_err("crashlog and per-thread log buffering unavailable!"); | |
1046 | hook_call(zlog_init, progname, protoname, instance, uid, gid); | |
1047 | } | |
1048 | ||
1049 | void zlog_fini(void) | |
1050 | { | |
1051 | hook_call(zlog_fini); | |
1052 | ||
1053 | if (zlog_tmpdirfd >= 0) { | |
1054 | close(zlog_tmpdirfd); | |
1055 | zlog_tmpdirfd = -1; | |
1056 | ||
1057 | if (rmdir(zlog_tmpdir)) | |
1058 | zlog_err("failed to rmdir \"%s\": %s", | |
1059 | zlog_tmpdir, strerror(errno)); | |
1060 | } | |
1061 | } |