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