Add the option of hi-res (millisecond) timestamps

examples/simplelog.c

@@ -113,7 +113,7 @@ my_tags_stringify(uint32_t tags)
 
 static void
 trace_logger(int32_t t,
-	     struct qb_log_callsite *cs, time_t timestamp, const char *msg)
+	     struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg)
 {
 	char output_buffer[QB_LOG_MAX_LEN];
 	output_buffer[0] = '\0';

include/qb/qblog.h

@@ -478,11 +478,11 @@ enum qb_log_filter_conf {
 
 typedef void (*qb_log_logger_fn)(int32_t t,
 				 struct qb_log_callsite *cs,
-				 time_t timestamp,
+				 struct timespec *timestamp,
 				 const char *msg);
 typedef void (*qb_log_vlogger_fn)(int32_t t,
 				 struct qb_log_callsite *cs,
-				 time_t timestamp,
+				 struct timespec *timestamp,
 				 va_list ap);
 
 typedef void (*qb_log_close_fn)(int32_t t);
@@ -622,6 +622,15 @@ int32_t qb_log_filter_fn_set(qb_log_filter_fn fn);
  */
 void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn);
 
+
+/**
+ *This is a Feature Test macro so that calling applications know that
+ * millisecond timestamps are implemented. Because %T a string in
+ * function call with an indirect effect, there is no easy test for it
+ * beyond the library version (which is a very blunt instrument)
+ */
+#define QB_FEATURE_LOG_HIRES_TIMESTAMPS 1
+
 /**
  * Set the format specifiers.
  *
@@ -630,6 +639,7 @@ void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn);
  * %l FILELINE
  * %p PRIORITY
  * %t TIMESTAMP
+ * %T TIMESTAMP with milliseconds
  * %b BUFFER
  * %g TAGS
  * %N name (passed into qb_log_init)
@@ -694,7 +704,7 @@ ssize_t qb_log_blackbox_write_to_file(const char *filename);
 /**
  * Read the blackbox for file and print it out.
  */
-void qb_log_blackbox_print_from_file(const char* filename);
+int qb_log_blackbox_print_from_file(const char* filename);
 
 /**
  * Open a custom log target.
@@ -733,7 +743,7 @@ int32_t qb_log_target_user_data_set(int32_t t, void *user_data);
  */
 void qb_log_target_format(int32_t target,
 			  struct qb_log_callsite *cs,
-			  time_t timestamp,
+			  struct timespec *timestamp,
 			  const char* formatted_message,
 			  char *output_buffer);
 

lib/Makefile.am

@@ -123,10 +123,15 @@ ALL_LINT_FLAGS = $(DEFS) $(DEFAULT_INCLUDES) $(INCLUDES) $(DEB_INCLUDES) \
 		 $(libqb_la_CPPFLAGS) $(CPPFLAGS) $(AM_CPPFLAGS) \
 		 $(LINT_FLAGS)
 # expected for the time being (but SHOULD be fixed eventually):
-# ipc_setup.c: (in function qb_ipcc_us_setup_connect)
-# ipc_setup.c:479:2: Return value (type int32_t) ignored: qb_ipc_us_ready(...
-# ipc_setup.c:494:2: Return value (type int32_t) ignored: qb_ipc_auth_cred...
-SPLINT_SUMMARY_EXP = " 2 code warnings"
+#  ipc_setup.c: (in function qb_ipcc_us_setup_connect)
+#  ipc_setup.c:479:2: Return value (type int32_t) ignored: qb_ipc_us_ready(...
+#  ipc_setup.c:494:2: Return value (type int32_t) ignored: qb_ipc_auth_cred...
+# splint is stupid:
+#  log_format.c:397:22: Arrow access field of non-struct or union pointer (struct
+#  log_format.c:408:22: Arrow access field of non-struct or union pointer (struct
+#  log_format.c:415:13: Arrow access field of non-struct or union pointer (struct
+
+SPLINT_SUMMARY_EXP = " 5 code warnings"
 
 run_splint.sh: $(top_srcdir)/configure.ac
 	@echo '$(SPLINT) $(ALL_LINT_FLAGS) \' > $@-t

lib/log.c

@@ -274,7 +274,7 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap)
 
 			} else if (t->vlogger) {
 				va_copy(ap_copy, ap);
-				t->vlogger(t->pos, cs, tv.tv_sec, ap_copy);
+				t->vlogger(t->pos, cs, &tv, ap_copy);
 				va_end(ap_copy);
 
 			} else if (t->logger) {
@@ -283,13 +283,13 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap)
 					formatted = QB_TRUE;
 				}
 				qb_do_extended(str, t->extended,
-					       t->logger(t->pos, cs, tv.tv_sec, str));
+					       t->logger(t->pos, cs, &tv, str));
 			}
 		}
 	}
 
 	if (found_threaded) {
-		qb_log_thread_log_post(cs, tv.tv_sec, str);
+		qb_log_thread_log_post(cs, &tv, str);
 	}
 	qb_atomic_int_set(&in_logger, QB_FALSE);
 
