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