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() */
36static int log_fac = LOG_DAEMON;
37static int log_stderr = 0;
38static int echo_stderr = 0;
39static int log_fd = -1;
40static int log_to_file = 0;
41static int entries_alloced = 0;
42static int entries_lost = 0;
43static int connection_good = 1;
44static int max_logs = 0;
45static int connection_type = SOCK_DGRAM;
46
47struct 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
54static struct log_entry *entries = NULL;
55static struct log_entry *free_entries = NULL;
56
57
58int 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
111int 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
143static 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
151static 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*/
277void 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
424void set_log_writer(void)
425{
426  if (entries && log_fd != -1 && connection_good)
427    poll_listen(log_fd, POLLOUT);
428}
429
430void check_log_writer(int force)
431{
432  if (log_fd != -1 && (force || poll_check(log_fd, POLLOUT)))
433    log_write();
434}
435
436void flush_log(void)
437{
438  /* write until queue empty, but don't loop forever if there's
439   no connection to the syslog in existance */
440  while (log_fd != -1)
441    {
442      struct timespec waiter;
443      log_write();
444      if (!entries || !connection_good)
445	{
446	  close(log_fd);
447	  break;
448	}
449      waiter.tv_sec = 0;
450      waiter.tv_nsec = 1000000; /* 1 ms */
451      nanosleep(&waiter, NULL);
452    }
453}
454
455void die(char *message, char *arg1, int exit_code)
456{
457  char *errmess = strerror(errno);
458
459  if (!arg1)
460    arg1 = errmess;
461
462  if (!log_stderr)
463    {
464      echo_stderr = 1; /* print as well as log when we die.... */
465      fputc('\n', stderr); /* prettyfy  startup-script message */
466    }
467  my_syslog(LOG_CRIT, message, arg1, errmess);
468  echo_stderr = 0;
469  my_syslog(LOG_CRIT, _("FAILED to start up"));
470  flush_log();
471
472  exit(exit_code);
473}
474