Try to preserve the integrity of the log file in case of errors/unexpected

shutdowns etc. Also check logfile integrity on startup and suspend
logging if an inconsistency is detected.
ok dhartmei@

3 files changed, 318 insertions, 63 deletions

diff --git a/sbin/pflogd/pflogd.8 b/sbin/pflogd/pflogd.8
index ab632593ac7..ed1e50f6914 100644
--- a/sbin/pflogd/pflogd.8
+++ b/sbin/pflogd/pflogd.8
@@ -1,4 +1,4 @@
-.\"	$OpenBSD: pflogd.8,v 1.22 2003/06/03 13:16:08 jmc Exp $
+.\"	$OpenBSD: pflogd.8,v 1.23 2004/01/15 20:15:14 canacar Exp $
 .\"
 .\" Copyright (c) 2001 Can Erkin Acar.  All rights reserved.
 .\"
@@ -36,6 +36,7 @@
 .Op Fl d Ar delay
 .Op Fl f Ar filename
 .Op Fl s Ar snaplen
+.Op Fl x
 .Op Ar expression
 .Sh DESCRIPTION
 .Nm
@@ -77,6 +78,16 @@ If the existing log file was created with a different snaplen,
 .Nm
 temporarily uses the old snaplen to keep the log file consistent.
 .Pp
+.Nm
+tries to preserve the integrity of the log file against I/O errors.
+Furthermore, integrity of an existing log file is verified before
+appending.  If there is an invalid log file or an I/O error, logging
+is suspended, until a
+.Va SIGHUP
+or a
+.Va SIGALRM
+is received.
+.Pp
 The options are as follows:
 .Bl -tag -width Ds
 .It Fl d Ar delay
@@ -98,6 +109,8 @@ bytes of data from each packet rather than the default of 96.
 The default of 96 is adequate for IP, ICMP, TCP, and UDP headers but may
 truncate protocol information for other protocols.
 Other file parsers may desire a higher snaplen.
+.It Fl x
+Check the integrity of an existing log file, and return.
 .It Ar expression
 Selects which packets will be dumped, using the regular language of
 .Xr tcpdump 8 .
diff --git a/sbin/pflogd/pflogd.c b/sbin/pflogd/pflogd.c
index 85d6baf2514..76536c34d4b 100644
--- a/sbin/pflogd/pflogd.c
+++ b/sbin/pflogd/pflogd.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: pflogd.c,v 1.24 2003/10/22 19:53:15 deraadt Exp $	*/
+/*	$OpenBSD: pflogd.c,v 1.25 2004/01/15 20:15:14 canacar Exp $	*/
 
 /*
  * Copyright (c) 2001 Theo de Raadt
@@ -49,10 +49,11 @@
 #include "pflogd.h"
 
 pcap_t *hpcap;
-pcap_dumper_t *dpcap;
+static FILE *dpcap;
 
 int Debug = 0;
-int snaplen = DEF_SNAPLEN;
+static int snaplen = DEF_SNAPLEN;
+static int cur_snaplen = DEF_SNAPLEN;
 
 volatile sig_atomic_t gotsig_close, gotsig_alrm, gotsig_hup;
 
@@ -65,15 +66,43 @@ char errbuf[PCAP_ERRBUF_SIZE];
 int log_debug = 0;
 unsigned int delay = FLUSH_DELAY;
 
-char *copy_argv(char * const *argv);
+char *copy_argv(char * const *);
+void  dump_packet(u_char *, const struct pcap_pkthdr *, const u_char *);
+void  dump_packet_nobuf(u_char *, const struct pcap_pkthdr *, const u_char *);
+int   flush_buffer(FILE *);
 int   init_pcap(void);
-void  logmsg(int priority, const char *message, ...);
+void  logmsg(int, const char *, ...);
+void  purge_buffer(void);
 int   reset_dump(void);
+int   scan_dump(FILE *, off_t);
+int   set_snaplen(int);
+void  set_suspended(int);
 void  sig_alrm(int);
 void  sig_close(int);
 void  sig_hup(int);
 void  usage(void);
 
+/* buffer must always be greater than snaplen */
+static int    bufpkt = 0;	/* number of packets in buffer */
+static int    buflen = 0;	/* allocated size of buffer */
+static char  *buffer = NULL;	/* packet buffer */
+static char  *bufpos = NULL;	/* position in buffer */
+static int    bufleft = 0;	/* bytes left in buffer */
+
+/* if error, stop logging but count dropped packets */
+static int suspended = -1;
+static long packets_dropped = 0;
+
+void
+set_suspended(int s)
+{
+	if (suspended == s)
+		return;
+
+	suspended = s;
+	setproctitle("[%s] -s %d -f %s",
+            suspended ? "suspended" : "running", cur_snaplen, filename);
+}
 
 char *
 copy_argv(char * const *argv)
