log.c revision 1.30
1/*	$OpenBSD: log.c,v 1.30 2002/08/08 13:25:28 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#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  struct stat st;
334  mode_t old_umask;
335  char *mode;
336
337  /* Allocate packet buffer first time through.  */
338  if (!packet_buf)
339    packet_buf = malloc (SNAPLEN);
340
341  if (!packet_buf)
342    {
343      log_error ("log_packet_init: malloc (%d) failed", SNAPLEN);
344      return;
345    }
346
347  if (pcaplog_file && strcmp (pcaplog_file, PCAP_FILE_DEFAULT) != 0)
348    free (pcaplog_file);
349
350  pcaplog_file = strdup (newname);
351  if (!pcaplog_file)
352    {
353      log_error ("log_packet_init: strdup (\"%s\") failed", newname);
354      return;
355    }
356
357  /* Does the file already exist?  XXX lstat() or stat()?  */
358  if (lstat (pcaplog_file, &st) == 0)
359    {
360      /* Sanity checks.  */
361      if ((st.st_mode & S_IFMT) != S_IFREG)
362	{
363	  log_print ("log_packet_init: existing capture file is "
364		     "not a regular file");
365	  return;
366	}
367
368      if ((st.st_mode & (S_IRWXG | S_IRWXO)) != 0)
369	{
370	  log_print ("log_packet_init: existing capture file has bad modes");
371	  return;
372	}
373
374      /* XXX It would be nice to check if it actually is a pcap file... */
375
376      mode = "a";
377    }
378  else
379    mode = "w";
380
381  old_umask = umask (S_IRWXG | S_IRWXO);
382  packet_log = fopen (pcaplog_file, mode);
383  umask (old_umask);
384
385  if (!packet_log)
386    {
387      log_error ("log_packet_init: fopen (\"%s\", \"%s\") failed",
388		 pcaplog_file, mode);
389      return;
390    }
391
392  log_print ("log_packet_init: starting IKE packet capture to file \"%s\"",
393	     pcaplog_file);
394
395  /* If this is a new file, we need to write a PCAP header to it.  */
396  if (*mode == 'w')
397    {
398      sf_hdr.magic = TCPDUMP_MAGIC;
399      sf_hdr.version_major = PCAP_VERSION_MAJOR;
400      sf_hdr.version_minor = PCAP_VERSION_MINOR;
401      sf_hdr.thiszone = 0;
402      sf_hdr.snaplen = SNAPLEN;
403      sf_hdr.sigfigs = 0;
404      sf_hdr.linktype = DLT_LOOP;
405
406      fwrite ((char *)&sf_hdr, sizeof sf_hdr, 1, packet_log);
407      fflush (packet_log);
408    }
409}
410
411void
412log_packet_restart (char *newname)
413{
414  if (packet_log)
415    {
416      log_print ("log_packet_restart: capture already active on file \"%s\"",
417		 pcaplog_file);
418      return;
419    }
420
421  if (newname)
422    log_packet_init (newname);
423  else if (!pcaplog_file)
424    log_packet_init (PCAP_FILE_DEFAULT);
425  else
426    log_packet_init (pcaplog_file);
427}
428
429void
430log_packet_stop (void)
431{
432  /* Stop capture.  */
433  if (packet_log)
434    {
435      fclose (packet_log);
436      log_print ("log_packet_stop: stopped capture");
437    }
438  packet_log = 0;
439}
440
441void
442log_packet_iov (struct sockaddr *src, struct sockaddr *dst, struct iovec *iov,
443		int iovcnt)
444{
445  struct isakmp_hdr *isakmphdr;
446  struct packhdr hdr;
447  struct udphdr udp;
448  int off, datalen, hdrlen, i;
449  struct timeval tv;
450
451  for (i = 0, datalen = 0; i < iovcnt; i++)
452    datalen += iov[i].iov_len;
453
454  if (!packet_log || datalen > SNAPLEN)
455    return;
456
457  /* copy packet into buffer */
458  for (i = 0, off = 0; i < iovcnt; i++)
459    {
460      memcpy (packet_buf + off, iov[i].iov_base, iov[i].iov_len);
461      off += iov[i].iov_len;
462    }
463
464  memset (&hdr, 0, sizeof hdr);
465  memset (&udp, 0, sizeof udp);
466
467  /* isakmp - turn off the encryption bit in the isakmp hdr */
468  isakmphdr = (struct isakmp_hdr *)packet_buf;
469  isakmphdr->flags &= ~(ISAKMP_FLAGS_ENC);
470
471  /* udp */
472  udp.uh_sport = udp.uh_dport = htons (500);
473  datalen += sizeof udp;
474  udp.uh_ulen = htons (datalen);
475
476  /* ip */
477  hdr.sa_family = htonl (src->sa_family);
478  switch (src->sa_family)
479    {
480    default:
481      /* Assume IPv4. XXX Can 'default' ever happen here?  */
482      hdr.sa_family = htonl (AF_INET);
483      hdr.ip.ip4.ip_src.s_addr = 0x02020202;
484      hdr.ip.ip4.ip_dst.s_addr = 0x01010101;
485      /* The rest of the setup is common to AF_INET.  */
486      goto setup_ip4;
487
488    case AF_INET:
489      hdr.ip.ip4.ip_src.s_addr = ((struct sockaddr_in *)src)->sin_addr.s_addr;
490      hdr.ip.ip4.ip_dst.s_addr = ((struct sockaddr_in *)dst)->sin_addr.s_addr;
491
492    setup_ip4:
493      hdrlen = sizeof hdr.ip.ip4;
494      hdr.ip.ip4.ip_v = 0x4;
495      hdr.ip.ip4.ip_hl = 0x5;
496      hdr.ip.ip4.ip_p = IPPROTO_UDP;
497      hdr.ip.ip4.ip_len = htons (datalen + hdrlen);
498      /* Let's use the IP ID as a "packet counter".  */
499      i = ntohs (hdr.ip.ip4.ip_id) + 1;
500      hdr.ip.ip4.ip_id = htons (i);
501      /* Calculate IP header checksum. */
502      hdr.ip.ip4.ip_sum = in_cksum ((u_int16_t *)&hdr.ip.ip4,
503				    hdr.ip.ip4.ip_hl << 2);
504      break;
505
506    case AF_INET6:
507      hdrlen = sizeof (hdr.ip.ip6);
508      hdr.ip.ip6.ip6_vfc = IPV6_VERSION;
509      hdr.ip.ip6.ip6_nxt = IPPROTO_UDP;
510      hdr.ip.ip6.ip6_plen = udp.uh_ulen;
511      memcpy (&hdr.ip.ip6.ip6_src, &((struct sockaddr_in6 *)src)->sin6_addr,
512	      sizeof hdr.ip.ip6.ip6_src);
513      memcpy (&hdr.ip.ip6.ip6_dst, &((struct sockaddr_in6 *)dst)->sin6_addr,
514	      sizeof hdr.ip.ip6.ip6_dst);
515      break;
516   }
517
518  /* Calculate UDP checksum.  */
519  udp.uh_sum = udp_cksum (&hdr, &udp, (u_int16_t *)packet_buf);
520  hdrlen += sizeof hdr.sa_family;
521
522  /* pcap file packet header */
523  gettimeofday (&tv, 0);
524  hdr.pcap.ts.tv_sec = tv.tv_sec;
525  hdr.pcap.ts.tv_usec = tv.tv_usec;
526  hdr.pcap.caplen = datalen + hdrlen;
527  hdr.pcap.len = datalen + hdrlen;
528
529  hdrlen += sizeof (struct pcap_pkthdr);
530  datalen -= sizeof (struct udphdr);
531
532  /* Write to pcap file.  */
533  fwrite (&hdr, hdrlen, 1, packet_log);			/* pcap + IP */
534  fwrite (&udp, sizeof (struct udphdr), 1, packet_log);	/* UDP */
535  fwrite (packet_buf, datalen, 1, packet_log);		/* IKE-data */
536  fflush (packet_log);
537  return;
538}
539
540/* Copied from tcpdump/print-udp.c, mostly rewritten.  */
541static int
542udp_cksum (struct packhdr *hdr, const struct udphdr *u, u_int16_t *d)
543{
544  int i, hdrlen, tlen = ntohs (u->uh_ulen) - sizeof (struct udphdr);
545  struct ip *ip4;
546  struct ip6_hdr *ip6;
547
548  union phu {
549    struct ip4pseudo {
550      struct in_addr src;
551      struct in_addr dst;
552      u_int8_t z;
553      u_int8_t proto;
554      u_int16_t len;
555    } ip4p;
556    struct ip6pseudo {
557      struct in6_addr src;
558      struct in6_addr dst;
559      u_int32_t plen;
560      u_int16_t z0;
561      u_int8_t z1;
562      u_int8_t nxt;
563    } ip6p;
564    u_int16_t pa[20];
565  } phu;
566  const u_int16_t *sp;
567  u_int32_t sum;
568
569  /* Setup pseudoheader.  */
570  memset (phu.pa, 0, sizeof phu);
571  switch (ntohl (hdr->sa_family))
572    {
573    case AF_INET:
574      ip4 = &hdr->ip.ip4;
575      memcpy (&phu.ip4p.src, &ip4->ip_src, sizeof (struct in_addr));
576      memcpy (&phu.ip4p.dst, &ip4->ip_dst, sizeof (struct in_addr));
577      phu.ip4p.proto = ip4->ip_p;
578      phu.ip4p.len = u->uh_ulen;
579      hdrlen = sizeof phu.ip4p;
580      break;
581
582    case AF_INET6:
583      ip6 = &hdr->ip.ip6;
584      memcpy (&phu.ip6p.src, &ip6->ip6_src, sizeof (phu.ip6p.src));
585      memcpy (&phu.ip6p.dst, &ip6->ip6_dst, sizeof (phu.ip6p.dst));
586      phu.ip6p.plen = u->uh_ulen;
587      phu.ip6p.nxt = ip6->ip6_nxt;
588      hdrlen = sizeof phu.ip6p;
589      break;
590
591    default:
592      return 0;
593    }
594
595  /* IPv6 wants a 0xFFFF checksum "on error", not 0x0.  */
596  if (tlen < 0)
597    return (ntohl (hdr->sa_family) == AF_INET ? 0 : 0xFFFF);
598
599  sum = 0;
600  for (i = 0; i < hdrlen; i += 2)
601    sum += phu.pa[i/2];
602
603  sp = (u_int16_t *)u;
604  for (i = 0; i < sizeof (struct udphdr); i += 2)
605    sum += *sp++;
606
607  sp = d;
608  for (i = 0; i < (tlen&~1); i += 2)
609    sum += *sp++;
610
611  if (tlen & 1)
612    sum += htons ((*(const char *)sp) << 8);
613
614  while (sum > 0xffff)
615    sum = (sum & 0xffff) + (sum >> 16);
616  sum = ~sum & 0xffff;
617
618  return sum;
619}
620
621/* Copied from tcpdump/print-ip.c, modified.  */
622static u_int16_t
623in_cksum (const u_int16_t *w, int len)
624{
625  int nleft = len, sum = 0;
626  u_int16_t answer;
627
628  while (nleft > 1)  {
629    sum += *w++;
630    nleft -= 2;
631  }
632  if (nleft == 1)
633    sum += htons (*(u_char *)w << 8);
634
635  sum = (sum >> 16) + (sum & 0xffff);     /* add hi 16 to low 16 */
636  sum += (sum >> 16);                     /* add carry */
637  answer = ~sum;                          /* truncate to 16 bits */
638  return answer;
639}
640
641#endif /* USE_DEBUG */
642