Fix the trace code to handle timing events better. [ISC-Bugs 20969]

2 files changed, 110 insertions, 107 deletions

diff --git a/RELNOTES b/RELNOTES
index 08474e46..ea0d2498 100644
--- a/RELNOTES
+++ b/RELNOTES
@@ -65,6 +65,9 @@ work on other platforms. Please report any problems and suggested fixes to
 
 - Add some debugging output for use with the DDNS code. [ISC-Bugs #20916]
 
+- Fix the trace code to handle timing events better and to truncate a file
+  before using instead of overwriting it.  [ISC-Bugs 20969]
+
 			Changes since 4.2.0a2
 
 - Update the fsync code to work with the changes to the DDNS code.  It now
diff --git a/omapip/trace.c b/omapip/trace.c
index 8b18d806..9fd3fb5e 100644
--- a/omapip/trace.c
+++ b/omapip/trace.c
@@ -5,7 +5,8 @@
    transactions... */
 
 /*
- * Copyright (c) 2004-2007,2009 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
@@ -143,7 +144,8 @@ isc_result_t trace_begin (const char *filename,
 	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, 0600);
+		traceoutfile = open (filename, O_WRONLY | O_EXCL | O_TRUNC,
+				     0600);
 	}
 
 	if (traceoutfile < 0) {
@@ -420,41 +422,41 @@ void trace_replay_init (void)
 
 void trace_file_replay (const char *filename)
 {
-	tracepacket_t *tpkt = (tracepacket_t *)0;
+	tracepacket_t *tpkt = NULL;
 	int status;
-	char *buf = (char *)0;
+	char *buf = NULL;
 	unsigned buflen;
 	unsigned bufmax = 0;
-	trace_type_t *ttype = (trace_type_t *)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);
+		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);
+	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);
+	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");
+		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));
+			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);
+	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);
+		log_error("%s: not a dhcp trace file.", filename);
 		goto out;
 	}
 	if (tracefile_header.version > TRACEFILE_VERSION) {
@@ -464,43 +466,43 @@ void trace_file_replay (const char *filename)
 		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);
+		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);
+		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);
+		status = fseek(traceinfile, (long)len, SEEK_CUR);
 		if (status < 0) {
-			log_error ("can't seek past header: %m");
+			log_error("can't seek past header: %m");
 			goto out;
 		}
 	}
 
-	tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL);
-	if (!tpkt) {
+	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 = (trace_type_t *)0;
+	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)
-		dfree (buf, MDL);
-	if (tpkt)
-		dfree (tpkt, MDL);
+	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
@@ -514,53 +516,80 @@ isc_result_t trace_get_next_packet (trace_type_t **ttp,
 {
 	trace_type_t *ttype;
 	unsigned paylen;
-	int status;
+	int status, curposok = 0;
 	fpos_t curpos;
 
-	status = fgetpos (traceinfile, &curpos);
-	if (status < 0)
-		log_error ("Can't save tracefile position: %m");
+	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;
-	}
+		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);
+		/* 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;
-	}
-
-	/* If we were just hunting for the time marker, we've found it,
-	   so back up to the beginning of the packet and return its
-	   type. */
-	if (ttp && *ttp == &trace_time_marker) {
-		*ttp = ttype;
-		status = fsetpos (traceinfile, &curpos);
-		if (status < 0) {
-			log_error ("fsetpos in tracefile failed: %m");
+		/* 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;
 		}
-		return ISC_R_EXISTS;
+
+		/*
+		 * 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,
@@ -604,9 +633,6 @@ isc_result_t trace_get_next_packet (trace_type_t **ttp,
 	/* Store the actual length of the payload. */
 	*buflen = tpkt -> length;
 
-	if (trace_set_time_hook)
-		(*trace_set_time_hook) (tpkt -> when);
-
 	if (ttp)
 		*ttp = ttype;
 	return ISC_R_SUCCESS;
@@ -634,32 +660,6 @@ isc_result_t trace_get_packet (trace_type_t **ttp,
 	return status;
 }
 
-time_t trace_snoop_time (trace_type_t **ptp)
-{
-	tracepacket_t *tpkt;
-	unsigned bufmax = 0;
-	unsigned buflen = 0;
-	char *buf = (char *)0;
-	time_t result;
-	trace_type_t *ttp;
-	
-	if (!ptp)
-		ptp = &ttp;
-
-	tpkt = dmalloc ((unsigned)tracefile_header.phlen, MDL);
-	if (!tpkt) {
-		log_error ("can't allocate trace packet header.");
-		return ISC_R_NOMEMORY;
-	}
-
-	*ptp = &trace_time_marker;
-	trace_get_next_packet (ptp, tpkt, &buf, &buflen, &bufmax);
-	result = tpkt -> when;
-
-	dfree (tpkt, MDL);
-	return result;
-}
-
 /* 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,