@@ -161,7 +190,6 @@ init_pcap(void)
 	hpcap = pcap_open_live(interface, snaplen, 1, PCAP_TO_MS, errbuf);
 	if (hpcap == NULL) {
 		logmsg(LOG_ERR, "Failed to initialize: %s", errbuf);
-		hpcap = NULL;
 		return (-1);
 	}
 
@@ -174,7 +202,7 @@ init_pcap(void)
 
 	set_pcap_filter();
 
-	snaplen = pcap_snapshot(hpcap);
+	cur_snaplen = snaplen = pcap_snapshot(hpcap);
 
 	/* lock */
 	if (ioctl(pcap_fileno(hpcap), BIOCLOCK) < 0) {
@@ -186,6 +214,20 @@ init_pcap(void)
 }
 
 int
+set_snaplen(int snap)
+{
+	if (priv_set_snaplen(snap))
+		return (1);
+
+	if (cur_snaplen > snap)
+		purge_buffer();
+
+	cur_snaplen = snap;
+
+	return (0);
+}
+
+int
 reset_dump(void)
 {
 	struct pcap_file_header hdr;
@@ -194,10 +236,12 @@ reset_dump(void)
 	FILE *fp;
 
 	if (hpcap == NULL)
-		return (1);
+		return (-1);
+
 	if (dpcap) {
-		pcap_dump_close(dpcap);
-		dpcap = 0;
+		flush_buffer(dpcap);
+		fclose(dpcap);
+		dpcap = NULL;
 	}
 
 	/*
@@ -219,14 +263,18 @@ reset_dump(void)
 		return (1);
 	}
 
-	dpcap = (pcap_dumper_t *)fp;
+	/* set FILE unbuffered, we do our own buffering */
+	if (setvbuf(fp, NULL, _IONBF, 0)) {
+		logmsg(LOG_ERR, "Failed to set output buffers");
+		return (1);
+	}
 
 #define TCPDUMP_MAGIC 0xa1b2c3d4
 
 	if (st.st_size == 0) {
-		if (snaplen != pcap_snapshot(hpcap)) {
+		if (snaplen != cur_snaplen) {
 			logmsg(LOG_NOTICE, "Using snaplen %d", snaplen);
-			if (priv_set_snaplen(snaplen)) {
+			if (set_snaplen(snaplen)) {
 				logmsg(LOG_WARNING,
 				    "Failed, using old settings");
 			}
@@ -240,52 +288,222 @@ reset_dump(void)
 		hdr.linktype = hpcap->linktype;
 
 		if (fwrite((char *)&hdr, sizeof(hdr), 1, fp) != 1) {
-			dpcap = NULL;
 			fclose(fp);
-			return (-1);
+			return (1);
 		}
-		return (0);
+	} else if (scan_dump(fp, st.st_size)) {
+		/* XXX move file and continue? */
+		fclose(fp);
+		return (1);
 	}
 
+	dpcap = fp;
+
+	set_suspended(0);
+	flush_buffer(fp);
+
+	return (0);
+}
+
+int
+scan_dump(FILE *fp, off_t size)
+{
+	struct pcap_file_header hdr;
+	struct pcap_pkthdr ph;
+	off_t pos;
+
 	/*
-	 * XXX Must read the file, compare the header against our new
+	 * Must read the file, compare the header against our new
 	 * options (in particular, snaplen) and adjust our options so
-	 * that we generate a correct file.
+	 * that we generate a correct file. Furthermore, check the file
+	 * for consistency so that we can append safely.
+	 *
+	 * XXX this may take a long time for large logs.
 	 */
 	(void) fseek(fp, 0L, SEEK_SET);
-	if (fread((char *)&hdr, sizeof(hdr), 1, fp) == 1) {
-		if (hdr.magic != TCPDUMP_MAGIC ||
-		    hdr.version_major != PCAP_VERSION_MAJOR ||
-		    hdr.version_minor != PCAP_VERSION_MINOR ||
-		    hdr.linktype != hpcap->linktype) {
-			logmsg(LOG_ERR,
-			    "Invalid/incompatible log file, move it away");
-			fclose(fp);
-			return (1);
-		}
-		if (hdr.snaplen != snaplen) {
+
+	if (fread((char *)&hdr, sizeof(hdr), 1, fp) != 1) {
+		logmsg(LOG_ERR, "Short file header");
+		return (1);
+	}
+
+	if (hdr.magic != TCPDUMP_MAGIC ||
+	    hdr.version_major != PCAP_VERSION_MAJOR ||
+	    hdr.version_minor != PCAP_VERSION_MINOR ||
+	    hdr.linktype != hpcap->linktype ||
+	    hdr.snaplen > PFLOGD_MAXSNAPLEN) {
+		logmsg(LOG_ERR, "Invalid/incompatible log file, move it away");
+		return (1);
+	}
+
+	pos = sizeof(hdr);
+
+	while (!feof(fp)) {
+		off_t len = fread((char *)&ph, 1, sizeof(ph), fp);
+		if (len == 0)
+			break;
+
+		if (len != sizeof(ph))
+			goto error;
+		if (ph.caplen > hdr.snaplen || ph.caplen > PFLOGD_MAXSNAPLEN)
+			goto error;
+		pos += sizeof(ph) + ph.caplen;
+		if (pos > size)
+			goto error;
+		fseek(fp, ph.caplen, SEEK_CUR);
+	}
+
+	if (pos != size)
+		goto error;
+
+	if (hdr.snaplen != cur_snaplen) {
+		logmsg(LOG_WARNING,
+		       "Existing file has different snaplen %u, using it",
+		       hdr.snaplen);
+		if (set_snaplen(hdr.snaplen)) {
 			logmsg(LOG_WARNING,
-			    "Existing file has different snaplen %u, using it",
-			    hdr.snaplen);
-			if (priv_set_snaplen(hdr.snaplen)) {
-				logmsg(LOG_WARNING,
-				    "Failed, using old settings, offset %llu",
-				    (unsigned long long) st.st_size);
-			}
+			       "Failed, using old settings, offset %llu",
+			       (unsigned long long) size);
+		}
+	}
+
+	return (0);
+
+ error:
+	logmsg(LOG_ERR, "Corrupted log file.");
+	return (1);
+}
+
+/* dump a packet directly to the stream, which is unbuffered */
+void
+dump_packet_nobuf(u_char *user, const struct pcap_pkthdr *h, const u_char *sp)
+{
+	FILE *f = (FILE *)user;
+
+	if (suspended) {
+		packets_dropped++;
+		return;
+	}
+
+	if (fwrite((char *)h, sizeof(*h), 1, f) != 1) {
+		/* try to undo header to prevent corruption */
+		off_t pos = ftello(f);
+		if (pos < sizeof(*h) ||
+		    ftruncate(fileno(f), pos - sizeof(*h))) {
+			logmsg(LOG_ERR, "Write failed, corrupted logfile!");
+			set_suspended(1);
+			gotsig_close = 1;
+			return;
 		}
+		goto error;
+	}
+
+	if (fwrite((char *)sp, h->caplen, 1, f) != 1)
+		goto error;
+
+	return;
+
+error:
+	set_suspended(1);
+	packets_dropped ++;
+	logmsg(LOG_ERR, "Logging suspended: fwrite: %s", strerror(errno));
+}
+
+int
+flush_buffer(FILE *f)
+{
+	off_t offset;
+	int len = bufpos - buffer;
+
+	if (len <= 0)
+		return (0);
+
+	offset = ftello(f);
+	if (offset == (off_t)-1) {
+		set_suspended(1);
+		logmsg(LOG_ERR, "Logging suspended: ftello: %s",
+		    strerror(errno));
+		return (1);
+	}
+
+	if (fwrite(buffer, len, 1, f) != 1) {
+		set_suspended(1);
+		logmsg(LOG_ERR, "Logging suspended: fwrite: %s",
+		    strerror(errno));
+		ftruncate(fileno(f), offset);
+		return (1);
 	}
 
-	(void) fseek(fp, 0L, SEEK_END);
+	set_suspended(0);
+	bufpos = buffer;
+	bufleft = buflen;
+	bufpkt = 0;
+
 	return (0);
 }
 
+void
+purge_buffer(void)
+{
+	packets_dropped += bufpkt;
+
+	set_suspended(0);
+	bufpos = buffer;
+	bufleft = buflen;
+	bufpkt = 0;
+}
+
+/* append packet to the buffer, flushing if necessary */
+void
+dump_packet(u_char *user, const struct pcap_pkthdr *h, const u_char *sp)
+{
+	FILE *f = (FILE *)user;
+	size_t len = sizeof(*h) + h->caplen;
+
+	if (len < sizeof(*h) || h->caplen > (size_t)cur_snaplen) {
+		logmsg(LOG_NOTICE, "invalid size %u (%u/%u), packet dropped",
+		       len, cur_snaplen, snaplen);
+		packets_dropped++;
+		return;
+	}
+
+	if (len <= bufleft)
+		goto append;
+
+	if (suspended) {
+		packets_dropped++;
+		return;
+	}
+
+	if (flush_buffer(f)) {
+		packets_dropped++;
+		return;
+	}
+
+	if (len > bufleft) {
+		dump_packet_nobuf(user, h, sp);
+		return;
+	}
+
+ append:	
+	memcpy(bufpos, h, sizeof(*h));
+	memcpy(bufpos + sizeof(*h), sp, h->caplen);
+
+	bufpos += len;
+	bufleft -= len;
+	bufpkt++;
+
+	return;
+}
+
 int
 main(int argc, char **argv)
 {
 	struct pcap_stat pstat;
-	int ch, np;
+	int ch, np, Xflag = 0;
+	pcap_handler phandler = dump_packet;
 
-	while ((ch = getopt(argc, argv, "Dd:s:f:")) != -1) {
+	while ((ch = getopt(argc, argv, "Dxd:s:f:")) != -1) {
 		switch (ch) {
 		case 'D':
 			Debug = 1;
@@ -302,6 +520,11 @@ main(int argc, char **argv)
 			snaplen = atoi(optarg);
 			if (snaplen <= 0)
 				snaplen = DEF_SNAPLEN;
+			if (snaplen > PFLOGD_MAXSNAPLEN)
+				snaplen = PFLOGD_MAXSNAPLEN;
+			break;
+		case 'x':
+			Xflag++;
 			break;
 		default:
 			usage();
@@ -343,6 +566,7 @@ main(int argc, char **argv)
 		exit(1);
 	}
 
+	setproctitle("[initializing]");
 	/* Process is now unprivileged and inside a chroot */
 	signal(SIGTERM, sig_close);
 	signal(SIGINT, sig_close);
@@ -351,14 +575,29 @@ main(int argc, char **argv)
 	signal(SIGHUP, sig_hup);
 	alarm(delay);
 
-	if (reset_dump()) {
-		logmsg(LOG_ERR, "Failed to open log file %s", filename);
-		pcap_close(hpcap);
-		exit(1);
+	buffer = malloc(PFLOGD_BUFSIZE);
+
+	if (buffer == NULL) {
+		logmsg(LOG_WARNING, "Failed to allocate output buffer");
+		phandler = dump_packet_nobuf;
+	} else {
+		bufleft = buflen = PFLOGD_BUFSIZE;
+		bufpos = buffer;
+		bufpkt = 0;
 	}
 
+	if (reset_dump()) {
+		if (Xflag)
+			return (1);
+
+		logmsg(LOG_ERR, "Logging suspended: open error");
+		set_suspended(1);
+	} else if (Xflag)
+		return (0);
+
 	while (1) {
-		np = pcap_dispatch(hpcap, PCAP_NUM_PKTS, pcap_dump, (u_char *)dpcap);
+		np = pcap_dispatch(hpcap, PCAP_NUM_PKTS,
+		    dump_packet, (u_char *)dpcap);
 		if (np < 0)
 			logmsg(LOG_NOTICE, "%s", pcap_geterr(hpcap));
 
@@ -366,37 +605,34 @@ main(int argc, char **argv)
 			break;
 		if (gotsig_hup) {
 			if (reset_dump()) {
-				logmsg(LOG_ERR, "Failed to open log file!");
-				break;
+				logmsg(LOG_ERR,
+				    "Logging suspended: open error");
+				set_suspended(1);
 			}
 			gotsig_hup = 0;
 		}
 
 		if (gotsig_alrm) {
-			/* XXX pcap_dumper is an incomplete type which libpcap
-			 * casts to a FILE* currently.  For now it is safe to
-			 * make the same assumption, however this may change
-			 * in the future.
-			 */
-			if (dpcap) {
-				if (fflush((FILE *)dpcap) == EOF) {
-					break;
-				}
-			}
+			if (dpcap)
+				flush_buffer(dpcap);
 			gotsig_alrm = 0;
 			alarm(delay);
 		}
 	}
 
-	logmsg(LOG_NOTICE, "Exiting due to signal");
-	if (dpcap)
-		pcap_dump_close(dpcap);
+	logmsg(LOG_NOTICE, "Exiting");
+	if (dpcap) {
+		flush_buffer(dpcap);
+		fclose(dpcap);
+	}
+	purge_buffer();
 
 	if (pcap_stats(hpcap, &pstat) < 0)
 		logmsg(LOG_WARNING, "Reading stats: %s", pcap_geterr(hpcap));
 	else
-		logmsg(LOG_NOTICE, "%u packets received, %u dropped",
-		    pstat.ps_recv, pstat.ps_drop);
+		logmsg(LOG_NOTICE,
+		    "%u packets received, %u/%u dropped (kernel/pflogd)",
+		    pstat.ps_recv, pstat.ps_drop, packets_dropped);
 
 	pcap_close(hpcap);
 	if (!Debug)
diff --git a/sbin/pflogd/pflogd.h b/sbin/pflogd/pflogd.h
index 765adb9a791..3baecb66fe6 100644
--- a/sbin/pflogd/pflogd.h
+++ b/sbin/pflogd/pflogd.h
@@ -1,3 +1,5 @@
+/*	$OpenBSD: pflogd.h,v 1.2 2004/01/15 20:15:14 canacar Exp $ */
+
 /*
  * Copyright (c) 2003 Can Erkin Acar
  *
@@ -14,17 +16,21 @@
  * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  */
 
+#include <sys/limits.h>
 #include <pcap.h>
 
 #define DEF_SNAPLEN 116		/* default plus allow for larger header of pflog */
 #define PCAP_TO_MS 500		/* pcap read timeout (ms) */
 #define PCAP_NUM_PKTS 1000	/* max number of packets to process at each loop */
-#define PCAP_OPT_FIL 0		/* filter optimization */
+#define PCAP_OPT_FIL 1		/* filter optimization */
 #define FLUSH_DELAY 60		/* flush delay */
 
 #define PFLOGD_LOG_FILE		"/var/log/pflog"
 #define PFLOGD_DEFAULT_IF	"pflog0"
 
+#define PFLOGD_MAXSNAPLEN	INT_MAX
+#define PFLOGD_BUFSIZE		65536	/* buffer size for incoming packets */
+
 void  logmsg(int priority, const char *message, ...);
 
 /* Privilege separation */