Add timestamps to the Corosync black-box output

This patch adds timestamps to the flight-data file so that its output
can be correlated with syslog to aid in debugging. It also adds a header to
the file so that corosync-fplay can tell whether it was generated by the new
code or the old code.

So corosync-fplay in this code can read new and old format fdata files. The old corosync-fplay will crash when trying to read new format files.

Signed-off-by: Christine Caulfield <ccaulfie@redhat.com>
Reviewed-By: Jan Friesse <jfriesse@redhat.com>

exec/logsys.c

@@ -1090,6 +1090,7 @@ int _logsys_rec_init (unsigned int fltsize)
 /*
  * u32 RECORD SIZE
  * u32 record ident
+ * u64 time_t timestamp
  * u32 arg count
  * u32 file line
  * u32 subsys length
@@ -1118,6 +1119,7 @@ void _logsys_log_rec (
 	unsigned int arguments = 0;
 	unsigned int record_reclaim_size = 0;
 	unsigned int index_start;
+	struct timeval the_timeval;
 	int words_written;
 	int subsysid;
 
@@ -1160,9 +1162,9 @@ void _logsys_log_rec (
 	index_start = idx;
 
 	/*
-	 * Reclaim data needed for record including 4 words for the header
+	 * Reclaim data needed for record including 6 words for the header
 	 */
-	records_reclaim (idx, record_reclaim_size + 4);
+	records_reclaim (idx, record_reclaim_size + 6);
 
 	/*
 	 * Write record size of zero and rest of header information
@@ -1178,6 +1180,14 @@ void _logsys_log_rec (
 
 	flt_data[idx++] = records_written;
 	idx_word_step(idx);
+
+	gettimeofday(&the_timeval, NULL);
+	flt_data[idx++] = the_timeval.tv_sec & 0xFFFFFFFF;
+	idx_word_step(idx);
+
+	flt_data[idx++] = the_timeval.tv_sec >> 32;
+	idx_word_step(idx);
+
 	/*
 	 * Encode all of the arguments into the log message
 	 */
@@ -1625,6 +1635,7 @@ int logsys_log_rec_store (const char *filename)
 	int fd;
 	ssize_t written_size = 0;
 	size_t this_write_size;
+	uint32_t header_magic=0xFFFFDABB; /* Flight Data Black Box */
 
 	fd = open (filename, O_CREAT|O_RDWR, 0700);
 	if (fd < 0) {
@@ -1633,6 +1644,17 @@ int logsys_log_rec_store (const char *filename)
 
 	logsys_flt_lock();
 
+	/* write a header that tells corosync-fplay this is a new-format
+	 * flightdata file, with timestamps. The header word has the top
+	 * bit set which makes it larger than any older fdata file so
+	 * that the tool can recognise old or new files.
+	 */
+	this_write_size = write (fd, &header_magic, sizeof(uint32_t));
+	if (this_write_size != sizeof(unsigned int)) {
+		goto error_exit;
+	}
+	written_size += this_write_size;
+
 	this_write_size = write (fd, &flt_data_size, sizeof(uint32_t));
 	if (this_write_size != sizeof(unsigned int)) {
 		goto error_exit;

tools/corosync-fplay.c

@@ -19,6 +19,7 @@
 #include <corosync/engine/logsys.h>
 
 uint32_t flt_data_size;
+uint32_t old_format_file;
 
 uint32_t *flt_data;
 #define FDHEAD_INDEX		(flt_data_size)
@@ -411,17 +412,32 @@ static void logsys_rec_print (const void *record)
 	unsigned int words_processed;
 	unsigned int found;
 	const char *arguments[64];
+	time_t timestamp;
+	struct tm timestamp_tm;
 	int arg_count = 0;
+	char ts_buf[132];
 
-	rec_size = buf_uint32t[rec_idx];
-	rec_ident = buf_uint32t[rec_idx+1];
-	line = buf_uint32t[rec_idx+2];
-	record_number = buf_uint32t[rec_idx+3];
+	rec_size = buf_uint32t[rec_idx++];
+	rec_ident = buf_uint32t[rec_idx++];
+	line = buf_uint32t[rec_idx++];
+	record_number = buf_uint32t[rec_idx++];
+
+	if (!old_format_file) {
+		timestamp = (time_t)(buf_uint32t[rec_idx] | (time_t)(buf_uint32t[rec_idx+1])<<32);
+		rec_idx += 2;
+	}
 
 	level = LOGSYS_DECODE_LEVEL(rec_ident);
 
 	printf ("rec=[%d] ", record_number);
-	arg_size_idx = rec_idx + 4;
+
+	if (!old_format_file) {
+		localtime_r(&timestamp, &timestamp_tm);
+		strftime(ts_buf, sizeof(ts_buf), "%F %T", &timestamp_tm);
+		printf ("time=[%s] ", ts_buf);
+	}
+
+	arg_size_idx = rec_idx;
 	words_processed = 4;
 	for (i = 0; words_processed < rec_size; i++) {
 		arguments[arg_count++] =
@@ -496,6 +512,7 @@ int main (void)
 	ssize_t n_read;
 	const char *data_file = LOCALSTATEDIR "/lib/corosync/fdata";
 	size_t n_required;
+	uint32_t flt_magic;
 
 	if ((fd = open (data_file, O_RDONLY)) < 0) {
 		fprintf (stderr, "failed to open %s: %s\n",
@@ -504,12 +521,30 @@ int main (void)
 	}
 
 	n_required = sizeof (uint32_t);
-	n_read = read (fd, &flt_data_size, n_required);
+	n_read = read (fd, &flt_magic, n_required);
 	if (n_read != n_required) {
-		fprintf (stderr, "Unable to read fdata header\n");
+		fprintf (stderr, "Unable to read fdata magic number\n");
 		return EXIT_FAILURE;
 	}
 
+	/* If the first word is a magic number then this is a new format
+	 * fdata file (with timestamps) and the next word is the length.
+	 * If not, then it's an old file and we just read the length, so use it
+	 */
+	if (flt_magic == 0xFFFFDABB) {
+		n_required = sizeof (uint32_t);
+		n_read = read (fd, &flt_data_size, n_required);
+		if (n_read != n_required) {
+			fprintf (stderr, "Unable to read fdata header\n");
+			return EXIT_FAILURE;
+		}
+		old_format_file = 0;
+	}
+	else {
+		flt_data_size = flt_magic;
+		old_format_file = 1;
+	}
+
 	n_required = ((flt_data_size + 2) * sizeof(uint32_t));
 
 	if ((flt_data = malloc (n_required)) == NULL) {