lib/zlog.c

   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 #ifdef __APPLE__
  36 #include <mach/mach_traps.h>
  37 #endif
  38
  39 #ifdef HAVE_LIBUNWIND
  40 #define UNW_LOCAL_ONLY
  41 #include <libunwind.h>
  42 #include <dlfcn.h>
  43 #endif
  44
  45 #include "memory.h"
  46 #include "atomlist.h"
  47 #include "printfrr.h"
  48 #include "frrcu.h"
  49 #include "zlog.h"
  50 #include "libfrr_trace.h"
  51 #include "frrevent.h"
  52
  53 DEFINE_MTYPE_STATIC(LIB, LOG_MESSAGE,  "log message");
  54 DEFINE_MTYPE_STATIC(LIB, LOG_TLSBUF,   "log thread-local buffer");
  55
  56 DEFINE_HOOK(zlog_init, (const char *progname, const char *protoname,
  57                         unsigned short instance, uid_t uid, gid_t gid),
  58                        (progname, protoname, instance, uid, gid));
  59 DEFINE_KOOH(zlog_fini, (), ());
  60 DEFINE_HOOK(zlog_aux_init, (const char *prefix, int prio_min),
  61                            (prefix, prio_min));
  62
  63 char zlog_prefix[128];
  64 size_t zlog_prefixsz;
  65 int zlog_tmpdirfd = -1;
  66 int zlog_instance = -1;
  67
  68 static atomic_bool zlog_ec = true, zlog_xid = true;
  69
  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
  81 /* Global setting for buffered vs immediate output. The default is
  82  * per-pthread buffering.
  83  */
  84 static bool default_immediate;
  85
  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;
 101         const struct xref_logmsg *xref;
 102
 103         char *stackbuf;
 104         size_t stackbufsz;
 105         char *text;
 106         size_t textlen;
 107         size_t hdrlen;
 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          */
 117         char ts_str[32], *ts_dot, ts_zonetail[8];
 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];
 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;
 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;
 163         bool do_unlink;
 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
 220 static intmax_t zlog_gettid(void)
 221 {
 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
 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
 248
 249 #ifndef __OpenBSD__
 250         cached_tid = rv;
 251 #endif
 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
 271         snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid());
 272
 273         mmfd = openat(zlog_tmpdirfd, mmpath,
 274                       O_RDWR | O_CREAT | O_EXCL | O_CLOEXEC, 0600);
 275         if (mmfd < 0) {
 276                 zlog_err("failed to open thread log buffer \"%s\": %s",
 277                          mmpath, strerror(errno));
 278                 goto out_anon;
 279         }
 280         fchown(mmfd, zlog_uid, zlog_gid);
 281
 282 #ifdef HAVE_POSIX_FALLOCATE
 283         if (posix_fallocate(mmfd, 0, TLS_LOG_BUF_SIZE) != 0)
 284         /* note next statement is under above if() */
 285 #endif
 286         if (ftruncate(mmfd, TLS_LOG_BUF_SIZE) < 0) {
 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         }
 299         zlog_tls->do_unlink = true;
 300
 301         close(mmfd);
 302         zlog_tls_set(zlog_tls);
 303         return;
 304
 305 out_anon_unlink:
 306         unlinkat(zlog_tmpdirfd, mmpath, 0);
 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];
 330         struct zlog_tls *zlog_tls = zlog_tls_get();
 331         bool do_unlink = zlog_tls ? zlog_tls->do_unlink : false;
 332
 333         zlog_tls_buffer_flush();
 334
 335         zlog_tls_free(zlog_tls);
 336         zlog_tls_set(NULL);
 337
 338         snprintfrr(mmpath, sizeof(mmpath), "logbuf.%jd", zlog_gettid());
 339         if (do_unlink && unlinkat(zlog_tmpdirfd, mmpath, 0))
 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
 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
 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();
 393         frr_each_safe (zlog_targets, &zlog_targets, zt) {
 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
 406 static void vzlog_notls(const struct xref_logmsg *xref, int prio,
 407                         const char *fmt, va_list ap)
 408 {
 409         struct zlog_target *zt;
 410         struct zlog_msg stackmsg = {
 411                 .prio = prio & LOG_PRIMASK,
 412                 .fmt = fmt,
 413                 .xref = xref,
 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();
 423         frr_each_safe (zlog_targets, &zlog_targets, zt) {
 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
 438 static void vzlog_tls(struct zlog_tls *zlog_tls, const struct xref_logmsg *xref,
 439                       int prio, const char *fmt, va_list ap)
 440 {
 441         struct zlog_target *zt;
 442         struct zlog_msg *msg;
 443         char *buf;
 444         bool ignoremsg = true;
 445         bool immediate = default_immediate;
 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;
 472         msg->xref = xref;
 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
 507 static void zlog_backtrace_msg(const struct xref_logmsg *xref, int prio)
 508 {
 509         struct event *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
 588 void vzlogx(const struct xref_logmsg *xref, int prio,
 589             const char *fmt, va_list ap)
 590 {
 591         struct zlog_tls *zlog_tls = zlog_tls_get();
 592
 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:
 600                 frrtracelog(TRACE_ERR, msg);
 601                 break;
 602         case LOG_WARNING:
 603                 frrtracelog(TRACE_WARNING, msg);
 604                 break;
 605         case LOG_DEBUG:
 606                 frrtracelog(TRACE_DEBUG, msg);
 607                 break;
 608         case LOG_NOTICE:
 609                 frrtracelog(TRACE_DEBUG, msg);
 610                 break;
 611         case LOG_INFO:
 612         default:
 613                 frrtracelog(TRACE_INFO, msg);
 614                 break;
 615         }
 616
 617         va_end(copy);
 618         XFREE(MTYPE_LOG_MESSAGE, msg);
 619 #endif
 620
 621         if (zlog_tls)
 622                 vzlog_tls(zlog_tls, xref, prio, fmt, ap);
 623         else
 624                 vzlog_notls(xref, prio, fmt, ap);
 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         }
 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
 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 = &ap;
 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 }
 691
 692 int zlog_msg_prio(struct zlog_msg *msg)
 693 {
 694         return msg->prio;
 695 }
 696
 697 const struct xref_logmsg *zlog_msg_xref(struct zlog_msg *msg)
 698 {
 699         return msg->xref;
 700 }
 701
 702 const char *zlog_msg_text(struct zlog_msg *msg, size_t *textlen)
 703 {
 704         if (!msg->text) {
 705                 va_list args;
 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
 727                 msg->hdrlen = hdrlen = need;
 728                 assert(hdrlen < msg->stackbufsz);
 729
 730                 fb.outpos = msg->argpos;
 731                 fb.outpos_n = array_size(msg->argpos);
 732                 fb.outpos_i = 0;
 733
 734                 va_copy(args, msg->args);
 735 #pragma GCC diagnostic push
 736 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
 737                 /* format-string checking is done further up the chain */
 738                 need += vbprintfrr(&fb, msg->fmt, args);
 739 #pragma GCC diagnostic pop
 740                 va_end(args);
 741
 742                 msg->textlen = need;
 743                 need += bputch(&fb, '\n');
 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;
 755                         fb.outpos_i = 0;
 756
 757                         va_copy(args, msg->args);
 758 #pragma GCC diagnostic push
 759 #pragma GCC diagnostic ignored "-Wformat-nonliteral"
 760                         /* same as above */
 761                         vbprintfrr(&fb, msg->fmt, args);
 762 #pragma GCC diagnostic pop
 763                         va_end(args);
 764
 765                         bputch(&fb, '\n');
 766                 }
 767
 768                 msg->n_argpos = fb.outpos_i;
 769         }
 770         if (textlen)
 771                 *textlen = msg->textlen;
 772         return msg->text;
 773 }
 774
 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
 789 #define ZLOG_TS_FORMAT          (ZLOG_TS_ISO8601 | ZLOG_TS_LEGACY)
 790 #define ZLOG_TS_FLAGS           ~ZLOG_TS_PREC
 791
 792 size_t zlog_msg_ts(struct zlog_msg *msg, struct fbuf *out, uint32_t flags)
 793 {
 794         size_t outsz = out ? (out->buf + out->len - out->pos) : 0;
 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) {
 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                 }
 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 '-':
 849                                 *out->pos++ = '/';
 850                                 break;
 851                         case 'T':
 852                                 *out->pos++ = ' ';
 853                                 break;
 854                         default:
 855                                 *out->pos++ = *p;
 856                         }
 857                 }
 858                 return len1;
 859         } else {
 860                 size_t len2 = strlen(msg->ts_zonetail);
 861
 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;
 875                 return len1 + len2;
 876         }
 877 }
 878
 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
 908 void zlog_msg_tsraw(struct zlog_msg *msg, struct timespec *ts)
 909 {
 910         memcpy(ts, &msg->ts, sizeof(*ts));
 911 }
 912
 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
 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
 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 }
 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;
 988         zlog_instance = instance;
 989
 990         if (instance) {
 991                 snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s-%d.%ld",
 992                            TMPBASEDIR, progname, instance, (long)getpid());
 993
 994                 zlog_prefixsz = snprintfrr(zlog_prefix, sizeof(zlog_prefix),
 995                                            "%s[%d]: ", protoname, instance);
 996         } else {
 997                 snprintfrr(zlog_tmpdir, sizeof(zlog_tmpdir), "%s/%s.%ld",
 998                            TMPBASEDIR, progname, (long)getpid());
 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 }