1/* trace.c 2 3 Subroutines that support tracing of OMAPI wire transactions and 4 provide a mechanism for programs using OMAPI to trace their own 5 transactions... */ 6 7/* 8 * Copyright (c) 2004 by Internet Systems Consortium, Inc. ("ISC") 9 * Copyright (c) 2001-2003 by Internet Software Consortium 10 * 11 * Permission to use, copy, modify, and distribute this software for any 12 * purpose with or without fee is hereby granted, provided that the above 13 * copyright notice and this permission notice appear in all copies. 14 * 15 * THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES 16 * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF 17 * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR 18 * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES 19 * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN 20 * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT 21 * OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. 22 * 23 * Internet Systems Consortium, Inc. 24 * 950 Charter Street 25 * Redwood City, CA 94063 26 * <info@isc.org> 27 * http://www.isc.org/ 28 * 29 * This software has been written for Internet Systems Consortium 30 * by Ted Lemon, as part of a project for Nominum, Inc. To learn more 31 * about Internet Systems Consortium, see http://www.isc.org/. To 32 * learn more about Nominum, Inc., see ``http://www.nominum.com''. 33 */ 34 35#include <omapip/omapip_p.h> 36 37#if defined (TRACING) 38void (*trace_set_time_hook) (u_int32_t); 39static int tracing_stopped; 40static int traceoutfile; 41static int traceindex; 42static trace_type_t **trace_types; 43static int trace_type_count; 44static int trace_type_max; 45static trace_type_t *new_trace_types; 46static FILE *traceinfile; 47static tracefile_header_t tracefile_header; 48static int trace_playback_flag; 49trace_type_t trace_time_marker; 50 51#if defined (DEBUG_MEMORY_LEAKAGE) || defined (DEBUG_MEMORY_LEAKAGE_ON_EXIT) 52extern omapi_array_t *trace_listeners; 53extern omapi_array_t *omapi_connections; 54 55void trace_free_all () 56{ 57 trace_type_t *tp; 58 int i; 59 tp = new_trace_types; 60 while (tp) { 61 new_trace_types = tp -> next; 62 if (tp -> name) { 63 dfree (tp -> name, MDL); 64 tp -> name = (char *)0; 65 } 66 dfree (tp, MDL); 67 tp = new_trace_types; 68 } 69 for (i = 0; i < trace_type_count; i++) { 70 if (trace_types [i]) { 71 if (trace_types [i] -> name) 72 dfree (trace_types [i] -> name, MDL); 73 dfree (trace_types [i], MDL); 74 } 75 } 76 dfree (trace_types, MDL); 77 trace_types = (trace_type_t **)0; 78 trace_type_count = trace_type_max = 0; 79 80 omapi_array_free (&trace_listeners, MDL); 81 omapi_array_free (&omapi_connections, MDL); 82} 83#endif 84 85static isc_result_t trace_type_record (trace_type_t *, 86 unsigned, const char *, int); 87 88int trace_playback () 89{ 90 return trace_playback_flag; 91} 92 93int trace_record () 94{ 95 if (traceoutfile && !tracing_stopped) 96 return 1; 97 return 0; 98} 99 100isc_result_t trace_init (void (*set_time) (u_int32_t), 101 const char *file, int line) 102{ 103 trace_type_t *root_type; 104 static int root_setup = 0; 105 106 if (root_setup) 107 return ISC_R_SUCCESS; 108 109 trace_set_time_hook = set_time; 110 111 root_type = trace_type_register ("trace-index-mapping", 112 (void *)0, trace_index_map_input, 113 trace_index_stop_tracing, file, line); 114 if (!root_type) 115 return ISC_R_UNEXPECTED; 116 if (new_trace_types == root_type) 117 new_trace_types = new_trace_types -> next; 118 root_type -> index = 0; 119 trace_type_stash (root_type); 120 121 root_setup = 1; 122 return ISC_R_SUCCESS; 123} 124 125isc_result_t trace_begin (const char *filename, 126 const char *file, int line) 127{ 128 tracefile_header_t tfh; 129 int status; 130 trace_type_t *tptr, *next; 131 isc_result_t result; 132 133 if (traceoutfile) { 134 log_error ("%s(%d): trace_begin called twice", 135 file, line); 136 return ISC_R_INVALIDARG; 137 } 138 139 traceoutfile = open (filename, O_CREAT | O_WRONLY | O_EXCL, 0644); 140 if (traceoutfile < 0) { 141 log_error ("%s(%d): trace_begin: %s: %m", 142 file, line, filename); 143 return ISC_R_UNEXPECTED; 144 } 145#if defined (HAVE_SETFD) 146 if (fcntl (traceoutfile, F_SETFD, 1) < 0) 147 log_error ("Can't set close-on-exec on %s: %m", filename); 148#endif 149 150 tfh.magic = htonl (TRACEFILE_MAGIC); 151 tfh.version = htonl (TRACEFILE_VERSION); 152 tfh.hlen = htonl (sizeof (tracefile_header_t)); 153 tfh.phlen = htonl (sizeof (tracepacket_t)); 154 155 status = write (traceoutfile, &tfh, sizeof tfh); 156 if (status < 0) { 157 log_error ("%s(%d): trace_begin write failed: %m", file, line); 158 return ISC_R_UNEXPECTED; 159 } else if (status != sizeof tfh) { 160 log_error ("%s(%d): trace_begin: short write (%d:%ld)", 161 file, line, status, (long)(sizeof tfh)); 162 trace_stop (); 163 return ISC_R_UNEXPECTED; 164 } 165 166 /* Stash all the types that have already been set up. */ 167 if (new_trace_types) { 168 next = new_trace_types; 169 new_trace_types = (trace_type_t *)0; 170 for (tptr = next; tptr; tptr = next) { 171 next = tptr -> next; 172 if (tptr -> index != 0) { 173 result = (trace_type_record 174 (tptr, 175 strlen (tptr -> name), file, line)); 176 if (result != ISC_R_SUCCESS) 177 return status; 178 } 179 } 180 } 181 182 return ISC_R_SUCCESS; 183} 184 185isc_result_t trace_write_packet (trace_type_t *ttype, unsigned length, 186 const char *buf, const char *file, int line) 187{ 188 trace_iov_t iov; 189 190 iov.buf = buf; 191 iov.len = length; 192 return trace_write_packet_iov (ttype, 1, &iov, file, line); 193} 194 195isc_result_t trace_write_packet_iov (trace_type_t *ttype, 196 int count, trace_iov_t *iov, 197 const char *file, int line) 198{ 199 tracepacket_t tmp; 200 int status; 201 int i; 202 int length; 203 204 /* Really shouldn't get called here, but it may be hard to turn off 205 tracing midstream if the trace file write fails or something. */ 206 if (tracing_stopped) 207 return 0; 208 209 if (!ttype) { 210 log_error ("%s(%d): trace_write_packet with null trace type", 211 file ? file : "<unknown file>", line); 212 return ISC_R_INVALIDARG; 213 } 214 if (!traceoutfile) { 215 log_error ("%s(%d): trace_write_packet with no tracefile.", 216 file ? file : "<unknown file>", line); 217 return ISC_R_INVALIDARG; 218 } 219 220 /* Compute the total length of the iov. */ 221 length = 0; 222 for (i = 0; i < count; i++) 223 length += iov [i].len; 224 225 /* We have to swap out the data, because it may be read back on a 226 machine of different endianness. */ 227 tmp.type_index = htonl (ttype -> index); 228 tmp.when = htonl (time ((time_t *)0)); /* XXX */ 229 tmp.length = htonl (length); 230 231 status = write (traceoutfile, &tmp, sizeof tmp); 232 if (status < 0) { 233 log_error ("%s(%d): trace_write_packet write failed: %m", 234 file, line); 235 return ISC_R_UNEXPECTED; 236 } else if (status != sizeof tmp) { 237 log_error ("%s(%d): trace_write_packet: short write (%d:%ld)", 238 file, line, status, (long)(sizeof tmp)); 239 trace_stop (); 240 } 241 242 for (i = 0; i < count; i++) { 243 status = write (traceoutfile, iov [i].buf, iov [i].len); 244 if (status < 0) { 245 log_error ("%s(%d): %s write failed: %m", 246 file, line, "trace_write_packet"); 247 return ISC_R_UNEXPECTED; 248 } else if (status != iov [i].len) { 249 log_error ("%s(%d): %s: short write (%d:%d)", 250 file, line, 251 "trace_write_packet", status, length); 252 trace_stop (); 253 } 254 } 255 256 /* Write padding on the end of the packet to align the next 257 packet to an 8-byte boundary. This is in case we decide to 258 use mmap in some clever way later on. */ 259 if (length % 8) { 260 static char zero [] = { 0, 0, 0, 0, 0, 0, 0 }; 261 unsigned padl = 8 - (length % 8); 262 263 status = write (traceoutfile, zero, padl); 264 if (status < 0) { 265 log_error ("%s(%d): trace_write_packet write failed: %m", 266 file, line); 267 return ISC_R_UNEXPECTED; 268 } else if (status != padl) { 269 log_error ("%s(%d): trace_write_packet: short write (%d:%d)", 270 file, line, status, padl); 271 trace_stop (); 272 } 273 } 274 275 return ISC_R_SUCCESS; 276} 277 278void trace_type_stash (trace_type_t *tptr) 279{ 280 trace_type_t **vec; 281 int delta; 282 if (trace_type_max <= tptr -> index) { 283 delta = tptr -> index - trace_type_max + 10; 284 vec = dmalloc (((trace_type_max + delta) * 285 sizeof (trace_type_t *)), MDL); 286 if (!vec) 287 return; 288 memset (&vec [trace_type_max], 0, 289 (sizeof (trace_type_t *)) * delta); 290 trace_type_max += delta; 291 if (trace_types) { 292 memcpy (vec, trace_types, 293 trace_type_count * sizeof (trace_type_t *)); 294 dfree (trace_types, MDL); 295 } 296 trace_types = vec; 297 } 298 trace_types [tptr -> index] = tptr; 299 if (tptr -> index >= trace_type_count) 300 trace_type_count = tptr -> index + 1; 301} 302 303trace_type_t *trace_type_register (const char *name, 304 void *baggage, 305 void (*have_packet) (trace_type_t *, 306 unsigned, char *), 307 void (*stop_tracing) (trace_type_t *), 308 const char *file, int line) 309{ 310 trace_type_t *ttmp; 311 unsigned slen = strlen (name); 312 isc_result_t status; 313 314 ttmp = dmalloc (sizeof *ttmp, file, line); 315 if (!ttmp) 316 return ttmp; 317 ttmp -> index = -1; 318 ttmp -> name = dmalloc (slen + 1, file, line); 319 if (!ttmp -> name) { 320 dfree (ttmp, file, line); 321 return (trace_type_t *)0; 322 } 323 strcpy (ttmp -> name, name); 324 ttmp -> have_packet = have_packet; 325 ttmp -> stop_tracing = stop_tracing; 326 327 if (traceoutfile) { 328 status = trace_type_record (ttmp, slen, file, line); 329 if (status != ISC_R_SUCCESS) { 330 dfree (ttmp -> name, file, line); 331 dfree (ttmp, file, line); 332 return (trace_type_t *)0; 333 } 334 } else { 335 ttmp -> next = new_trace_types; 336 new_trace_types = ttmp; 337 } 338 339 return ttmp; 340} 341 342static isc_result_t trace_type_record (trace_type_t *ttmp, unsigned slen, 343 const char *file, int line) 344{ 345 trace_index_mapping_t *tim; 346 isc_result_t status; 347 348 tim = dmalloc (slen + TRACE_INDEX_MAPPING_SIZE, file, line); 349 if (!tim) 350 return ISC_R_NOMEMORY; 351 ttmp -> index = ++traceindex; 352 trace_type_stash (ttmp); 353 tim -> index = htonl (ttmp -> index); 354 memcpy (tim -> name, ttmp -> name, slen); 355 status = trace_write_packet (trace_types [0], 356 slen + TRACE_INDEX_MAPPING_SIZE, 357 (char *)tim, file, line); 358 dfree (tim, file, line); 359 return status; 360} 361 362/* Stop all registered trace types from trying to trace. */ 363 364void trace_stop (void) 365{ 366 int i; 367 368 for (i = 0; i < trace_type_count; i++) 369 if (trace_types [i] -> stop_tracing) 370 (*(trace_types [i] -> stop_tracing)) 371 (trace_types [i]); 372 tracing_stopped = 1; 373} 374 375void trace_index_map_input (trace_type_t *ttype, unsigned length, char *buf) 376{ 377 trace_index_mapping_t *tmap; 378 unsigned len; 379 trace_type_t *tptr, **prev; 380 381 if (length < TRACE_INDEX_MAPPING_SIZE) { 382 log_error ("short trace index mapping"); 383 return; 384 } 385 tmap = (trace_index_mapping_t *)buf; 386 387 prev = &new_trace_types; 388 for (tptr = new_trace_types; tptr; tptr = tptr -> next) { 389 len = strlen (tptr -> name); 390 if (len == length - TRACE_INDEX_MAPPING_SIZE && 391 !memcmp (tptr -> name, tmap -> name, len)) { 392 tptr -> index = ntohl (tmap -> index); 393 trace_type_stash (tptr); 394 *prev = tptr -> next; 395 return; 396 } 397 prev = &tptr -> next; 398 } 399 400 log_error ("No registered trace type for type name %.*s", 401 (int)length - TRACE_INDEX_MAPPING_SIZE, tmap -> name); 402 return; 403} 404 405void trace_index_stop_tracing (trace_type_t *ttype) { } 406 407void trace_replay_init (void) 408{ 409 trace_playback_flag = 1; 410} 411 412void trace_file_replay (const char *filename) 413{ 414 tracepacket_t *tpkt = (tracepacket_t *)0; 415 int status; 416 char *buf = (char *)0; 417 unsigned buflen; 418 unsigned bufmax = 0; 419 trace_type_t *ttype = (trace_type_t *)0; 420 isc_result_t result; 421 int len; 422 423 traceinfile = fopen (filename, "r"); 424 if (!traceinfile) { 425 log_error ("Can't open tracefile %s: %m", filename); 426 return; 427 } 428#if defined (HAVE_SETFD) 429 if (fcntl (fileno (traceinfile), F_SETFD, 1) < 0) 430 log_error ("Can't set close-on-exec on %s: %m", filename); 431#endif 432 status = fread (&tracefile_header, 1, 433 sizeof tracefile_header, traceinfile); 434 if (status < sizeof tracefile_header) { 435 if (ferror (traceinfile)) 436 log_error ("Error reading trace file header: %m"); 437 else 438 log_error ("Short read on trace file header: %d %ld.", 439 status, (long)(sizeof tracefile_header)); 440 goto out; 441 } 442 tracefile_header.magic = ntohl (tracefile_header.magic); 443 tracefile_header.version = ntohl (tracefile_header.version); 444 tracefile_header.hlen = ntohl (tracefile_header.hlen); 445 tracefile_header.phlen = ntohl (tracefile_header.phlen); 446 447 if (tracefile_header.magic != TRACEFILE_MAGIC) { 448 log_error ("%s: not a dhcp trace file.", filename); 449 goto out; 450 } 451 if (tracefile_header.version > TRACEFILE_VERSION) { 452 log_error ("tracefile version %ld > current %ld.", 453 (long int)tracefile_header.version, 454 (long int)TRACEFILE_VERSION); 455 goto out; 456 } 457 if (tracefile_header.phlen < sizeof *tpkt) { 458 log_error ("tracefile packet size too small - %ld < %ld", 459 (long int)tracefile_header.phlen, 460 (long int)sizeof *tpkt); 461 goto out; 462 } 463 len = (sizeof tracefile_header) - tracefile_header.hlen; 464 if (len < 0) { 465 log_error ("tracefile header size too small - %ld < %ld", 466 (long int)tracefile_header.hlen, 467 (long int)sizeof tracefile_header); 468 goto out; 469 } 470 if (len > 0) { 471 status = fseek (traceinfile, (long)len, SEEK_CUR); 472 if (status < 0) { 473 log_error ("can't seek past header: %m"); 474 goto out; 475 } 476 } 477 478 tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL); 479 if (!tpkt) { 480 log_error ("can't allocate trace packet header."); 481 goto out; 482 } 483 484 while ((result = trace_get_next_packet (&ttype, tpkt, &buf, &buflen, 485 &bufmax)) == ISC_R_SUCCESS) { 486 (*ttype -> have_packet) (ttype, tpkt -> length, buf); 487 ttype = (trace_type_t *)0; 488 } 489 out: 490 fclose (traceinfile); 491 if (buf) 492 dfree (buf, MDL); 493 if (tpkt) 494 dfree (tpkt, MDL); 495} 496 497/* Get the next packet from the file. If ttp points to a nonzero pointer 498 to a trace type structure, check the next packet to see if it's of the 499 expected type, and back off if not. */ 500 501isc_result_t trace_get_next_packet (trace_type_t **ttp, 502 tracepacket_t *tpkt, 503 char **buf, unsigned *buflen, 504 unsigned *bufmax) 505{ 506 trace_type_t *ttype; 507 unsigned paylen; 508 int status; 509 fpos_t curpos; 510 511 status = fgetpos (traceinfile, &curpos); 512 if (status < 0) 513 log_error ("Can't save tracefile position: %m"); 514 515 status = fread (tpkt, 1, (size_t)tracefile_header.phlen, traceinfile); 516 if (status < tracefile_header.phlen) { 517 if (ferror (traceinfile)) 518 log_error ("Error reading trace packet header: %m"); 519 else if (status == 0) 520 return ISC_R_EOF; 521 else 522 log_error ("Short read on trace packet header: " 523 "%ld %ld.", 524 (long int)status, 525 (long int)tracefile_header.phlen); 526 return ISC_R_PROTOCOLERROR; 527 } 528 529 /* Swap the packet. */ 530 tpkt -> type_index = ntohl (tpkt -> type_index); 531 tpkt -> length = ntohl (tpkt -> length); 532 tpkt -> when = ntohl (tpkt -> when); 533 534 /* See if there's a handler for this packet type. */ 535 if (tpkt -> type_index < trace_type_count && 536 trace_types [tpkt -> type_index]) 537 ttype = trace_types [tpkt -> type_index]; 538 else { 539 log_error ("Trace packet with unknown index %ld", 540 (long int)tpkt -> type_index); 541 return ISC_R_PROTOCOLERROR; 542 } 543 544 /* If we were just hunting for the time marker, we've found it, 545 so back up to the beginning of the packet and return its 546 type. */ 547 if (ttp && *ttp == &trace_time_marker) { 548 *ttp = ttype; 549 status = fsetpos (traceinfile, &curpos); 550 if (status < 0) { 551 log_error ("fsetpos in tracefile failed: %m"); 552 return ISC_R_PROTOCOLERROR; 553 } 554 return ISC_R_EXISTS; 555 } 556 557 /* If we were supposed to get a particular kind of packet, 558 check to see that we got the right kind. */ 559 if (ttp && *ttp && ttype != *ttp) { 560 log_error ("Read packet type %s when expecting %s", 561 ttype -> name, (*ttp) -> name); 562 status = fsetpos (traceinfile, &curpos); 563 if (status < 0) { 564 log_error ("fsetpos in tracefile failed: %m"); 565 return ISC_R_PROTOCOLERROR; 566 } 567 return ISC_R_UNEXPECTEDTOKEN; 568 } 569 570 paylen = tpkt -> length; 571 if (paylen % 8) 572 paylen += 8 - (tpkt -> length % 8); 573 if (paylen > (*bufmax)) { 574 if ((*buf)) 575 dfree ((*buf), MDL); 576 (*bufmax) = ((paylen + 1023) & ~1023U); 577 (*buf) = dmalloc ((*bufmax), MDL); 578 if (!(*buf)) { 579 log_error ("Can't allocate input buffer sized %d", 580 (*bufmax)); 581 return ISC_R_NOMEMORY; 582 } 583 } 584 585 status = fread ((*buf), 1, paylen, traceinfile); 586 if (status < paylen) { 587 if (ferror (traceinfile)) 588 log_error ("Error reading trace payload: %m"); 589 else 590 log_error ("Short read on trace payload: %d %d.", 591 status, paylen); 592 return ISC_R_PROTOCOLERROR; 593 } 594 595 /* Store the actual length of the payload. */ 596 *buflen = tpkt -> length; 597 598 if (trace_set_time_hook) 599 (*trace_set_time_hook) (tpkt -> when); 600 601 if (ttp) 602 *ttp = ttype; 603 return ISC_R_SUCCESS; 604} 605 606isc_result_t trace_get_packet (trace_type_t **ttp, 607 unsigned *buflen, char **buf) 608{ 609 tracepacket_t *tpkt; 610 unsigned bufmax = 0; 611 isc_result_t status; 612 613 if (!buf || *buf) 614 return ISC_R_INVALIDARG; 615 616 tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL); 617 if (!tpkt) { 618 log_error ("can't allocate trace packet header."); 619 return ISC_R_NOMEMORY; 620 } 621 622 status = trace_get_next_packet (ttp, tpkt, buf, buflen, &bufmax); 623 624 dfree (tpkt, MDL); 625 return status; 626} 627 628time_t trace_snoop_time (trace_type_t **ptp) 629{ 630 tracepacket_t *tpkt; 631 unsigned bufmax = 0; 632 unsigned buflen = 0; 633 char *buf = (char *)0; 634 time_t result; 635 trace_type_t *ttp; 636 637 if (!ptp) 638 ptp = &ttp; 639 640 tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL); 641 if (!tpkt) { 642 log_error ("can't allocate trace packet header."); 643 return ISC_R_NOMEMORY; 644 } 645 646 *ptp = &trace_time_marker; 647 trace_get_next_packet (ptp, tpkt, &buf, &buflen, &bufmax); 648 result = tpkt -> when; 649 650 dfree (tpkt, MDL); 651 return result; 652} 653 654/* Get a packet from the trace input file that contains a file with the 655 specified name. We don't hunt for the packet - it should be the next 656 packet in the tracefile. If it's not, or something else bad happens, 657 return an error code. */ 658 659isc_result_t trace_get_file (trace_type_t *ttype, 660 const char *filename, unsigned *len, char **buf) 661{ 662 fpos_t curpos; 663 unsigned max = 0; 664 tracepacket_t *tpkt; 665 int status; 666 isc_result_t result; 667 668 /* Disallow some obvious bogosities. */ 669 if (!buf || !len || *buf) 670 return ISC_R_INVALIDARG; 671 672 /* Save file position in case of filename mismatch. */ 673 status = fgetpos (traceinfile, &curpos); 674 if (status < 0) 675 log_error ("Can't save tracefile position: %m"); 676 677 tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL); 678 if (!tpkt) { 679 log_error ("can't allocate trace packet header."); 680 return ISC_R_NOMEMORY; 681 } 682 683 result = trace_get_next_packet (&ttype, tpkt, buf, len, &max); 684 if (result != ISC_R_SUCCESS) { 685 dfree (tpkt, MDL); 686 if (*buf) 687 dfree (*buf, MDL); 688 return result; 689 } 690 691 /* Make sure the filename is right. */ 692 if (strcmp (filename, *buf)) { 693 log_error ("Read file %s when expecting %s", *buf, filename); 694 status = fsetpos (traceinfile, &curpos); 695 if (status < 0) { 696 log_error ("fsetpos in tracefile failed: %m"); 697 dfree (tpkt, MDL); 698 dfree (*buf, MDL); 699 return ISC_R_PROTOCOLERROR; 700 } 701 return ISC_R_UNEXPECTEDTOKEN; 702 } 703 704 dfree (tpkt, MDL); 705 return ISC_R_SUCCESS; 706} 707#endif /* TRACING */ 708