log.c revision 1.60
1/* $OpenBSD: log.c,v 1.60 2007/06/02 01:29:11 pvalchev Exp $	 */
2/* $EOM: log.c,v 1.30 2000/09/29 08:19:23 niklas Exp $	 */
3
4/*
5 * Copyright (c) 1998, 1999, 2001 Niklas Hallqvist.  All rights reserved.
6 * Copyright (c) 1999, 2000, 2001, 2003 H�kan Olsson.  All rights reserved.
7 *
8 * Redistribution and use in source and binary forms, with or without
9 * modification, are permitted provided that the following conditions
10 * are met:
11 * 1. Redistributions of source code must retain the above copyright
12 *    notice, this list of conditions and the following disclaimer.
13 * 2. Redistributions in binary form must reproduce the above copyright
14 *    notice, this list of conditions and the following disclaimer in the
15 *    documentation and/or other materials provided with the distribution.
16 *
17 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR
18 * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
19 * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED.
20 * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT,
21 * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT
22 * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
23 * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
24 * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
25 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
26 * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
27 */
28
29/*
30 * This code was written under funding by Ericsson Radio Systems.
31 */
32
33#include <sys/types.h>
34#include <sys/time.h>
35
36#include <sys/socket.h>
37#include <sys/stat.h>
38#include <sys/uio.h>
39#include <netinet/in.h>
40#include <netinet/in_systm.h>
41#include <netinet/ip.h>
42#include <netinet/ip6.h>
43#include <netinet/udp.h>
44#include <arpa/inet.h>
45
46#include <pcap.h>
47
48#include <errno.h>
49#include <stdio.h>
50#include <stdlib.h>
51#include <string.h>
52#include <syslog.h>
53#include <stdarg.h>
54#include <unistd.h>
55
56#include "conf.h"
57#include "isakmp_num.h"
58#include "log.h"
59#include "monitor.h"
60#include "util.h"
61
62static void	_log_print(int, int, const char *, va_list, int, int);
63
64static FILE	*log_output;
65
66int		verbose_logging = 0;
67static int	log_level[LOG_ENDCLASS];
68
69#define TCPDUMP_MAGIC	0xa1b2c3d4
70#define SNAPLEN		(64 * 1024)
71
72struct packhdr {
73	struct pcap_pkthdr pcap;/* pcap file packet header */
74	u_int32_t sa_family;	/* address family */
75	union {
76		struct ip       ip4;	/* IPv4 header (w/o options) */
77		struct ip6_hdr  ip6;	/* IPv6 header */
78	} ip;
79};
80
81struct isakmp_hdr {
82	u_int8_t        icookie[8], rcookie[8];
83	u_int8_t        next, ver, type, flags;
84	u_int32_t       msgid, len;
85};
86
87static char    *pcaplog_file = NULL;
88static FILE    *packet_log;
89static u_int8_t *packet_buf = NULL;
90
91static int      udp_cksum(struct packhdr *, const struct udphdr *,
92    u_int16_t *);
93static u_int16_t in_cksum(const u_int16_t *, int);
94
95void
96log_init(int debug)
97{
98	if (debug)
99		log_output = stderr;
100	else
101		log_to(0);	/* syslog */
102}
103
104void
105log_reinit(void)
106{
107	struct conf_list *logging;
108	struct conf_list_node *logclass;
109	int		class, level;
110
111	logging = conf_get_list("General", "Logverbose");
112	if (logging) {
113		verbose_logging = 1;
114		conf_free_list(logging);
115	}
116	logging = conf_get_list("General", "Loglevel");
117	if (!logging)
118		return;
119
120	for (logclass = TAILQ_FIRST(&logging->fields); logclass;
121	    logclass = TAILQ_NEXT(logclass, link)) {
122		if (sscanf(logclass->field, "%d=%d", &class, &level) != 2) {
123			if (sscanf(logclass->field, "A=%d", &level) == 1)
124				for (class = 0; class < LOG_ENDCLASS; class++)
125					log_debug_cmd(class, level);
126			else {
127				log_print("init: invalid logging class or "
128				    "level: %s", logclass->field);
129				continue;
130			}
131		} else
132			log_debug_cmd(class, level);
133	}
134	conf_free_list(logging);
135}
136
137void
138log_to(FILE *f)
139{
140	if (!log_output && f)
141		closelog();
142	log_output = f;
143	if (!f)
144		openlog("isakmpd", LOG_PID | LOG_CONS, LOG_DAEMON);
145}
146
147FILE *
148log_current(void)
149{
150	return log_output;
151}
152
153static char *
154_log_get_class(int error_class)
155{
156	/* XXX For test purposes. To be removed later on?  */
157	static char	*class_text[] = LOG_CLASSES_TEXT;
158
159	if (error_class < 0)
160		return "Dflt";
161	else if (error_class >= LOG_ENDCLASS)
162		return "Unkn";
163	else
164		return class_text[error_class];
165}
166
167static void
168_log_print(int error, int syslog_level, const char *fmt, va_list ap,
169    int class, int level)
170{
171	char		buffer[LOG_SIZE], nbuf[LOG_SIZE + 32];
172	static const char fallback_msg[] =
173	    "write to log file failed (errno %d), redirecting to syslog";
174	int		len;
175	struct tm      *tm;
176	struct timeval  now;
177	time_t          t;
178
179	len = vsnprintf(buffer, sizeof buffer, fmt, ap);
180	if (len > 0 && len < (int) sizeof buffer - 1 && error)
181		snprintf(buffer + len, sizeof buffer - len, ": %s",
182		    strerror(errno));
183	if (log_output) {
184		gettimeofday(&now, 0);
185		t = now.tv_sec;
186		tm = localtime(&t);
187		if (class >= 0)
188			snprintf(nbuf, sizeof nbuf,
189			    "%02d%02d%02d.%06ld %s %02d ",
190			    tm->tm_hour, tm->tm_min, tm->tm_sec, now.tv_usec,
191			    _log_get_class(class), level);
192		else /* LOG_PRINT (-1) or LOG_REPORT (-2) */
193			snprintf(nbuf, sizeof nbuf, "%02d%02d%02d.%06ld %s ",
194			    tm->tm_hour, tm->tm_min, tm->tm_sec, now.tv_usec,
195			    class == LOG_PRINT ? "Default" : "Report>");
196		strlcat(nbuf, buffer, sizeof nbuf);
197		strlcat(nbuf, getuid() ? "" : " [priv]", LOG_SIZE + 32);
198		strlcat(nbuf, "\n", sizeof nbuf);
199
200		if (fwrite(nbuf, strlen(nbuf), 1, log_output) == 0) {
201			/* Report fallback.  */
202			syslog(LOG_ALERT, fallback_msg, errno);
203			fprintf(log_output, fallback_msg, errno);
204
205			/*
206			 * Close log_output to prevent isakmpd from locking
207			 * the file.  We may need to explicitly close stdout
208			 * to do this properly.
209			 * XXX - Figure out how to match two FILE *'s and
210			 * rewrite.
211			 */
212			if (fileno(log_output) != -1 &&
213			    fileno(stdout) == fileno(log_output))
214				fclose(stdout);
215			fclose(log_output);
216
217			/* Fallback to syslog.  */
218			log_to(0);
219
220			/* (Re)send current message to syslog().  */
221			syslog(class == LOG_REPORT ? LOG_ALERT :
222			    syslog_level, "%s", buffer);
223		}
224	} else
225		syslog(class == LOG_REPORT ? LOG_ALERT : syslog_level, "%s",
226		    buffer);
227}
228
229void
230log_debug(int cls, int level, const char *fmt, ...)
231{
232	va_list         ap;
233
234	/*
235	 * If we are not debugging this class, or the level is too low, just
236	 * return.
237         */
238	if (cls >= 0 && (log_level[cls] == 0 || level > log_level[cls]))
239		return;
240	va_start(ap, fmt);
241	_log_print(0, LOG_INFO, fmt, ap, cls, level);
242	va_end(ap);
243}
244
245void
246log_debug_buf(int cls, int level, const char *header, const u_int8_t *buf,
247    size_t sz)
248{
249	size_t	i, j;
250	char	s[73];
251
252	/*
253	 * If we are not debugging this class, or the level is too low, just
254	 * return.
255         */
256	if (cls >= 0 && (log_level[cls] == 0 || level > log_level[cls]))
257		return;
258
259	log_debug(cls, level, "%s:", header);
260	for (i = j = 0; i < sz;) {
261		snprintf(s + j, sizeof s - j, "%02x", buf[i++]);
262		j += strlen(s + j);
263		if (i % 4 == 0) {
264			if (i % 32 == 0) {
265				s[j] = '\0';
266				log_debug(cls, level, "%s", s);
267				j = 0;
268			} else
269				s[j++] = ' ';
270		}
271	}
272	if (j) {
273		s[j] = '\0';
274		log_debug(cls, level, "%s", s);
275	}
276}
277
278void
279log_debug_cmd(int cls, int level)
280{
281	if (cls < 0 || cls >= LOG_ENDCLASS) {
282		log_print("log_debug_cmd: invalid debugging class %d", cls);
283		return;
284	}
285	if (level < 0) {
286		log_print("log_debug_cmd: invalid debugging level %d for "
287		    "class %d", level, cls);
288		return;
289	}
290	if (level == log_level[cls])
291		log_print("log_debug_cmd: log level unchanged for class %d",
292		    cls);
293	else {
294		log_print("log_debug_cmd: log level changed from %d to %d "
295		    "for class %d", log_level[cls], level, cls);
296		log_level[cls] = level;
297	}
298}
299
300void
301log_debug_toggle(void)
302{
303	static int	log_level_copy[LOG_ENDCLASS], toggle = 0;
304
305	if (!toggle) {
306		LOG_DBG((LOG_MISC, 50, "log_debug_toggle: "
307		    "debug levels cleared"));
308		memcpy(&log_level_copy, &log_level, sizeof log_level);
309		bzero(&log_level, sizeof log_level);
310	} else {
311		memcpy(&log_level, &log_level_copy, sizeof log_level);
312		LOG_DBG((LOG_MISC, 50, "log_debug_toggle: "
313		    "debug levels restored"));
314	}
315	toggle = !toggle;
316}
317
318void
319log_print(const char *fmt, ...)
320{
321	va_list	ap;
322
323	va_start(ap, fmt);
324	_log_print(0, LOG_NOTICE, fmt, ap, LOG_PRINT, 0);
325	va_end(ap);
326}
327
328void
329log_verbose(const char *fmt, ...)
330{
331	va_list	ap;
332	int	i;
333
334	if (verbose_logging == 0)
335		return;
336
337	for (i = 0; i < LOG_ENDCLASS; i++)
338		if (log_level[i] > 0)
339			return;
340
341	va_start(ap, fmt);
342	_log_print(0, LOG_NOTICE, fmt, ap, LOG_PRINT, 0);
343	va_end(ap);
344}
345
346void
347log_error(const char *fmt, ...)
348{
349	va_list	ap;
350
351	va_start(ap, fmt);
352	_log_print(1, LOG_ERR, fmt, ap, LOG_PRINT, 0);
353	va_end(ap);
354}
355
356void
357log_errorx(const char *fmt, ...)
358{
359	va_list ap;
360
361	va_start(ap, fmt);
362	_log_print(0, LOG_ERR, fmt, ap, LOG_PRINT, 0);
363	va_end(ap);
364}
365
366void
367log_fatal(const char *fmt, ...)
368{
369	va_list	ap;
370
371	va_start(ap, fmt);
372	_log_print(1, LOG_CRIT, fmt, ap, LOG_PRINT, 0);
373	va_end(ap);
374	monitor_exit(1);
375}
376
377void
378log_fatalx(const char *fmt, ...)
379{
380	va_list	ap;
381
382	va_start(ap, fmt);
383	_log_print(0, LOG_CRIT, fmt, ap, LOG_PRINT, 0);
384	va_end(ap);
385	monitor_exit(1);
386}
387
388void
389log_packet_init(char *newname)
390{
391	struct pcap_file_header sf_hdr;
392	struct stat     st;
393	mode_t          old_umask;
394	char           *mode;
395
396	/* Allocate packet buffer first time through.  */
397	if (!packet_buf)
398		packet_buf = malloc(SNAPLEN);
399
400	if (!packet_buf) {
401		log_error("log_packet_init: malloc (%d) failed", SNAPLEN);
402		return;
403	}
404	if (pcaplog_file && strcmp(pcaplog_file, PCAP_FILE_DEFAULT) != 0)
405		free(pcaplog_file);
406
407	pcaplog_file = strdup(newname);
408	if (!pcaplog_file) {
409		log_error("log_packet_init: strdup (\"%s\") failed", newname);
410		return;
411	}
412	/* Does the file already exist?  XXX lstat() or stat()?  */
413	/* XXX This is a fstat! */
414	if (monitor_stat(pcaplog_file, &st) == 0) {
415		/* Sanity checks.  */
416		if (!S_ISREG(st.st_mode)) {
417			log_print("log_packet_init: existing capture file is "
418			    "not a regular file");
419			return;
420		}
421		if ((st.st_mode & (S_IRWXG | S_IRWXO)) != 0) {
422			log_print("log_packet_init: existing capture "
423			    "file has bad modes");
424			return;
425		}
426		/*
427		 * XXX It would be nice to check if it actually is a pcap
428		 * file...
429		 */
430
431		mode = "a";
432	} else
433		mode = "w";
434
435	old_umask = umask(S_IRWXG | S_IRWXO);
436	packet_log = monitor_fopen(pcaplog_file, mode);
437	umask(old_umask);
438
439	if (!packet_log) {
440		log_error("log_packet_init: fopen (\"%s\", \"%s\") failed",
441		    pcaplog_file, mode);
442		return;
443	}
444	log_print("log_packet_init: "
445	    "starting IKE packet capture to file \"%s\"", pcaplog_file);
446
447	/* If this is a new file, we need to write a PCAP header to it.  */
448	if (*mode == 'w') {
449		sf_hdr.magic = TCPDUMP_MAGIC;
450		sf_hdr.version_major = PCAP_VERSION_MAJOR;
451		sf_hdr.version_minor = PCAP_VERSION_MINOR;
452		sf_hdr.thiszone = 0;
453		sf_hdr.snaplen = SNAPLEN;
454		sf_hdr.sigfigs = 0;
455		sf_hdr.linktype = DLT_LOOP;
456
457		fwrite((char *) &sf_hdr, sizeof sf_hdr, 1, packet_log);
458		fflush(packet_log);
459	}
460}
461
462void
463log_packet_restart(char *newname)
464{
465	if (packet_log) {
466		log_print("log_packet_restart: capture already active on "
467		    "file \"%s\"", pcaplog_file);
468		return;
469	}
470	if (newname)
471		log_packet_init(newname);
472	else if (!pcaplog_file)
473		log_packet_init(PCAP_FILE_DEFAULT);
474	else
475		log_packet_init(pcaplog_file);
476}
477
478void
479log_packet_stop(void)
480{
481	/* Stop capture.  */
482	if (packet_log) {
483		fclose(packet_log);
484		log_print("log_packet_stop: stopped capture");
485	}
486	packet_log = 0;
487}
488
489void
490log_packet_iov(struct sockaddr *src, struct sockaddr *dst, struct iovec *iov,
491    int iovcnt)
492{
493	struct isakmp_hdr *isakmphdr;
494	struct packhdr  hdr;
495	struct udphdr   udp;
496	struct timeval  tv;
497	int             off, datalen, hdrlen, i, add_espmarker = 0;
498	const u_int32_t	espmarker = 0;
499
500	for (i = 0, datalen = 0; i < iovcnt; i++)
501		datalen += iov[i].iov_len;
502
503	if (!packet_log || datalen > SNAPLEN)
504		return;
505
506	/* copy packet into buffer */
507	for (i = 0, off = 0; i < iovcnt; i++) {
508		memcpy(packet_buf + off, iov[i].iov_base, iov[i].iov_len);
509		off += iov[i].iov_len;
510	}
511
512	bzero(&hdr, sizeof hdr);
513	bzero(&udp, sizeof udp);
514
515	/* isakmp - turn off the encryption bit in the isakmp hdr */
516	isakmphdr = (struct isakmp_hdr *) packet_buf;
517	isakmphdr->flags &= ~(ISAKMP_FLAGS_ENC);
518
519	/* udp */
520	udp.uh_sport = sockaddr_port(src);
521	udp.uh_dport = sockaddr_port(dst);
522	datalen += sizeof udp;
523	if (ntohs(udp.uh_sport) == 4500 ||
524	    ntohs(udp.uh_dport) == 4500) { /* XXX Quick and dirty */
525		add_espmarker = 1;
526		datalen += sizeof espmarker;
527	}
528	udp.uh_ulen = htons(datalen);
529
530	/* ip */
531	hdr.sa_family = htonl(src->sa_family);
532	switch (src->sa_family) {
533	default:
534		/* Assume IPv4. XXX Can 'default' ever happen here?  */
535		hdr.sa_family = htonl(AF_INET);
536		hdr.ip.ip4.ip_src.s_addr = 0x02020202;
537		hdr.ip.ip4.ip_dst.s_addr = 0x01010101;
538		/* The rest of the setup is common to AF_INET.  */
539		goto setup_ip4;
540
541	case AF_INET:
542		hdr.ip.ip4.ip_src.s_addr =
543		    ((struct sockaddr_in *)src)->sin_addr.s_addr;
544		hdr.ip.ip4.ip_dst.s_addr =
545		    ((struct sockaddr_in *)dst)->sin_addr.s_addr;
546
547setup_ip4:
548		hdrlen = sizeof hdr.ip.ip4;
549		hdr.ip.ip4.ip_v = 0x4;
550		hdr.ip.ip4.ip_hl = 0x5;
551		hdr.ip.ip4.ip_p = IPPROTO_UDP;
552		hdr.ip.ip4.ip_len = htons(datalen + hdrlen);
553		/* Let's use the IP ID as a "packet counter".  */
554		i = ntohs(hdr.ip.ip4.ip_id) + 1;
555		hdr.ip.ip4.ip_id = htons(i);
556		/* Calculate IP header checksum. */
557		hdr.ip.ip4.ip_sum = in_cksum((u_int16_t *) & hdr.ip.ip4,
558		    hdr.ip.ip4.ip_hl << 2);
559		break;
560
561	case AF_INET6:
562		hdrlen = sizeof(hdr.ip.ip6);
563		hdr.ip.ip6.ip6_vfc = IPV6_VERSION;
564		hdr.ip.ip6.ip6_nxt = IPPROTO_UDP;
565		hdr.ip.ip6.ip6_plen = udp.uh_ulen;
566		memcpy(&hdr.ip.ip6.ip6_src,
567		    &((struct sockaddr_in6 *)src)->sin6_addr,
568		    sizeof hdr.ip.ip6.ip6_src);
569		memcpy(&hdr.ip.ip6.ip6_dst,
570		    &((struct sockaddr_in6 *)dst)->sin6_addr,
571		    sizeof hdr.ip.ip6.ip6_dst);
572		break;
573	}
574
575	/* Calculate UDP checksum.  */
576	udp.uh_sum = udp_cksum(&hdr, &udp, (u_int16_t *) packet_buf);
577	hdrlen += sizeof hdr.sa_family;
578
579	/* pcap file packet header */
580	gettimeofday(&tv, 0);
581	hdr.pcap.ts.tv_sec = tv.tv_sec;
582	hdr.pcap.ts.tv_usec = tv.tv_usec;
583	hdr.pcap.caplen = datalen + hdrlen;
584	hdr.pcap.len = datalen + hdrlen;
585
586	hdrlen += sizeof(struct pcap_pkthdr);
587	datalen -= sizeof(struct udphdr);
588
589	/* Write to pcap file.  */
590	fwrite(&hdr, hdrlen, 1, packet_log);	/* pcap + IP */
591	fwrite(&udp, sizeof(struct udphdr), 1, packet_log);	/* UDP */
592	if (add_espmarker) {
593		fwrite(&espmarker, sizeof espmarker, 1, packet_log);
594		datalen -= sizeof espmarker;
595	}
596	fwrite(packet_buf, datalen, 1, packet_log);	/* IKE-data */
597	fflush(packet_log);
598}
599
600/* Copied from tcpdump/print-udp.c, mostly rewritten.  */
601static int
602udp_cksum(struct packhdr *hdr, const struct udphdr *u, u_int16_t *d)
603{
604	struct ip	*ip4;
605	struct ip6_hdr	*ip6;
606	int	i, hdrlen, tlen = ntohs(u->uh_ulen) - sizeof(struct udphdr);
607
608	union phu {
609		struct ip4pseudo {
610			struct in_addr  src;
611			struct in_addr  dst;
612			u_int8_t        z;
613			u_int8_t        proto;
614			u_int16_t       len;
615		} ip4p;
616		struct ip6pseudo {
617			struct in6_addr src;
618			struct in6_addr dst;
619			u_int32_t       plen;
620			u_int16_t       z0;
621			u_int8_t        z1;
622			u_int8_t        nxt;
623		} ip6p;
624		u_int16_t       pa[20];
625	} phu;
626	const u_int16_t *sp;
627	u_int32_t       sum;
628
629	/* Setup pseudoheader.  */
630	bzero(phu.pa, sizeof phu);
631	switch (ntohl(hdr->sa_family)) {
632	case AF_INET:
633		ip4 = &hdr->ip.ip4;
634		memcpy(&phu.ip4p.src, &ip4->ip_src, sizeof(struct in_addr));
635		memcpy(&phu.ip4p.dst, &ip4->ip_dst, sizeof(struct in_addr));
636		phu.ip4p.proto = ip4->ip_p;
637		phu.ip4p.len = u->uh_ulen;
638		hdrlen = sizeof phu.ip4p;
639		break;
640
641	case AF_INET6:
642		ip6 = &hdr->ip.ip6;
643		memcpy(&phu.ip6p.src, &ip6->ip6_src, sizeof(phu.ip6p.src));
644		memcpy(&phu.ip6p.dst, &ip6->ip6_dst, sizeof(phu.ip6p.dst));
645		phu.ip6p.plen = u->uh_ulen;
646		phu.ip6p.nxt = ip6->ip6_nxt;
647		hdrlen = sizeof phu.ip6p;
648		break;
649
650	default:
651		return 0;
652	}
653
654	/* IPv6 wants a 0xFFFF checksum "on error", not 0x0.  */
655	if (tlen < 0)
656		return (ntohl(hdr->sa_family) == AF_INET ? 0 : 0xFFFF);
657
658	sum = 0;
659	for (i = 0; i < hdrlen; i += 2)
660		sum += phu.pa[i / 2];
661
662	sp = (const u_int16_t *)u;
663	for (i = 0; i < (int)sizeof(struct udphdr); i += 2)
664		sum += *sp++;
665
666	sp = d;
667	for (i = 0; i < (tlen & ~1); i += 2)
668		sum += *sp++;
669
670	if (tlen & 1)
671		sum += htons((*(const char *)sp) << 8);
672
673	while (sum > 0xffff)
674		sum = (sum & 0xffff) + (sum >> 16);
675	sum = ~sum & 0xffff;
676
677	return sum;
678}
679
680/* Copied from tcpdump/print-ip.c, modified.  */
681static u_int16_t
682in_cksum(const u_int16_t *w, int len)
683{
684	int		nleft = len, sum = 0;
685	u_int16_t       answer;
686
687	while (nleft > 1) {
688		sum += *w++;
689		nleft -= 2;
690	}
691	if (nleft == 1)
692		sum += htons(*(const u_char *)w << 8);
693
694	sum = (sum >> 16) + (sum & 0xffff);	/* add hi 16 to low 16 */
695	sum += (sum >> 16);	/* add carry */
696	answer = ~sum;		/* truncate to 16 bits */
697	return answer;
698}
699