blob: f532f93f64334b07a2dcf4c61f24084cd7f09083 [file] [log] [blame]
Simon Kelley61744352013-01-31 14:34:40 +00001/* dnsmasq is Copyright (c) 2000-2013 Simon Kelley
Simon Kelleyf2621c72007-04-29 19:47:21 +01002
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
Simon Kelley824af852008-02-12 20:43:05 +00005 the Free Software Foundation; version 2 dated June, 1991, or
6 (at your option) version 3 dated 29 June, 2007.
7
Simon Kelleyf2621c72007-04-29 19:47:21 +01008 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.
Simon Kelley824af852008-02-12 20:43:05 +000012
Simon Kelley73a08a22009-02-05 20:28:08 +000013 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/>.
Simon Kelleyf2621c72007-04-29 19:47:21 +010015*/
16
17#include "dnsmasq.h"
18
Simon Kelley572b41e2011-02-18 18:11:18 +000019#ifdef __ANDROID__
20# include <android/log.h>
21#endif
22
Simon Kelleyf2621c72007-04-29 19:47:21 +010023/* 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;
Simon Kelley8ef5ada2010-06-03 19:42:45 +010037static int log_stderr = 0;
38static int echo_stderr = 0;
Simon Kelleyf2621c72007-04-29 19:47:21 +010039static 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;
Simon Kelley5aabfc72007-08-29 11:24:47 +010045static int connection_type = SOCK_DGRAM;
Simon Kelleyf2621c72007-04-29 19:47:21 +010046
47struct log_entry {
48 int offset, length;
Simon Kelley5aabfc72007-08-29 11:24:47 +010049 pid_t pid; /* to avoid duplicates over a fork */
Simon Kelleyf2621c72007-04-29 19:47:21 +010050 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
Simon Kelley1a6bca82008-07-11 11:11:42 +010058int log_start(struct passwd *ent_pw, int errfd)
Simon Kelleyf2621c72007-04-29 19:47:21 +010059{
Simon Kelley1a6bca82008-07-11 11:11:42 +010060 int ret = 0;
61
Simon Kelley28866e92011-02-14 20:19:14 +000062 echo_stderr = option_bool(OPT_DEBUG);
Simon Kelleyf2621c72007-04-29 19:47:21 +010063
64 if (daemon->log_fac != -1)
65 log_fac = daemon->log_fac;
66#ifdef LOG_LOCAL0
Simon Kelley28866e92011-02-14 20:19:14 +000067 else if (option_bool(OPT_DEBUG))
Simon Kelleyf2621c72007-04-29 19:47:21 +010068 log_fac = LOG_LOCAL0;
69#endif
70
71 if (daemon->log_file)
Simon Kelley5aabfc72007-08-29 11:24:47 +010072 {
Simon Kelleyf2621c72007-04-29 19:47:21 +010073 log_to_file = 1;
74 daemon->max_logs = 0;
Simon Kelley8ef5ada2010-06-03 19:42:45 +010075 if (strcmp(daemon->log_file, "-") == 0)
76 {
77 log_stderr = 1;
78 echo_stderr = 0;
79 log_fd = dup(STDERR_FILENO);
80 }
Simon Kelleyf2621c72007-04-29 19:47:21 +010081 }
Simon Kelleyf2621c72007-04-29 19:47:21 +010082
Simon Kelley5aabfc72007-08-29 11:24:47 +010083 max_logs = daemon->max_logs;
84
85 if (!log_reopen(daemon->log_file))
Simon Kelley1a6bca82008-07-11 11:11:42 +010086 {
Simon Kelleyc72daea2012-01-05 21:33:27 +000087 send_event(errfd, EVENT_LOG_ERR, errno, daemon->log_file ? daemon->log_file : "");
Simon Kelley1a6bca82008-07-11 11:11:42 +010088 _exit(0);
89 }
90
Simon Kelleyf2621c72007-04-29 19:47:21 +010091 /* if queuing is inhibited, make sure we allocate
92 the one required buffer now. */
Simon Kelley5aabfc72007-08-29 11:24:47 +010093 if (max_logs == 0)
Simon Kelleyf2621c72007-04-29 19:47:21 +010094 {
95 free_entries = safe_malloc(sizeof(struct log_entry));
96 free_entries->next = NULL;
97 entries_alloced = 1;
98 }
Simon Kelley824af852008-02-12 20:43:05 +000099
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) */
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100104 if (log_to_file && !log_stderr && ent_pw && ent_pw->pw_uid != 0 &&
Simon Kelley1a6bca82008-07-11 11:11:42 +0100105 fchown(log_fd, ent_pw->pw_uid, -1) != 0)
106 ret = errno;
107
108 return ret;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100109}
Simon Kelleyf2621c72007-04-29 19:47:21 +0100110
Simon Kelley5aabfc72007-08-29 11:24:47 +0100111int log_reopen(char *log_file)
112{
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100113 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 {
Simon Kelley572b41e2011-02-18 18:11:18 +0000124#if defined(HAVE_SOLARIS_NETWORK) || defined(__ANDROID__)
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100125 /* Solaris logging is "different", /dev/log is not unix-domain socket.
126 Just leave log_fd == -1 and use the vsyslog call for everything.... */
Simon Kelley824af852008-02-12 20:43:05 +0000127# define _PATH_LOG "" /* dummy */
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100128 return 1;
Simon Kelley824af852008-02-12 20:43:05 +0000129#else
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100130 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);
Simon Kelley824af852008-02-12 20:43:05 +0000136#endif
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100137 }
138 }
139
140 return log_fd != -1;
Simon Kelleyf2621c72007-04-29 19:47:21 +0100141}
Simon Kelley5aabfc72007-08-29 11:24:47 +0100142
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
Simon Kelleyf2621c72007-04-29 19:47:21 +0100151static void log_write(void)
152{
153 ssize_t rc;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100154
Simon Kelleyf2621c72007-04-29 19:47:21 +0100155 while (entries)
156 {
Simon Kelley7de060b2011-08-26 17:24:52 +0100157 /* 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
Simon Kelley5aabfc72007-08-29 11:24:47 +0100170 /* Avoid duplicates over a fork() */
171 if (entries->pid != getpid())
172 {
173 free_entry();
174 continue;
175 }
176
Simon Kelleyf2621c72007-04-29 19:47:21 +0100177 connection_good = 1;
178
Simon Kelley7de060b2011-08-26 17:24:52 +0100179 if ((rc = write(log_fd, entries->payload + entries->offset, entries->length - len_adjust)) != -1)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100180 {
181 entries->length -= rc;
182 entries->offset += rc;
Simon Kelley7de060b2011-08-26 17:24:52 +0100183 if (entries->length == len_adjust)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100184 {
Simon Kelley5aabfc72007-08-29 11:24:47 +0100185 free_entry();
Simon Kelleyf2621c72007-04-29 19:47:21 +0100186 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
Simon Kelleyc72daea2012-01-05 21:33:27 +0000199 if (errno == EAGAIN || errno == EWOULDBLOCK)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100200 return; /* syslogd busy, go again when select() or poll() says so */
201
202 if (errno == ENOBUFS)
203 {
204 connection_good = 0;
205 return;
206 }
Simon Kelley5aabfc72007-08-29 11:24:47 +0100207
208 /* errors handling after this assumes sockets */
209 if (!log_to_file)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100210 {
Simon Kelley5aabfc72007-08-29 11:24:47 +0100211 /* Once a stream socket hits EPIPE, we have to close and re-open
212 (we ignore SIGPIPE) */
213 if (errno == EPIPE)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100214 {
Simon Kelley5aabfc72007-08-29 11:24:47 +0100215 if (log_reopen(NULL))
216 continue;
Simon Kelleyf2621c72007-04-29 19:47:21 +0100217 }
Simon Kelley5aabfc72007-08-29 11:24:47 +0100218 else if (errno == ECONNREFUSED ||
219 errno == ENOTCONN ||
220 errno == EDESTADDRREQ ||
221 errno == ECONNRESET)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100222 {
Simon Kelley5aabfc72007-08-29 11:24:47 +0100223 /* 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
Simon Kelley824af852008-02-12 20:43:05 +0000234 logaddr.sun_family = AF_UNIX;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100235 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 ||
Simon Kelleyc72daea2012-01-05 21:33:27 +0000247 errno == EAGAIN ||
248 errno == EWOULDBLOCK)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100249 {
Simon Kelley5aabfc72007-08-29 11:24:47 +0100250 /* 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;
Simon Kelleyf2621c72007-04-29 19:47:21 +0100261 }
262 }
263 }
Simon Kelley5aabfc72007-08-29 11:24:47 +0100264
Simon Kelleyf2621c72007-04-29 19:47:21 +0100265 /* 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
Simon Kelley7622fc02009-06-04 20:32:05 +0100273/* 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*/
Simon Kelleyf2621c72007-04-29 19:47:21 +0100277void 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;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100284 pid_t pid = getpid();
Simon Kelley7622fc02009-06-04 20:32:05 +0100285 char *func = "";
Simon Kelley5aabfc72007-08-29 11:24:47 +0100286
Simon Kelley7622fc02009-06-04 20:32:05 +0100287 if ((LOG_FACMASK & priority) == MS_TFTP)
288 func = "-tftp";
289 else if ((LOG_FACMASK & priority) == MS_DHCP)
290 func = "-dhcp";
291
Simon Kelley316e2732010-01-22 20:16:09 +0000292#ifdef LOG_PRI
Simon Kelley7622fc02009-06-04 20:32:05 +0100293 priority = LOG_PRI(priority);
Simon Kelley316e2732010-01-22 20:16:09 +0000294#else
295 /* Solaris doesn't have LOG_PRI */
296 priority &= LOG_PRIMASK;
297#endif
298
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100299 if (echo_stderr)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100300 {
Simon Kelley7622fc02009-06-04 20:32:05 +0100301 fprintf(stderr, "dnsmasq%s: ", func);
Simon Kelley824af852008-02-12 20:43:05 +0000302 va_start(ap, format);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100303 vfprintf(stderr, format, ap);
Simon Kelley824af852008-02-12 20:43:05 +0000304 va_end(ap);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100305 fputc('\n', stderr);
306 }
Simon Kelley824af852008-02-12 20:43:05 +0000307
Simon Kelleyf2621c72007-04-29 19:47:21 +0100308 if (log_fd == -1)
309 {
Simon Kelley572b41e2011-02-18 18:11:18 +0000310#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). */
Simon Kelleyf2621c72007-04-29 19:47:21 +0100330 static int isopen = 0;
Simon Kelley572b41e2011-02-18 18:11:18 +0000331
Simon Kelleyf2621c72007-04-29 19:47:21 +0100332 if (!isopen)
333 {
334 openlog("dnsmasq", LOG_PID, log_fac);
335 isopen = 1;
336 }
Simon Kelley824af852008-02-12 20:43:05 +0000337 va_start(ap, format);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100338 vsyslog(priority, format, ap);
339 va_end(ap);
Simon Kelley572b41e2011-02-18 18:11:18 +0000340#endif
341
Simon Kelleyf2621c72007-04-29 19:47:21 +0100342 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);
Simon Kelley7622fc02009-06-04 20:32:05 +0100369
Simon Kelley28866e92011-02-14 20:19:14 +0000370 /* 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);
Simon Kelley7622fc02009-06-04 20:32:05 +0100375
Simon Kelleyf2621c72007-04-29 19:47:21 +0100376 len = p - entry->payload;
Simon Kelley824af852008-02-12 20:43:05 +0000377 va_start(ap, format);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100378 len += vsnprintf(p, MAX_MESSAGE - len, format, ap) + 1; /* include zero-terminator */
Simon Kelley824af852008-02-12 20:43:05 +0000379 va_end(ap);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100380 entry->length = len > MAX_MESSAGE ? MAX_MESSAGE : len;
381 entry->offset = 0;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100382 entry->pid = pid;
Simon Kelleyf2621c72007-04-29 19:47:21 +0100383 }
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 }
Simon Kelleyf2621c72007-04-29 19:47:21 +0100422}
423
424void 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
433void check_log_writer(fd_set *set)
434{
Simon Kelley5aabfc72007-08-29 11:24:47 +0100435 if (log_fd != -1 && (!set || FD_ISSET(log_fd, set)))
Simon Kelleyf2621c72007-04-29 19:47:21 +0100436 log_write();
437}
438
Simon Kelley5aabfc72007-08-29 11:24:47 +0100439void flush_log(void)
440{
Simon Kelley28866e92011-02-14 20:19:14 +0000441 /* write until queue empty, but don't loop forever if there's
442 no connection to the syslog in existance */
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100443 while (log_fd != -1)
Simon Kelley5aabfc72007-08-29 11:24:47 +0100444 {
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100445 struct timespec waiter;
Simon Kelley5aabfc72007-08-29 11:24:47 +0100446 log_write();
Simon Kelley28866e92011-02-14 20:19:14 +0000447 if (!entries || !connection_good)
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100448 {
449 close(log_fd);
450 break;
451 }
452 waiter.tv_sec = 0;
453 waiter.tv_nsec = 1000000; /* 1 ms */
454 nanosleep(&waiter, NULL);
Simon Kelley5aabfc72007-08-29 11:24:47 +0100455 }
456}
457
458void die(char *message, char *arg1, int exit_code)
Simon Kelleyf2621c72007-04-29 19:47:21 +0100459{
460 char *errmess = strerror(errno);
461
462 if (!arg1)
463 arg1 = errmess;
464
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100465 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 }
Simon Kelleyf2621c72007-04-29 19:47:21 +0100470 my_syslog(LOG_CRIT, message, arg1, errmess);
Simon Kelley8ef5ada2010-06-03 19:42:45 +0100471 echo_stderr = 0;
Simon Kelleyf2621c72007-04-29 19:47:21 +0100472 my_syslog(LOG_CRIT, _("FAILED to start up"));
Simon Kelley5aabfc72007-08-29 11:24:47 +0100473 flush_log();
Simon Kelleyf2621c72007-04-29 19:47:21 +0100474
Simon Kelley5aabfc72007-08-29 11:24:47 +0100475 exit(exit_code);
Simon Kelleyf2621c72007-04-29 19:47:21 +0100476}