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