path: root/omapip/trace.c

/* trace.c

   Subroutines that support tracing of OMAPI wire transactions and
   provide a mechanism for programs using OMAPI to trace their own
   transactions... */

/*
 * Copyright (c) 2012,2014 by Internet Systems Consortium, Inc. ("ISC")
 * Copyright (c) 2009-2010 by Internet Systems Consortium, Inc. ("ISC")
 * Copyright (c) 2004-2007 by Internet Systems Consortium, Inc. ("ISC")
 * Copyright (c) 2001-2003 by Internet Software Consortium
 *
 * Permission to use, copy, modify, and distribute this software for any
 * purpose with or without fee is hereby granted, provided that the above
 * copyright notice and this permission notice appear in all copies.
 *
 * THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES
 * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
 * MERCHANTABILITY AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR
 * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
 * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
 * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
 * OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 *
 *   Internet Systems Consortium, Inc.
 *   950 Charter Street
 *   Redwood City, CA 94063
 *   <info@isc.org>
 *   https://www.isc.org/
 *
 */

#include "dhcpd.h"
#include <omapip/omapip_p.h>
#include <errno.h>

#if defined (TRACING)
void (*trace_set_time_hook) (TIME);
static int tracing_stopped;
static int traceoutfile;
static int traceindex;
static trace_type_t **trace_types;
static int trace_type_count;
static int trace_type_max;
static trace_type_t *new_trace_types;
static FILE *traceinfile;
static tracefile_header_t tracefile_header;
static int trace_playback_flag;
trace_type_t trace_time_marker;

#if defined (DEBUG_MEMORY_LEAKAGE) || defined (DEBUG_MEMORY_LEAKAGE_ON_EXIT)
extern omapi_array_t *trace_listeners;
extern omapi_array_t *omapi_connections;

extern int errno;

void trace_free_all ()
{
	trace_type_t *tp;
	int i;
	tp = new_trace_types;
	while (tp) {
		new_trace_types = tp -> next;
		if (tp -> name) {
			dfree (tp -> name, MDL);
			tp -> name = (char *)0;
		}
		dfree (tp, MDL);
		tp = new_trace_types;
	}
	for (i = 0; i < trace_type_count; i++) {
		if (trace_types [i]) {
			if (trace_types [i] -> name)
				dfree (trace_types [i] -> name, MDL);
			dfree (trace_types [i], MDL);
		}
	}
	dfree (trace_types, MDL);
	trace_types = (trace_type_t **)0;
	trace_type_count = trace_type_max = 0;

	omapi_array_free (&trace_listeners, MDL);
	omapi_array_free (&omapi_connections, MDL);
}
#endif

static isc_result_t trace_type_record (trace_type_t *,
				       unsigned, const char *, int);

int trace_playback ()
{
	return trace_playback_flag;
}

int trace_record ()
{
	if (traceoutfile && !tracing_stopped)
		return 1;
	return 0;
}

isc_result_t trace_init (void (*set_time) (TIME),
			 const char *file, int line)
{
	trace_type_t *root_type;
	static int root_setup = 0;

	if (root_setup)
		return ISC_R_SUCCESS;

	trace_set_time_hook = set_time;

	root_type = trace_type_register ("trace-index-mapping",
					 (void *)0, trace_index_map_input,
					 trace_index_stop_tracing, file, line);
	if (!root_type)
		return ISC_R_UNEXPECTED;
	if (new_trace_types == root_type)
		new_trace_types = new_trace_types -> next;
	root_type -> index = 0;
	trace_type_stash (root_type);

	root_setup = 1;
	return ISC_R_SUCCESS;
}

