[logging] Add new "log timestamp precision" command for subsecond timestamps

2007-04-28 Andrew J. Schorr <ajschorr@alumni.princeton.edu>

	* command.c: (config_write_host) Save "log timestamp precision"
	  if not default value.
	  (show_logging) Show configured timestamp precision.
	  (config_log_timestamp_precision) Enable configuration of timestamp
	  precision.
	  (no_config_log_timestamp_precision) Restore default timestamp
	  precision.
	  (cmd_init) Install new timestamp precision commands.
	* log.h: (struct zlog) New timestamp_precision field.
	  (quagga_timestamp) New function to generate a timestamp with the
	  desired precision.
	  (struct timestamp_control) Declare a structure for use in avoiding
	  repeated duplicate calls to quagga_timestamp.
	* log.c: (quagga_timestamp) New function to generate a timestamp
	  of the desired precision.
	  (time_print) Call quagga_timestamp if the time hasn't already been
	  calculated.
	  (vzlog) Initialize a timestamp_control structure and pass it to
	  time_print and vty_log.
	  (zlog_backtrace) Fix 64-bit problem: cannot print size_t with %u.
	* vty.h: Must now include "log.h".
	  (vty_log) Takes an additional struct timestamp_control argument.
	* vty.c: (vty_log_out) Use new struct timestamp_control and new
	  quagga_timestamp function to print timestamps of the desired
	  precision.
	  (vty_time_print) Use new quagga_timestamp function.
	  (vty_log) Accept new struct timestamp_control argument and pass it
	  down to vty_log_out.

1 files changed, 73 insertions, 22 deletions

diff --git a/lib/log.c b/lib/log.c
index c123f24f..76682227 100644
--- a/lib/log.c
+++ b/lib/log.c
@@ -66,32 +66,81 @@ const char *zlog_priority[] =
 
 
 /* For time string format. */
-#define TIME_BUF 27
 
-/* Utility routine for current time printing. */
-static void
-time_print (FILE *fp)
+size_t
+quagga_timestamp(int timestamp_precision, char *buf, size_t buflen)
 {
-  int ret;
-  char buf [TIME_BUF];
-  time_t clock;
-  struct tm *tm;
-  
-  time (&clock);
-  tm = localtime (&clock);
+  static struct {
+    time_t last;
+    size_t len;
+    char buf[28];
+  } cache;
+  struct timeval clock;
+
+  /* would it be sufficient to use global 'recent_time' here?  I fear not... */
+  gettimeofday(&clock, NULL);
+
+  /* first, we update the cache if the time has changed */
+  if (cache.last != clock.tv_sec)
+    {
+      struct tm *tm;
+      cache.last = clock.tv_sec;
+      tm = localtime(&cache.last);
+      cache.len = strftime(cache.buf, sizeof(cache.buf),
+      			   "%Y/%m/%d %H:%M:%S", tm);
+    }
+  /* note: it's not worth caching the subsecond part, because
+     chances are that back-to-back calls are not sufficiently close together
+     for the clock not to have ticked forward */
 
-  ret = strftime (buf, TIME_BUF, "%Y/%m/%d %H:%M:%S", tm);
-  if (ret == 0) {
-    zlog_warn ("strftime error");
-  }
+  if (buflen > cache.len)
+    {
+      memcpy(buf, cache.buf, cache.len);
+      if ((timestamp_precision > 0) &&
+	  (buflen > cache.len+1+timestamp_precision))
+	{
+	  /* should we worry about locale issues? */
+	  long divisor = 100000;
+	  char *p = buf+cache.len;
+	  *p++ = '.';
+	  do
+	    {
+	      *p++ = '0'+(clock.tv_usec/divisor);
+	      clock.tv_usec %= divisor;
+	      divisor /= 10;
+	    }
+	  while (--timestamp_precision > 0);
+	  *p = '\0';
+	  return p-buf;
+	}
+      buf[cache.len] = '\0';
+      return cache.len;
+    }
+  if (buflen > 0)
+    buf[0] = '\0';
+  return 0;
+}
 
-  fprintf (fp, "%s ", buf);
+/* Utility routine for current time printing. */
+static void
+time_print(FILE *fp, struct timestamp_control *ctl)
+{
+  if (!ctl->already_rendered)
+    {
+      ctl->len = quagga_timestamp(ctl->precision, ctl->buf, sizeof(ctl->buf));
+      ctl->already_rendered = 1;
+    }
+  fprintf(fp, "%s ", ctl->buf);
 }
+  
 
 /* va_list version of zlog. */
 static void
 vzlog (struct zlog *zl, int priority, const char *format, va_list args)
 {
+  struct timestamp_control tsctl;
+  tsctl.already_rendered = 0;
+
   /* If zlog is not specified, use default one. */
   if (zl == NULL)
     zl = zlog_default;
@@ -99,7 +148,8 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args)
   /* When zlog_default is also NULL, use stderr for logging. */
   if (zl == NULL)
     {
-      time_print (stderr);
+      tsctl.precision = 0;
+      time_print(stderr, &tsctl);
       fprintf (stderr, "%s: ", "unknown");
       vfprintf (stderr, format, args);
       fprintf (stderr, "\n");
@@ -108,6 +158,7 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args)
       /* In this case we return at here. */
       return;
     }
+  tsctl.precision = zl->timestamp_precision;
 
   /* Syslog output */
   if (priority <= zl->maxlvl[ZLOG_DEST_SYSLOG])
@@ -122,7 +173,7 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args)
   if ((priority <= zl->maxlvl[ZLOG_DEST_FILE]) && zl->fp)
     {
       va_list ac;
-      time_print (zl->fp);
+      time_print (zl->fp, &tsctl);
       if (zl->record_priority)
 	fprintf (zl->fp, "%s: ", zlog_priority[priority]);
       fprintf (zl->fp, "%s: ", zlog_proto_names[zl->protocol]);
@@ -137,7 +188,7 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args)
   if (priority <= zl->maxlvl[ZLOG_DEST_STDOUT])
     {
       va_list ac;
-      time_print (stdout);
+      time_print (stdout, &tsctl);
       if (zl->record_priority)
 	fprintf (stdout, "%s: ", zlog_priority[priority]);
       fprintf (stdout, "%s: ", zlog_proto_names[zl->protocol]);
@@ -151,7 +202,7 @@ vzlog (struct zlog *zl, int priority, const char *format, va_list args)
   /* Terminal monitor. */
   if (priority <= zl->maxlvl[ZLOG_DEST_MONITOR])
     vty_log ((zl->record_priority ? zlog_priority[priority] : NULL),
-	     zlog_proto_names[zl->protocol], format, args);
+	     zlog_proto_names[zl->protocol], format, &tsctl, args);
 }
 
 static char *
@@ -458,8 +509,8 @@ zlog_backtrace(int priority)
       ((size_t)size > sizeof(array)/sizeof(array[0])))
     {
       zlog_err("Cannot get backtrace, returned invalid # of frames %d "
-	       "(valid range is between 1 and %u)",
-	       size, sizeof(array)/sizeof(array[0]));
+	       "(valid range is between 1 and %lu)",
+	       size, (unsigned long)(sizeof(array)/sizeof(array[0])));
       return;
     }
   zlog(NULL, priority, "Backtrace for %d stack frames:", size);