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