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