@@ -310,7 +310,7 @@ qb_log_real_(struct qb_log_callsite *cs, ...)
 
 void
 qb_log_thread_log_write(struct qb_log_callsite *cs,
-			time_t timestamp, const char *buffer)
+			struct timespec *timestamp, const char *buffer)
 {
 	struct qb_log_target *t;
 	enum qb_log_target_slot pos;

lib/log_blackbox.c

@@ -53,7 +53,7 @@ _blackbox_reload(int32_t target)
  */
 static void
 _blackbox_vlogger(int32_t target,
-		  struct qb_log_callsite *cs, time_t timestamp, va_list ap)
+		  struct qb_log_callsite *cs, struct timespec *timestamp, va_list ap)
 {
 	size_t max_size;
 	size_t actual_size;
@@ -69,7 +69,7 @@ _blackbox_vlogger(int32_t target,
 
 	fn_size = strlen(cs->function) + 1;
 
-	actual_size = 4 * sizeof(uint32_t) + sizeof(uint8_t) + fn_size + sizeof(time_t);
+	actual_size = 4 * sizeof(uint32_t) + sizeof(uint8_t) + fn_size + sizeof(struct timespec);
 	max_size = actual_size + t->max_line_length;
 
 	chunk = qb_rb_chunk_alloc(t->instance, max_size);
@@ -102,8 +102,8 @@ _blackbox_vlogger(int32_t target,
 	chunk += fn_size;
 
 	/* timestamp */
-	memcpy(chunk, &timestamp, sizeof(time_t));
-	chunk += sizeof(time_t);
+	memcpy(chunk, timestamp, sizeof(struct timespec));
+	chunk += sizeof(struct timespec);
 
 	/* log message length */
 	msg_len_pt = chunk;
@@ -161,19 +161,54 @@ qb_log_blackbox_open(struct qb_log_target *t)
 	return 0;
 }
 
+/*
+ * This is designed to look as much like the ringbuffer header
+ * as possible so that we can distinguish an old RB dump
+ * from a new one with this header.
+ */
+
+struct _blackbox_file_header {
+	uint32_t word_size;
+	uint32_t read_pt;
+	uint32_t write_pt;
+	uint32_t version;
+	uint32_t hash;
+} __attribute__((packed));
+
+/* Values we expect for a 'new' header */
+#define QB_BLACKBOX_HEADER_WORDSIZE 0
+#define QB_BLACKBOX_HEADER_READPT   0xCCBBCCBB
+#define QB_BLACKBOX_HEADER_WRITEPT  0xBBCCBBCC
+#define QB_BLACKBOX_HEADER_VERSION  2
+#define QB_BLACKBOX_HEADER_HASH     0
+
 ssize_t
 qb_log_blackbox_write_to_file(const char *filename)
 {
 	ssize_t written_size = 0;
 	struct qb_log_target *t;
+	struct _blackbox_file_header header;
 	int fd = open(filename, O_CREAT | O_RDWR, 0700);
 
 	if (fd < 0) {
 		return -errno;
 	}
+
+	/* Write header, so we know this is a 'new' format blackbox */
+	header.word_size = QB_BLACKBOX_HEADER_WORDSIZE;
+	header.read_pt   = QB_BLACKBOX_HEADER_READPT;
+	header.write_pt  = QB_BLACKBOX_HEADER_WRITEPT;
+	header.version   = QB_BLACKBOX_HEADER_VERSION;
+	header.hash      = QB_BLACKBOX_HEADER_HASH;
+	written_size = write(fd, &header, sizeof(header));
+	if (written_size < sizeof(header)) {
+		close(fd);
+		return written_size;
+	}
+
 	t = qb_log_target_get(QB_LOG_BLACKBOX);
 	if (t->instance) {
-		written_size = qb_rb_write_to_file(t->instance, fd);
+		written_size += qb_rb_write_to_file(t->instance, fd);
 	} else {
 		written_size = -ENOENT;
 	}
@@ -182,25 +217,51 @@ qb_log_blackbox_write_to_file(const char *filename)
 	return written_size;
 }
 
-void
+int
 qb_log_blackbox_print_from_file(const char *bb_filename)
 {
 	qb_ringbuffer_t *instance;
 	ssize_t bytes_read;
 	int max_size = 2 * QB_LOG_MAX_LEN;
 	char *chunk;
 	int fd;
+	int err = 0;
+	int saved_errno;
+	struct _blackbox_file_header header;
+	int have_timespecs = 0;
 	char time_buf[64];
 
 	fd = open(bb_filename, 0);
 	if (fd < 0) {
+		saved_errno = errno;
 		qb_util_perror(LOG_ERR, "qb_log_blackbox_print_from_file");
-		return;
+		return -saved_errno;
+	}
+
+	/* Read the header. If it looks like one of ours then
+	   we know we have hi-res timestamps */
+	err = read(fd, &header, sizeof(header));
+	if (err < sizeof(header)) {
+		saved_errno = errno;
+		close(fd);
+		return -saved_errno;
 	}
+
+	if (header.word_size == QB_BLACKBOX_HEADER_WORDSIZE &&
+	    header.read_pt == QB_BLACKBOX_HEADER_READPT &&
+	    header.write_pt == QB_BLACKBOX_HEADER_WRITEPT &&
+	    header.version == QB_BLACKBOX_HEADER_VERSION &&
+	    header.hash == QB_BLACKBOX_HEADER_HASH) {
+		have_timespecs = 1;
+	} else {
+		lseek(fd, 0, SEEK_SET);
+	}
+
+
 	instance = qb_rb_create_from_file(fd, 0);
 	close(fd);
 	if (instance == NULL) {
-		return;
+		return -EIO;
 	}
 	chunk = malloc(max_size);
 
@@ -212,7 +273,8 @@ qb_log_blackbox_print_from_file(const char *bb_filename)
 		uint32_t fn_size;
 		char *function;
 		uint32_t len;
-		time_t timestamp;
+		struct timespec timestamp;
+		time_t time_sec;
 		uint32_t msg_len;
 		struct tm *tm;
 		char message[QB_LOG_MAX_LEN];
@@ -221,10 +283,12 @@ qb_log_blackbox_print_from_file(const char *bb_filename)
 
 		if (bytes_read >= 0 && bytes_read < BB_MIN_ENTRY_SIZE) {
 			printf("ERROR Corrupt file: blackbox header too small.\n");
+			err = -1;
 			goto cleanup;
 		} else if (bytes_read < 0) {
 			errno = -bytes_read;
 			perror("ERROR: qb_rb_chunk_read failed");
+			err = -EIO;
 			goto cleanup;
 		}
 		ptr = chunk;
@@ -246,12 +310,14 @@ qb_log_blackbox_print_from_file(const char *bb_filename)
 		if ((fn_size + BB_MIN_ENTRY_SIZE) > bytes_read) {
 #ifndef S_SPLINT_S
 			printf("ERROR Corrupt file: fn_size way too big %" PRIu32 "\n", fn_size);
+			err = -EIO;
 #endif /* S_SPLINT_S */
 			goto cleanup;
 		}
 		if (fn_size <= 0) {
 #ifndef S_SPLINT_S
 			printf("ERROR Corrupt file: fn_size negative %" PRIu32 "\n", fn_size);
+			err = -EIO;
 #endif /* S_SPLINT_S */
 			goto cleanup;
 		}
@@ -261,22 +327,32 @@ qb_log_blackbox_print_from_file(const char *bb_filename)
 		ptr += fn_size;
 
 		/* timestamp size & content */
-		memcpy(&timestamp, ptr, sizeof(time_t));
-		ptr += sizeof(time_t);
-		tm = localtime(&timestamp);
+		if (have_timespecs) {
+			memcpy(&timestamp, ptr, sizeof(struct timespec));
+			ptr += sizeof(struct timespec);
+			time_sec = timestamp.tv_sec;
+		} else {
+			memcpy(&time_sec, ptr, sizeof(time_t));
+			ptr += sizeof(time_t);
+			timestamp.tv_nsec = 0LL;
+		}
+
+		tm = localtime(&time_sec);
 		if (tm) {
-			(void)strftime(time_buf,
-				       sizeof(time_buf), "%b %d %T",
-				       tm);
+			int slen = strftime(time_buf,
+					    sizeof(time_buf), "%b %d %T",
+					    tm);
+			snprintf(time_buf+slen, sizeof(time_buf - slen), ".%03lld", timestamp.tv_nsec/QB_TIME_NS_IN_MSEC);
 		} else {
 			snprintf(time_buf, sizeof(time_buf), "%ld",
-				 (long int)timestamp);
+				 (long int)time_sec);
 		}
 		/* message length */
 		memcpy(&msg_len, ptr, sizeof(uint32_t));
 		if (msg_len > QB_LOG_MAX_LEN || msg_len <= 0) {
 #ifndef S_SPLINT_S
 			printf("ERROR Corrupt file: msg_len out of bounds %" PRIu32 "\n", msg_len);
+			err = -EIO;
 #endif /* S_SPLINT_S */
 			goto cleanup;
 		}
@@ -302,4 +378,5 @@ qb_log_blackbox_print_from_file(const char *bb_filename)
 cleanup:
 	qb_rb_close(instance);
 	free(chunk);
+	return err;
 }

lib/log_file.c

@@ -23,7 +23,7 @@
 
 static void
 _file_logger(int32_t t,
-	     struct qb_log_callsite *cs, time_t timestamp, const char *msg)
+	     struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg)
 {
 	char buffer[QB_LOG_MAX_LEN];
 	char *output_buffer = buffer;