[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.

6 files changed, 180 insertions, 43 deletions

diff --git a/lib/ChangeLog b/lib/ChangeLog
index ff32fcce..3e515f87 100644
--- a/lib/ChangeLog
+++ b/lib/ChangeLog
@@ -1,3 +1,34 @@
+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.
+
 2007-04-27 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
 
 	* smux.c: (smux_trap) Fix printf format to work with 64-bit size_t.
diff --git a/lib/command.c b/lib/command.c
index 316971e4..f3d96ede 100644
--- a/lib/command.c
+++ b/lib/command.c
@@ -594,6 +594,10 @@ config_write_host (struct vty *vty)
   if (zlog_default->record_priority == 1)
     vty_out (vty, "log record-priority%s", VTY_NEWLINE);
 
+  if (zlog_default->timestamp_precision > 0)
+    vty_out (vty, "log timestamp precision %d%s",
+	     zlog_default->timestamp_precision, VTY_NEWLINE);
+
   if (host.advanced)
     vty_out (vty, "service advanced-vty%s", VTY_NEWLINE);
 
@@ -3092,6 +3096,8 @@ DEFUN (show_logging,
   	   zlog_proto_names[zl->protocol], VTY_NEWLINE);
   vty_out (vty, "Record priority: %s%s",
   	   (zl->record_priority ? "enabled" : "disabled"), VTY_NEWLINE);
+  vty_out (vty, "Timestamp precision: %d%s",
+	   zl->timestamp_precision, VTY_NEWLINE);
 
   return CMD_SUCCESS;
 }
@@ -3416,6 +3422,37 @@ DEFUN (no_config_log_record_priority,
   return CMD_SUCCESS;
 }
 
+DEFUN (config_log_timestamp_precision,
+       config_log_timestamp_precision_cmd,
+       "log timestamp precision <0-6>",
+       "Logging control\n"
+       "Timestamp configuration\n"
+       "Set the timestamp precision\n"
+       "Number of subsecond digits\n")
+{
+  if (argc != 1)
+    {
+      vty_out (vty, "Insufficient arguments%s", VTY_NEWLINE);
+      return CMD_WARNING;
+    }
+
+  VTY_GET_INTEGER_RANGE("Timestamp Precision",
+  			zlog_default->timestamp_precision, argv[0], 0, 6);
+  return CMD_SUCCESS;
+}
+
+DEFUN (no_config_log_timestamp_precision,
+       no_config_log_timestamp_precision_cmd,
+       "no log timestamp precision",
+       NO_STR
+       "Logging control\n"
+       "Timestamp configuration\n"
+       "Reset the timestamp precision to the default value of 0\n")
+{
+  zlog_default->timestamp_precision = 0 ;
+  return CMD_SUCCESS;
+}
+
 DEFUN (banner_motd_file,
        banner_motd_file_cmd,
        "banner motd file [FILE]",
@@ -3571,6 +3608,8 @@ cmd_init (int terminal)
       install_element (CONFIG_NODE, &no_config_log_trap_cmd);
       install_element (CONFIG_NODE, &config_log_record_priority_cmd);
       install_element (CONFIG_NODE, &no_config_log_record_priority_cmd);
+      install_element (CONFIG_NODE, &config_log_timestamp_precision_cmd);
+      install_element (CONFIG_NODE, &no_config_log_timestamp_precision_cmd);
       install_element (CONFIG_NODE, &service_password_encrypt_cmd);
       install_element (CONFIG_NODE, &no_service_password_encrypt_cmd);
       install_element (CONFIG_NODE, &banner_motd_default_cmd);
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);
diff --git a/lib/log.h b/lib/log.h
index 0f058a8b..da8fbea8 100644
--- a/lib/log.h
+++ b/lib/log.h
@@ -1,5 +1,5 @@
 /*
- * $Id: log.h,v 1.18 2005/05/06 21:25:49 paul Exp $
+ * $Id$
  *
  * Zebra logging funcions.
  * Copyright (C) 1997, 1998, 1999 Kunihiro Ishiguro
@@ -83,6 +83,7 @@ struct zlog
   int record_priority;	/* should messages logged through stdio include the
   			   priority of the message? */
   int syslog_options;	/* 2nd arg to openlog */
+  int timestamp_precision;	/* # of digits of subsecond precision */
 };
 
 /* Message structure. */
@@ -168,6 +169,23 @@ extern void zlog_backtrace(int priority);
    that is logged in addition to the current backtrace. */
 extern void zlog_backtrace_sigsafe(int priority, void *program_counter);
 
