[ovs-dev] [netlink-errmsg v3] datapath: add netlink error message to help kernel userspace integration.

Andy Zhou azhou at nicira.com
Wed Jul 3 16:18:27 UTC 2013


When kernel rejects a netlink message, it usually returns EINVAL
error code to the userspace. The actual reason for rejecting the
netlinke message is not available, making it harder to debug netlink
issues.  This patch adds kernel log messages whenever a netlink message
is rejected with reasons. Those messages are logged at the info level.

Those messages are logged only once per message, to keep kernel log noise
level down. Reload the kernel module to re-enable already logged
messages.

The messages are meant to help developers to debug userspace and kernel
intergration issues. The actual message may change or be removed over time.
These messages are not expected to show up in a production environment.

Signed-off-by: Andy Zhou <azhou at nicira.com>
---
 datapath/datapath.c                          |    8 ++-
 datapath/datapath.h                          |    4 ++
 datapath/flow.c                              |   85 +++++++++++++++++++-------
 datapath/linux/compat/include/linux/kernel.h |   50 +++++++++++++++
 4 files changed, 123 insertions(+), 24 deletions(-)

diff --git a/datapath/datapath.c b/datapath/datapath.c
index 3680391..ad8f7fb 100644
--- a/datapath/datapath.c
+++ b/datapath/datapath.c
@@ -1358,8 +1358,10 @@ static int ovs_flow_cmd_new_or_set(struct sk_buff *skb, struct genl_info *info)
 
 		/* The unmasked key has to be the same for flow updates. */
 		error = -EINVAL;
-		if (!ovs_flow_cmp_unmasked_key(flow, &key, match.range.end))
+		if (!ovs_flow_cmp_unmasked_key(flow, &key, match.range.end)) {
+			OVS_NLERR("Flow modification message rejected, unmasked key does not match.\n");
 			goto err_unlock_ovs;
+		}
 
 		/* Update actions. */
 		old_acts = ovsl_dereference(flow->sf_acts);
@@ -1407,8 +1409,10 @@ static int ovs_flow_cmd_get(struct sk_buff *skb, struct genl_info *info)
 	struct sw_flow_match match;
 	int err;
 
-	if (!a[OVS_FLOW_ATTR_KEY])
+	if (!a[OVS_FLOW_ATTR_KEY]) {
+		OVS_NLERR("Flow get message rejected, Key attribute missing.\n");
 		return -EINVAL;
+	}
 
 	ovs_match_init(&match, &key, NULL);
 	err = ovs_match_from_nlattrs(&match, a[OVS_FLOW_ATTR_KEY], NULL);
diff --git a/datapath/datapath.h b/datapath/datapath.h
index 559df69..17b1db9 100644
--- a/datapath/datapath.h
+++ b/datapath/datapath.h
@@ -204,4 +204,8 @@ struct sk_buff *ovs_vport_cmd_build_info(struct vport *, u32 portid, u32 seq,
 
 int ovs_execute_actions(struct datapath *dp, struct sk_buff *skb);
 void ovs_dp_notify_wq(struct work_struct *work);
+
+#define OVS_NLERR(fmt, ...) \
+	pr_info_once(fmt " netlink: ", ##__VA_ARGS__)
+
 #endif /* datapath.h */
diff --git a/datapath/flow.c b/datapath/flow.c
index 2ac36b6..89bb496 100644
--- a/datapath/flow.c
+++ b/datapath/flow.c
@@ -205,13 +205,19 @@ static bool ovs_match_validate(const struct sw_flow_match *match,
 		}
 	}
 
-	if ((key_attrs & key_expected) != key_expected)
+	if ((key_attrs & key_expected) != key_expected) {
 		/* Key attributes check failed. */
+		OVS_NLERR("Missing expected key attributes. (key_attrs=%llx, expected = %llx)\n",
+				key_attrs, key_expected);
 		return false;
+	}
 
-	if ((mask_attrs & mask_allowed) != mask_attrs)
+	if ((mask_attrs & mask_allowed) != mask_attrs) {
 		/* Mask attributes check failed. */
+		OVS_NLERR("Contain more than allowed mask fields. (mask_attr = %llx, mask_allowed = %llx)\n",
+				mask_attrs, mask_allowed);
 		return false;
+	}
 
 	return true;
 }
