diff options
author | Andrew J. Schorr <ajschorr@alumni.princeton.edu> | 2007-04-28 22:14:10 +0000 |
---|---|---|
committer | Andrew J. Schorr <ajschorr@alumni.princeton.edu> | 2007-04-28 22:14:10 +0000 |
commit | 1ed72e0b3a643fa1be6f1efa904965798a575cd1 (patch) | |
tree | 052341ede20e44b6aa23b1cd799d08f9b762c1c2 | |
parent | eda9ba743c1eb7c32b2ae9b8989d3555f1890758 (diff) |
[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.
-rw-r--r-- | lib/ChangeLog | 31 | ||||
-rw-r--r-- | lib/command.c | 39 | ||||
-rw-r--r-- | lib/log.c | 95 | ||||
-rw-r--r-- | lib/log.h | 20 | ||||
-rw-r--r-- | lib/vty.c | 35 | ||||
-rw-r--r-- | lib/vty.h | 3 |
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); @@ -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); @@ -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)" @@ -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); } } @@ -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 *); |