src/log.c

   1 /* dnsmasq is Copyright (c) 2000-2022 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
 105      If we've created a file with group-id root, we also make
 106      the file group-writable. This gives processes in the root group
 107      write access to the file and avoids the problem that on some systems,
 108      once the file is owned by the dnsmasq user, it can't be written
 109      whilst dnsmasq is running as root during startup.
 110  */
 111   if (log_to_file && !log_stderr && ent_pw && ent_pw->pw_uid != 0)
 112     {
 113       struct stat ls;
 114       if (getgid() == 0 && fstat(log_fd, &ls) == 0 && ls.st_gid == 0 &&
 115           (ls.st_mode & S_IWGRP) == 0)
 116         (void)fchmod(log_fd, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP);
 117       if (fchown(log_fd, ent_pw->pw_uid, -1) != 0)
 118         ret = errno;
 119     }
 120
 121   return ret;
 122 }
 123
 124 int log_reopen(char *log_file)
 125 {
 126   if (!log_stderr)
 127     {
 128       if (log_fd != -1)
 129         close(log_fd);
 130
 131       /* NOTE: umask is set to 022 by the time this gets called */
 132
 133       if (log_file)
 134         log_fd = open(log_file, O_WRONLY|O_CREAT|O_APPEND, S_IRUSR|S_IWUSR|S_IRGRP);
 135       else
 136         {
 137 #if defined(HAVE_SOLARIS_NETWORK) || defined(__ANDROID__)
 138           /* Solaris logging is "different", /dev/log is not unix-domain socket.
 139              Just leave log_fd == -1 and use the vsyslog call for everything.... */
 140 #   define _PATH_LOG ""  /* dummy */
 141           return 1;
 142 #else
 143           int flags;
 144           log_fd = socket(AF_UNIX, connection_type, 0);
 145
 146           /* if max_logs is zero, leave the socket blocking */
 147           if (log_fd != -1 && max_logs != 0 && (flags = fcntl(log_fd, F_GETFL)) != -1)
 148             fcntl(log_fd, F_SETFL, flags | O_NONBLOCK);
 149 #endif
 150         }
 151     }
 152
 153   return log_fd != -1;
 154 }
 155
 156 static void free_entry(void)
 157 {
 158   struct log_entry *tmp = entries;
 159   entries = tmp->next;
 160   tmp->next = free_entries;
 161   free_entries = tmp;
 162 }
 163
 164 static void log_write(void)
 165 {
 166   ssize_t rc;
 167
 168   while (entries)
 169     {
 170       /* The data in the payload is written with a terminating zero character
 171          and the length reflects this. For a stream connection we need to
 172          send the zero as a record terminator, but this isn't done for a
 173          datagram connection, so treat the length as one less than reality
 174          to elide the zero. If we're logging to a file, turn the zero into
 175          a newline, and leave the length alone. */
 176       int len_adjust = 0;
 177
 178       if (log_to_file)
 179         entries->payload[entries->offset + entries->length - 1] = '\n';
 180       else if (connection_type == SOCK_DGRAM)
 181         len_adjust = 1;
 182
 183       /* Avoid duplicates over a fork() */
 184       if (entries->pid != getpid())
 185         {
 186           free_entry();
 187           continue;
 188         }
 189
 190       connection_good = 1;
 191
 192       if ((rc = write(log_fd, entries->payload + entries->offset, entries->length - len_adjust)) != -1)
 193         {
 194           entries->length -= rc;
 195           entries->offset += rc;
 196           if (entries->length == len_adjust)
 197             {
 198               free_entry();
 199               if (entries_lost != 0)
 200                 {
 201                   int e = entries_lost;
 202                   entries_lost = 0; /* avoid wild recursion */
 203                   my_syslog(LOG_WARNING, _("overflow: %d log entries lost"), e);
 204                 }
 205             }
 206           continue;
 207         }
 208
 209       if (errno == EINTR)
 210         continue;
 211
 212       if (errno == EAGAIN || errno == EWOULDBLOCK)
 213         return; /* syslogd busy, go again when select() or poll() says so */
 214
 215       if (errno == ENOBUFS)
 216         {
 217           connection_good = 0;
 218           return;
 219         }
 220
 221       /* errors handling after this assumes sockets */
 222       if (!log_to_file)
 223         {
 224           /* Once a stream socket hits EPIPE, we have to close and re-open
 225              (we ignore SIGPIPE) */
 226           if (errno == EPIPE)
 227             {
 228               if (log_reopen(NULL))
 229                 continue;
 230             }
 231           else if (errno == ECONNREFUSED ||
 232                    errno == ENOTCONN ||
 233                    errno == EDESTADDRREQ ||
 234                    errno == ECONNRESET)
 235             {
 236               /* socket went (syslogd down?), try and reconnect. If we fail,
 237                  stop trying until the next call to my_syslog()
 238                  ECONNREFUSED -> connection went down
 239                  ENOTCONN -> nobody listening
 240                  (ECONNRESET, EDESTADDRREQ are *BSD equivalents) */
 241
 242               struct sockaddr_un logaddr;
 243
 244 #ifdef HAVE_SOCKADDR_SA_LEN
 245               logaddr.sun_len = sizeof(logaddr) - sizeof(logaddr.sun_path) + strlen(_PATH_LOG) + 1;
 246 #endif
 247               logaddr.sun_family = AF_UNIX;
 248               safe_strncpy(logaddr.sun_path, _PATH_LOG, sizeof(logaddr.sun_path));
 249
 250               /* Got connection back? try again. */
 251               if (connect(log_fd, (struct sockaddr *)&logaddr, sizeof(logaddr)) != -1)
 252                 continue;
 253
 254               /* errors from connect which mean we should keep trying */
 255               if (errno == ENOENT ||
 256                   errno == EALREADY ||
 257                   errno == ECONNREFUSED ||
 258                   errno == EISCONN ||
 259                   errno == EINTR ||
 260                   errno == EAGAIN ||
 261                   errno == EWOULDBLOCK)
 262                 {
 263                   /* try again on next syslog() call */
 264                   connection_good = 0;
 265                   return;
 266                 }
 267
 268               /* try the other sort of socket... */
 269               if (errno == EPROTOTYPE)
 270                 {
 271                   connection_type = connection_type == SOCK_DGRAM ? SOCK_STREAM : SOCK_DGRAM;
 272                   if (log_reopen(NULL))
 273                     continue;
 274                 }
 275             }
 276         }
 277
 278       /* give up - fall back to syslog() - this handles out-of-space
 279          when logging to a file, for instance. */
 280       log_fd = -1;
 281       my_syslog(LOG_CRIT, _("log failed: %s"), strerror(errno));
 282       return;
 283     }
 284 }
 285
 286 /* priority is one of LOG_DEBUG, LOG_INFO, LOG_NOTICE, etc. See sys/syslog.h.
 287    OR'd to priority can be MS_TFTP, MS_DHCP, ... to be able to do log separation between
 288    DNS, DHCP and TFTP services.
 289    If OR'd with MS_DEBUG, the messages are suppressed unless --log-debug is set. */
 290 void my_syslog(int priority, const char *format, ...)
 291 {
 292   va_list ap;
 293   struct log_entry *entry;
 294   time_t time_now;
 295   char *p;
 296   size_t len;
 297   pid_t pid = getpid();
 298   char *func = "";
 299
 300   if ((LOG_FACMASK & priority) == MS_TFTP)
 301     func = "-tftp";
 302   else if ((LOG_FACMASK & priority) == MS_DHCP)
 303     func = "-dhcp";
 304   else if ((LOG_FACMASK & priority) == MS_SCRIPT)
 305     func = "-script";
 306   else if ((LOG_FACMASK & priority) == MS_DEBUG)
 307     {
 308       if (!option_bool(OPT_LOG_DEBUG))
 309         return;
 310       func = "-debug";
 311     }
 312
 313 #ifdef LOG_PRI
 314   priority = LOG_PRI(priority);
 315 #else
 316   /* Solaris doesn't have LOG_PRI */
 317   priority &= LOG_PRIMASK;
 318 #endif
 319
 320   if (echo_stderr)
 321     {
 322       fprintf(stderr, "dnsmasq%s: ", func);
 323       va_start(ap, format);
 324       vfprintf(stderr, format, ap);
 325       va_end(ap);
 326       fputc('\n', stderr);
 327     }
 328
 329   if (log_fd == -1)
 330     {
 331 #ifdef __ANDROID__
 332       /* do android-specific logging.
 333          log_fd is always -1 on Android except when logging to a file. */
 334       int alog_lvl;
 335
 336       if (priority <= LOG_ERR)
 337         alog_lvl = ANDROID_LOG_ERROR;
 338       else if (priority == LOG_WARNING)
 339         alog_lvl = ANDROID_LOG_WARN;
 340       else if (priority <= LOG_INFO)
 341         alog_lvl = ANDROID_LOG_INFO;
 342       else
 343         alog_lvl = ANDROID_LOG_DEBUG;
 344
 345       va_start(ap, format);
 346       __android_log_vprint(alog_lvl, "dnsmasq", format, ap);
 347       va_end(ap);
 348 #else
 349       /* fall-back to syslog if we die during startup or
 350          fail during running (always on Solaris). */
 351       static int isopen = 0;
 352
 353       if (!isopen)
 354         {
 355           openlog("dnsmasq", LOG_PID, log_fac);
 356           isopen = 1;
 357         }
 358       va_start(ap, format);
 359       vsyslog(priority, format, ap);
 360       va_end(ap);
 361 #endif
 362
 363       return;
 364     }
 365
 366   if ((entry = free_entries))
 367     free_entries = entry->next;
 368   else if (entries_alloced < max_logs && (entry = malloc(sizeof(struct log_entry))))
 369     entries_alloced++;
 370
 371   if (!entry)
 372     entries_lost++;
 373   else
 374     {
 375       /* add to end of list, consumed from the start */
 376       entry->next = NULL;
 377       if (!entries)
 378         entries = entry;
 379       else
 380         {
 381           struct log_entry *tmp;
 382           for (tmp = entries; tmp->next; tmp = tmp->next);
 383           tmp->next = entry;
 384         }
 385
 386       time(&time_now);
 387       p = entry->payload;
 388       if (!log_to_file)
 389         p += sprintf(p, "<%d>", priority | log_fac);
 390
 391       /* Omit timestamp for default daemontools situation */
 392       if (!log_stderr || !option_bool(OPT_NO_FORK))
 393         p += sprintf(p, "%.15s ", ctime(&time_now) + 4);
 394
 395       p += sprintf(p, "dnsmasq%s[%d]: ", func, (int)pid);
 396
 397       len = p - entry->payload;
 398       va_start(ap, format);
 399       len += vsnprintf(p, MAX_MESSAGE - len, format, ap) + 1; /* include zero-terminator */
 400       va_end(ap);
 401       entry->length = len > MAX_MESSAGE ? MAX_MESSAGE : len;
 402       entry->offset = 0;
 403       entry->pid = pid;
 404     }
 405
 406   /* almost always, logging won't block, so try and write this now,
 407      to save collecting too many log messages during a select loop. */
 408   log_write();
 409
 410   /* Since we're doing things asynchronously, a cache-dump, for instance,
 411      can now generate log lines very fast. With a small buffer (desirable),
 412      that means it can overflow the log-buffer very quickly,
 413      so that the cache dump becomes mainly a count of how many lines
 414      overflowed. To avoid this, we delay here, the delay is controlled
 415      by queue-occupancy, and grows exponentially. The delay is limited to (2^8)ms.
 416      The scaling stuff ensures that when the queue is bigger than 8, the delay
 417      only occurs for the last 8 entries. Once the queue is full, we stop delaying
 418      to preserve performance.
 419   */
 420
 421   if (entries && max_logs != 0)
 422     {
 423       int d;
 424
 425       for (d = 0,entry = entries; entry; entry = entry->next, d++);
 426
 427       if (d == max_logs)
 428         d = 0;
 429       else if (max_logs > 8)
 430         d -= max_logs - 8;
 431
 432       if (d > 0)
 433         {
 434           struct timespec waiter;
 435           waiter.tv_sec = 0;
 436           waiter.tv_nsec = 1000000 << (d - 1); /* 1 ms */
 437           nanosleep(&waiter, NULL);
 438
 439           /* Have another go now */
 440           log_write();
 441         }
 442     }
 443 }
 444
 445 void set_log_writer(void)
 446 {
 447   if (entries && log_fd != -1 && connection_good)
 448     poll_listen(log_fd, POLLOUT);
 449 }
 450
 451 void check_log_writer(int force)
 452 {
 453   if (log_fd != -1 && (force || poll_check(log_fd, POLLOUT)))
 454     log_write();
 455 }
 456
 457 void flush_log(void)
 458 {
 459   /* write until queue empty, but don't loop forever if there's
 460    no connection to the syslog in existence */
 461   while (log_fd != -1)
 462     {
 463       struct timespec waiter;
 464       log_write();
 465       if (!entries || !connection_good)
 466         {
 467           close(log_fd);
 468           break;
 469         }
 470       waiter.tv_sec = 0;
 471       waiter.tv_nsec = 1000000; /* 1 ms */
 472       nanosleep(&waiter, NULL);
 473     }
 474 }
 475
 476 void die(char *message, char *arg1, int exit_code)
 477 {
 478   char *errmess = strerror(errno);
 479
 480   if (!arg1)
 481     arg1 = errmess;
 482
 483   if (!log_stderr)
 484     {
 485       echo_stderr = 1; /* print as well as log when we die.... */
 486       fputc('\n', stderr); /* prettyfy  startup-script message */
 487     }
 488   my_syslog(LOG_CRIT, message, arg1, errmess);
 489   echo_stderr = 0;
 490   my_syslog(LOG_CRIT, _("FAILED to start up"));
 491   flush_log();
 492
 493   exit(exit_code);
 494 }