@@ -1126,24 +1132,27 @@ static int __parse_flow_nlattrs(const struct nlattr *attr,
 		u16 type = nla_type(nla);
 		int expected_len;
 
-		if (type > OVS_KEY_ATTR_MAX || attrs & (1ULL << type))
+		if (type > OVS_KEY_ATTR_MAX || attrs & (1ULL << type)) {
+			OVS_NLERR("Duplicate key attribute type %d.\n", type);
 			return -EINVAL;
+		}
 
 		expected_len = ovs_key_lens[type];
-		if (nla_len(nla) != expected_len && expected_len != -1)
-			return -EINVAL;
-
-		if (attrs & (1ULL << type))
-			/* Duplicated field. */
+		if (nla_len(nla) != expected_len && expected_len != -1) {
+			OVS_NLERR("Key attribute type %d length %d, not matching expected length %d.\n",
+			type, nla_len(nla), expected_len);
 			return -EINVAL;
+		}
 
 		if (!nz || !is_all_zero(nla_data(nla), expected_len)) {
 			attrs |= 1ULL << type;
 			a[type] = nla;
 		}
 	}
-	if (rem)
+	if (rem) {
+		OVS_NLERR("netlink message has %d unknown bytes.\n", rem);
 		return -EINVAL;
+	}
 
 	*attrsp = attrs;
 	return 0;
@@ -1181,9 +1190,17 @@ int ipv4_tun_from_nlattr(const struct nlattr *attr,
 			[OVS_TUNNEL_KEY_ATTR_CSUM] = 0,
 		};
 
