release/src/router/dnsmasq/src/log.c

   1 /* dnsmasq is Copyright (c) 2000-2010 Simon Kelley
   2
   3    This program is free software; you can redistribute it and/or modify
   4    it under the terms of the GNU General Public License as published by
   5    the Free Software Foundation; version 2 dated June, 1991, or
   6    (at your option) version 3 dated 29 June, 2007.
   7
   8    This program is distributed in the hope that it will be useful,
   9    but WITHOUT ANY WARRANTY; without even the implied warranty of
  10    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  11    GNU General Public License for more details.
  12
  13    You should have received a copy of the GNU General Public License
  14    along with this program.  If not, see <http://www.gnu.org/licenses/>.
  15 */
  16
  17 #include "dnsmasq.h"
  18
  19 /* Implement logging to /dev/log asynchronously. If syslogd is
  20    making DNS lookups through dnsmasq, and dnsmasq blocks awaiting
  21    syslogd, then the two daemons can deadlock. We get around this
  22    by not blocking when talking to syslog, instead we queue up to
  23    MAX_LOGS messages. If more are queued, they will be dropped,
  24    and the drop event itself logged. */
  25
  26 /* The "wire" protocol for logging is defined in RFC 3164 */
  27
  28 /* From RFC 3164 */
  29 #define MAX_MESSAGE 1024
  30
  31 /* defaults in case we die() before we log_start() */
  32 static int log_fac = LOG_DAEMON;
  33 static int log_stderr = 0;
  34 static int echo_stderr = 0;
  35 static int log_fd = -1;
  36 static int log_to_file = 0;
  37 static int entries_alloced = 0;
  38 static int entries_lost = 0;
  39 static int connection_good = 1;
  40 static int max_logs = 0;
  41 static int connection_type = SOCK_DGRAM;
  42
  43 struct log_entry {
  44   int offset, length;
  45   pid_t pid; /* to avoid duplicates over a fork */
  46   struct log_entry *next;
  47   char payload[MAX_MESSAGE];
  48 };
  49
  50 static struct log_entry *entries = NULL;
  51 static struct log_entry *free_entries = NULL;
  52
  53
  54 int log_start(struct passwd *ent_pw, int errfd)
  55 {
  56   int ret = 0;
  57
  58   echo_stderr = !!(daemon->options & OPT_DEBUG);
  59
  60   if (daemon->log_fac != -1)
  61     log_fac = daemon->log_fac;
  62 #ifdef LOG_LOCAL0
  63   else if (daemon->options & OPT_DEBUG)
  64     log_fac = LOG_LOCAL0;
  65 #endif
  66
  67   if (daemon->log_file)
  68     {
  69       log_to_file = 1;
  70       daemon->max_logs = 0;
  71       if (strcmp(daemon->log_file, "-") == 0)
  72         {
  73           log_stderr = 1;
  74           echo_stderr = 0;
  75           log_fd = dup(STDERR_FILENO);
  76         }
  77     }
  78
  79   max_logs = daemon->max_logs;
  80
  81   if (!log_reopen(daemon->log_file))
  82     {
  83       send_event(errfd, EVENT_LOG_ERR, errno);
  84       _exit(0);
  85     }
  86
  87   /* if queuing is inhibited, make sure we allocate
  88      the one required buffer now. */
  89   if (max_logs == 0)
  90     {
  91       free_entries = safe_malloc(sizeof(struct log_entry));
  92       free_entries->next = NULL;
  93       entries_alloced = 1;
  94     }
  95
  96   /* If we're running as root and going to change uid later,
  97      change the ownership here so that the file is always owned by
  98      the dnsmasq user. Then logrotate can just copy the owner.
  99      Failure of the chown call is OK, (for instance when started as non-root) */
 100   if (log_to_file && !log_stderr && ent_pw && ent_pw->pw_uid != 0 &&
 101       fchown(log_fd, ent_pw->pw_uid, -1) != 0)
 102     ret = errno;
 103
 104   return ret;
 105 }
 106
 107 int log_reopen(char *log_file)
 108 {
 109   if (!log_stderr)
 110     {
 111       if (log_fd != -1)
 112         close(log_fd);
 113
 114       /* NOTE: umask is set to 022 by the time this gets called */
 115
 116       if (log_file)
 117         log_fd = open(log_file, O_WRONLY|O_CREAT|O_APPEND, S_IRUSR|S_IWUSR|S_IRGRP);
 118       else
 119         {
 120 #ifdef HAVE_SOLARIS_NETWORK
 121           /* Solaris logging is "different", /dev/log is not unix-domain socket.
 122              Just leave log_fd == -1 and use the vsyslog call for everything.... */
 123 #   define _PATH_LOG ""  /* dummy */
 124           return 1;
 125 #else
 126           int flags;
 127           log_fd = socket(AF_UNIX, connection_type, 0);
 128
 129           /* if max_logs is zero, leave the socket blocking */
 130           if (log_fd != -1 && max_logs != 0 && (flags = fcntl(log_fd, F_GETFL)) != -1)
 131             fcntl(log_fd, F_SETFL, flags | O_NONBLOCK);
 132 #endif
 133         }
 134     }
 135
 136   return log_fd != -1;
 137 }
 138
 139 static void free_entry(void)
 140 {
 141   struct log_entry *tmp = entries;
 142   entries = tmp->next;
 143   tmp->next = free_entries;
 144   free_entries = tmp;
 145 }
 146
 147 static void log_write(void)
 148 {
 149   ssize_t rc;
 150
 151   while (entries)
 152     {
 153       /* Avoid duplicates over a fork() */
 154       if (entries->pid != getpid())
 155         {
 156           free_entry();
 157           continue;
 158         }
 159
 160       connection_good = 1;
 161
 162       if ((rc = write(log_fd, entries->payload + entries->offset, entries->length)) != -1)
 163         {
 164           entries->length -= rc;
 165           entries->offset += rc;
 166           if (entries->length == 0)
 167             {
 168               free_entry();
 169               if (entries_lost != 0)
 170                 {
 171                   int e = entries_lost;
 172                   entries_lost = 0; /* avoid wild recursion */
 173                   my_syslog(LOG_WARNING, _("overflow: %d log entries lost"), e);
 174                 }
 175             }
 176           continue;
 177         }
 178
 179       if (errno == EINTR)
 180         continue;
 181
 182       if (errno == EAGAIN)
 183         return; /* syslogd busy, go again when select() or poll() says so */
 184
 185       if (errno == ENOBUFS)
 186         {
 187           connection_good = 0;
 188           return;
 189         }
 190
 191       /* errors handling after this assumes sockets */
 192       if (!log_to_file)
 193         {
 194           /* Once a stream socket hits EPIPE, we have to close and re-open
 195              (we ignore SIGPIPE) */
 196           if (errno == EPIPE)
 197             {
 198               if (log_reopen(NULL))
 199                 continue;
 200             }
 201           else if (errno == ECONNREFUSED ||
 202                    errno == ENOTCONN ||
 203                    errno == EDESTADDRREQ ||
 204                    errno == ECONNRESET)
 205             {
 206               /* socket went (syslogd down?), try and reconnect. If we fail,
 207                  stop trying until the next call to my_syslog()
 208                  ECONNREFUSED -> connection went down
 209                  ENOTCONN -> nobody listening
 210                  (ECONNRESET, EDESTADDRREQ are *BSD equivalents) */
 211
 212               struct sockaddr_un logaddr;
 213
 214 #ifdef HAVE_SOCKADDR_SA_LEN
 215               logaddr.sun_len = sizeof(logaddr) - sizeof(logaddr.sun_path) + strlen(_PATH_LOG) + 1;
 216 #endif
 217               logaddr.sun_family = AF_UNIX;
 218               strncpy(logaddr.sun_path, _PATH_LOG, sizeof(logaddr.sun_path));
 219
 220               /* Got connection back? try again. */
 221               if (connect(log_fd, (struct sockaddr *)&logaddr, sizeof(logaddr)) != -1)
 222                 continue;
 223
 224               /* errors from connect which mean we should keep trying */
 225               if (errno == ENOENT ||
 226                   errno == EALREADY ||
 227                   errno == ECONNREFUSED ||
 228                   errno == EISCONN ||
 229                   errno == EINTR ||
 230                   errno == EAGAIN)
 231                 {
 232                   /* try again on next syslog() call */
 233                   connection_good = 0;
 234                   return;
 235                 }
 236
 237               /* try the other sort of socket... */
 238               if (errno == EPROTOTYPE)
 239                 {
 240                   connection_type = connection_type == SOCK_DGRAM ? SOCK_STREAM : SOCK_DGRAM;
 241                   if (log_reopen(NULL))
 242                     continue;
 243                 }
 244             }
 245         }
 246
 247       /* give up - fall back to syslog() - this handles out-of-space
 248          when logging to a file, for instance. */
 249       log_fd = -1;
 250       my_syslog(LOG_CRIT, _("log failed: %s"), strerror(errno));
 251       return;
 252     }
 253 }
 254
 255 /* priority is one of LOG_DEBUG, LOG_INFO, LOG_NOTICE, etc. See sys/syslog.h.
 256    OR'd to priority can be MS_TFTP, MS_DHCP, ... to be able to do log separation between
 257    DNS, DHCP and TFTP services.
 258 */
 259 void my_syslog(int priority, const char *format, ...)
 260 {
 261   va_list ap;
 262   struct log_entry *entry;
 263   time_t time_now;
 264   char *p;
 265   size_t len;
 266   pid_t pid = getpid();
 267   char *func = "";
 268
 269   if ((LOG_FACMASK & priority) == MS_TFTP)
 270     func = "-tftp";
 271   else if ((LOG_FACMASK & priority) == MS_DHCP)
 272     func = "-dhcp";
 273
 274 #ifdef LOG_PRI
 275   priority = LOG_PRI(priority);
 276 #else
 277   /* Solaris doesn't have LOG_PRI */
 278   priority &= LOG_PRIMASK;
 279 #endif
 280
 281   if (echo_stderr)
 282     {
 283       fprintf(stderr, "dnsmasq%s: ", func);
 284       va_start(ap, format);
 285       vfprintf(stderr, format, ap);
 286       va_end(ap);
 287       fputc('\n', stderr);
 288     }
 289
 290   if (log_fd == -1)
 291     {
 292       /* fall-back to syslog if we die during startup or fail during running. */
 293       static int isopen = 0;
 294       if (!isopen)
 295         {
 296           openlog("dnsmasq", LOG_PID, log_fac);
 297           isopen = 1;
 298         }
 299       va_start(ap, format);
 300       vsyslog(priority, format, ap);
 301       va_end(ap);
 302       return;
 303     }
 304
 305   if ((entry = free_entries))
 306     free_entries = entry->next;
 307   else if (entries_alloced < max_logs && (entry = malloc(sizeof(struct log_entry))))
 308     entries_alloced++;
 309
 310   if (!entry)
 311     entries_lost++;
 312   else
 313     {
 314       /* add to end of list, consumed from the start */
 315       entry->next = NULL;
 316       if (!entries)
 317         entries = entry;
 318       else
 319         {
 320           struct log_entry *tmp;
 321           for (tmp = entries; tmp->next; tmp = tmp->next);
 322           tmp->next = entry;
 323         }
 324
 325       time(&time_now);
 326       p = entry->payload;
 327       if (!log_to_file)
 328         p += sprintf(p, "<%d>", priority | log_fac);
 329
 330       p += sprintf(p, "%.15s dnsmasq%s[%d]: ", ctime(&time_now) + 4, func, (int)pid);
 331
 332       len = p - entry->payload;
 333       va_start(ap, format);
 334       len += vsnprintf(p, MAX_MESSAGE - len, format, ap) + 1; /* include zero-terminator */
 335       va_end(ap);
 336       entry->length = len > MAX_MESSAGE ? MAX_MESSAGE : len;
 337       entry->offset = 0;
 338       entry->pid = pid;
 339
 340       /* replace terminator with \n */
 341       if (log_to_file)
 342         entry->payload[entry->length - 1] = '\n';
 343     }
 344
 345   /* almost always, logging won't block, so try and write this now,
 346      to save collecting too many log messages during a select loop. */
 347   log_write();
 348
 349   /* Since we're doing things asynchronously, a cache-dump, for instance,
 350      can now generate log lines very fast. With a small buffer (desirable),
 351      that means it can overflow the log-buffer very quickly,
 352      so that the cache dump becomes mainly a count of how many lines
 353      overflowed. To avoid this, we delay here, the delay is controlled
 354      by queue-occupancy, and grows exponentially. The delay is limited to (2^8)ms.
 355      The scaling stuff ensures that when the queue is bigger than 8, the delay
 356      only occurs for the last 8 entries. Once the queue is full, we stop delaying
 357      to preserve performance.
 358   */
 359
 360   if (entries && max_logs != 0)
 361     {
 362       int d;
 363
 364       for (d = 0,entry = entries; entry; entry = entry->next, d++);
 365
 366       if (d == max_logs)
 367         d = 0;
 368       else if (max_logs > 8)
 369         d -= max_logs - 8;
 370
 371       if (d > 0)
 372         {
 373           struct timespec waiter;
 374           waiter.tv_sec = 0;
 375           waiter.tv_nsec = 1000000 << (d - 1); /* 1 ms */
 376           nanosleep(&waiter, NULL);
 377
 378           /* Have another go now */
 379           log_write();
 380         }
 381     }
 382 }
 383
 384 void set_log_writer(fd_set *set, int *maxfdp)
 385 {
 386   if (entries && log_fd != -1 && connection_good)
 387     {
 388       FD_SET(log_fd, set);
 389       bump_maxfd(log_fd, maxfdp);
 390     }
 391 }
 392
 393 void check_log_writer(fd_set *set)
 394 {
 395   if (log_fd != -1 && (!set || FD_ISSET(log_fd, set)))
 396     log_write();
 397 }
 398
 399 void flush_log(void)
 400 {
 401   /* write until queue empty */
 402   while (log_fd != -1)
 403     {
 404       struct timespec waiter;
 405       log_write();
 406       if (!entries)
 407         {
 408           close(log_fd);
 409           break;
 410         }
 411       waiter.tv_sec = 0;
 412       waiter.tv_nsec = 1000000; /* 1 ms */
 413       nanosleep(&waiter, NULL);
 414     }
 415 }
 416
 417 void die(char *message, char *arg1, int exit_code)
 418 {
 419   char *errmess = strerror(errno);
 420
 421   if (!arg1)
 422     arg1 = errmess;
 423
 424   if (!log_stderr)
 425     {
 426       echo_stderr = 1; /* print as well as log when we die.... */
 427       fputc('\n', stderr); /* prettyfy  startup-script message */
 428     }
 429   my_syslog(LOG_CRIT, message, arg1, errmess);
 430   echo_stderr = 0;
 431   my_syslog(LOG_CRIT, _("FAILED to start up"));
 432   flush_log();
 433
 434   exit(exit_code);
 435 }