isc_result_t trace_begin (const char *filename,
			  const char *file, int line)
{
	tracefile_header_t tfh;
	int status;
	trace_type_t *tptr, *next;
	isc_result_t result;

	if (traceoutfile) {
		log_error ("%s(%d): trace_begin called twice",
			   file, line);
		return DHCP_R_INVALIDARG;
	}

	traceoutfile = open (filename, O_CREAT | O_WRONLY | O_EXCL, 0600);
	if (traceoutfile < 0 && errno == EEXIST) {
		log_error ("WARNING: Overwriting trace file \"%s\"", filename);
		traceoutfile = open (filename, O_WRONLY | O_EXCL | O_TRUNC,
				     0600);
	}

	if (traceoutfile < 0) {
		log_error ("%s(%d): trace_begin: %s: %m",
			   file, line, filename);
		return ISC_R_UNEXPECTED;
	}
#if defined (HAVE_SETFD)
	if (fcntl (traceoutfile, F_SETFD, 1) < 0)
		log_error ("Can't set close-on-exec on %s: %m", filename);
#endif

	tfh.magic = htonl (TRACEFILE_MAGIC);
	tfh.version = htonl (TRACEFILE_VERSION);
	tfh.hlen = htonl (sizeof (tracefile_header_t));
	tfh.phlen = htonl (sizeof (tracepacket_t));
	
	status = write (traceoutfile, &tfh, sizeof tfh);
	if (status < 0) {
		log_error ("%s(%d): trace_begin write failed: %m", file, line);
		return ISC_R_UNEXPECTED;
	} else if (status != sizeof tfh) {
		log_error ("%s(%d): trace_begin: short write (%d:%ld)",
			   file, line, status, (long)(sizeof tfh));
		trace_stop ();
		return ISC_R_UNEXPECTED;
	}

	/* Stash all the types that have already been set up. */
	if (new_trace_types) {
		next = new_trace_types;
		new_trace_types = (trace_type_t *)0;
		for (tptr = next; tptr; tptr = next) {
			next = tptr -> next;
			if (tptr -> index != 0) {
				result = (trace_type_record
					  (tptr,
					   strlen (tptr -> name), file, line));
				if (result != ISC_R_SUCCESS)
					return status;
			}
		}
	}
	
	return ISC_R_SUCCESS;
}

isc_result_t trace_write_packet (trace_type_t *ttype, unsigned length,
				 const char *buf, const char *file, int line)
{
	trace_iov_t iov;

	iov.buf = buf;
	iov.len = length;
	return trace_write_packet_iov (ttype, 1, &iov, file, line);
}

isc_result_t trace_write_packet_iov (trace_type_t *ttype,
				     int count, trace_iov_t *iov,
				     const char *file, int line)
{
	tracepacket_t tmp;
	int status;
	int i;
	int length;

	/* Really shouldn't get called here, but it may be hard to turn off
	   tracing midstream if the trace file write fails or something. */
	if (tracing_stopped)
		return 0;

	if (!ttype) {
		log_error ("%s(%d): trace_write_packet with null trace type",
			   file ? file : "<unknown file>", line);
		return DHCP_R_INVALIDARG;
	}
	if (!traceoutfile) {
		log_error ("%s(%d): trace_write_packet with no tracefile.",
			   file ? file : "<unknown file>", line);
		return DHCP_R_INVALIDARG;
	}
	
	/* Compute the total length of the iov. */
	length = 0;
	for (i = 0; i < count; i++)
		length += iov [i].len;

	/* We have to swap out the data, because it may be read back on a
	   machine of different endianness. */
	memset(&tmp, 0, sizeof(tmp));
	tmp.type_index = htonl (ttype -> index);
	tmp.when = htonl (time ((time_t *)0)); /* XXX */
	tmp.length = htonl (length);

	status = write (traceoutfile, &tmp, sizeof tmp);
	if (status < 0) {
		log_error ("%s(%d): trace_write_packet write failed: %m",
			   file, line);
		return ISC_R_UNEXPECTED;
	} else if (status != sizeof tmp) {
		log_error ("%s(%d): trace_write_packet: short write (%d:%ld)",
			   file, line, status, (long)(sizeof tmp));
		trace_stop ();
	}

	for (i = 0; i < count; i++) {
		status = write (traceoutfile, iov [i].buf, iov [i].len);
		if (status < 0) {
			log_error ("%s(%d): %s write failed: %m",
				   file, line, "trace_write_packet");
			return ISC_R_UNEXPECTED;
		} else if (status != iov [i].len) {
			log_error ("%s(%d): %s: short write (%d:%d)",
				   file, line,
				   "trace_write_packet", status, length);
			trace_stop ();
		}
	}

	/* Write padding on the end of the packet to align the next
	   packet to an 8-byte boundary.   This is in case we decide to
	   use mmap in some clever way later on. */
	if (length % 8) {
	    static char zero [] = { 0, 0, 0, 0, 0, 0, 0 };
	    unsigned padl = 8 - (length % 8);
		
	    status = write (traceoutfile, zero, padl);
	    if (status < 0) {
		log_error ("%s(%d): trace_write_packet write failed: %m",
			   file, line);
		return ISC_R_UNEXPECTED;
	    } else if (status != padl) {
		log_error ("%s(%d): trace_write_packet: short write (%d:%d)",
			   file, line, status, padl);
		trace_stop ();
	    }
	}

	return ISC_R_SUCCESS;
}