-		if (type > OVS_TUNNEL_KEY_ATTR_MAX ||
-			ovs_tunnel_key_lens[type] != nla_len(a))
+		if (type > OVS_TUNNEL_KEY_ATTR_MAX) {
+			OVS_NLERR("Unexpected IPv4 tunnel attribute. (type = %d, MAX=%d)\n",
+			type, OVS_TUNNEL_KEY_ATTR_MAX);
+			return -EINVAL;
+		}
+
+		if (ovs_tunnel_key_lens[type] != nla_len(a)) {
+			OVS_NLERR("IPv4 tunnel attribute type %d length %d does not equal to expected length %d.\n",
+				type, nla_len(a), ovs_tunnel_key_lens[type]);
 			return -EINVAL;
+		}
 
 		switch (type) {
 		case OVS_TUNNEL_KEY_ATTR_ID:
@@ -1221,14 +1238,20 @@ int ipv4_tun_from_nlattr(const struct nlattr *attr,
 
 	SW_FLOW_KEY_PUT(match, tun_key.tun_flags, tun_flags, is_mask);
 
-	if (rem > 0)
+	if (rem > 0) {
+		OVS_NLERR("IPv4 tunnel attribute has %d unknown bytes.\n", rem);
 		return -EINVAL;
+	}
 
-	if (!match->key->tun_key.ipv4_dst)
+	if (!match->key->tun_key.ipv4_dst) {
+		OVS_NLERR("IPv4 tunnel destination address is zero.\n");
 		return -EINVAL;
+	}
 
-	if (!ttl)
+	if (!ttl) {
+		OVS_NLERR("IPv4 tunnel TTL is zero.\n");
 		return -EINVAL;
+	}
 
 	return 0;
 }
@@ -1289,8 +1312,10 @@ static int metadata_from_nlattrs(struct sw_flow_match *match,  u64 *attrs,
 	if (*attrs & (1ULL << OVS_KEY_ATTR_SKB_MARK)) {
 		uint32_t mark = nla_get_u32(a[OVS_KEY_ATTR_SKB_MARK]);
 #if LINUX_VERSION_CODE < KERNEL_VERSION(2,6,20) && !defined(CONFIG_NETFILTER)
-		if (!is_mask && mark != 0)
+		if (!is_mask && mark != 0) {
+			OVS_NLERR("Flow meta data mark is not zero.\n");
 			return -EINVAL;
+		}
 #endif
 		SW_FLOW_KEY_PUT(match, phy.skb_mark, mark, is_mask);
 		*attrs &= ~(1ULL << OVS_KEY_ATTR_SKB_MARK);
@@ -1330,8 +1355,10 @@ static int ovs_key_from_nlattrs(struct sw_flow_match *match,  u64 attrs,
 
 		tci = nla_get_be16(a[OVS_KEY_ATTR_VLAN]);
 		if (!is_mask)
-			if (!(tci & htons(VLAN_TAG_PRESENT)))
+			if (!(tci & htons(VLAN_TAG_PRESENT))) {
+				OVS_NLERR("VLAN tci does not have VLAN_TAG_PRESENT bit set.\n");
 				return -EINVAL;
+			}
 
 		SW_FLOW_KEY_PUT(match, eth.tci, tci, is_mask);
 		attrs &= ~(1ULL << OVS_KEY_ATTR_VLAN);
@@ -1341,8 +1368,11 @@ static int ovs_key_from_nlattrs(struct sw_flow_match *match,  u64 attrs,
 		__be16 eth_type;
 
 		eth_type = nla_get_be16(a[OVS_KEY_ATTR_ETHERTYPE]);
-		if (!is_mask && ntohs(eth_type) < ETH_P_802_3_MIN)
+		if (!is_mask && ntohs(eth_type) < ETH_P_802_3_MIN) {
+			OVS_NLERR("Ethertype value %x is less than %x.\n",
+					eth_type, ETH_P_802_3_MIN);
 			return -EINVAL;
+		}
 
 		SW_FLOW_KEY_PUT(match, eth.type, eth_type, is_mask);
 		attrs &= ~(1ULL << OVS_KEY_ATTR_ETHERTYPE);
@@ -1354,8 +1384,11 @@ static int ovs_key_from_nlattrs(struct sw_flow_match *match,  u64 attrs,
 		const struct ovs_key_ipv4 *ipv4_key;
 
 		ipv4_key = nla_data(a[OVS_KEY_ATTR_IPV4]);
-		if (!is_mask && ipv4_key->ipv4_frag > OVS_FRAG_TYPE_MAX)
+		if (!is_mask && ipv4_key->ipv4_frag > OVS_FRAG_TYPE_MAX) {
+			OVS_NLERR("IPv4 frag type value %d is larger than %d.\n",
+				ipv4_key->ipv4_frag, OVS_FRAG_TYPE_MAX);
 			return -EINVAL;
+		}
 		SW_FLOW_KEY_PUT(match, ip.proto,
 				ipv4_key->ipv4_proto, is_mask);
 		SW_FLOW_KEY_PUT(match, ip.tos,
@@ -1375,8 +1408,10 @@ static int ovs_key_from_nlattrs(struct sw_flow_match *match,  u64 attrs,
 		const struct ovs_key_ipv6 *ipv6_key;
 
 		ipv6_key = nla_data(a[OVS_KEY_ATTR_IPV6]);
-		if (!is_mask && ipv6_key->ipv6_frag > OVS_FRAG_TYPE_MAX)
+		if (!is_mask && ipv6_key->ipv6_frag > OVS_FRAG_TYPE_MAX) {
+			OVS_NLERR("IPv6 frag type value is larger than OVS_FRAG_TYPE_MAX.\n");
 			return -EINVAL;
+		}
 		SW_FLOW_KEY_PUT(match, ipv6.label,
 				ipv6_key->ipv6_label, is_mask);
 		SW_FLOW_KEY_PUT(match, ip.proto,
@@ -1403,8 +1438,10 @@ static int ovs_key_from_nlattrs(struct sw_flow_match *match,  u64 attrs,
 		const struct ovs_key_arp *arp_key;
 
 		arp_key = nla_data(a[OVS_KEY_ATTR_ARP]);
-		if (!is_mask && (arp_key->arp_op & htons(0xff00)))
+		if (!is_mask && (arp_key->arp_op & htons(0xff00))) {
+			OVS_NLERR("ARP op value high 16-bits are not clear.\n");
 			return -EINVAL;
+		}
 
 		SW_FLOW_KEY_PUT(match, ipv4.addr.src,
 				arp_key->arp_sip, is_mask);
@@ -1539,8 +1576,10 @@ int ovs_match_from_nlattrs(struct sw_flow_match *match,
 				encap_valid = true;
 				key_attrs &= ~(1ULL << OVS_KEY_ATTR_ETHERTYPE);
 				err = parse_flow_nlattrs(encap, a, &key_attrs);
-			} else
+			} else {
+				OVS_NLERR("Encap attribute is set for a non-VLAN frame.\n");
 				err = -EINVAL;
+			}
 
 			if (err)
 				return err;
@@ -1566,8 +1605,10 @@ int ovs_match_from_nlattrs(struct sw_flow_match *match,
 				mask_attrs &= ~(1ULL << OVS_KEY_ATTR_ETHERTYPE);
 				encap = a[OVS_KEY_ATTR_ENCAP];
 				err = parse_flow_mask_nlattrs(encap, a, &mask_attrs);
-			} else
+			} else {
+				OVS_NLERR("Ethertype 8021Q is not exact match.\n");
 				err = -EINVAL;
+			}
 
 			if (err)
 				return err;
diff --git a/datapath/linux/compat/include/linux/kernel.h b/datapath/linux/compat/include/linux/kernel.h
index 2fa5cc8..16c25fe 100644
--- a/datapath/linux/compat/include/linux/kernel.h
+++ b/datapath/linux/compat/include/linux/kernel.h
@@ -39,6 +39,56 @@
 #define pr_warn pr_warning
 #endif
 
+/*
+ * Print a one-time message (analogous to WARN_ONCE() et al):
+ */
+#if LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 38)
+#ifdef CONFIG_PRINTK
+#undef printk_once
+#define printk_once(fmt, ...)			\
+({						\
+	static bool __print_once;		\
+						\
+	if (!__print_once) {			\
+		__print_once = true;		\
+		printk(fmt, ##__VA_ARGS__);	\
+	}					\
+})
+#else
+#define printk_once(fmt, ...)			\
+	no_printk(fmt, ##__VA_ARGS__)
+#endif
+
+#undef pr_fmt
+#define pr_fmt(fmt) fmt
+
+#define pr_emerg_once(fmt, ...)					\
+	printk_once(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_once(fmt, ...)					\
+	printk_once(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_once(fmt, ...)					\
+	printk_once(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_once(fmt, ...)					\
+	printk_once(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_once(fmt, ...)					\
+	printk_once(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_once(fmt, ...)				\
+	printk_once(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_once(fmt, ...)					\
+	printk_once(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_cont_once(fmt, ...)					\
+	printk_once(KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* If you are writing a driver, please use dev_dbg instead */
+#if defined(DEBUG)
+#define pr_debug_once(fmt, ...)					\
+	printk_once(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+#else
+#define pr_debug_once(fmt, ...)					\
+	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
+#endif
+
+#endif
+
 #if defined(CONFIG_PREEMPT) && LINUX_VERSION_CODE < KERNEL_VERSION(2,6,21)
 #error "CONFIG_PREEMPT is broken before 2.6.21--see commit 4498121ca3, \"[NET]: Handle disabled preemption in gfp_any()\""
 #endif
-- 
1.7.9.5




More information about the dev mailing list