From 316989d379abadf899308e6325e452a7b49576b7 Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Fri, 13 Mar 2009 16:03:15 -0700 Subject: [PATCH] dpif: Make higher-verbosity flow logging available. --- lib/dpif.c | 192 +++++++++++++++++++++---------------------------- lib/flow.c | 23 ++++-- lib/flow.h | 2 + lib/odp-util.c | 97 +++++++++++++++++++++++++ lib/odp-util.h | 8 +++ 5 files changed, 205 insertions(+), 117 deletions(-) diff --git a/lib/dpif.c b/lib/dpif.c index 0a4c86a2..589d9746 100644 --- 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; } -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, ""); - } 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 5e3898f2..f2eb3564 100644 --- a/lib/flow.c +++ b/lib/flow.c @@ -37,6 +37,7 @@ #include #include #include +#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 967b0b03..0b65df88 100644 --- 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 5522aec4..4fd4e0a7 100644 --- a/lib/odp-util.c +++ b/lib/odp-util.c @@ -33,8 +33,13 @@ #include #include "odp-util.h" +#include #include #include +#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 3c33794e..8604fbc9 100644 --- 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 */ -- 2.30.2