#undef DHCLIENT_STATE
};
+static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(60, 60);
+
static const char *
state_name(enum dhclient_state state)
{
{
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;
}
{
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;
}
}
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;
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;
}
#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 *
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);
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;
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;
}
}
}
} 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);
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;
}
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);
}
#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;
|| 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;
}
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;
}
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;
}
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;
}
* 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);
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 *,
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;
}
} 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);
}
}
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));
}
}
}
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);
}
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;
}
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);
} 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 {
/* 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);
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;
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;
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;
}
#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);
\f
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;
}
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;
}
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;
}
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;
}
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);
/* 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;
}
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;
}
}
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;
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);
}
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; ) {
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;
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;
}
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;
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) {
/* 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);
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:
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: {
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;
}
}
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;
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;
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;
} 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,
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;
}
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;
}
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)
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;
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;
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;
}
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;
}
&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)
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;
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);
}
int retval;
while ((retval = vconn_send(vconn, msg)) == EAGAIN) {
vconn_send_wait(vconn);
- VLOG_DBG("blocking on vconn send");
poll_block();
}
return retval;
int retval;
while ((retval = vconn_recv(vconn, msgp)) == EAGAIN) {
vconn_recv_wait(vconn);
- VLOG_DBG("blocking on vconn receive");
poll_block();
}
return retval;
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);
}
}
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;
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;
}
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;
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;
}
/* 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)
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;
}
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;
}
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;
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 *);
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);
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;
}
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 {
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;
}
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'.
}
} 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);
? 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;
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) {
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;
}
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;
}
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;
}
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;
}
}
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);