src/log.c

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