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