sysdep/unix/log.c

   1 /*
   2  *      BIRD Library -- Logging Functions
   3  *
   4  *      (c) 1998--2000 Martin Mares <mj@ucw.cz>
   5  *
   6  *      Can be freely distributed and used under the terms of the GNU GPL.
   7  */
   8
   9 /**
  10  * DOC: Logging
  11  *
  12  * The Logging module offers a simple set of functions for writing
  13  * messages to system logs and to the debug output. Message classes
  14  * used by this module are described in |birdlib.h| and also in the
  15  * user's manual.
  16  */
  17
  18 #include <stdio.h>
  19 #include <stdlib.h>
  20 #include <stdarg.h>
  21 #include <time.h>
  22 #include <sys/types.h>
  23 #include <sys/stat.h>
  24 #include <unistd.h>
  25 #include <errno.h>
  26
  27 #include "nest/bird.h"
  28 #include "nest/cli.h"
  29 #include "conf/conf.h"
  30 #include "lib/string.h"
  31 #include "lib/lists.h"
  32 #include "lib/socket.h"
  33 #include "sysdep/unix/unix.h"
  34
  35 static int dbg_fd = -1;
  36 static FILE *dbgf;
  37 static list *current_log_list;
  38 static char *current_syslog_name; /* NULL -> syslog closed */
  39
  40
  41 #ifdef USE_PTHREADS
  42
  43 #include <pthread.h>
  44
  45 static pthread_mutex_t log_mutex;
  46 static inline void log_lock(void) { pthread_mutex_lock(&log_mutex); }
  47 static inline void log_unlock(void) { pthread_mutex_unlock(&log_mutex); }
  48
  49 static pthread_t main_thread;
  50 void main_thread_init(void) { main_thread = pthread_self(); }
  51 static int main_thread_self(void) { return pthread_equal(pthread_self(), main_thread); }
  52
  53 #else
  54
  55 static inline void log_lock(void) {  }
  56 static inline void log_unlock(void) {  }
  57 void main_thread_init(void) { }
  58 static int main_thread_self(void) { return 1; }
  59
  60 #endif
  61
  62
  63 #ifdef HAVE_SYSLOG_H
  64 #include <sys/syslog.h>
  65
  66 static int syslog_priorities[L_MAX] = {
  67   LOG_DEBUG,
  68   LOG_DEBUG,
  69   LOG_DEBUG,
  70   LOG_INFO,
  71   LOG_ERR,
  72   LOG_WARNING,
  73   LOG_ERR,
  74   LOG_ERR,
  75   LOG_CRIT,
  76   LOG_CRIT
  77 };
  78 #endif
  79
  80 static char *class_names[L_MAX] = {
  81   "???",
  82   "DBG",
  83   "TRACE",
  84   "INFO",
  85   "RMT",
  86   "WARN",
  87   "ERR",
  88   "AUTH",
  89   "FATAL",
  90   "BUG"
  91 };
  92
  93 static inline off_t
  94 log_size(struct log_config *l)
  95 {
  96   struct stat st;
  97   return (!fstat(rf_fileno(l->rf), &st) && S_ISREG(st.st_mode)) ? st.st_size : 0;
  98 }
  99
 100 static void
 101 log_close(struct log_config *l)
 102 {
 103   rfree(l->rf);
 104   l->rf = NULL;
 105   l->fh = NULL;
 106 }
 107
 108 static int
 109 log_open(struct log_config *l)
 110 {
 111   l->rf = rf_open(config->pool, l->filename, "a");
 112   if (!l->rf)
 113   {
 114     /* Well, we cannot do much in case of error as log is closed */
 115     l->mask = 0;
 116     return -1;
 117   }
 118
 119   l->fh = rf_file(l->rf);
 120   l->pos = log_size(l);
 121
 122   return 0;
 123 }
 124
 125 static int
 126 log_rotate(struct log_config *l)
 127 {
 128   log_close(l);
 129
 130   /* If we cannot rename the logfile, we at least try to delete it
 131      in order to continue logging and not exceeding logfile size */
 132   if ((rename(l->filename, l->backup) < 0) &&
 133       (unlink(l->filename) < 0))
 134   {
 135     l->mask = 0;
 136     return -1;
 137   }
 138
 139   return log_open(l);
 140 }
 141
 142 /* Expected to be called during config parsing */
 143 int
 144 log_open_udp(struct log_config *l, pool *p)
 145 {
 146   ASSERT(l->host || ipa_nonzero(l->ip));
 147
 148   if (l->host && ipa_zero(l->ip))
 149   {
 150     const char *err_msg;
 151     l->ip = resolve_hostname(l->host, SK_UDP, &err_msg);
 152
 153     if (ipa_zero(l->ip))
 154     {
 155       cf_warn("Cannot resolve hostname '%s': %s", l->host, err_msg);
 156       goto err0;
 157     }
 158   }
 159
 160   sock *sk = sk_new(p);
 161   sk->type = SK_UDP;
 162   sk->daddr = l->ip;
 163   sk->dport = l->port;
 164   sk->flags = SKF_CONNECT | SKF_THREAD;
 165
 166   if (sk_open(sk) < 0)
 167   {
 168     cf_warn("Cannot open UDP log socket: %s%#m", sk->err);
 169     goto err1;
 170   }
 171
 172   /* Move fd from sk resource to rf resource */
 173   l->rf = rf_fdopen(p, sk->fd, "a");
 174   if (!l->rf)
 175     goto err1;
 176
 177   l->fh = rf_file(l->rf);
 178
 179   sk->fd = -1;
 180   rfree(sk);
 181
 182   return 0;
 183
 184 err1:
 185   rfree(sk);
 186 err0:
 187   l->mask = 0;
 188   return -1;
 189 }
 190
 191 /**
 192  * log_commit - commit a log message
 193  * @class: message class information (%L_DEBUG to %L_BUG, see |lib/birdlib.h|)
 194  * @buf: message to write
 195  *
 196  * This function writes a message prepared in the log buffer to the
 197  * log file (as specified in the configuration). The log buffer is
 198  * reset after that. The log message is a full line, log_commit()
 199  * terminates it.
 200  *
 201  * The message class is an integer, not a first char of a string like
 202  * in log(), so it should be written like *L_INFO.
 203  */
 204 void
 205 log_commit(int class, buffer *buf)
 206 {
 207   struct log_config *l;
 208
 209   if (buf->pos == buf->end)
 210     strcpy(buf->end - 100, " ... <too long>");
 211
 212   log_lock();
 213   WALK_LIST(l, *current_log_list)
 214     {
 215       if (!(l->mask & (1 << class)))
 216         continue;
 217       if (l->fh)
 218         {
 219           if (l->terminal_flag)
 220             fputs("bird: ", l->fh);
 221           else if (l->udp_flag)
 222             {
 223               int pri = LOG_DAEMON | syslog_priorities[class];
 224               char tbuf[TM_DATETIME_BUFFER_SIZE];
 225               const char *hostname = (config && config->hostname) ? config->hostname : "<none>";
 226               const char *fmt = "%b %d %T.%6f";
 227               if (!tm_format_real_time(tbuf, sizeof(tbuf), fmt, current_real_time()))
 228                 strcpy(tbuf, "<error>");
 229
 230               /* Legacy RFC 3164 format, but with us precision */
 231               fprintf(l->fh, "<%d>%s %s %s: ", pri, tbuf, hostname, bird_name);
 232             }
 233           else
 234             {
 235               byte tbuf[TM_DATETIME_BUFFER_SIZE];
 236               const char *fmt = config ? config->tf_log.fmt1 : "%F %T.%3f";
 237               if (!tm_format_real_time(tbuf, sizeof(tbuf), fmt, current_real_time()))
 238                 strcpy(tbuf, "<error>");
 239
 240               if (l->limit)
 241               {
 242                 off_t msg_len = strlen(tbuf) + strlen(class_names[class]) +
 243                   (buf->pos - buf->start) + 5;
 244
 245                 if (l->pos < 0)
 246                   l->pos = log_size(l);
 247
 248                 if (l->pos + msg_len > l->limit)
 249                   if (log_rotate(l) < 0)
 250                     continue;
 251
 252                 l->pos += msg_len;
 253               }
 254
 255               fprintf(l->fh, "%s <%s> ", tbuf, class_names[class]);
 256             }
 257           fputs(buf->start, l->fh);
 258           fputc('\n', l->fh);
 259           fflush(l->fh);
 260         }
 261 #ifdef HAVE_SYSLOG_H
 262       else
 263         syslog(syslog_priorities[class], "%s", buf->start);
 264 #endif
 265     }
 266   log_unlock();
 267
 268   /* cli_echo is not thread-safe, so call it just from the main thread */
 269   if (main_thread_self())
 270     cli_echo(class, buf->start);
 271
 272   buf->pos = buf->start;
 273 }
 274
 275 int buffer_vprint(buffer *buf, const char *fmt, va_list args);
 276
 277 void
 278 vlog(int class, const char *msg, va_list args)
 279 {
 280   buffer buf;
 281   LOG_BUFFER_INIT(buf);
 282   buffer_vprint(&buf, msg, args);
 283   log_commit(class, &buf);
 284 }
 285
 286
 287 /**
 288  * log - log a message
 289  * @msg: printf-like formatting string with message class information
 290  * prepended (%L_DEBUG to %L_BUG, see |lib/birdlib.h|)
 291  *
 292  * This function formats a message according to the format string @msg
 293  * and writes it to the corresponding log file (as specified in the
 294  * configuration). Please note that the message is automatically
 295  * formatted as a full line, no need to include |\n| inside.
 296  * It is essentially a sequence of log_reset(), logn() and log_commit().
 297  */
 298 void
 299 log_msg(const char *msg, ...)
 300 {
 301   int class = 1;
 302   va_list args;
 303
 304   va_start(args, msg);
 305   if (*msg >= 1 && *msg < L_MAX)
 306     class = *msg++;
 307   vlog(class, msg, args);
 308   va_end(args);
 309 }
 310
 311 void
 312 log_rl(struct tbf *f, const char *msg, ...)
 313 {
 314   int class = 1;
 315   va_list args;
 316
 317   /* Rate limiting is a bit tricky here as it also logs '...' during the first hit */
 318   if (tbf_limit(f) && (f->drop > 1))
 319     return;
 320
 321   if (*msg >= 1 && *msg < L_MAX)
 322     class = *msg++;
 323
 324   va_start(args, msg);
 325   vlog(class, (f->drop ? "..." : msg), args);
 326   va_end(args);
 327 }
 328
 329 /**
 330  * bug - report an internal error
 331  * @msg: a printf-like error message
 332  *
 333  * This function logs an internal error and aborts execution
 334  * of the program.
 335  */
 336 void
 337 bug(const char *msg, ...)
 338 {
 339   va_list args;
 340
 341   va_start(args, msg);
 342   vlog(L_BUG[0], msg, args);
 343   va_end(args);
 344   abort();
 345 }
 346
 347 /**
 348  * bug - report a fatal error
 349  * @msg: a printf-like error message
 350  *
 351  * This function logs a fatal error and aborts execution
 352  * of the program.
 353  */
 354 void
 355 die(const char *msg, ...)
 356 {
 357   va_list args;
 358
 359   va_start(args, msg);
 360   vlog(L_FATAL[0], msg, args);
 361   va_end(args);
 362   exit(1);
 363 }
 364
 365 /**
 366  * debug - write to debug output
 367  * @msg: a printf-like message
 368  *
 369  * This function formats the message @msg and prints it out
 370  * to the debugging output. No newline character is appended.
 371  */
 372 void
 373 debug(const char *msg, ...)
 374 {
 375 #define MAX_DEBUG_BUFSIZE 16384
 376   va_list args;
 377   char buf[MAX_DEBUG_BUFSIZE];
 378
 379   va_start(args, msg);
 380   if (dbgf)
 381     {
 382       if (bvsnprintf(buf, MAX_DEBUG_BUFSIZE, msg, args) < 0)
 383         bug("Extremely long debug output, split it.");
 384
 385       fputs(buf, dbgf);
 386     }
 387   va_end(args);
 388 }
 389
 390 /**
 391  * debug_safe - async-safe write to debug output
 392  * @msg: a string message
 393  *
 394  * This function prints the message @msg to the debugging output in a
 395  * way that is async safe and can be used in signal handlers. No newline
 396  * character is appended.
 397  */
 398 void
 399 debug_safe(const char *msg)
 400 {
 401   if (dbg_fd >= 0)
 402     write(dbg_fd, msg, strlen(msg));
 403 }
 404
 405 static list *
 406 default_log_list(int initial, const char **syslog_name)
 407 {
 408   static list log_list;
 409   init_list(&log_list);
 410   *syslog_name = NULL;
 411
 412 #ifdef HAVE_SYSLOG_H
 413   if (!dbgf)
 414     {
 415       static struct log_config lc_syslog;
 416       lc_syslog = (struct log_config){
 417         .mask = ~0
 418       };
 419
 420       add_tail(&log_list, &lc_syslog.n);
 421       *syslog_name = bird_name;
 422     }
 423 #endif
 424
 425   if (dbgf && (dbgf != stderr))
 426     {
 427       static struct log_config lc_debug;
 428       lc_debug = (struct log_config){
 429         .mask = ~0,
 430         .fh = dbgf
 431       };
 432
 433       add_tail(&log_list, &lc_debug.n);
 434     }
 435
 436   if (initial || (dbgf == stderr))
 437     {
 438       static struct log_config lc_stderr;
 439       lc_stderr = (struct log_config){
 440         .mask = ~0,
 441         .terminal_flag = 1,
 442         .fh = stderr
 443       };
 444
 445       add_tail(&log_list, &lc_stderr.n);
 446     }
 447
 448   return &log_list;
 449 }
 450
 451 void
 452 log_switch(int initial, list *logs, const char *new_syslog_name)
 453 {
 454   struct log_config *l;
 455
 456   /* We should not manipulate with log list when other threads may use it */
 457   log_lock();
 458
 459   if (!logs || EMPTY_LIST(*logs))
 460     logs = default_log_list(initial, &new_syslog_name);
 461
 462   /* Close the logs to avoid pinning them on disk when deleted */
 463   if (current_log_list)
 464     WALK_LIST(l, *current_log_list)
 465       if (l->filename && l->rf)
 466         log_close(l);
 467
 468   /* Reopen the logs, needed for 'configure undo' */
 469   if (logs)
 470     WALK_LIST(l, *logs)
 471       if (l->filename && !l->rf)
 472         log_open(l);
 473
 474   current_log_list = logs;
 475
 476 #ifdef HAVE_SYSLOG_H
 477   if (!bstrcmp(current_syslog_name, new_syslog_name))
 478     goto done;
 479
 480   if (current_syslog_name)
 481   {
 482     closelog();
 483     xfree(current_syslog_name);
 484     current_syslog_name = NULL;
 485   }
 486
 487   if (new_syslog_name)
 488   {
 489     current_syslog_name = xstrdup(new_syslog_name);
 490     openlog(current_syslog_name, LOG_CONS | LOG_NDELAY, LOG_DAEMON);
 491   }
 492
 493 #endif
 494
 495 done:
 496   /* Logs exchange done, let the threads log as before */
 497   log_unlock();
 498 }
 499
 500 void
 501 log_init_debug(char *f)
 502 {
 503   dbg_fd = -1;
 504   if (dbgf && dbgf != stderr)
 505     fclose(dbgf);
 506
 507   if (!f)
 508     dbgf = NULL;
 509   else if (!*f)
 510     dbgf = stderr;
 511   else if (!(dbgf = fopen(f, "a")))
 512   {
 513     /* Cannot use die() nor log() here, logging is not yet initialized */
 514     fprintf(stderr, "bird: Unable to open debug file %s: %s\n", f, strerror(errno));
 515     exit(1);
 516   }
 517
 518   if (dbgf)
 519   {
 520     setvbuf(dbgf, NULL, _IONBF, 0);
 521     dbg_fd = fileno(dbgf);
 522   }
 523 }