dpif: Make higher-verbosity flow logging available.

diff --git a/lib/dpif.c b/lib/dpif.c
index 0a4c86a280c857a15bfaac41fce359e8bcfc5d96..589d97462b0d35dddd653f0ebac8233baf5d9fb5 100644 (file)
--- a/lib/dpif.c
+++ b/lib/dpif.c
@@ -54,6 +54,7 @@
 #include "dynamic-string.h"
 #include "flow.h"
 #include "netlink.h"
+#include "odp-util.h"
 #include "ofp-print.h"
 #include "ofpbuf.h"
 #include "packets.h"
@@ -77,8 +78,6 @@ static int name_to_minor(const char *name, unsigned int *minor);
 static int lookup_minor(const char *name, unsigned int *minor);
 static int open_by_minor(unsigned int minor, struct dpif *);
 static int make_openflow_device(unsigned int minor, char **fnp);
-static char *odp_actions_to_string(const union odp_action actions[],
-                                   size_t n_actions);
 static void check_rw_odp_flow(struct odp_flow *);
 
 int
@@ -124,21 +123,21 @@ dpif_close(struct dpif *dpif)
     }
 }
 
-#define IOCTL(DPIF, CMD, ARG) do_ioctl(DPIF, CMD, #CMD, ARG)
-
 static int
 do_ioctl(const struct dpif *dpif, int cmd, const char *cmd_name,
          const void *arg)
 {
-    if (ioctl(dpif->fd, cmd, arg)) {
-        VLOG_WARN_RL(&error_rl, "dp%u: ioctl(%s) failed (%s)",
-                     dpif->minor, cmd_name, strerror(errno));
-        return errno;
-    } else {
-        VLOG_DBG_RL(&dpmsg_rl, "dp%u: ioctl(%s): success",
-                    dpif->minor, cmd_name);
-        return 0;
+    int error = ioctl(dpif->fd, cmd, arg) ? errno : 0;
+    if (cmd_name) {
+        if (error) {
+            VLOG_WARN_RL(&error_rl, "dp%u: ioctl(%s) failed (%s)",
+                         dpif->minor, cmd_name, strerror(errno));
+        } else {
+            VLOG_DBG_RL(&dpmsg_rl, "dp%u: ioctl(%s): success",
+                        dpif->minor, cmd_name);
+        }
     }
+    return error;
 }
 
 int
@@ -204,21 +203,21 @@ dpif_get_name(struct dpif *dpif, char *name, size_t name_size)
 int
 dpif_delete(struct dpif *dpif)
 {
-    return IOCTL(dpif, ODP_DP_DESTROY, NULL);
+    return do_ioctl(dpif, ODP_DP_DESTROY, "ODP_DP_DESTROY", NULL);
 }
 
 int
 dpif_get_dp_stats(const struct dpif *dpif, struct odp_stats *stats)
 {
     memset(stats, 0, sizeof *stats);
-    return IOCTL(dpif, ODP_DP_STATS, stats);
+    return do_ioctl(dpif, ODP_DP_STATS, "ODP_DP_STATS", stats);
 }
 
 int
 dpif_get_drop_frags(const struct dpif *dpif, bool *drop_frags)
 {
     int tmp;
-    int error = IOCTL(dpif, ODP_GET_DROP_FRAGS, &tmp);
+    int error = do_ioctl(dpif, ODP_GET_DROP_FRAGS, "ODP_GET_DROP_FRAGS", &tmp);
     *drop_frags = error ? tmp & 1 : false;
     return error;
 }
@@ -227,13 +226,14 @@ int
 dpif_set_drop_frags(struct dpif *dpif, bool drop_frags)
 {
     int tmp = drop_frags;
-    return IOCTL(dpif, ODP_SET_DROP_FRAGS, &tmp);
+    return do_ioctl(dpif, ODP_SET_DROP_FRAGS, "ODP_SET_DROP_FRAGS", &tmp);
 }
 
 int
 dpif_get_listen_mask(const struct dpif *dpif, int *listen_mask)
 {
-    int error = IOCTL(dpif, ODP_GET_LISTEN_MASK, listen_mask);
+    int error = do_ioctl(dpif, ODP_GET_LISTEN_MASK, "ODP_GET_LISTEN_MASK",
+                         listen_mask);
     if (error) {
         *listen_mask = 0;
     }
@@ -243,7 +243,8 @@ dpif_get_listen_mask(const struct dpif *dpif, int *listen_mask)
 int
 dpif_set_listen_mask(struct dpif *dpif, int listen_mask)
 {
-    return IOCTL(dpif, ODP_SET_LISTEN_MASK, &listen_mask);
+    return do_ioctl(dpif, ODP_SET_LISTEN_MASK, "ODP_SET_LISTEN_MASK",
+                    &listen_mask);
 }
 
 int
@@ -293,7 +294,7 @@ int
 dpif_port_del(struct dpif *dpif, uint16_t port_no)
 {
     int tmp = port_no;
-    return IOCTL(dpif, ODP_PORT_DEL, &tmp);
+    return do_ioctl(dpif, ODP_PORT_DEL, "ODP_PORT_DEL", &tmp);
 }
 
 int
@@ -347,7 +348,7 @@ dpif_port_list(const struct dpif *dpif,
         *ports = xcalloc(1, stats.n_ports * sizeof **ports);
         pv.ports = *ports;
         pv.n_ports = stats.n_ports;
-        error = IOCTL(dpif, ODP_PORT_LIST, &pv);
+        error = do_ioctl(dpif, ODP_PORT_LIST, "ODP_PORT_LIST", &pv);
         if (error) {
             free(*ports);
             goto error;
@@ -372,7 +373,7 @@ dpif_port_group_set(struct dpif *dpif, uint16_t group,
     pg.group = group;
     pg.ports = (uint16_t *) ports;
     pg.n_ports = n_ports;
-    return IOCTL(dpif, ODP_PORT_GROUP_SET, &pg);
+    return do_ioctl(dpif, ODP_PORT_GROUP_SET, "ODP_PORT_GROUP_SET", &pg);
 }
 
 /* Careful: '*n_out' can be greater than 'n_ports' on return, if 'n_ports' is
@@ -388,7 +389,7 @@ dpif_port_group_get(const struct dpif *dpif, uint16_t group,
     pg.group = group;
     pg.ports = ports;
     pg.n_ports = n_ports;
-    error = IOCTL(dpif, ODP_PORT_GROUP_GET, &pg);
+    error = do_ioctl(dpif, ODP_PORT_GROUP_GET, "ODP_PORT_GROUP_GET", &pg);
     *n_out = error ? 0 : pg.n_ports;
     return error;
 }
@@ -396,22 +397,58 @@ dpif_port_group_get(const struct dpif *dpif, uint16_t group,
 int
 dpif_flow_flush(struct dpif *dpif)
 {
-    return IOCTL(dpif, ODP_FLOW_FLUSH, NULL);
+    return do_ioctl(dpif, ODP_FLOW_FLUSH, "ODP_FLOW_FLUSH", NULL);
+}
+
+static void
+log_flow_message(const struct dpif *dpif, enum vlog_level level, int error,
+                 const char *operation,
+                 const flow_t *flow, const struct odp_flow_stats *stats,
+                 const union odp_action *actions, size_t n_actions)
+{
+    struct ds ds = DS_EMPTY_INITIALIZER;
+    ds_put_format(&ds, "dp%u: ", dpif->minor);
+    if (error) {
+        ds_put_cstr(&ds, "failed to ");
+    }
+    ds_put_format(&ds, "%s ", operation);
+    if (error) {
+        ds_put_format(&ds, "(%s) ", strerror(error));
+    }
+    flow_format(&ds, flow);
+    if (stats) {
+        ds_put_cstr(&ds, ", ");
+        format_odp_flow_stats(&ds, stats);
+    }
+    if (actions || n_actions) {
+        ds_put_cstr(&ds, ", actions:");
+        format_odp_actions(&ds, actions, n_actions);
+    }
+    vlog(THIS_MODULE, level, "%s", ds_cstr(&ds));
+    ds_destroy(&ds);
+}
+
+static int
+do_flow_ioctl(const struct dpif *dpif, int cmd, struct odp_flow *flow,
+              const char *operation, bool show_stats)
+{
+    int error = do_ioctl(dpif, cmd, NULL, flow);
+    if (error && show_stats) {
+        flow->n_actions = 0;
+    }
+    if (!(error ? VLOG_DROP_WARN(&error_rl) : VLOG_DROP_DBG(&dpmsg_rl))) {
+        log_flow_message(dpif, error ? VLL_WARN : VLL_DBG, error, operation,
+                         &flow->key,
+                         show_stats && !error ? &flow->stats : NULL,
+                         flow->actions, flow->n_actions);
+    }
+    return error;
 }
 
 int
 dpif_flow_add(struct dpif *dpif, struct odp_flow *flow)
 {
-    if (VLOG_IS_DBG_ENABLED()) {
-        char *actions_string = odp_actions_to_string(flow->actions,
-                                                     flow->n_actions);
-        char *flow_string = flow_to_string(&flow->key);
-        VLOG_DBG("adding flow %s with actions %s",
-                 flow_string, actions_string);
-        free(flow_string);
-        free(actions_string);
-    }
-    return IOCTL(dpif, ODP_FLOW_ADD, flow);
+    return do_flow_ioctl(dpif, ODP_FLOW_ADD, flow, "add flow", false);
 }
 
 int
@@ -423,21 +460,22 @@ dpif_flow_set_actions(struct dpif *dpif, const struct odp_flow_key *key,
     flow.key = *key;
     flow.actions = (union odp_action *) actions;
     flow.n_actions = n_actions;
-    return IOCTL(dpif, ODP_FLOW_SET_ACTS, &flow);
+    return do_flow_ioctl(dpif, ODP_FLOW_SET_ACTS, &flow, "set flow actions",
+                         false);
 }
 
 int
 dpif_flow_del(struct dpif *dpif, struct odp_flow *flow)
 {
     check_rw_odp_flow(flow);
-    return IOCTL(dpif, ODP_FLOW_DEL, flow);
+    return do_flow_ioctl(dpif, ODP_FLOW_DEL, flow, "delete flow", true);
 }
 
 int
 dpif_flow_query(const struct dpif *dpif, struct odp_flow *flow)
 {
     check_rw_odp_flow(flow);
-    return IOCTL(dpif, ODP_FLOW_QUERY, flow);
+    return do_flow_ioctl(dpif, ODP_FLOW_QUERY, flow, "query flow", true);
 }
 
 int
@@ -452,7 +490,8 @@ dpif_flow_query_multiple(const struct dpif *dpif,
     for (i = 0; i < n; i++) {
         check_rw_odp_flow(&flows[i]);
     }
-    return IOCTL(dpif, ODP_FLOW_QUERY_MULTIPLE, &fv);
+    return do_ioctl(dpif, ODP_FLOW_QUERY_MULTIPLE, "ODP_FLOW_QUERY_MULTIPLE",
+                    &fv);
 }
 
 int
@@ -473,7 +512,7 @@ dpif_flow_list(const struct dpif *dpif, struct odp_flow flows[], size_t n,
             flows[i].n_actions = 0;
         }
     }
-    error = IOCTL(dpif, ODP_FLOW_LIST, &fv);
+    error = do_ioctl(dpif, ODP_FLOW_LIST, "ODP_FLOW_LIST", &fv);
     *n_out = error ? 0 : fv.n_flows;
     return error;
 }
@@ -524,6 +563,7 @@ dpif_execute(struct dpif *dpif, uint16_t in_port,
     execute.n_actions = n_actions;
     execute.data = buf->data;
     execute.length = buf->size;
+#if 0
     if (VLOG_IS_DBG_ENABLED()) {
         char *actions_string = odp_actions_to_string(actions, n_actions);
         char *packet_string = ofp_packet_to_string(buf->data, buf->size,
@@ -533,20 +573,21 @@ dpif_execute(struct dpif *dpif, uint16_t in_port,
         free(actions_string);
         free(packet_string);
     }
-    return IOCTL(dpif, ODP_EXECUTE, &execute);
+#endif
+    return do_ioctl(dpif, ODP_EXECUTE, "ODP_EXECUTE", &execute);
 }
 
 int
 dpif_snat_add_port(struct dpif *dpif, const struct odp_snat_config *osc)
 {
-    return IOCTL(dpif, ODP_SNAT_ADD_PORT, osc);
+    return do_ioctl(dpif, ODP_SNAT_ADD_PORT, "ODP_SNAT_ADD_PORT", osc);
 }
 
 int
 dpif_snat_del_port(struct dpif *dpif, uint16_t port)
 {
     int tmp = port;
-    return IOCTL(dpif, ODP_SNAT_DEL_PORT, &tmp);
+    return do_ioctl(dpif, ODP_SNAT_DEL_PORT, "ODP_SNAT_DEL_PORT", &tmp);
 }
 
 int
@@ -963,75 +1004,6 @@ open_by_minor(unsigned int minor, struct dpif *dpif)
     return 0;
 }
 \f
-static char *
-odp_actions_to_string(const union odp_action actions[], size_t n_actions)
-{
-    struct ds ds = DS_EMPTY_INITIALIZER;
-    if (!n_actions) {
-        ds_put_cstr(&ds, "<no actions>");
-    } else {
-        const union odp_action *a;
-        for (a = actions; a < &actions[n_actions]; a++) {
-            if (a != actions) {
-                ds_put_char(&ds, ',');
-            }
-            switch (a->type) {
-            case ODPAT_OUTPUT:
-                ds_put_format(&ds, "out:%"PRIu16, a->output.port);
-                break;
-            case ODPAT_OUTPUT_GROUP:
-                ds_put_format(&ds, "group:%"PRIu16, a->output_group.group);
-                break;
-            case ODPAT_CONTROLLER:
-                ds_put_format(&ds, "controller(arg:%"PRIu32")",
-                            a->controller.arg);
-                break;
-            case ODPAT_SET_VLAN_VID:
-                ds_put_format(&ds, "vid:%"PRIu16, ntohs(a->vlan_vid.vlan_vid));
-                break;
-            case ODPAT_SET_VLAN_PCP:
-                ds_put_format(&ds, "pri:%"PRIu8, a->vlan_pcp.vlan_pcp);
-                break;
-            case ODPAT_STRIP_VLAN:
-                ds_put_cstr(&ds, "strip-vlan");
-                break;
-            case ODPAT_SET_DL_SRC:
-                ds_put_format(&ds, "dl-src:"ETH_ADDR_FMT,
-                              ETH_ADDR_ARGS(a->dl_addr.dl_addr));
-                break;
-            case ODPAT_SET_DL_DST:
-                ds_put_format(&ds, "dl-dst:"ETH_ADDR_FMT,
-                              ETH_ADDR_ARGS(a->dl_addr.dl_addr));
-                break;
-            case ODPAT_SET_NW_SRC:
-                ds_put_format(&ds, "nw-src:"IP_FMT,
-                              IP_ARGS(&a->nw_addr.nw_addr));
-                break;
-            case ODPAT_SET_NW_DST:
-                ds_put_format(&ds, "nw-dst:"IP_FMT,
-                              IP_ARGS(&a->nw_addr.nw_addr));
-                break;
-            case ODPAT_SET_TP_SRC:
-                ds_put_format(&ds, "tp-src:%"PRIu16,
-                              ntohs(a->tp_port.tp_port));
-                break;
-            case ODPAT_SET_TP_DST:
-                ds_put_format(&ds, "tp-dst:%"PRIu16,
-                              ntohs(a->tp_port.tp_port));
-                break;
-            case ODPAT_SNAT:
-                ds_put_format(&ds, "snat:%"PRIu16, a->snat.port);
-                break;
-            default:
-                ds_put_format(&ds, "unknown(%"PRIu16")", a->type);
-                break;
-            }
-        }
-
-    }
-    return ds_cstr(&ds);
-}
-
 /* There is a tendency to construct odp_flow objects on the stack and to
  * forget to properly initialize their "actions" and "n_actions" members.
  * When this happens, we get memory corruption because the kernel

diff --git a/lib/flow.c b/lib/flow.c
index 5e3898f252a75b96d12b001ee39025e5d631b231..f2eb356418c7e799b1bc357cc60a2b4d58331a69 100644 (file)
--- a/lib/flow.c
+++ b/lib/flow.c
@@ -37,6 +37,7 @@
 #include <netinet/in.h>
 #include <stdlib.h>
 #include <string.h>
+#include "dynamic-string.h"
 #include "hash.h"
 #include "ofpbuf.h"
 #include "openflow/datapath-protocol.h"
@@ -245,13 +246,21 @@ flow_from_match(flow_t *flow, uint32_t *wildcards,
 char *
 flow_to_string(const flow_t *flow)
 {
-    return xasprintf("port%04x:vlan%d mac"ETH_ADDR_FMT"->"ETH_ADDR_FMT" "
-                     "type%04x proto%"PRId8" ip"IP_FMT"->"IP_FMT" port%d->%d",
-                     flow->in_port, ntohs(flow->dl_vlan),
-                     ETH_ADDR_ARGS(flow->dl_src), ETH_ADDR_ARGS(flow->dl_dst),
-                     ntohs(flow->dl_type), flow->nw_proto,
-                     IP_ARGS(&flow->nw_src), IP_ARGS(&flow->nw_dst),
-                     ntohs(flow->tp_src), ntohs(flow->tp_dst));
+    struct ds ds = DS_EMPTY_INITIALIZER;
+    flow_format(&ds, flow);
+    return ds_cstr(&ds);
+}
+
+void
+flow_format(struct ds *ds, const flow_t *flow)
+{
+    ds_put_format(ds, "port%04x:vlan%d mac"ETH_ADDR_FMT"->"ETH_ADDR_FMT" "
+                  "type%04x proto%"PRId8" ip"IP_FMT"->"IP_FMT" port%d->%d",
+                  flow->in_port, ntohs(flow->dl_vlan),
+                  ETH_ADDR_ARGS(flow->dl_src), ETH_ADDR_ARGS(flow->dl_dst),
+                  ntohs(flow->dl_type), flow->nw_proto,
+                  IP_ARGS(&flow->nw_src), IP_ARGS(&flow->nw_dst),
+                  ntohs(flow->tp_src), ntohs(flow->tp_dst));
 }
 
 void

diff --git a/lib/flow.h b/lib/flow.h
index 967b0b03a85aeab19292c485e5d19acda8a922fc..0b65df881446f8dfacd1c539204824ea988ac219 100644 (file)
--- a/lib/flow.h
+++ b/lib/flow.h
@@ -43,6 +43,7 @@
 #include "openflow/openflow.h"
 #include "util.h"
 
+struct ds;
 struct ofp_match;
 struct ofpbuf;
 
@@ -52,6 +53,7 @@ int flow_extract(struct ofpbuf *, uint16_t in_port, flow_t *);
 void flow_to_match(const flow_t *, uint32_t wildcards, struct ofp_match *);
 void flow_from_match(flow_t *, uint32_t *wildcards, const struct ofp_match *);
 char *flow_to_string(const flow_t *);
+void flow_format(struct ds *, const flow_t *);
 void flow_print(FILE *, const flow_t *);
 static inline int flow_compare(const flow_t *, const flow_t *);
 static inline bool flow_equal(const flow_t *, const flow_t *);

diff --git a/lib/odp-util.c b/lib/odp-util.c
index 5522aec4e4376939ab28e8f98e6cce4dd0978760..4fd4e0a7a535ab151de3dc4790a3eae36c319c77 100644 (file)
--- a/lib/odp-util.c
+++ b/lib/odp-util.c
@@ -33,8 +33,13 @@
 
 #include <config.h>
 #include "odp-util.h"
+#include <inttypes.h>
 #include <stdlib.h>
 #include <string.h>
+#include "dynamic-string.h"
+#include "flow.h"
+#include "packets.h"
+#include "timeval.h"
 #include "util.h"
 
 void
@@ -66,3 +71,95 @@ odp_actions_add(struct odp_actions *actions, uint16_t type)
     return a;
 }
 
+void
+format_odp_action(struct ds *ds, const union odp_action *a)
+{
+    switch (a->type) {
+    case ODPAT_OUTPUT:
+        ds_put_format(ds, "%"PRIu16, a->output.port);
+        break;
+    case ODPAT_OUTPUT_GROUP:
+        ds_put_format(ds, "g%"PRIu16, a->output_group.group);
+        break;
+    case ODPAT_CONTROLLER:
+        ds_put_format(ds, "ctl(%"PRIu32")", a->controller.arg);
+        break;
+    case ODPAT_SET_VLAN_VID:
+        ds_put_format(ds, "set_vlan(%"PRIu16")", ntohs(a->vlan_vid.vlan_vid));
+        break;
+    case ODPAT_SET_VLAN_PCP:
+        ds_put_format(ds, "set_vlan_pcp(%"PRIu8")", a->vlan_pcp.vlan_pcp);
+        break;
+    case ODPAT_STRIP_VLAN:
+        ds_put_format(ds, "strip_vlan");
+        break;
+    case ODPAT_SET_DL_SRC:
+        ds_put_format(ds, "set_dl_src("ETH_ADDR_FMT")",
+               ETH_ADDR_ARGS(a->dl_addr.dl_addr));
+        break;
+    case ODPAT_SET_DL_DST:
+        ds_put_format(ds, "set_dl_dst("ETH_ADDR_FMT")",
+               ETH_ADDR_ARGS(a->dl_addr.dl_addr));
+        break;
+    case ODPAT_SET_NW_SRC:
+        ds_put_format(ds, "set_nw_src("IP_FMT")",
+                      IP_ARGS(&a->nw_addr.nw_addr));
+        break;
+    case ODPAT_SET_NW_DST:
+        ds_put_format(ds, "set_nw_dst("IP_FMT")",
+                      IP_ARGS(&a->nw_addr.nw_addr));
+        break;
+    case ODPAT_SET_TP_SRC:
+        ds_put_format(ds, "set_tp_src(%"PRIu16")", ntohs(a->tp_port.tp_port));
+        break;
+    case ODPAT_SET_TP_DST:
+        ds_put_format(ds, "set_tp_dst(%"PRIu16")", ntohs(a->tp_port.tp_port));
+        break;
+    case ODPAT_SNAT:
+        ds_put_format(ds, "snat(%"PRIu16")", a->snat.port);
+        break;
+    default:
+        ds_put_format(ds, "***bad action %"PRIu16"***", a->type);
+        break;
+    }
+}
+
+void
+format_odp_actions(struct ds *ds, const union odp_action *actions,
+                   size_t n_actions)
+{
+    size_t i;
+    for (i = 0; i < n_actions; i++) {
+        if (i) {
+            ds_put_char(ds, ',');
+        }
+        format_odp_action(ds, &actions[i]);
+    }
+    if (!n_actions) {
+        ds_put_cstr(ds, "drop");
+    }
+}
+
+void
+format_odp_flow_stats(struct ds *ds, const struct odp_flow_stats *s)
+{
+    ds_put_format(ds, "packets:%"PRIu64", bytes:%"PRIu64", used:",
+                  s->n_packets, s->n_bytes);
+    if (s->used_sec) {
+        long long int used = s->used_sec * 1000 + s->used_nsec / 1000000;
+        ds_put_format(ds, "%.3fs", (time_msec() - used) / 1000.0);
+    } else {
+        ds_put_format(ds, "never");
+    }
+}
+
+void
+format_odp_flow(struct ds *ds, const struct odp_flow *f)
+{
+    flow_format(ds, &f->key);
+    ds_put_cstr(ds, ", ");
+    format_odp_flow_stats(ds, &f->stats);
+    ds_put_cstr(ds, ", actions:");
+    format_odp_actions(ds, f->actions, f->n_actions);
+}
+

diff --git a/lib/odp-util.h b/lib/odp-util.h
index 3c33794ef2c1e72ad8dc8561e13eef8ed7e74301..8604fbc9cba22daa48f45bf85a16fb63e5da7b23 100644 (file)
--- a/lib/odp-util.h
+++ b/lib/odp-util.h
@@ -38,6 +38,8 @@
 #include "openflow/datapath-protocol.h"
 #include "openflow/openflow.h"
 
+struct ds;
+
 struct odp_actions {
     union odp_action *actions;
     size_t n_actions, allocated_actions;
@@ -73,4 +75,10 @@ odp_port_to_ofp_port(uint16_t odp_port)
     }
 }
 
+void format_odp_action(struct ds *, const union odp_action *);
+void format_odp_actions(struct ds *, const union odp_action *actions,
+                        size_t n_actions);
+void format_odp_flow_stats(struct ds *, const struct odp_flow_stats *);
+void format_odp_flow(struct ds *, const struct odp_flow *);
+
 #endif /* odp-util.h */