+/* Puts a current timestamp in buf and returns the number of characters
+   written (not including the terminating NUL).  The purpose of
+   this function is to avoid calls to localtime appearing all over the code.
+   It caches the most recent localtime result and can therefore
+   avoid multiple calls within the same second.  If buflen is too small,
+   *buf will be set to '\0', and 0 will be returned. */
+extern size_t quagga_timestamp(int timestamp_precision /* # subsecond digits */,
+			       char *buf, size_t buflen);
+
+/* structure useful for avoiding repeated rendering of the same timestamp */
+struct timestamp_control {
+   size_t len;		/* length of rendered timestamp */
+   int precision;	/* configuration parameter */
+   int already_rendered; /* should be initialized to 0 */
+   char buf[40];	/* will contain the rendered timestamp */
+};
+
 /* Defines for use in command construction: */
 
 #define LOG_LEVELS "(emergencies|alerts|critical|errors|warnings|notifications|informational|debugging)"
diff --git a/lib/vty.c b/lib/vty.c
index 4288e150..6cb8b487 100644
--- a/lib/vty.c
+++ b/lib/vty.c
@@ -149,17 +149,22 @@ vty_out (struct vty *vty, const char *format, ...)
 
 static int
 vty_log_out (struct vty *vty, const char *level, const char *proto_str,
-	     const char *format, va_list va)
+	     const char *format, struct timestamp_control *ctl, va_list va)
 {
   int ret;
   int len;
   char buf[1024];
-  struct tm *tm;
 
-  if ((tm = localtime(&recent_time.tv_sec)) != NULL)
-    len = strftime(buf, sizeof(buf), "%Y/%m/%d %H:%M:%S ", tm);
-  else
-    len = 0;
+  if (!ctl->already_rendered)
+    {
+      ctl->len = quagga_timestamp(ctl->precision, ctl->buf, sizeof(ctl->buf));
+      ctl->already_rendered = 1;
+    }
+  if (ctl->len+1 >= sizeof(buf))
+    return -1;
+  memcpy(buf, ctl->buf, len = ctl->len);
+  buf[len++] = ' ';
+  buf[len] = '\0';
 
   if (level)
     ret = snprintf(buf+len, sizeof(buf)-len, "%s: %s: ", level, proto_str);
@@ -199,19 +204,11 @@ vty_log_out (struct vty *vty, const char *level, const char *proto_str,
 void
 vty_time_print (struct vty *vty, int cr)
 {
-  time_t clock;
-  struct tm *tm;
-#define TIME_BUF 25
-  char buf [TIME_BUF];
-  int ret;
+  char buf [25];
   
-  time (&clock);
-  tm = localtime (&clock);
-
-  ret = strftime (buf, TIME_BUF, "%Y/%m/%d %H:%M:%S", tm);
-  if (ret == 0)
+  if (quagga_timestamp(0, buf, sizeof(buf)) == 0)
     {
-      zlog (NULL, LOG_INFO, "strftime error");
+      zlog (NULL, LOG_INFO, "quagga_timestamp error");
       return;
     }
   if (cr)
@@ -2417,7 +2414,7 @@ vty_read_config (char *config_file,
 /* Small utility function which output log to the VTY. */
 void
 vty_log (const char *level, const char *proto_str,
-	 const char *format, va_list va)
+	 const char *format, struct timestamp_control *ctl, va_list va)
 {
   unsigned int i;
   struct vty *vty;
@@ -2431,7 +2428,7 @@ vty_log (const char *level, const char *proto_str,
 	{
 	  va_list ac;
 	  va_copy(ac, va);
-	  vty_log_out (vty, level, proto_str, format, ac);
+	  vty_log_out (vty, level, proto_str, format, ctl, ac);
 	  va_end(ac);
 	}
 }
diff --git a/lib/vty.h b/lib/vty.h
index 5a02e65f..65ae6201 100644
--- a/lib/vty.h
+++ b/lib/vty.h
@@ -22,6 +22,7 @@ Software Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA
 #define _ZEBRA_VTY_H
 
 #include "thread.h"
+#include "log.h"
 
 #define VTY_BUFSIZ 512
 #define VTY_MAXHIST 20
@@ -211,7 +212,7 @@ extern void vty_serv_sock (const char *, unsigned short, const char *);
 extern void vty_close (struct vty *);
 extern char *vty_get_cwd (void);
 extern void vty_log (const char *level, const char *proto, 
-                     const char *fmt, va_list);
+                     const char *fmt, struct timestamp_control *, va_list);
 extern int vty_config_lock (struct vty *);
 extern int vty_config_unlock (struct vty *);
 extern int vty_shell (struct vty *);