void trace_type_stash (trace_type_t *tptr)
{
	trace_type_t **vec;
	int delta;
	if (trace_type_max <= tptr -> index) {
		delta = tptr -> index - trace_type_max + 10;
		vec = dmalloc (((trace_type_max + delta) *
				sizeof (trace_type_t *)), MDL);
		if (!vec)
			return;
		memset (&vec [trace_type_max], 0,
			(sizeof (trace_type_t *)) * delta);
		trace_type_max += delta;
		if (trace_types) {
		    memcpy (vec, trace_types,
			    trace_type_count * sizeof (trace_type_t *));
		    dfree (trace_types, MDL);
		}
		trace_types = vec;
	}
	trace_types [tptr -> index] = tptr;
	if (tptr -> index >= trace_type_count)
		trace_type_count = tptr -> index + 1;
}

trace_type_t *trace_type_register (const char *name,
				   void *baggage,
				   void (*have_packet) (trace_type_t *,
							unsigned, char *),
				   void (*stop_tracing) (trace_type_t *),
				   const char *file, int line)
{
	trace_type_t *ttmp;
	unsigned slen = strlen (name);
	isc_result_t status;

	ttmp = dmalloc (sizeof *ttmp, file, line);
	if (!ttmp)
		return ttmp;
	ttmp -> index = -1;
	ttmp -> name = dmalloc (slen + 1, file, line);
	if (!ttmp -> name) {
		dfree (ttmp, file, line);
		return (trace_type_t *)0;
	}
	strcpy (ttmp -> name, name);
	ttmp -> have_packet = have_packet;
	ttmp -> stop_tracing = stop_tracing;
	
	if (traceoutfile) {
		status = trace_type_record (ttmp, slen, file, line);
		if (status != ISC_R_SUCCESS) {
			dfree (ttmp -> name, file, line);
			dfree (ttmp, file, line);
			return (trace_type_t *)0;
		}
	} else {
		ttmp -> next = new_trace_types;
		new_trace_types = ttmp;
	}

	return ttmp;
}
						   
static isc_result_t trace_type_record (trace_type_t *ttmp, unsigned slen,
				       const char *file, int line)
{
	trace_index_mapping_t *tim;
	isc_result_t status;

	tim = dmalloc (slen + TRACE_INDEX_MAPPING_SIZE, file, line);
	if (!tim)
		return ISC_R_NOMEMORY;
	ttmp -> index = ++traceindex;
	trace_type_stash (ttmp);
	tim -> index = htonl (ttmp -> index);
	memcpy (tim -> name, ttmp -> name, slen);
	status = trace_write_packet (trace_types [0],
				     slen + TRACE_INDEX_MAPPING_SIZE,
				     (char *)tim, file, line);
	dfree (tim, file, line);
	return status;
}

/* Stop all registered trace types from trying to trace. */

void trace_stop (void)
{
	int i;

	for (i = 0; i < trace_type_count; i++)
		if (trace_types [i] -> stop_tracing)
			(*(trace_types [i] -> stop_tracing))
				(trace_types [i]);
	tracing_stopped = 1;
}

void trace_index_map_input (trace_type_t *ttype, unsigned length, char *buf)
{
	trace_index_mapping_t *tmap;
	unsigned len;
	trace_type_t *tptr, **prev;

	if (length < TRACE_INDEX_MAPPING_SIZE) {
		log_error ("short trace index mapping");
		return;
	}
	tmap = (trace_index_mapping_t *)buf;

	prev = &new_trace_types;
	for (tptr = new_trace_types; tptr; tptr = tptr -> next) {
		len = strlen (tptr -> name);
		if (len == length - TRACE_INDEX_MAPPING_SIZE &&
		    !memcmp (tptr -> name, tmap -> name, len)) {
			tptr -> index = ntohl (tmap -> index);
			trace_type_stash (tptr);
			*prev = tptr -> next;
			return;
		}
		prev = &tptr -> next;
	}
	
	log_error ("No registered trace type for type name %.*s",
		   (int)length - TRACE_INDEX_MAPPING_SIZE, tmap -> name);
	return;
}

void trace_index_stop_tracing (trace_type_t *ttype) { }

void trace_replay_init (void)
{
	trace_playback_flag = 1;
}

