datapath: add netlink error message to help kernel userspace integration.

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@nicira.com>
Signed-off-by: Jesse Gross <jesse@nicira.com>

diff --git a/datapath/datapath.c b/datapath/datapath.c
index 744a9a4..2f02f71 100644 (file)
--- a/datapath/datapath.c
+++ b/datapath/datapath.c
@@ -1361,8 +1361,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);
@@ -1410,8 +1412,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..d14a162 100644 (file)
--- 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..c76c18d 100644 (file)
--- 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_attrs=%llx, mask_allowed=%llx).\n",
+                               mask_attrs, mask_allowed);
                return false;
+       }
 
        return true;
 }
@@ -1126,24 +1132,33 @@ 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))
-                       return -EINVAL;
+               if (type > OVS_KEY_ATTR_MAX) {
+                       OVS_NLERR("Unknown key attribute (type=%d, max=%d).\n",
+                                 type, OVS_KEY_ATTR_MAX);
+               }
 
-               expected_len = ovs_key_lens[type];
-               if (nla_len(nla) != expected_len && expected_len != -1)
+               if (attrs & (1ULL << type)) {
+                       OVS_NLERR("Duplicate key attribute (type %d).\n", type);
                        return -EINVAL;
+               }
 
-               if (attrs & (1ULL << type))
-                       /* Duplicated field. */
+               expected_len = ovs_key_lens[type];
+               if (nla_len(nla) != expected_len && expected_len != -1) {
+                       OVS_NLERR("Key attribute has unexpected length (type=%d"
+                                 ", length=%d, expected=%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("Message has %d unknown bytes.\n", rem);
                return -EINVAL;
+       }
 
        *attrsp = attrs;
        return 0;
@@ -1181,9 +1196,18 @@ 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("Unknown 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 has unexpected "
+                                 " legnth (type=%d, length=%d, expected=%d.)\n",
+                                 type, nla_len(a), ovs_tunnel_key_lens[type]);
                        return -EINVAL;
+               }
 
                switch (type) {
                case OVS_TUNNEL_KEY_ATTR_ID:
@@ -1221,14 +1245,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 +1319,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("skb->mark must be zero on this kernel (mark=%d).\n", mark);
                        return -EINVAL;
+               }
 #endif
                SW_FLOW_KEY_PUT(match, phy.skb_mark, mark, is_mask);
                *attrs &= ~(1ULL << OVS_KEY_ATTR_SKB_MARK);
@@ -1330,8 +1362,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 +1375,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 is less than mimimum (type=%x, min=%x).\n",
+                                       ntohs(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 +1391,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("Unknown IPv4 fragment type (value=%d, max=%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 +1415,11 @@ 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("Unknown IPv6 fragment type (value=%d, max=%d).\n",
+                               ipv6_key->ipv6_frag, OVS_FRAG_TYPE_MAX);
                        return -EINVAL;
+               }
                SW_FLOW_KEY_PUT(match, ipv6.label,
                                ipv6_key->ipv6_label, is_mask);
                SW_FLOW_KEY_PUT(match, ip.proto,
@@ -1403,8 +1446,11 @@ 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("Unknown ARP opcode (opcode=%d).\n",
+                                 arp_key->arp_op);
                        return -EINVAL;
+               }
 
                SW_FLOW_KEY_PUT(match, ipv4.addr.src,
                                arp_key->arp_sip, is_mask);
@@ -1539,8 +1585,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 +1614,12 @@ 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("VLAN frames must have an exact match"
+                                        " on the TPID (mask=%x).\n",
+                                        ntohs(eth_type));
                                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..fdd2005 100644 (file)
--- a/datapath/linux/compat/include/linux/kernel.h
+++ b/datapath/linux/compat/include/linux/kernel.h
@@ -39,6 +39,40 @@
 #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)
+#undef printk_once
+#define printk_once(fmt, ...)                  \
+({                                             \
+       static bool __print_once;               \
+                                               \
+       if (!__print_once) {                    \
+               __print_once = true;            \
+               printk(fmt, ##__VA_ARGS__);     \
+       }                                       \
+})
+
+#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__)
+
+#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