From ab43666b205d968b4ce7428b9a730b70ff81042f Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Tue, 19 Aug 2008 15:18:51 -0700 Subject: [PATCH] vlog: Apply rate-limiting everywhere it seems warranted. --- lib/dhcp-client.c | 50 +++++++++++++++++++----------------- lib/dhcp.c | 53 +++++++++++++++++++++----------------- lib/dpif.c | 23 ++++++++++------- lib/flow.c | 5 ++-- lib/learning-switch.c | 30 ++++++++++++---------- lib/mac-learning.c | 5 ++-- lib/netdev.c | 30 +++++++++++++--------- lib/netlink.c | 55 ++++++++++++++++++++++------------------ lib/poll-loop.c | 3 ++- lib/socket-util.c | 22 +++++++++------- lib/vconn-ssl.c | 44 ++++++++++++++++++++------------ lib/vconn-stream.c | 11 +++++--- lib/vconn.c | 21 ++++++++------- secchan/secchan.c | 27 ++++++++++++-------- switch/datapath.c | 40 +++++++++++++++-------------- utilities/ofp-discover.c | 3 ++- 16 files changed, 243 insertions(+), 179 deletions(-) diff --git a/lib/dhcp-client.c b/lib/dhcp-client.c index c05b61493..a43c01c80 100644 --- a/lib/dhcp-client.c +++ b/lib/dhcp-client.c @@ -73,6 +73,8 @@ enum dhclient_state { #undef DHCLIENT_STATE }; +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60); + static const char * state_name(enum dhclient_state state) { @@ -541,14 +543,15 @@ dhcp_receive(struct dhclient *cli, unsigned int msgs, struct dhcp_msg *msg) { while (do_receive_msg(cli, msg)) { if (msg->type < 0 || msg->type > 31 || !((1u << msg->type) & msgs)) { - VLOG_DBG("received unexpected %s in %s state: %s", - dhcp_type_name(msg->type), state_name(cli->state), - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "received unexpected %s in %s state: %s", + dhcp_type_name(msg->type), state_name(cli->state), + dhcp_msg_to_string(msg, false, &cli->s)); } else if (msg->xid != cli->xid) { - VLOG_DBG("ignoring %s with xid != %08"PRIx32" in %s state: %s", - dhcp_type_name(msg->type), msg->xid, - state_name(cli->state), - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG_RL(&rl, + "ignoring %s with xid != %08"PRIx32" in %s state: %s", + dhcp_type_name(msg->type), msg->xid, + state_name(cli->state), + dhcp_msg_to_string(msg, false, &cli->s)); } else { return true; } @@ -562,18 +565,18 @@ validate_offered_options(struct dhclient *cli, const struct dhcp_msg *msg) { uint32_t lease, netmask; if (!dhcp_msg_get_secs(msg, DHCP_CODE_LEASE_TIME, 0, &lease)) { - VLOG_WARN("%s lacks lease time: %s", dhcp_type_name(msg->type), - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_WARN_RL(&rl, "%s lacks lease time: %s", dhcp_type_name(msg->type), + dhcp_msg_to_string(msg, false, &cli->s)); } else if (!dhcp_msg_get_ip(msg, DHCP_CODE_SUBNET_MASK, 0, &netmask)) { - VLOG_WARN("%s lacks netmask: %s", dhcp_type_name(msg->type), - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_WARN_RL(&rl, "%s lacks netmask: %s", dhcp_type_name(msg->type), + dhcp_msg_to_string(msg, false, &cli->s)); } else if (lease < MIN_ACCEPTABLE_LEASE) { - VLOG_WARN("Ignoring %s with %"PRIu32"-second lease time: %s", - dhcp_type_name(msg->type), lease, - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_WARN_RL(&rl, "Ignoring %s with %"PRIu32"-second lease time: %s", + dhcp_type_name(msg->type), lease, + dhcp_msg_to_string(msg, false, &cli->s)); } else if (cli->validate_offer && !cli->validate_offer(msg, cli->aux)) { - VLOG_DBG("client validation hook refused offer: %s", - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "client validation hook refused offer: %s", + dhcp_msg_to_string(msg, false, &cli->s)); } else { return true; } @@ -596,13 +599,13 @@ dhclient_run_SELECTING(struct dhclient *cli) } if (!dhcp_msg_get_ip(&msg, DHCP_CODE_SERVER_IDENTIFIER, 0, &cli->server_ip)) { - VLOG_WARN("DHCPOFFER lacks server identifier: %s", - dhcp_msg_to_string(&msg, false, &cli->s)); + VLOG_WARN_RL(&rl, "DHCPOFFER lacks server identifier: %s", + dhcp_msg_to_string(&msg, false, &cli->s)); continue; } - VLOG_DBG("accepting DHCPOFFER: %s", - dhcp_msg_to_string(&msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "accepting DHCPOFFER: %s", + dhcp_msg_to_string(&msg, false, &cli->s)); cli->ipaddr = msg.yiaddr; state_transition(cli, S_REQUESTING); break; @@ -901,20 +904,21 @@ do_receive_msg(struct dhclient *cli, struct dhcp_msg *msg) ip = b.l3; if (IP_IS_FRAGMENT(ip->ip_frag_off)) { /* We don't do reassembly. */ - VLOG_WARN("ignoring fragmented DHCP datagram"); + VLOG_WARN_RL(&rl, "ignoring fragmented DHCP datagram"); continue; } dhcp = b.l7; if (!dhcp) { - VLOG_WARN("ignoring DHCP datagram with missing payload"); + VLOG_WARN_RL(&rl, "ignoring DHCP datagram with missing payload"); continue; } buffer_pull(&b, b.l7 - b.data); error = dhcp_parse(msg, &b); if (!error) { - VLOG_DBG("received %s", dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "received %s", + dhcp_msg_to_string(msg, false, &cli->s)); buffer_uninit(&b); return true; } diff --git a/lib/dhcp.c b/lib/dhcp.c index 1e6628ad2..2e9f3dfbb 100644 --- a/lib/dhcp.c +++ b/lib/dhcp.c @@ -73,6 +73,11 @@ static struct option_class classes[DHCP_N_OPTIONS] = { #undef DHCP_OPT }; +/* A single (bad) DHCP message can in theory dump out many, many log messages, + * especially at high logging levels, so the burst size is set quite high + * here to avoid missing useful information. */ +struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 600); + static void copy_data(struct dhcp_msg *); const char * @@ -570,15 +575,15 @@ parse_options(struct dhcp_msg *msg, const char *name, void *data, size_t size, len = buffer_try_pull(&b, 1); if (!len) { - VLOG_DBG("reached end of %s expecting length byte", name); + VLOG_DBG_RL(&rl, "reached end of %s expecting length byte", name); break; } payload = buffer_try_pull(&b, *len); if (!payload) { - VLOG_DBG("expected %"PRIu8" bytes of option-%"PRIu8" payload " - "with only %zu bytes of %s left", - *len, *code, b.size, name); + VLOG_DBG_RL(&rl, "expected %"PRIu8" bytes of option-%"PRIu8" " + "payload with only %zu bytes of %s left", + *len, *code, b.size, name); break; } dhcp_msg_put(msg, *code + option_offset, payload, *len); @@ -599,23 +604,23 @@ validate_options(struct dhcp_msg *msg) size_t remainder = opt->n % type->size; bool ok = true; if (remainder) { - VLOG_DBG("%s option has %zu %zu-byte %s arguments with " - "%zu bytes left over", - class->name, n_elems, type->size, - type->name, remainder); + VLOG_DBG_RL(&rl, "%s option has %zu %zu-byte %s arguments " + "with %zu bytes left over", + class->name, n_elems, type->size, + type->name, remainder); ok = false; } if (n_elems < class->min_args || n_elems > class->max_args) { - VLOG_DBG("%s option has %zu %zu-byte %s arguments but " - "between %zu and %zu are required", - class->name, n_elems, type->size, type->name, - class->min_args, class->max_args); + VLOG_DBG_RL(&rl, "%s option has %zu %zu-byte %s arguments but " + "between %zu and %zu are required", + class->name, n_elems, type->size, type->name, + class->min_args, class->max_args); ok = false; } if (!ok) { struct ds ds = DS_EMPTY_INITIALIZER; - VLOG_DBG("%s option contains: %s", - class->name, dhcp_option_to_string(opt, code, &ds)); + VLOG_DBG_RL(&rl, "%s option contains: %s", class->name, + dhcp_option_to_string(opt, code, &ds)); ds_destroy(&ds); opt->n = 0; @@ -639,20 +644,21 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_) dhcp = buffer_try_pull(&b, sizeof *dhcp); if (!dhcp) { - VLOG_DBG("buffer too small for DHCP header (%zu bytes)", b.size); + VLOG_DBG_RL(&rl, "buffer too small for DHCP header (%zu bytes)", + b.size); goto error; } if (dhcp->op != DHCP_BOOTREPLY && dhcp->op != DHCP_BOOTREQUEST) { - VLOG_DBG("invalid DHCP op (%"PRIu8")", dhcp->op); + VLOG_DBG_RL(&rl, "invalid DHCP op (%"PRIu8")", dhcp->op); goto error; } if (dhcp->htype != ARP_HRD_ETHERNET) { - VLOG_DBG("invalid DHCP htype (%"PRIu8")", dhcp->htype); + VLOG_DBG_RL(&rl, "invalid DHCP htype (%"PRIu8")", dhcp->htype); goto error; } if (dhcp->hlen != ETH_ADDR_LEN) { - VLOG_DBG("invalid DHCP hlen (%"PRIu8")", dhcp->hlen); + VLOG_DBG_RL(&rl, "invalid DHCP hlen (%"PRIu8")", dhcp->hlen); goto error; } @@ -685,10 +691,11 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_) } } } else { - VLOG_DBG("bad DHCP options cookie: %08"PRIx32, ntohl(*cookie)); + VLOG_DBG_RL(&rl, "bad DHCP options cookie: %08"PRIx32, + ntohl(*cookie)); } } else { - VLOG_DBG("DHCP packet has no options"); + VLOG_DBG_RL(&rl, "DHCP packet has no options"); } vendor_class = dhcp_msg_get_string(msg, DHCP_CODE_VENDOR_CLASS); @@ -702,7 +709,7 @@ dhcp_parse(struct dhcp_msg *msg, const struct buffer *b_) validate_options(msg); if (!dhcp_msg_get_uint8(msg, DHCP_CODE_DHCP_MSG_TYPE, 0, &type)) { - VLOG_DBG("missing DHCP message type"); + VLOG_DBG_RL(&rl, "missing DHCP message type"); dhcp_msg_uninit(msg); goto error; } @@ -715,11 +722,11 @@ error: ds_init(&ds); ds_put_hex_dump(&ds, b_->data, b_->size, 0, true); - VLOG_DBG("invalid DHCP message dump:\n%s", ds_cstr(&ds)); + VLOG_DBG_RL(&rl, "invalid DHCP message dump:\n%s", ds_cstr(&ds)); ds_clear(&ds); dhcp_msg_to_string(msg, false, &ds); - VLOG_DBG("partially dissected DHCP message: %s", ds_cstr(&ds)); + VLOG_DBG_RL(&rl, "partially dissected DHCP message: %s", ds_cstr(&ds)); ds_destroy(&ds); } diff --git a/lib/dpif.c b/lib/dpif.c index 202a18283..4f993123c 100644 --- a/lib/dpif.c +++ b/lib/dpif.c @@ -54,6 +54,9 @@ #include "vlog.h" #define THIS_MODULE VLM_dpif +/* Not really much point in logging many dpif errors. */ +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 60); + /* The Generic Netlink family number used for OpenFlow. */ static int openflow_family; @@ -142,18 +145,18 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp, || nl_msg_nlmsghdr(buffer)->nlmsg_type == NLMSG_DONE))); if (retval) { if (retval != EAGAIN) { - VLOG_WARN("dpif_recv_openflow: %s", strerror(retval)); + VLOG_WARN_RL(&rl, "dpif_recv_openflow: %s", strerror(retval)); } return retval; } if (nl_msg_genlmsghdr(buffer) == NULL) { - VLOG_DBG("received packet too short for Generic Netlink"); + VLOG_DBG_RL(&rl, "received packet too short for Generic Netlink"); goto error; } if (nl_msg_nlmsghdr(buffer)->nlmsg_type != openflow_family) { - VLOG_DBG("received type (%"PRIu16") != openflow family (%d)", - nl_msg_nlmsghdr(buffer)->nlmsg_type, openflow_family); + VLOG_DBG_RL(&rl, "received type (%"PRIu16") != openflow family (%d)", + nl_msg_nlmsghdr(buffer)->nlmsg_type, openflow_family); goto error; } @@ -162,8 +165,9 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp, goto error; } if (nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]) != dp->dp_idx) { - VLOG_WARN("received dp_idx (%"PRIu32") differs from expected (%d)", - nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]), dp->dp_idx); + VLOG_WARN_RL(&rl, "received dp_idx (%"PRIu32") differs from expected " + "(%d)", nl_attr_get_u32(attrs[DP_GENL_A_DP_IDX]), + dp->dp_idx); goto error; } @@ -171,8 +175,9 @@ dpif_recv_openflow(struct dpif *dp, struct buffer **bufferp, buffer->size = nl_attr_get_size(attrs[DP_GENL_A_OPENFLOW]); ofp_len = ntohs(oh->length); if (ofp_len != buffer->size) { - VLOG_WARN("ofp_header.length %"PRIu16" != attribute length %zu\n", - ofp_len, buffer->size); + VLOG_WARN_RL(&rl, + "ofp_header.length %"PRIu16" != attribute length %zu\n", + ofp_len, buffer->size); buffer->size = MIN(ofp_len, buffer->size); } *bufferp = buffer; @@ -234,7 +239,7 @@ dpif_send_openflow(struct dpif *dp, struct buffer *buffer, bool wait) } retval = nl_sock_sendv(dp->sock, iov, n_iov, false); if (retval && retval != EAGAIN) { - VLOG_WARN("dpif_send_openflow: %s", strerror(retval)); + VLOG_WARN_RL(&rl, "dpif_send_openflow: %s", strerror(retval)); } return retval; } diff --git a/lib/flow.c b/lib/flow.c index 5eea06b2e..795731b59 100644 --- a/lib/flow.c +++ b/lib/flow.c @@ -101,8 +101,9 @@ flow_extract(struct buffer *packet, uint16_t in_port, struct flow *flow) * can end up with runt frames, e.g. frames that only ever passed * through virtual network devices and never touched a physical * Ethernet. */ - VLOG_DBG("packet length %zu less than minimum size %d", - b.size, ETH_TOTAL_MIN); + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 60); + VLOG_DBG_RL(&rl, "packet length %zu less than minimum size %d", + b.size, ETH_TOTAL_MIN); } memset(flow, 0, sizeof *flow); diff --git a/lib/learning-switch.c b/lib/learning-switch.c index 27271fa2d..f056b9161 100644 --- a/lib/learning-switch.c +++ b/lib/learning-switch.c @@ -68,6 +68,10 @@ struct lswitch { int n_queued; }; +/* The log messages here could actually be useful in debugging, so keep the + * rate limit relatively high. */ +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(30, 300); + static void queue_tx(struct lswitch *, struct rconn *, struct buffer *); static void send_features_request(struct lswitch *, struct rconn *); static void process_packet_in(struct lswitch *, struct rconn *, @@ -124,9 +128,10 @@ lswitch_process_packet(struct lswitch *sw, struct rconn *rconn, oh = msg->data; if (msg->size < min_size[oh->type]) { - VLOG_WARN("%s: too short (%zu bytes) for type %"PRIu8" (min %zu)", - rconn_get_name(rconn), - msg->size, oh->type, min_size[oh->type]); + VLOG_WARN_RL(&rl, + "%s: too short (%zu bytes) for type %"PRIu8" (min %zu)", + rconn_get_name(rconn), + msg->size, oh->type, min_size[oh->type]); return; } @@ -142,7 +147,7 @@ lswitch_process_packet(struct lswitch *sw, struct rconn *rconn, } else { if (VLOG_IS_DBG_ENABLED()) { char *p = ofp_to_string(msg->data, msg->size, 2); - VLOG_DBG("OpenFlow packet ignored: %s", p); + VLOG_DBG_RL(&rl, "OpenFlow packet ignored: %s", p); free(p); } } @@ -185,15 +190,12 @@ static void queue_tx(struct lswitch *sw, struct rconn *rconn, struct buffer *b) { int retval = rconn_send_with_limit(rconn, b, &sw->n_queued, 10); - if (retval) { + if (retval && retval != ENOTCONN) { if (retval == EAGAIN) { - /* FIXME: ratelimit. */ - VLOG_WARN("%s: tx queue overflow", rconn_get_name(rconn)); - } else if (retval == ENOTCONN) { - /* Ignore. */ + VLOG_WARN_RL(&rl, "%s: tx queue overflow", rconn_get_name(rconn)); } else { - /* FIXME: ratelimit. */ - VLOG_WARN("%s: send: %s", rconn_get_name(rconn), strerror(retval)); + VLOG_WARN_RL(&rl, "%s: send: %s", + rconn_get_name(rconn), strerror(retval)); } } } @@ -218,9 +220,9 @@ process_packet_in(struct lswitch *sw, struct rconn *rconn, if (sw->ml) { if (mac_learning_learn(sw->ml, flow.dl_src, in_port)) { - VLOG_DBG("learned that "ETH_ADDR_FMT" is on datapath %" - PRIx64" port %"PRIu16, ETH_ADDR_ARGS(flow.dl_src), - ntohll(sw->datapath_id), in_port); + VLOG_DBG_RL(&rl, "learned that "ETH_ADDR_FMT" is on datapath %" + PRIx64" port %"PRIu16, ETH_ADDR_ARGS(flow.dl_src), + ntohll(sw->datapath_id), in_port); } out_port = mac_learning_lookup(sw->ml, flow.dl_dst); } diff --git a/lib/mac-learning.c b/lib/mac-learning.c index ad3a0b8dd..8b79dc6f8 100644 --- a/lib/mac-learning.c +++ b/lib/mac-learning.c @@ -129,8 +129,9 @@ mac_learning_learn(struct mac_learning *ml, struct list *bucket; if (eth_addr_is_multicast(src_mac)) { - VLOG_DBG("multicast packet source "ETH_ADDR_FMT, - ETH_ADDR_ARGS(src_mac)); + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(30, 30); + VLOG_DBG_RL(&rl, "multicast packet source "ETH_ADDR_FMT, + ETH_ADDR_ARGS(src_mac)); return false; } diff --git a/lib/netdev.c b/lib/netdev.c index d9ac42598..581b362a1 100644 --- a/lib/netdev.c +++ b/lib/netdev.c @@ -80,11 +80,16 @@ struct netdev { int changed_flags; /* Flags that we changed. */ }; +/* All open network devices. */ static struct list netdev_list = LIST_INITIALIZER(&netdev_list); /* An AF_INET socket (used for ioctl operations). */ static int af_inet_sock = -1; +/* This is set pretty low because we probably won't learn anything from the + * additional log messages. */ +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 20); + static void init_netdev(void); static int restore_flags(struct netdev *netdev); static int get_flags(const struct netdev *, int *flagsp); @@ -372,8 +377,8 @@ netdev_recv(struct netdev *netdev, struct buffer *buffer) } while (n_bytes < 0 && errno == EINTR); if (n_bytes < 0) { if (errno != EAGAIN) { - VLOG_WARN("error receiving Ethernet packet on %s: %s", - strerror(errno), netdev->name); + VLOG_WARN_RL(&rl, "error receiving Ethernet packet on %s: %s", + strerror(errno), netdev->name); } return errno; } else { @@ -421,8 +426,8 @@ netdev_send(struct netdev *netdev, const struct buffer *buffer) /* Pull out the Ethernet header. */ if (buffer->size < ETH_HEADER_LEN) { - VLOG_WARN("cannot send %zu-byte frame on %s", - buffer->size, netdev->name); + VLOG_WARN_RL(&rl, "cannot send %zu-byte frame on %s", + buffer->size, netdev->name); return EMSGSIZE; } eh = buffer_at_assert(buffer, 0, sizeof *eh); @@ -438,13 +443,14 @@ netdev_send(struct netdev *netdev, const struct buffer *buffer) if (errno == ENOBUFS) { return EAGAIN; } else if (errno != EAGAIN) { - VLOG_WARN("error sending Ethernet packet on %s: %s", - netdev->name, strerror(errno)); + VLOG_WARN_RL(&rl, "error sending Ethernet packet on %s: %s", + netdev->name, strerror(errno)); } return errno; } else if (n_bytes != buffer->size) { - VLOG_WARN("send partial Ethernet packet (%d bytes of %zu) on %s", - (int) n_bytes, buffer->size, netdev->name); + VLOG_WARN_RL(&rl, + "send partial Ethernet packet (%d bytes of %zu) on %s", + (int) n_bytes, buffer->size, netdev->name); return EMSGSIZE; } else { return 0; @@ -544,8 +550,8 @@ netdev_get_in4(const struct netdev *netdev, struct in_addr *in4) struct sockaddr_in *sin = (struct sockaddr_in *) &ifr.ifr_addr; ip = sin->sin_addr; } else { - VLOG_DBG("%s: ioctl(SIOCGIFADDR) failed: %s", - netdev->name, strerror(errno)); + VLOG_DBG_RL(&rl, "%s: ioctl(SIOCGIFADDR) failed: %s", + netdev->name, strerror(errno)); } if (in4) { *in4 = ip; @@ -748,8 +754,8 @@ netdev_arp_lookup(const struct netdev *netdev, if (!retval) { memcpy(mac, r.arp_ha.sa_data, ETH_ADDR_LEN); } else if (retval != ENXIO) { - VLOG_WARN("%s: could not look up ARP entry for "IP_FMT": %s", - netdev->name, IP_ARGS(&ip), strerror(retval)); + VLOG_WARN_RL(&rl, "%s: could not look up ARP entry for "IP_FMT": %s", + netdev->name, IP_ARGS(&ip), strerror(retval)); } return retval; } diff --git a/lib/netlink.c b/lib/netlink.c index 9abe26a55..1316547f1 100644 --- a/lib/netlink.c +++ b/lib/netlink.c @@ -55,6 +55,11 @@ #define SOL_NETLINK 270 #endif +/* A single (bad) Netlink message can in theory dump out many, many log + * messages, so the burst size is set quite high here to avoid missing useful + * information. Also, at high logging levels we log *all* Netlink messages. */ +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 600); + static void log_nlmsg(const char *function, int error, const void *message, size_t size); @@ -321,15 +326,15 @@ try_again: buffer_delete(buf); return ENOBUFS; } else { - VLOG_ERR("failed to remove nlmsg from socket: %s\n", - strerror(errno)); + VLOG_ERR_RL(&rl, "failed to remove nlmsg from socket: %s\n", + strerror(errno)); } } if (nbytes < sizeof *nlmsghdr || nlmsghdr->nlmsg_len < sizeof *nlmsghdr || nlmsghdr->nlmsg_len > nbytes) { - VLOG_ERR("received invalid nlmsg (%zd bytes < %d)", - bufsize, NLMSG_HDRLEN); + VLOG_ERR_RL(&rl, "received invalid nlmsg (%zd bytes < %d)", + bufsize, NLMSG_HDRLEN); buffer_delete(buf); return EPROTO; } @@ -394,7 +399,7 @@ recv: retval = nl_sock_recv(sock, &reply, true); if (retval) { if (retval == ENOBUFS) { - VLOG_DBG("receive buffer overflow, resending request"); + VLOG_DBG_RL(&rl, "receive buffer overflow, resending request"); goto send; } else { return retval; @@ -402,14 +407,15 @@ recv: } nlmsghdr = nl_msg_nlmsghdr(reply); if (seq != nlmsghdr->nlmsg_seq) { - VLOG_DBG("ignoring seq %"PRIu32" != expected %"PRIu32, - nl_msg_nlmsghdr(reply)->nlmsg_seq, seq); + VLOG_DBG_RL(&rl, "ignoring seq %"PRIu32" != expected %"PRIu32, + nl_msg_nlmsghdr(reply)->nlmsg_seq, seq); buffer_delete(reply); goto recv; } if (nl_msg_nlmsgerr(reply, &retval)) { if (retval) { - VLOG_DBG("received NAK error=%d (%s)", retval, strerror(retval)); + VLOG_DBG_RL(&rl, "received NAK error=%d (%s)", + retval, strerror(retval)); } return retval != EAGAIN ? retval : EPROTO; } @@ -458,8 +464,8 @@ nl_msg_nlmsgerr(const struct buffer *msg, int *errorp) struct nlmsgerr *err = buffer_at(msg, NLMSG_HDRLEN, sizeof *err); int code = EPROTO; if (!err) { - VLOG_ERR("received invalid nlmsgerr (%zd bytes < %zd)", - msg->size, NLMSG_HDRLEN + sizeof *err); + VLOG_ERR_RL(&rl, "received invalid nlmsgerr (%zd bytes < %zd)", + msg->size, NLMSG_HDRLEN + sizeof *err); } else if (err->error <= 0 && err->error > INT_MIN) { code = -err->error; } @@ -778,7 +784,7 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[], p = buffer_at(msg, NLMSG_HDRLEN + GENL_HDRLEN, 0); if (p == NULL) { - VLOG_DBG("missing headers in nl_policy_parse"); + VLOG_DBG_RL(&rl, "missing headers in nl_policy_parse"); return false; } tail = buffer_tail(msg); @@ -791,16 +797,16 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[], /* Make sure its claimed length is plausible. */ if (nla->nla_len < NLA_HDRLEN) { - VLOG_DBG("%zu: attr shorter than NLA_HDRLEN (%"PRIu16")", - offset, nla->nla_len); + VLOG_DBG_RL(&rl, "%zu: attr shorter than NLA_HDRLEN (%"PRIu16")", + offset, nla->nla_len); return false; } len = nla->nla_len - NLA_HDRLEN; aligned_len = NLA_ALIGN(len); if (aligned_len > tail - p) { - VLOG_DBG("%zu: attr %"PRIu16" aligned data len (%zu) " - "> bytes left (%tu)", - offset, nla->nla_type, aligned_len, tail - p); + VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" aligned data len (%zu) " + "> bytes left (%tu)", + offset, nla->nla_type, aligned_len, tail - p); return false; } @@ -813,19 +819,20 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[], min_len = p->min_len ? p->min_len : attr_len_range[p->type][0]; max_len = p->max_len ? p->max_len : attr_len_range[p->type][1]; if (len < min_len || len > max_len) { - VLOG_DBG("%zu: attr %"PRIu16" length %zu not in allowed range " - "%zu...%zu", offset, type, len, min_len, max_len); + VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" length %zu not in " + "allowed range %zu...%zu", + offset, type, len, min_len, max_len); return false; } if (p->type == NL_A_STRING) { if (((char *) nla)[nla->nla_len - 1]) { - VLOG_DBG("%zu: attr %"PRIu16" lacks null terminator", - offset, type); + VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" lacks null at end", + offset, type); return false; } if (memchr(nla + 1, '\0', len - 1) != NULL) { - VLOG_DBG("%zu: attr %"PRIu16" lies about string length", - offset, type); + VLOG_DBG_RL(&rl, "%zu: attr %"PRIu16" has bad length", + offset, type); return false; } } @@ -840,7 +847,7 @@ nl_policy_parse(const struct buffer *msg, const struct nl_policy policy[], p += NLA_ALIGN(nla->nla_len); } if (n_required) { - VLOG_DBG("%zu required attrs missing", n_required); + VLOG_DBG_RL(&rl, "%zu required attrs missing", n_required); return false; } return true; @@ -1059,7 +1066,7 @@ log_nlmsg(const char *function, int error, buffer.data = (void *) message; buffer.size = size; nlmsg = nlmsg_to_string(&buffer); - VLOG_DBG("%s (%s): %s", function, strerror(error), nlmsg); + VLOG_DBG_RL(&rl, "%s (%s): %s", function, strerror(error), nlmsg); free(nlmsg); } diff --git a/lib/poll-loop.c b/lib/poll-loop.c index 6bf05ddd6..d65c6afb1 100644 --- a/lib/poll-loop.c +++ b/lib/poll-loop.c @@ -146,7 +146,8 @@ poll_block(void) retval = time_poll(pollfds, n_pollfds, timeout); if (retval < 0) { - VLOG_ERR("poll: %s", strerror(-retval)); + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); + VLOG_ERR_RL(&rl, "poll: %s", strerror(-retval)); } for (node = waiters.next; node != &waiters; ) { diff --git a/lib/socket-util.c b/lib/socket-util.c index 35dbcd63b..8fa663ad7 100644 --- a/lib/socket-util.c +++ b/lib/socket-util.c @@ -77,12 +77,13 @@ lookup_ip(const char *host_name, struct in_addr *addr) if (!inet_aton(host_name, addr)) { struct hostent *he = gethostbyname(host_name); if (he == NULL) { - VLOG_ERR("gethostbyname(%s): %s", host_name, - (h_errno == HOST_NOT_FOUND ? "host not found" - : h_errno == TRY_AGAIN ? "try again" - : h_errno == NO_RECOVERY ? "non-recoverable error" - : h_errno == NO_ADDRESS ? "no address" - : "unknown error")); + struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); + VLOG_ERR_RL(&rl, "gethostbyname(%s): %s", host_name, + (h_errno == HOST_NOT_FOUND ? "host not found" + : h_errno == TRY_AGAIN ? "try again" + : h_errno == NO_RECOVERY ? "non-recoverable error" + : h_errno == NO_ADDRESS ? "no address" + : "unknown error")); return ENOENT; } addr->s_addr = *(uint32_t *) he->h_addr; @@ -98,8 +99,9 @@ get_socket_error(int fd) int error; socklen_t len = sizeof(error); if (getsockopt(fd, SOL_SOCKET, SO_ERROR, &error, &len) < 0) { + struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10); error = errno; - VLOG_ERR("getsockopt(SO_ERROR): %s", strerror(error)); + VLOG_ERR_RL(&rl, "getsockopt(SO_ERROR): %s", strerror(error)); } return error; } @@ -118,7 +120,8 @@ check_connection_completion(int fd) if (retval == 1) { return get_socket_error(fd); } else if (retval < 0) { - VLOG_ERR("poll: %s", strerror(errno)); + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10); + VLOG_ERR_RL(&rl, "poll: %s", strerror(errno)); return errno; } else { return EAGAIN; @@ -138,7 +141,8 @@ drain_rcvbuf(int fd) rcvbuf_len = sizeof rcvbuf; if (getsockopt(fd, SOL_SOCKET, SO_RCVBUF, &rcvbuf, &rcvbuf_len) < 0) { - VLOG_ERR("getsockopt(SO_RCVBUF) failed: %s", strerror(errno)); + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(5, 10); + VLOG_ERR_RL(&rl, "getsockopt(SO_RCVBUF) failed: %s", strerror(errno)); return errno; } while (rcvbuf > 0) { diff --git a/lib/vconn-ssl.c b/lib/vconn-ssl.c index d109cfdb0..41fd1d1d6 100644 --- a/lib/vconn-ssl.c +++ b/lib/vconn-ssl.c @@ -145,6 +145,10 @@ static SSL_CTX *ctx; /* Required configuration. */ static bool has_private_key, has_certificate, has_ca_cert; +/* Who knows what can trigger various SSL errors, so let's throttle them down + * quite a bit. */ +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(10, 25); + static int ssl_init(void); static int do_ssl_init(void); static bool ssl_wants_io(int ssl_error); @@ -368,11 +372,11 @@ interpret_ssl_error(const char *function, int ret, int error, switch (error) { case SSL_ERROR_NONE: - VLOG_ERR("%s: unexpected SSL_ERROR_NONE", function); + VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_NONE", function); break; case SSL_ERROR_ZERO_RETURN: - VLOG_ERR("%s: unexpected SSL_ERROR_ZERO_RETURN", function); + VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_ZERO_RETURN", function); break; case SSL_ERROR_WANT_READ: @@ -384,15 +388,16 @@ interpret_ssl_error(const char *function, int ret, int error, return EAGAIN; case SSL_ERROR_WANT_CONNECT: - VLOG_ERR("%s: unexpected SSL_ERROR_WANT_CONNECT", function); + VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_CONNECT", function); break; case SSL_ERROR_WANT_ACCEPT: - VLOG_ERR("%s: unexpected SSL_ERROR_WANT_ACCEPT", function); + VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_ACCEPT", function); break; case SSL_ERROR_WANT_X509_LOOKUP: - VLOG_ERR("%s: unexpected SSL_ERROR_WANT_X509_LOOKUP", function); + VLOG_ERR_RL(&rl, "%s: unexpected SSL_ERROR_WANT_X509_LOOKUP", + function); break; case SSL_ERROR_SYSCALL: { @@ -400,14 +405,17 @@ interpret_ssl_error(const char *function, int ret, int error, if (queued_error == 0) { if (ret < 0) { int status = errno; - VLOG_WARN("%s: system error (%s)", function, strerror(status)); + VLOG_WARN_RL(&rl, "%s: system error (%s)", + function, strerror(status)); return status; } else { - VLOG_WARN("%s: unexpected SSL connection close", function); + VLOG_WARN_RL(&rl, "%s: unexpected SSL connection close", + function); return EPROTO; } } else { - VLOG_DBG("%s: %s", function, ERR_error_string(queued_error, NULL)); + VLOG_DBG_RL(&rl, "%s: %s", + function, ERR_error_string(queued_error, NULL)); break; } } @@ -415,15 +423,17 @@ interpret_ssl_error(const char *function, int ret, int error, case SSL_ERROR_SSL: { int queued_error = ERR_get_error(); if (queued_error != 0) { - VLOG_DBG("%s: %s", function, ERR_error_string(queued_error, NULL)); + VLOG_DBG_RL(&rl, "%s: %s", + function, ERR_error_string(queued_error, NULL)); } else { - VLOG_ERR("%s: SSL_ERROR_SSL without queued error", function); + VLOG_ERR_RL(&rl, "%s: SSL_ERROR_SSL without queued error", + function); } break; } default: - VLOG_ERR("%s: bad SSL error code %d", function, error); + VLOG_ERR_RL(&rl, "%s: bad SSL error code %d", function, error); break; } return EIO; @@ -450,7 +460,8 @@ again: struct ofp_header *oh = rx->data; size_t length = ntohs(oh->length); if (length < sizeof(struct ofp_header)) { - VLOG_ERR("received too-short ofp_header (%zu bytes)", length); + VLOG_ERR_RL(&rl, "received too-short ofp_header (%zu bytes)", + length); return EPROTO; } want_bytes = length - rx->size; @@ -493,7 +504,7 @@ again: if (error == SSL_ERROR_ZERO_RETURN) { /* Connection closed (EOF). */ if (rx->size) { - VLOG_WARN("SSL_read: unexpected connection close"); + VLOG_WARN_RL(&rl, "SSL_read: unexpected connection close"); return EPROTO; } else { return EOF; @@ -541,7 +552,7 @@ ssl_do_tx(struct vconn *vconn) } else { int ssl_error = SSL_get_error(sslv->ssl, ret); if (ssl_error == SSL_ERROR_ZERO_RETURN) { - VLOG_WARN("SSL_write: connection closed"); + VLOG_WARN_RL(&rl, "SSL_write: connection closed"); return EPIPE; } else { return interpret_ssl_error("SSL_write", ret, ssl_error, @@ -749,7 +760,7 @@ pssl_accept(struct vconn *vconn, struct vconn **new_vconnp) if (new_fd < 0) { int error = errno; if (error != EAGAIN) { - VLOG_DBG("accept: %s", strerror(error)); + VLOG_DBG_RL(&rl, "accept: %s", strerror(error)); } return error; } @@ -865,7 +876,8 @@ tmp_dh_callback(SSL *ssl, int is_export UNUSED, int keylength) return dh->dh; } } - VLOG_ERR("no Diffie-Hellman parameters for key length %d", keylength); + VLOG_ERR_RL(&rl, "no Diffie-Hellman parameters for key length %d", + keylength); return NULL; } diff --git a/lib/vconn-stream.c b/lib/vconn-stream.c index 28d963549..beb239c3c 100644 --- a/lib/vconn-stream.c +++ b/lib/vconn-stream.c @@ -63,6 +63,8 @@ struct stream_vconn static struct vconn_class stream_vconn_class; +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(10, 25); + int new_stream_vconn(const char *name, int fd, int connect_status, uint32_t ip, struct vconn **vconnp) @@ -124,7 +126,8 @@ again: struct ofp_header *oh = rx->data; size_t length = ntohs(oh->length); if (length < sizeof(struct ofp_header)) { - VLOG_ERR("received too-short ofp_header (%zu bytes)", length); + VLOG_ERR_RL(&rl, "received too-short ofp_header (%zu bytes)", + length); return EPROTO; } want_bytes = length - rx->size; @@ -151,7 +154,7 @@ again: return EAGAIN; } else if (retval == 0) { if (rx->size) { - VLOG_ERR("connection dropped mid-packet"); + VLOG_ERR_RL(&rl, "connection dropped mid-packet"); return EPROTO; } else { return EOF; @@ -177,7 +180,7 @@ stream_do_tx(int fd UNUSED, short int revents UNUSED, void *vconn_) ssize_t n = write(s->fd, s->txbuf->data, s->txbuf->size); if (n < 0) { if (errno != EAGAIN) { - VLOG_ERR("send: %s", strerror(errno)); + VLOG_ERR_RL(&rl, "send: %s", strerror(errno)); stream_clear_txbuf(s); return; } @@ -323,7 +326,7 @@ pstream_accept(struct vconn *vconn, struct vconn **new_vconnp) if (new_fd < 0) { int retval = errno; if (retval != EAGAIN) { - VLOG_DBG("accept: %s", strerror(retval)); + VLOG_DBG_RL(&rl, "accept: %s", strerror(retval)); } return retval; } diff --git a/lib/vconn.c b/lib/vconn.c index 7df6d27b2..bac38d91f 100644 --- a/lib/vconn.c +++ b/lib/vconn.c @@ -65,6 +65,11 @@ static struct vconn_class *vconn_classes[] = { &punix_vconn_class, }; +/* 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); + /* Check the validity of the vconn class structures. */ static void check_vconn_classes(void) @@ -282,15 +287,15 @@ vconn_recv(struct vconn *vconn, struct buffer **msgp) if (VLOG_IS_DBG_ENABLED()) { char *s = ofp_to_string((*msgp)->data, (*msgp)->size, 1); - VLOG_DBG("received: %s", s); + VLOG_DBG_RL(&rl, "received: %s", s); free(s); } oh = buffer_at_assert(*msgp, 0, sizeof *oh); if (oh->version != OFP_VERSION) { - VLOG_ERR("received OpenFlow version %02"PRIx8" " - "!= expected %02x", - oh->version, OFP_VERSION); + VLOG_ERR_RL(&rl, "received OpenFlow version %02"PRIx8" " + "!= expected %02x", + oh->version, OFP_VERSION); buffer_delete(*msgp); *msgp = NULL; return EPROTO; @@ -327,7 +332,7 @@ vconn_send(struct vconn *vconn, struct buffer *msg) char *s = ofp_to_string(msg->data, msg->size, 1); retval = (vconn->class->send)(vconn, msg); if (retval != EAGAIN) { - VLOG_DBG("sent (%s): %s", strerror(retval), s); + VLOG_DBG_RL(&rl, "sent (%s): %s", strerror(retval), s); } free(s); } @@ -342,7 +347,6 @@ vconn_send_block(struct vconn *vconn, struct buffer *msg) int retval; while ((retval = vconn_send(vconn, msg)) == EAGAIN) { vconn_send_wait(vconn); - VLOG_DBG("blocking on vconn send"); poll_block(); } return retval; @@ -355,7 +359,6 @@ vconn_recv_block(struct vconn *vconn, struct buffer **msgp) int retval; while ((retval = vconn_recv(vconn, msgp)) == EAGAIN) { vconn_recv_wait(vconn); - VLOG_DBG("blocking on vconn receive"); poll_block(); } return retval; @@ -394,8 +397,8 @@ vconn_transact(struct vconn *vconn, struct buffer *request, return 0; } - VLOG_DBG("received reply with xid %08"PRIx32" != expected %08"PRIx32, - recv_xid, send_xid); + VLOG_DBG_RL(&rl, "received reply with xid %08"PRIx32" != expected " + "%08"PRIx32, recv_xid, send_xid); buffer_delete(reply); } } diff --git a/secchan/secchan.c b/secchan/secchan.c index f3396ff73..8906eb031 100644 --- a/secchan/secchan.c +++ b/secchan/secchan.c @@ -128,6 +128,8 @@ struct hook { void *aux; }; +static struct vlog_rate_limit vrl = VLOG_RATE_LIMIT_INIT(60, 60); + static void parse_options(int argc, char *argv[], struct settings *); static void usage(void) NO_RETURN; @@ -353,7 +355,7 @@ relay_accept(const struct settings *s, struct vconn *listen_vconn) retval = vconn_accept(listen_vconn, &new_remote); if (retval) { if (retval != EAGAIN) { - VLOG_WARN("accept failed (%s)", strerror(retval)); + VLOG_WARN_RL(&vrl, "accept failed (%s)", strerror(retval)); } return NULL; } @@ -367,8 +369,8 @@ relay_accept(const struct settings *s, struct vconn *listen_vconn) nl_name_without_subscription = xasprintf("%s:0", s->nl_name); retval = vconn_open(nl_name_without_subscription, &new_local); if (retval) { - VLOG_ERR("could not connect to %s (%s)", - nl_name_without_subscription, strerror(retval)); + VLOG_ERR_RL(&vrl, "could not connect to %s (%s)", + nl_name_without_subscription, strerror(retval)); vconn_close(new_remote); free(nl_name_without_subscription); return NULL; @@ -582,7 +584,8 @@ in_band_packet_cb(struct relay *r, int half, void *in_band_) return false; } if (msg->size < offsetof(struct ofp_packet_in, data)) { - VLOG_WARN("packet too short (%zu bytes) for packet_in", msg->size); + VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for packet_in", + msg->size); return false; } @@ -604,8 +607,8 @@ in_band_packet_cb(struct relay *r, int half, void *in_band_) /* Sent to secure channel. */ out_port = OFPP_LOCAL; if (mac_learning_learn(in_band->ml, flow.dl_src, in_port)) { - VLOG_DBG("learned that "ETH_ADDR_FMT" is on port %"PRIu16, - ETH_ADDR_ARGS(flow.dl_src), in_port); + VLOG_DBG_RL(&vrl, "learned that "ETH_ADDR_FMT" is on port %"PRIu16, + ETH_ADDR_ARGS(flow.dl_src), in_port); } } else if (flow.dl_type == htons(ETH_TYPE_ARP) && eth_addr_is_broadcast(flow.dl_dst) @@ -900,7 +903,8 @@ rate_limit_packet_cb(struct relay *r, int half, void *rl_) return false; } if (msg->size < offsetof(struct ofp_packet_in, data)) { - VLOG_WARN("packet too short (%zu bytes) for packet_in", msg->size); + VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for packet_in", + msg->size); return false; } @@ -1036,7 +1040,8 @@ switch_status_packet_cb(struct relay *r, int half, void *ss_) return false; } if (msg->size < sizeof(struct ofp_stats_request)) { - VLOG_WARN("packet too short (%zu bytes) for stats_request", msg->size); + VLOG_WARN_RL(&vrl, "packet too short (%zu bytes) for stats_request", + msg->size); return false; } @@ -1317,13 +1322,13 @@ validate_dhcp_offer(const struct dhcp_msg *msg, void *s_) vconn_name = dhcp_msg_get_string(msg, DHCP_CODE_OFP_CONTROLLER_VCONN); if (!vconn_name) { - VLOG_WARN("rejecting DHCP offer missing controller vconn"); + VLOG_WARN_RL(&vrl, "rejecting DHCP offer missing controller vconn"); return false; } accept = !regexec(&s->accept_controller_regex, vconn_name, 0, NULL, 0); if (!accept) { - VLOG_WARN("rejecting controller vconn that fails to match %s", - s->accept_controller_re); + VLOG_WARN_RL(&vrl, "rejecting controller vconn that fails to match %s", + s->accept_controller_re); } free(vconn_name); return accept; diff --git a/switch/datapath.c b/switch/datapath.c index 26fb06c60..4776c6199 100644 --- a/switch/datapath.c +++ b/switch/datapath.c @@ -139,6 +139,8 @@ struct datapath { struct list port_list; /* List of ports, for flooding. */ }; +static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60); + static struct remote *remote_create(struct datapath *, struct rconn *); static void remote_run(struct datapath *, struct remote *); static void remote_wait(struct remote *); @@ -331,8 +333,8 @@ dp_run(struct datapath *dp) fwd_port_input(dp, buffer, port_no(dp, p)); buffer = NULL; } else if (error != EAGAIN) { - VLOG_ERR("error receiving data from %s: %s", - netdev_get_name(p->netdev), strerror(error)); + VLOG_ERR_RL(&rl, "error receiving data from %s: %s", + netdev_get_name(p->netdev), strerror(error)); } } buffer_delete(buffer); @@ -349,7 +351,7 @@ dp_run(struct datapath *dp) retval = vconn_accept(dp->listen_vconn, &new_vconn); if (retval) { if (retval != EAGAIN) { - VLOG_WARN("accept failed (%s)", strerror(retval)); + VLOG_WARN_RL(&rl, "accept failed (%s)", strerror(retval)); } break; } @@ -385,7 +387,7 @@ remote_run(struct datapath *dp, struct remote *r) sender.xid = oh->xid; fwd_control_input(dp, &sender, buffer->data, buffer->size); } else { - VLOG_WARN("received too-short OpenFlow message"); + VLOG_WARN_RL(&rl, "received too-short OpenFlow message"); } buffer_delete(buffer); } else { @@ -393,7 +395,8 @@ remote_run(struct datapath *dp, struct remote *r) int error = r->cb_dump(dp, r->cb_aux); if (error <= 0) { if (error) { - VLOG_WARN("dump callback error: %s", strerror(-error)); + VLOG_WARN_RL(&rl, "dump callback error: %s", + strerror(-error)); } r->cb_done(r->cb_aux); r->cb_dump = NULL; @@ -555,8 +558,7 @@ output_packet(struct datapath *dp, struct buffer *buffer, int out_port) } buffer_delete(buffer); - /* FIXME: ratelimit */ - VLOG_DBG("can't forward to bad port %d\n", out_port); + VLOG_DBG_RL(&rl, "can't forward to bad port %d\n", out_port); } /* Takes ownership of 'buffer' and transmits it to 'out_port' on 'dp'. @@ -581,8 +583,7 @@ dp_output_port(struct datapath *dp, struct buffer *buffer, } } else { if (in_port == out_port) { - /* FIXME: ratelimit */ - VLOG_DBG("can't directly forward to input port"); + VLOG_DBG_RL(&rl, "can't directly forward to input port"); return; } output_packet(dp, buffer, out_port); @@ -610,8 +611,8 @@ send_openflow_buffer(struct datapath *dp, struct buffer *buffer, ? rconn_send(rconn, buffer, &remote->n_txq) : EAGAIN); if (retval) { - VLOG_WARN("send to %s failed: %s", - rconn_get_name(rconn), strerror(retval)); + VLOG_WARN_RL(&rl, "send to %s failed: %s", + rconn_get_name(rconn), strerror(retval)); buffer_delete(buffer); } return retval; @@ -746,8 +747,8 @@ update_port_status(struct sw_port *p) uint32_t orig_status = p->status; if (netdev_get_flags(p->netdev, &flags) < 0) { - VLOG_WARN("could not get netdev flags for %s", - netdev_get_name(p->netdev)); + VLOG_WARN_RL(&rl, "could not get netdev flags for %s", + netdev_get_name(p->netdev)); return 0; } else { if (flags & NETDEV_UP) { @@ -1110,7 +1111,7 @@ recv_packet_out(struct datapath *dp, const struct sender *sender UNUSED, int act_len = n_actions * sizeof opo->actions[0]; if (act_len > (ntohs(opo->header.length) - sizeof *opo)) { - VLOG_DBG("message too short for number of actions"); + VLOG_DBG_RL(&rl, "message too short for number of actions"); return -EINVAL; } @@ -1574,7 +1575,7 @@ recv_stats_request(struct datapath *dp, const struct sender *sender, type = ntohs(rq->type); if (type >= ARRAY_SIZE(stats) || !stats[type].dump) { - VLOG_WARN("received stats request of unknown type %d", type); + VLOG_WARN_RL(&rl, "received stats request of unknown type %d", type); return -EINVAL; } @@ -1587,8 +1588,8 @@ recv_stats_request(struct datapath *dp, const struct sender *sender, body_len = rq_len - offsetof(struct ofp_stats_request, body); if (body_len < cb->s->min_body || body_len > cb->s->max_body) { - VLOG_WARN("stats request type %d with bad body length %d", - type, body_len); + VLOG_WARN_RL(&rl, "stats request type %d with bad body length %d", + type, body_len); err = -EINVAL; goto error; } @@ -1596,8 +1597,9 @@ recv_stats_request(struct datapath *dp, const struct sender *sender, if (cb->s->init) { err = cb->s->init(dp, rq->body, body_len, &cb->state); if (err) { - VLOG_WARN("failed initialization of stats request type %d: %s", - type, strerror(-err)); + VLOG_WARN_RL(&rl, + "failed initialization of stats request type %d: %s", + type, strerror(-err)); goto error; } } diff --git a/utilities/ofp-discover.c b/utilities/ofp-discover.c index bf5e92d4e..70c53ee82 100644 --- a/utilities/ofp-discover.c +++ b/utilities/ofp-discover.c @@ -272,12 +272,13 @@ modify_dhcp_request(struct dhcp_msg *msg, void *aux) static bool validate_dhcp_offer(const struct dhcp_msg *msg, void *aux) { + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60); char *vconn_name; bool accept; vconn_name = dhcp_msg_get_string(msg, DHCP_CODE_OFP_CONTROLLER_VCONN); if (!vconn_name) { - VLOG_WARN("rejecting DHCP offer missing controller vconn"); + VLOG_WARN_RL(&rl, "rejecting DHCP offer missing controller vconn"); return false; } accept = !regexec(&accept_controller_regex, vconn_name, 0, NULL, 0); -- 2.43.0