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