[ovs-dev] [RFC 3/4] bfd: Add logging function to BFD state machine.
Alex Wang
alexw at nicira.com
Mon Mar 17 17:42:24 UTC 2014
This commit requires user define logging functions in bfd-aux.h.
Code is added in bfd.c to log the variable and operation status.
Signed-off-by: Alex Wang <alexw at nicira.com>
---
lib/bfd-aux.h | 60 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++-
lib/bfd.c | 49 ++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 108 insertions(+), 1 deletion(-)
diff --git a/lib/bfd-aux.h b/lib/bfd-aux.h
index 9f9db71..7a828cc 100644
--- a/lib/bfd-aux.h
+++ b/lib/bfd-aux.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2014, 2013 Nicira, Inc.
+/* Copyright (c) 2013, 2014 Nicira, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
@@ -28,10 +28,68 @@
* This should be a thread-safe function and returns a random unsigned
* integer, which will be used as the jitter in bfd_set_next_ts().
*
+ *
+ * Logging
+ * -------
+ *
+ * log-level macros:
+ *
+ * Users are responsible for supporting the following log levels:
+ *
+ * WARN A low-level operation failed, but higher-level subsystems may
+ * be able to recover. e.g. BFD control packet format error.
+ *
+ * INFO Information that may be useful in retrospect when
+ * investigating a problem. e.g. POLL sequence start.
+ *
+ * DBG Information useful only to someone with intricate knowledge
+ * of the system, or that would commonly cause too-voluminous
+ * log output. Log messages at this level are not logged by
+ * default. e.g. send and recv of BFD control packets.
+ *
+ * bfd_log(level, format, ...)
+ *
+ * This function logs the content given in the Variadic Macros "..."
+ * with the specified 'level'.
+ *
+ * To reduce logging overhead, users may also implement rate-limiting
+ * logic, like shown in the following pseudocode:
+ *
+ * bfd_log(level, format, ...)
+ * {
+ * if (bfd_should_log(level)) {
+ * * logging code here. *
+ * }
+ * }
* */
#include "random.h"
+#include "vlog.h"
#define bfd_get_random() random_uint32()
+VLOG_DEFINE_THIS_MODULE(bfd);
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(20, 20);
+
+/* Compatible with VLOG_LEVELS. */
+enum bfd_log_levels {
+ BFD_LOG_WARN = VLL_WARN,
+ BFD_LOG_INFO = VLL_INFO,
+ BFD_LOG_DBG = VLL_DBG
+};
+
+#define bfd_should_log(LEVEL) !vlog_should_drop(THIS_MODULE, LEVEL, &rl)
+
+static void
+bfd_log(enum bfd_log_levels level, const char *format, ...)
+{
+ if (bfd_should_log((enum vlog_level) level)) {
+ va_list args;
+
+ va_start(args, format);
+ vlog_valist(THIS_MODULE, (enum vlog_level) level, format, args);
+ va_end(args);
+ }
+}
+
#endif /* bfd-aux.h */
diff --git a/lib/bfd.c b/lib/bfd.c
index 4ba2093..46f8025 100644
--- a/lib/bfd.c
+++ b/lib/bfd.c
@@ -138,6 +138,10 @@ bfd_set_state(struct bfd *bfd, enum bfd_state state, enum bfd_diag diag,
}
if (bfd->state != state || bfd->diag != diag) {
+ bfd_log(BFD_LOG_INFO, "%s: BFD state change: %s->%s"
+ " \"%s\"->\"%s\".", bfd->name, bfd_state_to_str(bfd->state),
+ bfd_state_to_str(state), bfd_diag_to_str(bfd->diag),
+ bfd_diag_to_str(diag));
bfd->state = state;
bfd->diag = diag;
@@ -176,9 +180,35 @@ bfd_poll(struct bfd *bfd)
bfd->poll_min_rx = bfd->in_decay ? bfd->decay_min_rx : bfd->cfg_min_rx;
bfd->flags |= FLAG_POLL;
bfd->next_tx = 0;
+ bfd_log(BFD_LOG_INFO, "%s: Initiating poll sequence", bfd->name);
}
}
+static void
+bfd_log_msg(enum bfd_log_levels level, char *message, const struct bfd_msg *p,
+ const struct bfd *bfd)
+{
+ char flag_str[BFD_FLAG_STR_SIZE];
+
+ bfd_log(level, "%s: %s."
+ "\n\tvers:%"PRIu8" diag:\"%s\" state:%s mult:%"PRIu8
+ " length:%"PRIu8
+ "\n\tflags: %s"
+ "\n\tmy_disc:0x%"PRIx32" your_disc:0x%"PRIx32
+ "\n\tmin_tx:%"PRIu32"us (%"PRIu32"ms)"
+ "\n\tmin_rx:%"PRIu32"us (%"PRIu32"ms)"
+ "\n\tmin_rx_echo:%"PRIu32"us (%"PRIu32"ms)",
+ bfd->name, message, p->vers_diag >> VERS_SHIFT,
+ bfd_diag_to_str(p->vers_diag & DIAG_MASK),
+ bfd_state_to_str(p->flags & STATE_MASK),
+ p->mult, p->length,
+ bfd_flag_to_str(p->flags & FLAGS_MASK, flag_str),
+ ntohl(p->my_disc), ntohl(p->your_disc),
+ ntohl(p->min_tx), ntohl(p->min_tx) / 1000,
+ ntohl(p->min_rx), ntohl(p->min_rx) / 1000,
+ ntohl(p->min_rx_echo), ntohl(p->min_rx_echo) / 1000);
+}
+
/* Configures 'bfd' using the 'setting'. Returns 0 if successful, a positive
* error number otherwise. */
@@ -434,6 +464,8 @@ bfd_put_packet(struct bfd *bfd, void *p, size_t len, long long int now)
bfd->last_tx = now;
bfd_set_next_tx(bfd);
+ bfd_log(BFD_LOG_DBG, "%s: Sending BFD Message", bfd->name);
+
return BFD_PASS;
}
@@ -478,31 +510,40 @@ bfd_process_packet(struct bfd *bfd, void *p, size_t len, long long int now)
rmt_state = msg->flags & STATE_MASK;
version = msg->vers_diag >> VERS_SHIFT;
+ bfd_log_msg(BFD_LOG_DBG, "Received BFD control message", p, bfd);
+
if (version != BFD_VERSION) {
+ bfd_log_msg(BFD_LOG_WARN, "Incorrect version", p, bfd);
goto err;
}
/* Technically this should happen after the length check. We don't support
* authentication however, so it's simpler to do the check first. */
if (flags & FLAG_AUTH) {
+ bfd_log_msg(BFD_LOG_WARN, "Authenticated control message with"
+ " authentication disabled", p, bfd);
goto err;
}
if (msg->length != BFD_PACKET_LEN) {
+ bfd_log_msg(BFD_LOG_WARN, "Unexpected length", p, bfd);
if (msg->length < BFD_PACKET_LEN) {
goto err;
}
}
if (!msg->mult) {
+ bfd_log_msg(BFD_LOG_WARN, "Zero multiplier", p, bfd);
goto err;
}
if (flags & FLAG_MULTIPOINT) {
+ bfd_log_msg(BFD_LOG_WARN, "Unsupported multipoint flag", p, bfd);
goto err;
}
if (!msg->my_disc) {
+ bfd_log_msg(BFD_LOG_WARN, "NULL my_disc", p, bfd);
goto err;
}
@@ -514,9 +555,11 @@ bfd_process_packet(struct bfd *bfd, void *p, size_t len, long long int now)
* transparently. This doesn't fit in with the OVS structure very
* well, so in this respect, we are not compliant. */
if (pkt_your_disc != bfd->disc) {
+ bfd_log_msg(BFD_LOG_WARN, "Incorrect your_disc", p, bfd);
goto err;
}
} else if (rmt_state > STATE_DOWN) {
+ bfd_log_msg(BFD_LOG_WARN, "Null your_disc", p, bfd);
goto err;
}
@@ -529,6 +572,7 @@ bfd_process_packet(struct bfd *bfd, void *p, size_t len, long long int now)
bfd->min_tx = bfd->poll_min_tx;
bfd->min_rx = bfd->poll_min_rx;
bfd->flags &= ~FLAG_POLL;
+ bfd_log_msg(BFD_LOG_INFO, "Poll sequence terminated", p, bfd);
}
if (flags & FLAG_POLL) {
@@ -547,12 +591,15 @@ bfd_process_packet(struct bfd *bfd, void *p, size_t len, long long int now)
if (bfd->next_tx) {
bfd_set_next_tx(bfd);
}
+ bfd_log_msg(BFD_LOG_INFO, "New remote min_rx", p, bfd);
}
bfd->rmt_min_tx = MAX(ntohl(msg->min_tx) / 1000, 1);
bfd->detect_time = bfd_rx_interval(bfd) * bfd->mult + now;
if (bfd->state == STATE_ADMIN_DOWN) {
+ bfd_log_msg(BFD_LOG_DBG, "Administratively down, dropping control"
+ " message.", p, bfd);
goto out;
}
@@ -577,6 +624,8 @@ bfd_process_packet(struct bfd *bfd, void *p, size_t len, long long int now)
case STATE_UP:
if (rmt_state <= STATE_DOWN) {
bfd_set_state(bfd, STATE_DOWN, DIAG_RMT_DOWN, now);
+ bfd_log_msg(BFD_LOG_INFO, "Remote signaled STATE_DOWN",
+ p, bfd);
}
break;
case STATE_ADMIN_DOWN:
--
1.7.9.5
More information about the dev
mailing list