[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.
diff --git a/lib/ChangeLog b/lib/ChangeLog
index ff32fcc..3e515f8 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 316971e..f3d96ed 100644
--- a/lib/command.c
+++ b/lib/command.c
@@ -594,6 +594,10 @@
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 @@
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 @@
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 @@
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 c123f24..7668222 100644
--- a/lib/log.c
+++ b/lib/log.c
@@ -66,32 +66,81 @@
/* For time string format. */
-#define TIME_BUF 27
+
+size_t
+quagga_timestamp(int timestamp_precision, char *buf, size_t buflen)
+{
+ 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 */
+
+ 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;
+}
/* Utility routine for current time printing. */
static void
-time_print (FILE *fp)
+time_print(FILE *fp, struct timestamp_control *ctl)
{
- int ret;
- char buf [TIME_BUF];
- time_t clock;
- struct tm *tm;
-
- time (&clock);
- tm = localtime (&clock);
-
- ret = strftime (buf, TIME_BUF, "%Y/%m/%d %H:%M:%S", tm);
- if (ret == 0) {
- zlog_warn ("strftime error");
- }
-
- fprintf (fp, "%s ", buf);
+ 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 @@
/* 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 @@
/* 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 @@
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 @@
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 @@
/* 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 @@
((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 0f058a8..da8fbea 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 @@
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 @@
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 4288e15..6cb8b48 100644
--- a/lib/vty.c
+++ b/lib/vty.c
@@ -149,17 +149,22 @@
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 @@
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 @@
/* 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 @@
{
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 5a02e65..65ae620 100644
--- a/lib/vty.h
+++ b/lib/vty.h
@@ -22,6 +22,7 @@
#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_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 *);