void trace_file_replay (const char *filename)
{
	tracepacket_t *tpkt = NULL;
	int status;
	char *buf = NULL;
	unsigned buflen;
	unsigned bufmax = 0;
	trace_type_t *ttype = NULL;
	isc_result_t result;
	int len;

	traceinfile = fopen (filename, "r");
	if (!traceinfile) {
		log_error("Can't open tracefile %s: %m", filename);
		return;
	}
#if defined (HAVE_SETFD)
	if (fcntl (fileno(traceinfile), F_SETFD, 1) < 0)
		log_error("Can't set close-on-exec on %s: %m", filename);
#endif
	status = fread(&tracefile_header, 1,
		       sizeof tracefile_header, traceinfile);
	if (status < sizeof tracefile_header) {
		if (ferror(traceinfile))
			log_error("Error reading trace file header: %m");
		else
			log_error("Short read on trace file header: %d %ld.",
				  status, (long)(sizeof tracefile_header));
		goto out;
	}
	tracefile_header.magic = ntohl(tracefile_header.magic);
	tracefile_header.version = ntohl(tracefile_header.version);
	tracefile_header.hlen = ntohl(tracefile_header.hlen);
	tracefile_header.phlen = ntohl(tracefile_header.phlen);

	if (tracefile_header.magic != TRACEFILE_MAGIC) {
		log_error("%s: not a dhcp trace file.", filename);
		goto out;
	}
	if (tracefile_header.version > TRACEFILE_VERSION) {
		log_error ("tracefile version %ld > current %ld.",
			   (long int)tracefile_header.version,
			   (long int)TRACEFILE_VERSION);
		goto out;
	}
	if (tracefile_header.phlen < sizeof *tpkt) {
		log_error("tracefile packet size too small - %ld < %ld",
			  (long int)tracefile_header.phlen,
			  (long int)sizeof *tpkt);
		goto out;
	}
	len = (sizeof tracefile_header) - tracefile_header.hlen;
	if (len < 0) {
		log_error("tracefile header size too small - %ld < %ld",
			  (long int)tracefile_header.hlen,
			  (long int)sizeof tracefile_header);
		goto out;
	}
	if (len > 0) {
		status = fseek(traceinfile, (long)len, SEEK_CUR);
		if (status < 0) {
			log_error("can't seek past header: %m");
			goto out;
		}
	}

	tpkt = dmalloc((unsigned)tracefile_header.phlen, MDL);
	if (tpkt == NULL) {
		log_error ("can't allocate trace packet header.");
		goto out;
	}

	while ((result = trace_get_next_packet(&ttype, tpkt, &buf, &buflen,
					       &bufmax)) == ISC_R_SUCCESS) {
	    (*ttype->have_packet)(ttype, tpkt->length, buf);
	    ttype = NULL;
	}
      out:
	fclose(traceinfile);
	if (buf != NULL)
		dfree(buf, MDL);
	if (tpkt != NULL)
		dfree(tpkt, MDL);
}

/* Get the next packet from the file.   If ttp points to a nonzero pointer
   to a trace type structure, check the next packet to see if it's of the
   expected type, and back off if not. */

