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