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