isc_result_t trace_get_next_packet (trace_type_t **ttp,
				    tracepacket_t *tpkt,
				    char **buf, unsigned *buflen,
				    unsigned *bufmax)
{
	trace_type_t *ttype;
	unsigned paylen;
	int status, curposok = 0;
	fpos_t curpos;

	while(1) {
		curposok = 0;
		status = fgetpos(traceinfile, &curpos);
		if (status < 0) {
			log_error("Can't save tracefile position: %m");
		} else {
			curposok = 1;
		}

		status = fread(tpkt, 1, (size_t)tracefile_header.phlen,
			       traceinfile);
		if (status < tracefile_header.phlen) {
			if (ferror(traceinfile))
				log_error("Error reading trace packet header: "
					  "%m");
			else if (status == 0)
				return ISC_R_EOF;
			else
				log_error ("Short read on trace packet header:"
					   " %ld %ld.",
					   (long int)status,
					   (long int)tracefile_header.phlen);
			return DHCP_R_PROTOCOLERROR;
		}

		/* Swap the packet. */
		tpkt->type_index = ntohl(tpkt -> type_index);
		tpkt->length = ntohl(tpkt -> length);
		tpkt->when = ntohl(tpkt -> when);
	
		/* See if there's a handler for this packet type. */
		if (tpkt->type_index < trace_type_count &&
		    trace_types[tpkt->type_index])
			ttype = trace_types[tpkt->type_index];
		else {
			log_error ("Trace packet with unknown index %ld",
				   (long int)tpkt->type_index);
			return DHCP_R_PROTOCOLERROR;
		}

		/*
		 * Determine if we should try to expire any timer events.
		 * We do so if:
		 *   we aren't looking for a specific type of packet
		 *   we have a hook to use to update the timer
		 *   the timestamp on the packet doesn't match the current time
		 * When we do so we rewind the file to the beginning of this
		 * packet and then try for a new packet.  This allows
		 * any code triggered by a timeout to get the current packet
		 * while we get the next one.
		 */

		if ((ttp != NULL) && (*ttp == NULL) &&
		    (tpkt->when != cur_tv.tv_sec) &&
		    (trace_set_time_hook != NULL)) {
			if (curposok == 0) {
				log_error("no curpos for fsetpos in "
					  "tracefile");
				return DHCP_R_PROTOCOLERROR;
			}
				
			status = fsetpos(traceinfile, &curpos);
			if (status < 0) {
				log_error("fsetpos in tracefile failed: %m");
				return DHCP_R_PROTOCOLERROR;
			}

			(*trace_set_time_hook) (tpkt->when);
			continue;
		}
		break;
	}

	/* If we were supposed to get a particular kind of packet,
	   check to see that we got the right kind. */
	if (ttp && *ttp && ttype != *ttp) {
		log_error ("Read packet type %s when expecting %s",
			   ttype -> name, (*ttp) -> name);
		status = fsetpos (traceinfile, &curpos);
		if (status < 0) {
			log_error ("fsetpos in tracefile failed: %m");
			return DHCP_R_PROTOCOLERROR;
		}
		return ISC_R_UNEXPECTEDTOKEN;
	}

	paylen = tpkt -> length;
	if (paylen % 8)
		paylen += 8 - (tpkt -> length % 8);
	if (paylen > (*bufmax)) {
		if ((*buf))
			dfree ((*buf), MDL);
		(*bufmax) = ((paylen + 1023) & ~1023U);
		(*buf) = dmalloc ((*bufmax), MDL);
		if (!(*buf)) {
			log_error ("Can't allocate input buffer sized %d",
				   (*bufmax));
			return ISC_R_NOMEMORY;
		}
	}
	
	status = fread ((*buf), 1, paylen, traceinfile);
	if (status < paylen) {
		if (ferror (traceinfile))
			log_error ("Error reading trace payload: %m");
		else
			log_error ("Short read on trace payload: %d %d.",
				   status, paylen);
		return DHCP_R_PROTOCOLERROR;
	}

	/* Store the actual length of the payload. */
	*buflen = tpkt -> length;

	if (ttp)
		*ttp = ttype;
	return ISC_R_SUCCESS;
}

isc_result_t trace_get_packet (trace_type_t **ttp,
			       unsigned *buflen, char **buf)
{
	tracepacket_t *tpkt;
	unsigned bufmax = 0;
	isc_result_t status;

	if (!buf || *buf)
		return DHCP_R_INVALIDARG;

	tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL);
	if (!tpkt) {
		log_error ("can't allocate trace packet header.");
		return ISC_R_NOMEMORY;
	}

	status = trace_get_next_packet (ttp, tpkt, buf, buflen, &bufmax);

	dfree (tpkt, MDL);
	return status;
}

/* Get a packet from the trace input file that contains a file with the
   specified name.   We don't hunt for the packet - it should be the next
   packet in the tracefile.   If it's not, or something else bad happens,
   return an error code. */

isc_result_t trace_get_file (trace_type_t *ttype,
			     const char *filename, unsigned *len, char **buf)
{
	fpos_t curpos;
	unsigned max = 0;
	tracepacket_t *tpkt;
	int status;
	isc_result_t result;

	/* Disallow some obvious bogosities. */
	if (!buf || !len || *buf)
		return DHCP_R_INVALIDARG;

	/* Save file position in case of filename mismatch. */
	status = fgetpos (traceinfile, &curpos);
	if (status < 0)
		log_error ("Can't save tracefile position: %m");

	tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL);
	if (!tpkt) {
		log_error ("can't allocate trace packet header.");
		return ISC_R_NOMEMORY;
	}

	result = trace_get_next_packet (&ttype, tpkt, buf, len, &max);
	/* done with tpkt, free it */
	dfree (tpkt, MDL);
	if (result != ISC_R_SUCCESS) {
		if (*buf) {
			dfree (*buf, MDL);
			*buf = NULL;
		}
		return result;
	}

	/* Make sure the filename is right. */
	if (strcmp (filename, *buf)) {
		log_error ("Read file %s when expecting %s", *buf, filename);
		dfree (*buf, MDL);
		*buf = NULL;

		status = fsetpos (traceinfile, &curpos);
		if (status < 0) {
			log_error ("fsetpos in tracefile failed: %m");
			return DHCP_R_PROTOCOLERROR;
		}
		return ISC_R_UNEXPECTEDTOKEN;
	}

	return ISC_R_SUCCESS;
}
#endif /* TRACING */