From ebe4bb874c891e91070d1ffe2d72882c51b0f0a1 Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Mon, 2 Mar 2009 11:07:53 -0800 Subject: [PATCH] vconn: Distinguish between parse errors and other messages in rate-limiting. The vconn code wants to rate-limit errors, which there's not too much point in reporting a lot of, from the log of all OpenFlow messages, which are very important if we really want to log them at all. So use a different rate-limiter for each category. --- lib/vconn.c | 76 ++++++++++++++++++++++++++++++----------------------- 1 file changed, 43 insertions(+), 33 deletions(-) diff --git a/lib/vconn.c b/lib/vconn.c index 043312ce..1dec3073 100644 --- a/lib/vconn.c +++ b/lib/vconn.c @@ -85,10 +85,14 @@ static struct pvconn_class *pvconn_classes[] = { #endif }; -/* High rate limit because most of the rate-limiting here is individual - * OpenFlow messages going over the vconn. If those are enabled then we - * really need to see them. */ -static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(600, 600); +/* Rate limit for individual OpenFlow messages going over the vconn, output at + * DBG level. This is very high because, if these are enabled, it is because + * we really need to see them. */ +static struct vlog_rate_limit ofmsg_rl = VLOG_RATE_LIMIT_INIT(600, 600); + +/* Rate limit for OpenFlow message parse errors. These always indicate a bug + * in the peer and so there's not much point in showing a lot of them. */ +static struct vlog_rate_limit bad_ofmsg_rl = VLOG_RATE_LIMIT_INIT(1, 5); static int do_recv(struct vconn *, struct ofpbuf **); static int do_send(struct vconn *, struct ofpbuf *); @@ -334,13 +338,14 @@ vcs_recv_hello(struct vconn *vconn) struct ds msg = DS_EMPTY_INITIALIZER; ds_put_format(&msg, "%s: extra-long hello:\n", vconn->name); ds_put_hex_dump(&msg, b->data, b->size, 0, true); - VLOG_WARN_RL(&rl, "%s", ds_cstr(&msg)); + VLOG_WARN_RL(&bad_ofmsg_rl, "%s", ds_cstr(&msg)); ds_destroy(&msg); } vconn->version = MIN(OFP_VERSION, oh->version); if (vconn->version < vconn->min_version) { - VLOG_WARN_RL(&rl, "%s: version negotiation failed: we support " + VLOG_WARN_RL(&bad_ofmsg_rl, + "%s: version negotiation failed: we support " "versions 0x%02x to 0x%02x inclusive but peer " "supports no later than version 0x%02"PRIx8, vconn->name, vconn->min_version, OFP_VERSION, @@ -358,7 +363,8 @@ vcs_recv_hello(struct vconn *vconn) return; } else { char *s = ofp_to_string(b->data, b->size, 1); - VLOG_WARN_RL(&rl, "%s: received message while expecting hello: %s", + VLOG_WARN_RL(&bad_ofmsg_rl, + "%s: received message while expecting hello: %s", vconn->name, s); free(s); retval = EPROTO; @@ -471,7 +477,7 @@ again: if (VLOG_IS_DBG_ENABLED()) { char *s = ofp_to_string((*msgp)->data, (*msgp)->size, 1); - VLOG_DBG_RL(&rl, "%s: received: %s", vconn->name, s); + VLOG_DBG_RL(&ofmsg_rl, "%s: received: %s", vconn->name, s); free(s); } @@ -498,11 +504,13 @@ again: ofpbuf_delete(*msgp); goto again; } - VLOG_ERR_RL(&rl, "%s: received OpenFlow message type %"PRIu8" " + VLOG_ERR_RL(&bad_ofmsg_rl, + "%s: received OpenFlow message type %"PRIu8" " "before version negotiation complete", vconn->name, oh->type); } else { - VLOG_ERR_RL(&rl, "%s: received OpenFlow version 0x%02"PRIx8" " + VLOG_ERR_RL(&bad_ofmsg_rl, + "%s: received OpenFlow version 0x%02"PRIx8" " "!= expected %02x", vconn->name, oh->version, vconn->version); } @@ -550,7 +558,7 @@ do_send(struct vconn *vconn, struct ofpbuf *msg) char *s = ofp_to_string(msg->data, msg->size, 1); retval = (vconn->class->send)(vconn, msg); if (retval != EAGAIN) { - VLOG_DBG_RL(&rl, "%s: sent (%s): %s", + VLOG_DBG_RL(&ofmsg_rl, "%s: sent (%s): %s", vconn->name, strerror(retval), s); } free(s); @@ -607,8 +615,8 @@ vconn_recv_xid(struct vconn *vconn, uint32_t xid, struct ofpbuf **replyp) return 0; } - VLOG_DBG_RL(&rl, "%s: received reply with xid %08"PRIx32" != expected " - "%08"PRIx32, vconn->name, recv_xid, xid); + VLOG_DBG_RL(&bad_ofmsg_rl, "%s: received reply with xid %08"PRIx32 + " != expected %08"PRIx32, vconn->name, recv_xid, xid); ofpbuf_delete(reply); } } @@ -1000,8 +1008,9 @@ check_message_type(uint8_t got_type, uint8_t want_type) if (got_type != want_type) { char *want_type_name = ofp_message_type_to_string(want_type); char *got_type_name = ofp_message_type_to_string(got_type); - VLOG_WARN("received bad message type %s (expected %s)", - got_type_name, want_type_name); + VLOG_WARN_RL(&bad_ofmsg_rl, + "received bad message type %s (expected %s)", + got_type_name, want_type_name); free(want_type_name); free(got_type_name); return false; @@ -1023,8 +1032,9 @@ check_ofp_message(const struct ofp_header *msg, uint8_t type, size_t size) got_size = ntohs(msg->length); if (got_size != size) { char *type_name = ofp_message_type_to_string(type); - VLOG_WARN("received %s message of length %"PRIu16" (expected %zu)", - type_name, got_size, size); + VLOG_WARN_RL(&bad_ofmsg_rl, + "received %s message of length %"PRIu16" (expected %zu)", + type_name, got_size, size); free(type_name); return EINVAL; } @@ -1055,19 +1065,20 @@ check_ofp_message_array(const struct ofp_header *msg, uint8_t type, got_size = ntohs(msg->length); if (got_size < min_size) { char *type_name = ofp_message_type_to_string(type); - VLOG_WARN("received %s message of length %"PRIu16" " - "(expected at least %zu)", - type_name, got_size, min_size); + VLOG_WARN_RL(&bad_ofmsg_rl, "received %s message of length %"PRIu16" " + "(expected at least %zu)", + type_name, got_size, min_size); free(type_name); return EINVAL; } if ((got_size - min_size) % array_elt_size) { char *type_name = ofp_message_type_to_string(type); - VLOG_WARN("received %s message of bad length %"PRIu16": the " - "excess over %zu (%zu) is not evenly divisible by %zu " - "(remainder is %zu)", - type_name, got_size, min_size, got_size - min_size, - array_elt_size, (got_size - min_size) % array_elt_size); + VLOG_WARN_RL(&bad_ofmsg_rl, + "received %s message of bad length %"PRIu16": the " + "excess over %zu (%zu) is not evenly divisible by %zu " + "(remainder is %zu)", + type_name, got_size, min_size, got_size - min_size, + array_elt_size, (got_size - min_size) % array_elt_size); free(type_name); return EINVAL; } @@ -1090,15 +1101,14 @@ flow_stats_first(struct flow_stats_iterator *iter, const struct ofp_flow_stats * flow_stats_next(struct flow_stats_iterator *iter) { - static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); ptrdiff_t bytes_left = iter->end - iter->pos; const struct ofp_flow_stats *fs; size_t length; if (bytes_left < sizeof *fs) { if (bytes_left != 0) { - VLOG_WARN_RL(&rl, "%td leftover bytes in flow stats reply", - bytes_left); + VLOG_WARN_RL(&bad_ofmsg_rl, + "%td leftover bytes in flow stats reply", bytes_left); } return NULL; } @@ -1106,15 +1116,15 @@ flow_stats_next(struct flow_stats_iterator *iter) fs = (const void *) iter->pos; length = ntohs(fs->length); if (length < sizeof *fs) { - VLOG_WARN_RL(&rl, "flow stats length %zu is shorter than min %zu", - length, sizeof *fs); + VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu is shorter than " + "min %zu", length, sizeof *fs); return NULL; } else if (length > bytes_left) { - VLOG_WARN_RL(&rl, "flow stats length %zu but only %td bytes left", - length, bytes_left); + VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu but only %td " + "bytes left", length, bytes_left); return NULL; } else if ((length - sizeof *fs) % sizeof fs->actions[0]) { - VLOG_WARN_RL(&rl, "flow stats length %zu has %zu bytes " + VLOG_WARN_RL(&bad_ofmsg_rl, "flow stats length %zu has %zu bytes " "left over in final action", length, (length - sizeof *fs) % sizeof fs->actions[0]); return NULL; -- 2.30.2