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