| Message ID | 20211206090950.1959998-1-mheib@redhat.com |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [ovs-dev,v3] controller/pinctrl: improve packet-in debuggability | expand |
| Context | Check | Description |
|---|---|---|
| ovsrobot/apply-robot | success | apply and check: success |
| ovsrobot/github-robot-_Build_and_Test | success | github build: passed |
| ovsrobot/github-robot-_ovn-kubernetes | success | github build: passed |
On 12/6/21 10:09, Mohammad Heib wrote: > Improve packet-in debuggability within pinctrl module > by printing basic details about each received packet-in > message, those messages will be printed to the logs only > when DBG log level is enabled. > > Also, add two coverage counters that will indicate the total > packet-in messages that were received and the number of times > that the pinctrl main thread was notified to handle a change > in the local DBs, those counters can be used by the user as > an indicator to enable the DBG logs level and see more details > about the received packet-in in the logs. > > Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 > Signed-off-by: Mohammad Heib <mheib@redhat.com> > --- > controller/pinctrl.c | 39 ++++++++++++++ > include/ovn/actions.h | 1 + > lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ > tests/ovn.at | 8 +++ > 4 files changed, 171 insertions(+) > > diff --git a/controller/pinctrl.c b/controller/pinctrl.c > index 0d443c150..4ce16ac74 100644 > --- a/controller/pinctrl.c > +++ b/controller/pinctrl.c > @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); > COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); > COVERAGE_DEFINE(pinctrl_drop_controller_event); > COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); > +COVERAGE_DEFINE(pinctrl_notify_main_thread); > +COVERAGE_DEFINE(pinctrl_total_pin_pkts); > > struct empty_lb_backends_event { > struct hmap_node hmap_node; > @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > ntohl(ah->opcode)); > break; > } > + > + > + if (VLOG_IS_DBG_ENABLED()) { > + struct ds pin_str = DS_EMPTY_INITIALIZER; > + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); > + > + ds_put_format(&pin_str, > + "pinctrl received packet-in | opcode=%s", > + opc_str); > + > + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); > + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, > + ntohll(pin.cookie)); > + > + if (pin.flow_metadata.flow.in_port.ofp_port) { > + ds_put_format(&pin_str, "| in-port=%u", > + pin.flow_metadata.flow.in_port.ofp_port); > + } > + > + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", > + ETH_ADDR_ARGS(headers.dl_src)); > + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, > + ETH_ADDR_ARGS(headers.dl_dst)); > + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { > + ds_put_format(&pin_str, "| src-ip="IP_FMT",", > + IP_ARGS(headers.nw_src)); > + ds_put_format(&pin_str, " dst-ip="IP_FMT, > + IP_ARGS(headers.nw_dst)); > + } > + > + VLOG_DBG("%s \n", ds_cstr(&pin_str)); > + ds_destroy(&pin_str); > + free(opc_str); > + } > + > } > > /* Called with in the pinctrl_handler thread context. */ > @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, > config.miss_send_len = UINT16_MAX; > set_switch_config(swconn, &config); > } else if (type == OFPTYPE_PACKET_IN) { > + COVERAGE_INC(pinctrl_total_pin_pkts); > process_packet_in(swconn, oh); > } else { > if (VLOG_IS_DBG_ENABLED()) { > @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) > static void > notify_pinctrl_main(void) > { > + COVERAGE_INC(pinctrl_notify_main_thread); > seq_change(pinctrl_main_seq); > } > > diff --git a/include/ovn/actions.h b/include/ovn/actions.h > index ede5eb93c..cdef5fb03 100644 > --- a/include/ovn/actions.h > +++ b/include/ovn/actions.h > @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, > struct ofpbuf *ofpacts); > > void ovnacts_free(struct ovnact[], size_t ovnacts_len); > +char *ovnact_op_to_string(uint32_t); > > #endif /* ovn/actions.h */ > diff --git a/lib/actions.c b/lib/actions.c > index 6b9a426ae..a0ff0cb6a 100644 > --- a/lib/actions.c > +++ b/lib/actions.c > @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) > } > } > } > + > +/* Return ovn action opcode string representation. > + * The returned memory is dynamically allocated > + * and the caller must free it using free(). > + */ > + > +char * > +ovnact_op_to_string(uint32_t ovnact_opc) > +{ > + struct ds opc_str = DS_EMPTY_INITIALIZER; > + > + switch (ovnact_opc) { > + case ACTION_OPCODE_ARP: > + ds_put_cstr(&opc_str, "ARP"); > + break; > + case ACTION_OPCODE_IGMP: > + ds_put_cstr(&opc_str, "IGMP"); > + break; > + > + case ACTION_OPCODE_PUT_ARP: > + ds_put_cstr(&opc_str, "PUT_ARP"); > + break; > + > + case ACTION_OPCODE_PUT_DHCP_OPTS: > + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); > + break; > + > + case ACTION_OPCODE_ND_NA: > + ds_put_cstr(&opc_str, "ND_NA"); > + break; > + > + case ACTION_OPCODE_ND_NA_ROUTER: > + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); > + break; > + > + case ACTION_OPCODE_PUT_ND: > + ds_put_cstr(&opc_str, "PUT_ND"); > + break; > + > + case ACTION_OPCODE_PUT_FDB: > + ds_put_cstr(&opc_str, "PUT_FDB"); > + break; > + > + case ACTION_OPCODE_PUT_DHCPV6_OPTS: > + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); > + break; > + > + case ACTION_OPCODE_DNS_LOOKUP: > + ds_put_cstr(&opc_str, "DNS_LOOKUP"); > + break; > + > + case ACTION_OPCODE_LOG: > + ds_put_cstr(&opc_str, "LOG"); > + break; > + > + case ACTION_OPCODE_PUT_ND_RA_OPTS: > + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); > + break; > + > + case ACTION_OPCODE_ND_NS: > + ds_put_cstr(&opc_str, "ND_NS"); > + break; > + > + case ACTION_OPCODE_ICMP: > + ds_put_cstr(&opc_str, "ICMP"); > + break; > + > + case ACTION_OPCODE_ICMP4_ERROR: > + case ACTION_OPCODE_ICMP6_ERROR: > + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { > + ds_put_cstr(&opc_str, "ICMP4_ERROR"); > + } else { > + ds_put_cstr(&opc_str, "ICMP6_ERROR"); > + } > + break; > + > + case ACTION_OPCODE_TCP_RESET: > + ds_put_cstr(&opc_str, "TCP_RESET"); > + break; > + > + case ACTION_OPCODE_SCTP_ABORT: > + ds_put_cstr(&opc_str, "SCTP_ABORT"); > + break; > + > + case ACTION_OPCODE_REJECT: > + ds_put_cstr(&opc_str, "REJECT"); > + break; > + > + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: > + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: > + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { > + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); > + } else { > + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); > + } > + break; > + > + case ACTION_OPCODE_EVENT: > + ds_put_cstr(&opc_str, "EVENT"); > + break; > + > + case ACTION_OPCODE_BIND_VPORT: > + ds_put_cstr(&opc_str, "BIND_VPORT"); > + break; > + case ACTION_OPCODE_DHCP6_SERVER: > + ds_put_cstr(&opc_str, "DHCP6_SERVER"); > + break; > + > + case ACTION_OPCODE_HANDLE_SVC_CHECK: > + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); > + break; > + > + case ACTION_OPCODE_BFD_MSG: > + ds_put_cstr(&opc_str, "BFD_MSG"); > + break; > + > + default: > + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", > + ovnact_opc); > + break; > + } > + return ds_steal_cstr(&opc_str); > +} I didn't look at the patch from a functional standpoint, but can we replace the above function with something like this (not tested): char * ovnact_op_to_string(uint32_t ovnact_opc) { switch (ovnact_opc) { #define OVNACT(ENUM, STRUCT) \ case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); OVNACTS #undef OVNACT default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); } } ? Best regards, Ilya Maximets.
On 12/6/21 14:35, Ilya Maximets wrote: > On 12/6/21 10:09, Mohammad Heib wrote: >> Improve packet-in debuggability within pinctrl module >> by printing basic details about each received packet-in >> message, those messages will be printed to the logs only >> when DBG log level is enabled. >> >> Also, add two coverage counters that will indicate the total >> packet-in messages that were received and the number of times >> that the pinctrl main thread was notified to handle a change >> in the local DBs, those counters can be used by the user as >> an indicator to enable the DBG logs level and see more details >> about the received packet-in in the logs. >> >> Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 >> Signed-off-by: Mohammad Heib <mheib@redhat.com> >> --- >> controller/pinctrl.c | 39 ++++++++++++++ >> include/ovn/actions.h | 1 + >> lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ >> tests/ovn.at | 8 +++ >> 4 files changed, 171 insertions(+) >> >> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >> index 0d443c150..4ce16ac74 100644 >> --- a/controller/pinctrl.c >> +++ b/controller/pinctrl.c >> @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); >> COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); >> COVERAGE_DEFINE(pinctrl_drop_controller_event); >> COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); >> +COVERAGE_DEFINE(pinctrl_notify_main_thread); >> +COVERAGE_DEFINE(pinctrl_total_pin_pkts); >> >> struct empty_lb_backends_event { >> struct hmap_node hmap_node; >> @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> ntohl(ah->opcode)); >> break; >> } >> + >> + >> + if (VLOG_IS_DBG_ENABLED()) { >> + struct ds pin_str = DS_EMPTY_INITIALIZER; >> + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); >> + >> + ds_put_format(&pin_str, >> + "pinctrl received packet-in | opcode=%s", >> + opc_str); >> + >> + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); >> + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, >> + ntohll(pin.cookie)); >> + >> + if (pin.flow_metadata.flow.in_port.ofp_port) { >> + ds_put_format(&pin_str, "| in-port=%u", >> + pin.flow_metadata.flow.in_port.ofp_port); >> + } >> + >> + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", >> + ETH_ADDR_ARGS(headers.dl_src)); >> + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, >> + ETH_ADDR_ARGS(headers.dl_dst)); >> + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { >> + ds_put_format(&pin_str, "| src-ip="IP_FMT",", >> + IP_ARGS(headers.nw_src)); >> + ds_put_format(&pin_str, " dst-ip="IP_FMT, >> + IP_ARGS(headers.nw_dst)); >> + } >> + >> + VLOG_DBG("%s \n", ds_cstr(&pin_str)); >> + ds_destroy(&pin_str); >> + free(opc_str); >> + } >> + >> } >> >> /* Called with in the pinctrl_handler thread context. */ >> @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, >> config.miss_send_len = UINT16_MAX; >> set_switch_config(swconn, &config); >> } else if (type == OFPTYPE_PACKET_IN) { >> + COVERAGE_INC(pinctrl_total_pin_pkts); >> process_packet_in(swconn, oh); >> } else { >> if (VLOG_IS_DBG_ENABLED()) { >> @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) >> static void >> notify_pinctrl_main(void) >> { >> + COVERAGE_INC(pinctrl_notify_main_thread); >> seq_change(pinctrl_main_seq); >> } >> >> diff --git a/include/ovn/actions.h b/include/ovn/actions.h >> index ede5eb93c..cdef5fb03 100644 >> --- a/include/ovn/actions.h >> +++ b/include/ovn/actions.h >> @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, >> struct ofpbuf *ofpacts); >> >> void ovnacts_free(struct ovnact[], size_t ovnacts_len); >> +char *ovnact_op_to_string(uint32_t); >> >> #endif /* ovn/actions.h */ >> diff --git a/lib/actions.c b/lib/actions.c >> index 6b9a426ae..a0ff0cb6a 100644 >> --- a/lib/actions.c >> +++ b/lib/actions.c >> @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) >> } >> } >> } >> + >> +/* Return ovn action opcode string representation. >> + * The returned memory is dynamically allocated >> + * and the caller must free it using free(). >> + */ >> + >> +char * >> +ovnact_op_to_string(uint32_t ovnact_opc) >> +{ >> + struct ds opc_str = DS_EMPTY_INITIALIZER; >> + >> + switch (ovnact_opc) { >> + case ACTION_OPCODE_ARP: >> + ds_put_cstr(&opc_str, "ARP"); >> + break; >> + case ACTION_OPCODE_IGMP: >> + ds_put_cstr(&opc_str, "IGMP"); >> + break; >> + >> + case ACTION_OPCODE_PUT_ARP: >> + ds_put_cstr(&opc_str, "PUT_ARP"); >> + break; >> + >> + case ACTION_OPCODE_PUT_DHCP_OPTS: >> + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); >> + break; >> + >> + case ACTION_OPCODE_ND_NA: >> + ds_put_cstr(&opc_str, "ND_NA"); >> + break; >> + >> + case ACTION_OPCODE_ND_NA_ROUTER: >> + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); >> + break; >> + >> + case ACTION_OPCODE_PUT_ND: >> + ds_put_cstr(&opc_str, "PUT_ND"); >> + break; >> + >> + case ACTION_OPCODE_PUT_FDB: >> + ds_put_cstr(&opc_str, "PUT_FDB"); >> + break; >> + >> + case ACTION_OPCODE_PUT_DHCPV6_OPTS: >> + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); >> + break; >> + >> + case ACTION_OPCODE_DNS_LOOKUP: >> + ds_put_cstr(&opc_str, "DNS_LOOKUP"); >> + break; >> + >> + case ACTION_OPCODE_LOG: >> + ds_put_cstr(&opc_str, "LOG"); >> + break; >> + >> + case ACTION_OPCODE_PUT_ND_RA_OPTS: >> + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); >> + break; >> + >> + case ACTION_OPCODE_ND_NS: >> + ds_put_cstr(&opc_str, "ND_NS"); >> + break; >> + >> + case ACTION_OPCODE_ICMP: >> + ds_put_cstr(&opc_str, "ICMP"); >> + break; >> + >> + case ACTION_OPCODE_ICMP4_ERROR: >> + case ACTION_OPCODE_ICMP6_ERROR: >> + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { >> + ds_put_cstr(&opc_str, "ICMP4_ERROR"); >> + } else { >> + ds_put_cstr(&opc_str, "ICMP6_ERROR"); >> + } >> + break; >> + >> + case ACTION_OPCODE_TCP_RESET: >> + ds_put_cstr(&opc_str, "TCP_RESET"); >> + break; >> + >> + case ACTION_OPCODE_SCTP_ABORT: >> + ds_put_cstr(&opc_str, "SCTP_ABORT"); >> + break; >> + >> + case ACTION_OPCODE_REJECT: >> + ds_put_cstr(&opc_str, "REJECT"); >> + break; >> + >> + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >> + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >> + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >> + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); >> + } else { >> + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); >> + } >> + break; >> + >> + case ACTION_OPCODE_EVENT: >> + ds_put_cstr(&opc_str, "EVENT"); >> + break; >> + >> + case ACTION_OPCODE_BIND_VPORT: >> + ds_put_cstr(&opc_str, "BIND_VPORT"); >> + break; >> + case ACTION_OPCODE_DHCP6_SERVER: >> + ds_put_cstr(&opc_str, "DHCP6_SERVER"); >> + break; >> + >> + case ACTION_OPCODE_HANDLE_SVC_CHECK: >> + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); >> + break; >> + >> + case ACTION_OPCODE_BFD_MSG: >> + ds_put_cstr(&opc_str, "BFD_MSG"); >> + break; >> + >> + default: >> + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", >> + ovnact_opc); >> + break; >> + } >> + return ds_steal_cstr(&opc_str); >> +} > > I didn't look at the patch from a functional standpoint, but can we > replace the above function with something like this (not tested): > > char * > ovnact_op_to_string(uint32_t ovnact_opc) > { > switch (ovnact_opc) { > #define OVNACT(ENUM, STRUCT) \ > case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); > OVNACTS > #undef OVNACT > default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); > } > } > > ? Or maybe that will not work since not all actions has an opcode.... In this case, something like this should work: char * ovnact_op_to_string(uint32_t ovnact_opc) { const char *s; switch (ovnact_opc) { #define ACTION_OPCODES(ENUM) ACTION_OPCODE(ARP) \ ACTION_OPCODE(IGMP) \ ACTION_OPCODE(PUT_ARP) \ ACTION_OPCODE(PUT_DHCP_OPTS) \ ACTION_OPCODE(ND_NA) \ ACTION_OPCODE(ND_NA_ROUTER) \ ACTION_OPCODE(PUT_ND) \ ACTION_OPCODE(PUT_FDB) \ ACTION_OPCODE(PUT_DHCPV6_OPTS) \ ACTION_OPCODE(DNS_LOOKUP) \ ACTION_OPCODE(LOG) \ ACTION_OPCODE(PUT_ND_RA_OPTS) \ ACTION_OPCODE(ND_NS) \ ACTION_OPCODE(ICMP) \ ACTION_OPCODE(ICMP4_ERROR) \ ACTION_OPCODE(ICMP6_ERROR) \ ACTION_OPCODE(TCP_RESET) \ ACTION_OPCODE(SCTP_ABORT) \ ACTION_OPCODE(REJECT) \ ACTION_OPCODE(PUT_ICMP4_FRAG_MTU) \ ACTION_OPCODE(PUT_ICMP6_FRAG_MTU) \ ACTION_OPCODE(EVENT) \ ACTION_OPCODE(BIND_VPORT) \ ACTION_OPCODE(DHCP6_SERVER) \ ACTION_OPCODE(HANDLE_SVC_CHECK) \ ACTION_OPCODE(BFD_MSG) #define ACTION_OPCODE(ENUM) \ case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); ACTION_OPCODES #undef ACTION_OPCODE default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); } return xstrdup(s); } Should be easier to track and modify in the future. > > Best regards, Ilya Maximets. >
On 12/6/21 15:01, Ilya Maximets wrote: > On 12/6/21 14:35, Ilya Maximets wrote: >> On 12/6/21 10:09, Mohammad Heib wrote: >>> Improve packet-in debuggability within pinctrl module >>> by printing basic details about each received packet-in >>> message, those messages will be printed to the logs only >>> when DBG log level is enabled. >>> >>> Also, add two coverage counters that will indicate the total >>> packet-in messages that were received and the number of times >>> that the pinctrl main thread was notified to handle a change >>> in the local DBs, those counters can be used by the user as >>> an indicator to enable the DBG logs level and see more details >>> about the received packet-in in the logs. >>> >>> Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 >>> Signed-off-by: Mohammad Heib <mheib@redhat.com> >>> --- >>> controller/pinctrl.c | 39 ++++++++++++++ >>> include/ovn/actions.h | 1 + >>> lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ >>> tests/ovn.at | 8 +++ >>> 4 files changed, 171 insertions(+) >>> >>> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >>> index 0d443c150..4ce16ac74 100644 >>> --- a/controller/pinctrl.c >>> +++ b/controller/pinctrl.c >>> @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); >>> COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); >>> COVERAGE_DEFINE(pinctrl_drop_controller_event); >>> COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); >>> +COVERAGE_DEFINE(pinctrl_notify_main_thread); >>> +COVERAGE_DEFINE(pinctrl_total_pin_pkts); >>> >>> struct empty_lb_backends_event { >>> struct hmap_node hmap_node; >>> @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >>> ntohl(ah->opcode)); >>> break; >>> } >>> + >>> + >>> + if (VLOG_IS_DBG_ENABLED()) { >>> + struct ds pin_str = DS_EMPTY_INITIALIZER; >>> + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); >>> + >>> + ds_put_format(&pin_str, >>> + "pinctrl received packet-in | opcode=%s", >>> + opc_str); >>> + >>> + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); >>> + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, >>> + ntohll(pin.cookie)); >>> + >>> + if (pin.flow_metadata.flow.in_port.ofp_port) { >>> + ds_put_format(&pin_str, "| in-port=%u", >>> + pin.flow_metadata.flow.in_port.ofp_port); >>> + } >>> + >>> + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", >>> + ETH_ADDR_ARGS(headers.dl_src)); >>> + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, >>> + ETH_ADDR_ARGS(headers.dl_dst)); >>> + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { >>> + ds_put_format(&pin_str, "| src-ip="IP_FMT",", >>> + IP_ARGS(headers.nw_src)); >>> + ds_put_format(&pin_str, " dst-ip="IP_FMT, >>> + IP_ARGS(headers.nw_dst)); >>> + } >>> + >>> + VLOG_DBG("%s \n", ds_cstr(&pin_str)); >>> + ds_destroy(&pin_str); >>> + free(opc_str); >>> + } >>> + >>> } >>> >>> /* Called with in the pinctrl_handler thread context. */ >>> @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, >>> config.miss_send_len = UINT16_MAX; >>> set_switch_config(swconn, &config); >>> } else if (type == OFPTYPE_PACKET_IN) { >>> + COVERAGE_INC(pinctrl_total_pin_pkts); >>> process_packet_in(swconn, oh); >>> } else { >>> if (VLOG_IS_DBG_ENABLED()) { >>> @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) >>> static void >>> notify_pinctrl_main(void) >>> { >>> + COVERAGE_INC(pinctrl_notify_main_thread); >>> seq_change(pinctrl_main_seq); >>> } >>> >>> diff --git a/include/ovn/actions.h b/include/ovn/actions.h >>> index ede5eb93c..cdef5fb03 100644 >>> --- a/include/ovn/actions.h >>> +++ b/include/ovn/actions.h >>> @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, >>> struct ofpbuf *ofpacts); >>> >>> void ovnacts_free(struct ovnact[], size_t ovnacts_len); >>> +char *ovnact_op_to_string(uint32_t); >>> >>> #endif /* ovn/actions.h */ >>> diff --git a/lib/actions.c b/lib/actions.c >>> index 6b9a426ae..a0ff0cb6a 100644 >>> --- a/lib/actions.c >>> +++ b/lib/actions.c >>> @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) >>> } >>> } >>> } >>> + >>> +/* Return ovn action opcode string representation. >>> + * The returned memory is dynamically allocated >>> + * and the caller must free it using free(). >>> + */ >>> + >>> +char * >>> +ovnact_op_to_string(uint32_t ovnact_opc) >>> +{ >>> + struct ds opc_str = DS_EMPTY_INITIALIZER; >>> + >>> + switch (ovnact_opc) { >>> + case ACTION_OPCODE_ARP: >>> + ds_put_cstr(&opc_str, "ARP"); >>> + break; >>> + case ACTION_OPCODE_IGMP: >>> + ds_put_cstr(&opc_str, "IGMP"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_ARP: >>> + ds_put_cstr(&opc_str, "PUT_ARP"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_DHCP_OPTS: >>> + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); >>> + break; >>> + >>> + case ACTION_OPCODE_ND_NA: >>> + ds_put_cstr(&opc_str, "ND_NA"); >>> + break; >>> + >>> + case ACTION_OPCODE_ND_NA_ROUTER: >>> + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_ND: >>> + ds_put_cstr(&opc_str, "PUT_ND"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_FDB: >>> + ds_put_cstr(&opc_str, "PUT_FDB"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_DHCPV6_OPTS: >>> + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); >>> + break; >>> + >>> + case ACTION_OPCODE_DNS_LOOKUP: >>> + ds_put_cstr(&opc_str, "DNS_LOOKUP"); >>> + break; >>> + >>> + case ACTION_OPCODE_LOG: >>> + ds_put_cstr(&opc_str, "LOG"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_ND_RA_OPTS: >>> + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); >>> + break; >>> + >>> + case ACTION_OPCODE_ND_NS: >>> + ds_put_cstr(&opc_str, "ND_NS"); >>> + break; >>> + >>> + case ACTION_OPCODE_ICMP: >>> + ds_put_cstr(&opc_str, "ICMP"); >>> + break; >>> + >>> + case ACTION_OPCODE_ICMP4_ERROR: >>> + case ACTION_OPCODE_ICMP6_ERROR: >>> + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { >>> + ds_put_cstr(&opc_str, "ICMP4_ERROR"); >>> + } else { >>> + ds_put_cstr(&opc_str, "ICMP6_ERROR"); >>> + } >>> + break; >>> + >>> + case ACTION_OPCODE_TCP_RESET: >>> + ds_put_cstr(&opc_str, "TCP_RESET"); >>> + break; >>> + >>> + case ACTION_OPCODE_SCTP_ABORT: >>> + ds_put_cstr(&opc_str, "SCTP_ABORT"); >>> + break; >>> + >>> + case ACTION_OPCODE_REJECT: >>> + ds_put_cstr(&opc_str, "REJECT"); >>> + break; >>> + >>> + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >>> + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >>> + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >>> + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); >>> + } else { >>> + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); >>> + } >>> + break; >>> + >>> + case ACTION_OPCODE_EVENT: >>> + ds_put_cstr(&opc_str, "EVENT"); >>> + break; >>> + >>> + case ACTION_OPCODE_BIND_VPORT: >>> + ds_put_cstr(&opc_str, "BIND_VPORT"); >>> + break; >>> + case ACTION_OPCODE_DHCP6_SERVER: >>> + ds_put_cstr(&opc_str, "DHCP6_SERVER"); >>> + break; >>> + >>> + case ACTION_OPCODE_HANDLE_SVC_CHECK: >>> + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); >>> + break; >>> + >>> + case ACTION_OPCODE_BFD_MSG: >>> + ds_put_cstr(&opc_str, "BFD_MSG"); >>> + break; >>> + >>> + default: >>> + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", >>> + ovnact_opc); >>> + break; >>> + } >>> + return ds_steal_cstr(&opc_str); >>> +} >> >> I didn't look at the patch from a functional standpoint, but can we >> replace the above function with something like this (not tested): >> >> char * >> ovnact_op_to_string(uint32_t ovnact_opc) >> { >> switch (ovnact_opc) { >> #define OVNACT(ENUM, STRUCT) \ >> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >> OVNACTS >> #undef OVNACT >> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >> } >> } >> >> ? > > Or maybe that will not work since not all actions has an opcode.... > > In this case, something like this should work: > > char * > ovnact_op_to_string(uint32_t ovnact_opc) > { > const char *s; > > switch (ovnact_opc) { > #define ACTION_OPCODES(ENUM) > ACTION_OPCODE(ARP) \ > ACTION_OPCODE(IGMP) \ > ACTION_OPCODE(PUT_ARP) \ > ACTION_OPCODE(PUT_DHCP_OPTS) \ > ACTION_OPCODE(ND_NA) \ > ACTION_OPCODE(ND_NA_ROUTER) \ > ACTION_OPCODE(PUT_ND) \ > ACTION_OPCODE(PUT_FDB) \ > ACTION_OPCODE(PUT_DHCPV6_OPTS) \ > ACTION_OPCODE(DNS_LOOKUP) \ > ACTION_OPCODE(LOG) \ > ACTION_OPCODE(PUT_ND_RA_OPTS) \ > ACTION_OPCODE(ND_NS) \ > ACTION_OPCODE(ICMP) \ > ACTION_OPCODE(ICMP4_ERROR) \ > ACTION_OPCODE(ICMP6_ERROR) \ > ACTION_OPCODE(TCP_RESET) \ > ACTION_OPCODE(SCTP_ABORT) \ > ACTION_OPCODE(REJECT) \ > ACTION_OPCODE(PUT_ICMP4_FRAG_MTU) \ > ACTION_OPCODE(PUT_ICMP6_FRAG_MTU) \ > ACTION_OPCODE(EVENT) \ > ACTION_OPCODE(BIND_VPORT) \ > ACTION_OPCODE(DHCP6_SERVER) \ > ACTION_OPCODE(HANDLE_SVC_CHECK) \ > ACTION_OPCODE(BFD_MSG) > #define ACTION_OPCODE(ENUM) \ > case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); > ACTION_OPCODES > #undef ACTION_OPCODE > default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); > } > return xstrdup(s); And this line is obviously not needed. Ugh. And sorry for the trailing whitespaces. > } > > Should be easier to track and modify in the future. > >> >> Best regards, Ilya Maximets. >> >
On 12/6/21 4:08 PM, Ilya Maximets wrote: > On 12/6/21 15:01, Ilya Maximets wrote: >> On 12/6/21 14:35, Ilya Maximets wrote: >>> On 12/6/21 10:09, Mohammad Heib wrote: >>>> Improve packet-in debuggability within pinctrl module >>>> by printing basic details about each received packet-in >>>> message, those messages will be printed to the logs only >>>> when DBG log level is enabled. >>>> >>>> Also, add two coverage counters that will indicate the total >>>> packet-in messages that were received and the number of times >>>> that the pinctrl main thread was notified to handle a change >>>> in the local DBs, those counters can be used by the user as >>>> an indicator to enable the DBG logs level and see more details >>>> about the received packet-in in the logs. >>>> >>>> Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 >>>> Signed-off-by: Mohammad Heib <mheib@redhat.com> >>>> --- >>>> controller/pinctrl.c | 39 ++++++++++++++ >>>> include/ovn/actions.h | 1 + >>>> lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ >>>> tests/ovn.at | 8 +++ >>>> 4 files changed, 171 insertions(+) >>>> >>>> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >>>> index 0d443c150..4ce16ac74 100644 >>>> --- a/controller/pinctrl.c >>>> +++ b/controller/pinctrl.c >>>> @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); >>>> COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); >>>> COVERAGE_DEFINE(pinctrl_drop_controller_event); >>>> COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); >>>> +COVERAGE_DEFINE(pinctrl_notify_main_thread); >>>> +COVERAGE_DEFINE(pinctrl_total_pin_pkts); >>>> >>>> struct empty_lb_backends_event { >>>> struct hmap_node hmap_node; >>>> @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >>>> ntohl(ah->opcode)); >>>> break; >>>> } >>>> + >>>> + >>>> + if (VLOG_IS_DBG_ENABLED()) { >>>> + struct ds pin_str = DS_EMPTY_INITIALIZER; >>>> + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); >>>> + >>>> + ds_put_format(&pin_str, >>>> + "pinctrl received packet-in | opcode=%s", >>>> + opc_str); >>>> + >>>> + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); >>>> + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, >>>> + ntohll(pin.cookie)); >>>> + >>>> + if (pin.flow_metadata.flow.in_port.ofp_port) { >>>> + ds_put_format(&pin_str, "| in-port=%u", >>>> + pin.flow_metadata.flow.in_port.ofp_port); >>>> + } >>>> + >>>> + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", >>>> + ETH_ADDR_ARGS(headers.dl_src)); >>>> + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, >>>> + ETH_ADDR_ARGS(headers.dl_dst)); >>>> + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { >>>> + ds_put_format(&pin_str, "| src-ip="IP_FMT",", >>>> + IP_ARGS(headers.nw_src)); >>>> + ds_put_format(&pin_str, " dst-ip="IP_FMT, >>>> + IP_ARGS(headers.nw_dst)); >>>> + } >>>> + >>>> + VLOG_DBG("%s \n", ds_cstr(&pin_str)); >>>> + ds_destroy(&pin_str); >>>> + free(opc_str); >>>> + } >>>> + >>>> } >>>> >>>> /* Called with in the pinctrl_handler thread context. */ >>>> @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, >>>> config.miss_send_len = UINT16_MAX; >>>> set_switch_config(swconn, &config); >>>> } else if (type == OFPTYPE_PACKET_IN) { >>>> + COVERAGE_INC(pinctrl_total_pin_pkts); >>>> process_packet_in(swconn, oh); >>>> } else { >>>> if (VLOG_IS_DBG_ENABLED()) { >>>> @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) >>>> static void >>>> notify_pinctrl_main(void) >>>> { >>>> + COVERAGE_INC(pinctrl_notify_main_thread); >>>> seq_change(pinctrl_main_seq); >>>> } >>>> >>>> diff --git a/include/ovn/actions.h b/include/ovn/actions.h >>>> index ede5eb93c..cdef5fb03 100644 >>>> --- a/include/ovn/actions.h >>>> +++ b/include/ovn/actions.h >>>> @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, >>>> struct ofpbuf *ofpacts); >>>> >>>> void ovnacts_free(struct ovnact[], size_t ovnacts_len); >>>> +char *ovnact_op_to_string(uint32_t); >>>> >>>> #endif /* ovn/actions.h */ >>>> diff --git a/lib/actions.c b/lib/actions.c >>>> index 6b9a426ae..a0ff0cb6a 100644 >>>> --- a/lib/actions.c >>>> +++ b/lib/actions.c >>>> @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) >>>> } >>>> } >>>> } >>>> + >>>> +/* Return ovn action opcode string representation. >>>> + * The returned memory is dynamically allocated >>>> + * and the caller must free it using free(). >>>> + */ >>>> + >>>> +char * >>>> +ovnact_op_to_string(uint32_t ovnact_opc) >>>> +{ >>>> + struct ds opc_str = DS_EMPTY_INITIALIZER; >>>> + >>>> + switch (ovnact_opc) { >>>> + case ACTION_OPCODE_ARP: >>>> + ds_put_cstr(&opc_str, "ARP"); >>>> + break; >>>> + case ACTION_OPCODE_IGMP: >>>> + ds_put_cstr(&opc_str, "IGMP"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_ARP: >>>> + ds_put_cstr(&opc_str, "PUT_ARP"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_DHCP_OPTS: >>>> + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_ND_NA: >>>> + ds_put_cstr(&opc_str, "ND_NA"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_ND_NA_ROUTER: >>>> + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_ND: >>>> + ds_put_cstr(&opc_str, "PUT_ND"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_FDB: >>>> + ds_put_cstr(&opc_str, "PUT_FDB"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_DHCPV6_OPTS: >>>> + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_DNS_LOOKUP: >>>> + ds_put_cstr(&opc_str, "DNS_LOOKUP"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_LOG: >>>> + ds_put_cstr(&opc_str, "LOG"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_ND_RA_OPTS: >>>> + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_ND_NS: >>>> + ds_put_cstr(&opc_str, "ND_NS"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_ICMP: >>>> + ds_put_cstr(&opc_str, "ICMP"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_ICMP4_ERROR: >>>> + case ACTION_OPCODE_ICMP6_ERROR: >>>> + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { >>>> + ds_put_cstr(&opc_str, "ICMP4_ERROR"); >>>> + } else { >>>> + ds_put_cstr(&opc_str, "ICMP6_ERROR"); >>>> + } >>>> + break; >>>> + >>>> + case ACTION_OPCODE_TCP_RESET: >>>> + ds_put_cstr(&opc_str, "TCP_RESET"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_SCTP_ABORT: >>>> + ds_put_cstr(&opc_str, "SCTP_ABORT"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_REJECT: >>>> + ds_put_cstr(&opc_str, "REJECT"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >>>> + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >>>> + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >>>> + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); >>>> + } else { >>>> + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); >>>> + } >>>> + break; >>>> + >>>> + case ACTION_OPCODE_EVENT: >>>> + ds_put_cstr(&opc_str, "EVENT"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_BIND_VPORT: >>>> + ds_put_cstr(&opc_str, "BIND_VPORT"); >>>> + break; >>>> + case ACTION_OPCODE_DHCP6_SERVER: >>>> + ds_put_cstr(&opc_str, "DHCP6_SERVER"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_HANDLE_SVC_CHECK: >>>> + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); >>>> + break; >>>> + >>>> + case ACTION_OPCODE_BFD_MSG: >>>> + ds_put_cstr(&opc_str, "BFD_MSG"); >>>> + break; >>>> + >>>> + default: >>>> + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", >>>> + ovnact_opc); >>>> + break; >>>> + } >>>> + return ds_steal_cstr(&opc_str); >>>> +} >>> I didn't look at the patch from a functional standpoint, but can we >>> replace the above function with something like this (not tested): Hi Ilya, thank you for the review. i submitted a new version <https://patchwork.ozlabs.org/project/ovn/patch/20211208135954.425965-1-mheib@redhat.com/> with your proposed changes. >>> >>> char * >>> ovnact_op_to_string(uint32_t ovnact_opc) >>> { >>> switch (ovnact_opc) { >>> #define OVNACT(ENUM, STRUCT) \ >>> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >>> OVNACTS >>> #undef OVNACT >>> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >>> } >>> } >>> >>> ? >> Or maybe that will not work since not all actions has an opcode.... >> >> In this case, something like this should work: >> >> char * >> ovnact_op_to_string(uint32_t ovnact_opc) >> { >> const char *s; >> >> switch (ovnact_opc) { >> #define ACTION_OPCODES(ENUM) i guess (ENUM) is redundant here? >> >> ACTION_OPCODE(ARP) \ >> ACTION_OPCODE(IGMP) \ >> ACTION_OPCODE(PUT_ARP) \ >> ACTION_OPCODE(PUT_DHCP_OPTS) \ >> ACTION_OPCODE(ND_NA) \ >> ACTION_OPCODE(ND_NA_ROUTER) \ >> ACTION_OPCODE(PUT_ND) \ >> ACTION_OPCODE(PUT_FDB) \ >> ACTION_OPCODE(PUT_DHCPV6_OPTS) \ >> ACTION_OPCODE(DNS_LOOKUP) \ >> ACTION_OPCODE(LOG) \ >> ACTION_OPCODE(PUT_ND_RA_OPTS) \ >> ACTION_OPCODE(ND_NS) \ >> ACTION_OPCODE(ICMP) \ >> ACTION_OPCODE(ICMP4_ERROR) \ >> ACTION_OPCODE(ICMP6_ERROR) \ >> ACTION_OPCODE(TCP_RESET) \ >> ACTION_OPCODE(SCTP_ABORT) \ >> ACTION_OPCODE(REJECT) \ >> ACTION_OPCODE(PUT_ICMP4_FRAG_MTU) \ >> ACTION_OPCODE(PUT_ICMP6_FRAG_MTU) \ >> ACTION_OPCODE(EVENT) \ >> ACTION_OPCODE(BIND_VPORT) \ >> ACTION_OPCODE(DHCP6_SERVER) \ >> ACTION_OPCODE(HANDLE_SVC_CHECK) \ >> ACTION_OPCODE(BFD_MSG) >> #define ACTION_OPCODE(ENUM) \ >> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >> ACTION_OPCODES >> #undef ACTION_OPCODE >> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >> } >> return xstrdup(s); it was a bit complicated for me to understand the macros so if you please can take a look and see if it's implemented properly. > And this line is obviously not needed. Ugh. > And sorry for the trailing whitespaces. > thanks :) >> } >> >> Should be easier to track and modify in the future. >> >>> Best regards, Ilya Maximets. >>>
On 12/8/21 15:11, Mohammad Heib wrote: > > On 12/6/21 4:08 PM, Ilya Maximets wrote: >> On 12/6/21 15:01, Ilya Maximets wrote: >>> On 12/6/21 14:35, Ilya Maximets wrote: >>>> On 12/6/21 10:09, Mohammad Heib wrote: >>>>> Improve packet-in debuggability within pinctrl module >>>>> by printing basic details about each received packet-in >>>>> message, those messages will be printed to the logs only >>>>> when DBG log level is enabled. >>>>> >>>>> Also, add two coverage counters that will indicate the total >>>>> packet-in messages that were received and the number of times >>>>> that the pinctrl main thread was notified to handle a change >>>>> in the local DBs, those counters can be used by the user as >>>>> an indicator to enable the DBG logs level and see more details >>>>> about the received packet-in in the logs. >>>>> >>>>> Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 >>>>> Signed-off-by: Mohammad Heib <mheib@redhat.com> >>>>> --- >>>>> controller/pinctrl.c | 39 ++++++++++++++ >>>>> include/ovn/actions.h | 1 + >>>>> lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ >>>>> tests/ovn.at | 8 +++ >>>>> 4 files changed, 171 insertions(+) >>>>> >>>>> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >>>>> index 0d443c150..4ce16ac74 100644 >>>>> --- a/controller/pinctrl.c >>>>> +++ b/controller/pinctrl.c >>>>> @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); >>>>> COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); >>>>> COVERAGE_DEFINE(pinctrl_drop_controller_event); >>>>> COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); >>>>> +COVERAGE_DEFINE(pinctrl_notify_main_thread); >>>>> +COVERAGE_DEFINE(pinctrl_total_pin_pkts); >>>>> >>>>> struct empty_lb_backends_event { >>>>> struct hmap_node hmap_node; >>>>> @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >>>>> ntohl(ah->opcode)); >>>>> break; >>>>> } >>>>> + >>>>> + >>>>> + if (VLOG_IS_DBG_ENABLED()) { >>>>> + struct ds pin_str = DS_EMPTY_INITIALIZER; >>>>> + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); >>>>> + >>>>> + ds_put_format(&pin_str, >>>>> + "pinctrl received packet-in | opcode=%s", >>>>> + opc_str); >>>>> + >>>>> + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); >>>>> + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, >>>>> + ntohll(pin.cookie)); >>>>> + >>>>> + if (pin.flow_metadata.flow.in_port.ofp_port) { >>>>> + ds_put_format(&pin_str, "| in-port=%u", >>>>> + pin.flow_metadata.flow.in_port.ofp_port); >>>>> + } >>>>> + >>>>> + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", >>>>> + ETH_ADDR_ARGS(headers.dl_src)); >>>>> + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, >>>>> + ETH_ADDR_ARGS(headers.dl_dst)); >>>>> + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { >>>>> + ds_put_format(&pin_str, "| src-ip="IP_FMT",", >>>>> + IP_ARGS(headers.nw_src)); >>>>> + ds_put_format(&pin_str, " dst-ip="IP_FMT, >>>>> + IP_ARGS(headers.nw_dst)); >>>>> + } >>>>> + >>>>> + VLOG_DBG("%s \n", ds_cstr(&pin_str)); >>>>> + ds_destroy(&pin_str); >>>>> + free(opc_str); >>>>> + } >>>>> + >>>>> } >>>>> >>>>> /* Called with in the pinctrl_handler thread context. */ >>>>> @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, >>>>> config.miss_send_len = UINT16_MAX; >>>>> set_switch_config(swconn, &config); >>>>> } else if (type == OFPTYPE_PACKET_IN) { >>>>> + COVERAGE_INC(pinctrl_total_pin_pkts); >>>>> process_packet_in(swconn, oh); >>>>> } else { >>>>> if (VLOG_IS_DBG_ENABLED()) { >>>>> @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) >>>>> static void >>>>> notify_pinctrl_main(void) >>>>> { >>>>> + COVERAGE_INC(pinctrl_notify_main_thread); >>>>> seq_change(pinctrl_main_seq); >>>>> } >>>>> >>>>> diff --git a/include/ovn/actions.h b/include/ovn/actions.h >>>>> index ede5eb93c..cdef5fb03 100644 >>>>> --- a/include/ovn/actions.h >>>>> +++ b/include/ovn/actions.h >>>>> @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, >>>>> struct ofpbuf *ofpacts); >>>>> >>>>> void ovnacts_free(struct ovnact[], size_t ovnacts_len); >>>>> +char *ovnact_op_to_string(uint32_t); >>>>> >>>>> #endif /* ovn/actions.h */ >>>>> diff --git a/lib/actions.c b/lib/actions.c >>>>> index 6b9a426ae..a0ff0cb6a 100644 >>>>> --- a/lib/actions.c >>>>> +++ b/lib/actions.c >>>>> @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) >>>>> } >>>>> } >>>>> } >>>>> + >>>>> +/* Return ovn action opcode string representation. >>>>> + * The returned memory is dynamically allocated >>>>> + * and the caller must free it using free(). >>>>> + */ >>>>> + >>>>> +char * >>>>> +ovnact_op_to_string(uint32_t ovnact_opc) >>>>> +{ >>>>> + struct ds opc_str = DS_EMPTY_INITIALIZER; >>>>> + >>>>> + switch (ovnact_opc) { >>>>> + case ACTION_OPCODE_ARP: >>>>> + ds_put_cstr(&opc_str, "ARP"); >>>>> + break; >>>>> + case ACTION_OPCODE_IGMP: >>>>> + ds_put_cstr(&opc_str, "IGMP"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_ARP: >>>>> + ds_put_cstr(&opc_str, "PUT_ARP"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_DHCP_OPTS: >>>>> + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_ND_NA: >>>>> + ds_put_cstr(&opc_str, "ND_NA"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_ND_NA_ROUTER: >>>>> + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_ND: >>>>> + ds_put_cstr(&opc_str, "PUT_ND"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_FDB: >>>>> + ds_put_cstr(&opc_str, "PUT_FDB"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_DHCPV6_OPTS: >>>>> + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_DNS_LOOKUP: >>>>> + ds_put_cstr(&opc_str, "DNS_LOOKUP"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_LOG: >>>>> + ds_put_cstr(&opc_str, "LOG"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_ND_RA_OPTS: >>>>> + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_ND_NS: >>>>> + ds_put_cstr(&opc_str, "ND_NS"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_ICMP: >>>>> + ds_put_cstr(&opc_str, "ICMP"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_ICMP4_ERROR: >>>>> + case ACTION_OPCODE_ICMP6_ERROR: >>>>> + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { >>>>> + ds_put_cstr(&opc_str, "ICMP4_ERROR"); >>>>> + } else { >>>>> + ds_put_cstr(&opc_str, "ICMP6_ERROR"); >>>>> + } >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_TCP_RESET: >>>>> + ds_put_cstr(&opc_str, "TCP_RESET"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_SCTP_ABORT: >>>>> + ds_put_cstr(&opc_str, "SCTP_ABORT"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_REJECT: >>>>> + ds_put_cstr(&opc_str, "REJECT"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >>>>> + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >>>>> + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >>>>> + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); >>>>> + } else { >>>>> + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); >>>>> + } >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_EVENT: >>>>> + ds_put_cstr(&opc_str, "EVENT"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_BIND_VPORT: >>>>> + ds_put_cstr(&opc_str, "BIND_VPORT"); >>>>> + break; >>>>> + case ACTION_OPCODE_DHCP6_SERVER: >>>>> + ds_put_cstr(&opc_str, "DHCP6_SERVER"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_HANDLE_SVC_CHECK: >>>>> + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); >>>>> + break; >>>>> + >>>>> + case ACTION_OPCODE_BFD_MSG: >>>>> + ds_put_cstr(&opc_str, "BFD_MSG"); >>>>> + break; >>>>> + >>>>> + default: >>>>> + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", >>>>> + ovnact_opc); >>>>> + break; >>>>> + } >>>>> + return ds_steal_cstr(&opc_str); >>>>> +} >>>> I didn't look at the patch from a functional standpoint, but can we >>>> replace the above function with something like this (not tested): > > Hi Ilya, > thank you for the review. > i submitted a new version <https://patchwork.ozlabs.org/project/ovn/patch/20211208135954.425965-1-mheib@redhat.com/> with your proposed changes. > >>>> char * >>>> ovnact_op_to_string(uint32_t ovnact_opc) >>>> { >>>> switch (ovnact_opc) { >>>> #define OVNACT(ENUM, STRUCT) \ >>>> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >>>> OVNACTS >>>> #undef OVNACT >>>> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >>>> } >>>> } >>>> >>>> ? >>> Or maybe that will not work since not all actions has an opcode.... >>> >>> In this case, something like this should work: >>> >>> char * >>> ovnact_op_to_string(uint32_t ovnact_opc) >>> { >>> const char *s; >>> >>> switch (ovnact_opc) { >>> #define ACTION_OPCODES(ENUM) > i guess (ENUM) is redundant here? Yep. >>> >>> ACTION_OPCODE(ARP) \ >>> ACTION_OPCODE(IGMP) \ >>> ACTION_OPCODE(PUT_ARP) \ >>> ACTION_OPCODE(PUT_DHCP_OPTS) \ >>> ACTION_OPCODE(ND_NA) \ >>> ACTION_OPCODE(ND_NA_ROUTER) \ >>> ACTION_OPCODE(PUT_ND) \ >>> ACTION_OPCODE(PUT_FDB) \ >>> ACTION_OPCODE(PUT_DHCPV6_OPTS) \ >>> ACTION_OPCODE(DNS_LOOKUP) \ >>> ACTION_OPCODE(LOG) \ >>> ACTION_OPCODE(PUT_ND_RA_OPTS) \ >>> ACTION_OPCODE(ND_NS) \ >>> ACTION_OPCODE(ICMP) \ >>> ACTION_OPCODE(ICMP4_ERROR) \ >>> ACTION_OPCODE(ICMP6_ERROR) \ >>> ACTION_OPCODE(TCP_RESET) \ >>> ACTION_OPCODE(SCTP_ABORT) \ >>> ACTION_OPCODE(REJECT) \ >>> ACTION_OPCODE(PUT_ICMP4_FRAG_MTU) \ >>> ACTION_OPCODE(PUT_ICMP6_FRAG_MTU) \ >>> ACTION_OPCODE(EVENT) \ >>> ACTION_OPCODE(BIND_VPORT) \ >>> ACTION_OPCODE(DHCP6_SERVER) \ >>> ACTION_OPCODE(HANDLE_SVC_CHECK) \ >>> ACTION_OPCODE(BFD_MSG) >>> #define ACTION_OPCODE(ENUM) \ >>> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >>> ACTION_OPCODES >>> #undef ACTION_OPCODE >>> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >>> } >>> return xstrdup(s); > > it was a bit complicated for me to understand the macros so if you please can take a look > and see if it's implemented properly. Seems correct. In general, to test tricky macros, you may just invoke a preprocessor and look at the final result. For OVN it will be something like this: gcc -E lib/actions.c -I ./include -I ./lib -I./ -I./ovs -I./ovs/lib -I./ovs/include | less To make the code even better, we need to use this trick directly on the 'enum action_opcode', so we will have all the definitions in the same place and will not need to remember that we need to adjust the to_string function every time the enum changed. It should look like this: diff --git a/include/ovn/actions.h b/include/ovn/actions.h index ede5eb93c..668210834 100644 --- a/include/ovn/actions.h +++ b/include/ovn/actions.h @@ -500,XX +500,XX @@ void *ovnact_put(struct ofpbuf *, enum ovnact_type, size_t len); OVNACTS #undef OVNACT -enum action_opcode { - /* "arp { ...actions... }". - * - * The actions, in OpenFlow 1.3 format, follow the action_header. - */ - ACTION_OPCODE_ARP, - - /* "put_arp(port, ip, mac)" - * - * Arguments are passed through the packet metadata and data, as follows: - * - * MFF_REG0 = ip - * MFF_LOG_INPORT = port - * MFF_ETH_SRC = mac - */ - ACTION_OPCODE_PUT_ARP, - - <........> - +#define ACTION_OPCODES \ + /* "arp { ...actions... }". \ + * \ + * The actions, in OpenFlow 1.3 format, follow the action_header. \ + */ \ + ACTION_OPCODE(ARP) \ + \ + /* "put_arp(port, ip, mac)" \ + * \ + * Arguments are passed through the packet metadata and data, as follows: \ + * \ + * MFF_REG0 = ip \ + * MFF_LOG_INPORT = port \ + * MFF_ETH_SRC = mac \ + */ \ + ACTION_OPCODE(PUT_ARP) \ + \ + <........> \ + + +enum action_opcode { +#define ACTION_OPCODE(NAME) ACTION_OPCODE_##NAME, + ACTION_OPCODES +#undef ACTION_OPCODE +}; --- After that you may re-use the 'ACTION_OPCODES' macro inside the ovnact_op_to_string() without re-defining. This is something that definitely needs to be done, but I'm not sure if that needs to be done in this patch. Maybe as a separate patch/prerequisite to this one. Best regards, Ilya Maximets. >> And this line is obviously not needed. Ugh. >> And sorry for the trailing whitespaces. >> > thanks :) >>> } >>> >>> Should be easier to track and modify in the future. >>> >>>> Best regards, Ilya Maximets. >>>>
On 12/8/21 5:26 PM, Ilya Maximets wrote: > On 12/8/21 15:11, Mohammad Heib wrote: >> On 12/6/21 4:08 PM, Ilya Maximets wrote: >>> On 12/6/21 15:01, Ilya Maximets wrote: >>>> On 12/6/21 14:35, Ilya Maximets wrote: >>>>> On 12/6/21 10:09, Mohammad Heib wrote: >>>>>> Improve packet-in debuggability within pinctrl module >>>>>> by printing basic details about each received packet-in >>>>>> message, those messages will be printed to the logs only >>>>>> when DBG log level is enabled. >>>>>> >>>>>> Also, add two coverage counters that will indicate the total >>>>>> packet-in messages that were received and the number of times >>>>>> that the pinctrl main thread was notified to handle a change >>>>>> in the local DBs, those counters can be used by the user as >>>>>> an indicator to enable the DBG logs level and see more details >>>>>> about the received packet-in in the logs. >>>>>> >>>>>> Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 >>>>>> Signed-off-by: Mohammad Heib <mheib@redhat.com> >>>>>> --- >>>>>> controller/pinctrl.c | 39 ++++++++++++++ >>>>>> include/ovn/actions.h | 1 + >>>>>> lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ >>>>>> tests/ovn.at | 8 +++ >>>>>> 4 files changed, 171 insertions(+) >>>>>> >>>>>> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >>>>>> index 0d443c150..4ce16ac74 100644 >>>>>> --- a/controller/pinctrl.c >>>>>> +++ b/controller/pinctrl.c >>>>>> @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); >>>>>> COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); >>>>>> COVERAGE_DEFINE(pinctrl_drop_controller_event); >>>>>> COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); >>>>>> +COVERAGE_DEFINE(pinctrl_notify_main_thread); >>>>>> +COVERAGE_DEFINE(pinctrl_total_pin_pkts); >>>>>> >>>>>> struct empty_lb_backends_event { >>>>>> struct hmap_node hmap_node; >>>>>> @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >>>>>> ntohl(ah->opcode)); >>>>>> break; >>>>>> } >>>>>> + >>>>>> + >>>>>> + if (VLOG_IS_DBG_ENABLED()) { >>>>>> + struct ds pin_str = DS_EMPTY_INITIALIZER; >>>>>> + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); >>>>>> + >>>>>> + ds_put_format(&pin_str, >>>>>> + "pinctrl received packet-in | opcode=%s", >>>>>> + opc_str); >>>>>> + >>>>>> + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); >>>>>> + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, >>>>>> + ntohll(pin.cookie)); >>>>>> + >>>>>> + if (pin.flow_metadata.flow.in_port.ofp_port) { >>>>>> + ds_put_format(&pin_str, "| in-port=%u", >>>>>> + pin.flow_metadata.flow.in_port.ofp_port); >>>>>> + } >>>>>> + >>>>>> + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", >>>>>> + ETH_ADDR_ARGS(headers.dl_src)); >>>>>> + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, >>>>>> + ETH_ADDR_ARGS(headers.dl_dst)); >>>>>> + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { >>>>>> + ds_put_format(&pin_str, "| src-ip="IP_FMT",", >>>>>> + IP_ARGS(headers.nw_src)); >>>>>> + ds_put_format(&pin_str, " dst-ip="IP_FMT, >>>>>> + IP_ARGS(headers.nw_dst)); >>>>>> + } >>>>>> + >>>>>> + VLOG_DBG("%s \n", ds_cstr(&pin_str)); >>>>>> + ds_destroy(&pin_str); >>>>>> + free(opc_str); >>>>>> + } >>>>>> + >>>>>> } >>>>>> >>>>>> /* Called with in the pinctrl_handler thread context. */ >>>>>> @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, >>>>>> config.miss_send_len = UINT16_MAX; >>>>>> set_switch_config(swconn, &config); >>>>>> } else if (type == OFPTYPE_PACKET_IN) { >>>>>> + COVERAGE_INC(pinctrl_total_pin_pkts); >>>>>> process_packet_in(swconn, oh); >>>>>> } else { >>>>>> if (VLOG_IS_DBG_ENABLED()) { >>>>>> @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) >>>>>> static void >>>>>> notify_pinctrl_main(void) >>>>>> { >>>>>> + COVERAGE_INC(pinctrl_notify_main_thread); >>>>>> seq_change(pinctrl_main_seq); >>>>>> } >>>>>> >>>>>> diff --git a/include/ovn/actions.h b/include/ovn/actions.h >>>>>> index ede5eb93c..cdef5fb03 100644 >>>>>> --- a/include/ovn/actions.h >>>>>> +++ b/include/ovn/actions.h >>>>>> @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, >>>>>> struct ofpbuf *ofpacts); >>>>>> >>>>>> void ovnacts_free(struct ovnact[], size_t ovnacts_len); >>>>>> +char *ovnact_op_to_string(uint32_t); >>>>>> >>>>>> #endif /* ovn/actions.h */ >>>>>> diff --git a/lib/actions.c b/lib/actions.c >>>>>> index 6b9a426ae..a0ff0cb6a 100644 >>>>>> --- a/lib/actions.c >>>>>> +++ b/lib/actions.c >>>>>> @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) >>>>>> } >>>>>> } >>>>>> } >>>>>> + >>>>>> +/* Return ovn action opcode string representation. >>>>>> + * The returned memory is dynamically allocated >>>>>> + * and the caller must free it using free(). >>>>>> + */ >>>>>> + >>>>>> +char * >>>>>> +ovnact_op_to_string(uint32_t ovnact_opc) >>>>>> +{ >>>>>> + struct ds opc_str = DS_EMPTY_INITIALIZER; >>>>>> + >>>>>> + switch (ovnact_opc) { >>>>>> + case ACTION_OPCODE_ARP: >>>>>> + ds_put_cstr(&opc_str, "ARP"); >>>>>> + break; >>>>>> + case ACTION_OPCODE_IGMP: >>>>>> + ds_put_cstr(&opc_str, "IGMP"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_ARP: >>>>>> + ds_put_cstr(&opc_str, "PUT_ARP"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_DHCP_OPTS: >>>>>> + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_ND_NA: >>>>>> + ds_put_cstr(&opc_str, "ND_NA"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_ND_NA_ROUTER: >>>>>> + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_ND: >>>>>> + ds_put_cstr(&opc_str, "PUT_ND"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_FDB: >>>>>> + ds_put_cstr(&opc_str, "PUT_FDB"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_DHCPV6_OPTS: >>>>>> + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_DNS_LOOKUP: >>>>>> + ds_put_cstr(&opc_str, "DNS_LOOKUP"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_LOG: >>>>>> + ds_put_cstr(&opc_str, "LOG"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_ND_RA_OPTS: >>>>>> + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_ND_NS: >>>>>> + ds_put_cstr(&opc_str, "ND_NS"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_ICMP: >>>>>> + ds_put_cstr(&opc_str, "ICMP"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_ICMP4_ERROR: >>>>>> + case ACTION_OPCODE_ICMP6_ERROR: >>>>>> + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { >>>>>> + ds_put_cstr(&opc_str, "ICMP4_ERROR"); >>>>>> + } else { >>>>>> + ds_put_cstr(&opc_str, "ICMP6_ERROR"); >>>>>> + } >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_TCP_RESET: >>>>>> + ds_put_cstr(&opc_str, "TCP_RESET"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_SCTP_ABORT: >>>>>> + ds_put_cstr(&opc_str, "SCTP_ABORT"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_REJECT: >>>>>> + ds_put_cstr(&opc_str, "REJECT"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >>>>>> + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >>>>>> + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >>>>>> + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); >>>>>> + } else { >>>>>> + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); >>>>>> + } >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_EVENT: >>>>>> + ds_put_cstr(&opc_str, "EVENT"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_BIND_VPORT: >>>>>> + ds_put_cstr(&opc_str, "BIND_VPORT"); >>>>>> + break; >>>>>> + case ACTION_OPCODE_DHCP6_SERVER: >>>>>> + ds_put_cstr(&opc_str, "DHCP6_SERVER"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_HANDLE_SVC_CHECK: >>>>>> + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); >>>>>> + break; >>>>>> + >>>>>> + case ACTION_OPCODE_BFD_MSG: >>>>>> + ds_put_cstr(&opc_str, "BFD_MSG"); >>>>>> + break; >>>>>> + >>>>>> + default: >>>>>> + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", >>>>>> + ovnact_opc); >>>>>> + break; >>>>>> + } >>>>>> + return ds_steal_cstr(&opc_str); >>>>>> +} >>>>> I didn't look at the patch from a functional standpoint, but can we >>>>> replace the above function with something like this (not tested): >> Hi Ilya, >> thank you for the review. >> i submitted a new version <https://patchwork.ozlabs.org/project/ovn/patch/20211208135954.425965-1-mheib@redhat.com/> with your proposed changes. >> >>>>> char * >>>>> ovnact_op_to_string(uint32_t ovnact_opc) >>>>> { >>>>> switch (ovnact_opc) { >>>>> #define OVNACT(ENUM, STRUCT) \ >>>>> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >>>>> OVNACTS >>>>> #undef OVNACT >>>>> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >>>>> } >>>>> } >>>>> >>>>> ? >>>> Or maybe that will not work since not all actions has an opcode.... >>>> >>>> In this case, something like this should work: >>>> >>>> char * >>>> ovnact_op_to_string(uint32_t ovnact_opc) >>>> { >>>> const char *s; >>>> >>>> switch (ovnact_opc) { >>>> #define ACTION_OPCODES(ENUM) >> i guess (ENUM) is redundant here? > Yep. > >>>> >>>> ACTION_OPCODE(ARP) \ >>>> ACTION_OPCODE(IGMP) \ >>>> ACTION_OPCODE(PUT_ARP) \ >>>> ACTION_OPCODE(PUT_DHCP_OPTS) \ >>>> ACTION_OPCODE(ND_NA) \ >>>> ACTION_OPCODE(ND_NA_ROUTER) \ >>>> ACTION_OPCODE(PUT_ND) \ >>>> ACTION_OPCODE(PUT_FDB) \ >>>> ACTION_OPCODE(PUT_DHCPV6_OPTS) \ >>>> ACTION_OPCODE(DNS_LOOKUP) \ >>>> ACTION_OPCODE(LOG) \ >>>> ACTION_OPCODE(PUT_ND_RA_OPTS) \ >>>> ACTION_OPCODE(ND_NS) \ >>>> ACTION_OPCODE(ICMP) \ >>>> ACTION_OPCODE(ICMP4_ERROR) \ >>>> ACTION_OPCODE(ICMP6_ERROR) \ >>>> ACTION_OPCODE(TCP_RESET) \ >>>> ACTION_OPCODE(SCTP_ABORT) \ >>>> ACTION_OPCODE(REJECT) \ >>>> ACTION_OPCODE(PUT_ICMP4_FRAG_MTU) \ >>>> ACTION_OPCODE(PUT_ICMP6_FRAG_MTU) \ >>>> ACTION_OPCODE(EVENT) \ >>>> ACTION_OPCODE(BIND_VPORT) \ >>>> ACTION_OPCODE(DHCP6_SERVER) \ >>>> ACTION_OPCODE(HANDLE_SVC_CHECK) \ >>>> ACTION_OPCODE(BFD_MSG) >>>> #define ACTION_OPCODE(ENUM) \ >>>> case ACTION_OPCODE_##ENUM: return xstrdup(#ENUM); >>>> ACTION_OPCODES >>>> #undef ACTION_OPCODE >>>> default: return xasprintf("unrecognized(%"PRIu32")", ovnact_opc); >>>> } >>>> return xstrdup(s); >> it was a bit complicated for me to understand the macros so if you please can take a look >> and see if it's implemented properly. > Seems correct. In general, to test tricky macros, you may just > invoke a preprocessor and look at the final result. For OVN > it will be something like this: > > gcc -E lib/actions.c -I ./include -I ./lib -I./ -I./ovs -I./ovs/lib -I./ovs/include | less wonderful trick :) thank you for sharing this :) > > To make the code even better, we need to use this trick directly > on the 'enum action_opcode', so we will have all the definitions > in the same place and will not need to remember that we need > to adjust the to_string function every time the enum changed. > > It should look like this: > > diff --git a/include/ovn/actions.h b/include/ovn/actions.h > index ede5eb93c..668210834 100644 > --- a/include/ovn/actions.h > +++ b/include/ovn/actions.h > @@ -500,XX +500,XX @@ void *ovnact_put(struct ofpbuf *, enum ovnact_type, size_t len); > OVNACTS > #undef OVNACT > > -enum action_opcode { > - /* "arp { ...actions... }". > - * > - * The actions, in OpenFlow 1.3 format, follow the action_header. > - */ > - ACTION_OPCODE_ARP, > - > - /* "put_arp(port, ip, mac)" > - * > - * Arguments are passed through the packet metadata and data, as follows: > - * > - * MFF_REG0 = ip > - * MFF_LOG_INPORT = port > - * MFF_ETH_SRC = mac > - */ > - ACTION_OPCODE_PUT_ARP, > - > - <........> > - > +#define ACTION_OPCODES \ > + /* "arp { ...actions... }". \ > + * \ > + * The actions, in OpenFlow 1.3 format, follow the action_header. \ > + */ \ > + ACTION_OPCODE(ARP) \ > + \ > + /* "put_arp(port, ip, mac)" \ > + * \ > + * Arguments are passed through the packet metadata and data, as follows: \ > + * \ > + * MFF_REG0 = ip \ > + * MFF_LOG_INPORT = port \ > + * MFF_ETH_SRC = mac \ > + */ \ > + ACTION_OPCODE(PUT_ARP) \ > + \ > + <........> \ > + > + > +enum action_opcode { > +#define ACTION_OPCODE(NAME) ACTION_OPCODE_##NAME, > + ACTION_OPCODES > +#undef ACTION_OPCODE > +}; > --- > > After that you may re-use the 'ACTION_OPCODES' macro inside the > ovnact_op_to_string() without re-defining. > > This is something that definitely needs to be done, but I'm not > sure if that needs to be done in this patch. Maybe as a > separate patch/prerequisite to this one. > > Best regards, Ilya Maximets. yes, i will try to add it as a separate patch since this patch already merged. thank you so much :) > >>> And this line is obviously not needed. Ugh. >>> And sorry for the trailing whitespaces. >>> >> thanks :) >>>> } >>>> >>>> Should be easier to track and modify in the future. >>>> >>>>> Best regards, Ilya Maximets. >>>>>
diff --git a/controller/pinctrl.c b/controller/pinctrl.c index 0d443c150..4ce16ac74 100644 --- a/controller/pinctrl.c +++ b/controller/pinctrl.c @@ -364,6 +364,8 @@ COVERAGE_DEFINE(pinctrl_drop_put_mac_binding); COVERAGE_DEFINE(pinctrl_drop_buffered_packets_map); COVERAGE_DEFINE(pinctrl_drop_controller_event); COVERAGE_DEFINE(pinctrl_drop_put_vport_binding); +COVERAGE_DEFINE(pinctrl_notify_main_thread); +COVERAGE_DEFINE(pinctrl_total_pin_pkts); struct empty_lb_backends_event { struct hmap_node hmap_node; @@ -3268,6 +3270,41 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) ntohl(ah->opcode)); break; } + + + if (VLOG_IS_DBG_ENABLED()) { + struct ds pin_str = DS_EMPTY_INITIALIZER; + char * opc_str = ovnact_op_to_string(ntohl(ah->opcode)); + + ds_put_format(&pin_str, + "pinctrl received packet-in | opcode=%s", + opc_str); + + ds_put_format(&pin_str, "| OF_Table_ID=%u", pin.table_id); + ds_put_format(&pin_str, "| OF_Cookie_ID=0x%"PRIx64, + ntohll(pin.cookie)); + + if (pin.flow_metadata.flow.in_port.ofp_port) { + ds_put_format(&pin_str, "| in-port=%u", + pin.flow_metadata.flow.in_port.ofp_port); + } + + ds_put_format(&pin_str, "| src-mac="ETH_ADDR_FMT",", + ETH_ADDR_ARGS(headers.dl_src)); + ds_put_format(&pin_str, " dst-mac="ETH_ADDR_FMT, + ETH_ADDR_ARGS(headers.dl_dst)); + if (headers.dl_type != htons(ETH_TYPE_IPV6)) { + ds_put_format(&pin_str, "| src-ip="IP_FMT",", + IP_ARGS(headers.nw_src)); + ds_put_format(&pin_str, " dst-ip="IP_FMT, + IP_ARGS(headers.nw_dst)); + } + + VLOG_DBG("%s \n", ds_cstr(&pin_str)); + ds_destroy(&pin_str); + free(opc_str); + } + } /* Called with in the pinctrl_handler thread context. */ @@ -3285,6 +3322,7 @@ pinctrl_recv(struct rconn *swconn, const struct ofp_header *oh, config.miss_send_len = UINT16_MAX; set_switch_config(swconn, &config); } else if (type == OFPTYPE_PACKET_IN) { + COVERAGE_INC(pinctrl_total_pin_pkts); process_packet_in(swconn, oh); } else { if (VLOG_IS_DBG_ENABLED()) { @@ -3309,6 +3347,7 @@ notify_pinctrl_handler(void) static void notify_pinctrl_main(void) { + COVERAGE_INC(pinctrl_notify_main_thread); seq_change(pinctrl_main_seq); } diff --git a/include/ovn/actions.h b/include/ovn/actions.h index ede5eb93c..cdef5fb03 100644 --- a/include/ovn/actions.h +++ b/include/ovn/actions.h @@ -806,5 +806,6 @@ void ovnacts_encode(const struct ovnact[], size_t ovnacts_len, struct ofpbuf *ofpacts); void ovnacts_free(struct ovnact[], size_t ovnacts_len); +char *ovnact_op_to_string(uint32_t); #endif /* ovn/actions.h */ diff --git a/lib/actions.c b/lib/actions.c index 6b9a426ae..a0ff0cb6a 100644 --- a/lib/actions.c +++ b/lib/actions.c @@ -4315,3 +4315,126 @@ ovnacts_free(struct ovnact *ovnacts, size_t ovnacts_len) } } } + +/* Return ovn action opcode string representation. + * The returned memory is dynamically allocated + * and the caller must free it using free(). + */ + +char * +ovnact_op_to_string(uint32_t ovnact_opc) +{ + struct ds opc_str = DS_EMPTY_INITIALIZER; + + switch (ovnact_opc) { + case ACTION_OPCODE_ARP: + ds_put_cstr(&opc_str, "ARP"); + break; + case ACTION_OPCODE_IGMP: + ds_put_cstr(&opc_str, "IGMP"); + break; + + case ACTION_OPCODE_PUT_ARP: + ds_put_cstr(&opc_str, "PUT_ARP"); + break; + + case ACTION_OPCODE_PUT_DHCP_OPTS: + ds_put_cstr(&opc_str, "PUT_DHCP_OPTS"); + break; + + case ACTION_OPCODE_ND_NA: + ds_put_cstr(&opc_str, "ND_NA"); + break; + + case ACTION_OPCODE_ND_NA_ROUTER: + ds_put_cstr(&opc_str, "ND_NA_ROUTER"); + break; + + case ACTION_OPCODE_PUT_ND: + ds_put_cstr(&opc_str, "PUT_ND"); + break; + + case ACTION_OPCODE_PUT_FDB: + ds_put_cstr(&opc_str, "PUT_FDB"); + break; + + case ACTION_OPCODE_PUT_DHCPV6_OPTS: + ds_put_cstr(&opc_str, "PUT_DHCPV6_OPTS"); + break; + + case ACTION_OPCODE_DNS_LOOKUP: + ds_put_cstr(&opc_str, "DNS_LOOKUP"); + break; + + case ACTION_OPCODE_LOG: + ds_put_cstr(&opc_str, "LOG"); + break; + + case ACTION_OPCODE_PUT_ND_RA_OPTS: + ds_put_cstr(&opc_str, "PUT_ND_RA_OPTS"); + break; + + case ACTION_OPCODE_ND_NS: + ds_put_cstr(&opc_str, "ND_NS"); + break; + + case ACTION_OPCODE_ICMP: + ds_put_cstr(&opc_str, "ICMP"); + break; + + case ACTION_OPCODE_ICMP4_ERROR: + case ACTION_OPCODE_ICMP6_ERROR: + if (ovnact_opc == ACTION_OPCODE_ICMP4_ERROR) { + ds_put_cstr(&opc_str, "ICMP4_ERROR"); + } else { + ds_put_cstr(&opc_str, "ICMP6_ERROR"); + } + break; + + case ACTION_OPCODE_TCP_RESET: + ds_put_cstr(&opc_str, "TCP_RESET"); + break; + + case ACTION_OPCODE_SCTP_ABORT: + ds_put_cstr(&opc_str, "SCTP_ABORT"); + break; + + case ACTION_OPCODE_REJECT: + ds_put_cstr(&opc_str, "REJECT"); + break; + + case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: + case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: + if (ovnact_opc == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { + ds_put_cstr(&opc_str, "PUT_ICMP4_FRAG_MTU"); + } else { + ds_put_cstr(&opc_str, "PUT_ICMP6_FRAG_MTU"); + } + break; + + case ACTION_OPCODE_EVENT: + ds_put_cstr(&opc_str, "EVENT"); + break; + + case ACTION_OPCODE_BIND_VPORT: + ds_put_cstr(&opc_str, "BIND_VPORT"); + break; + case ACTION_OPCODE_DHCP6_SERVER: + ds_put_cstr(&opc_str, "DHCP6_SERVER"); + break; + + case ACTION_OPCODE_HANDLE_SVC_CHECK: + ds_put_cstr(&opc_str, "HANDLE_SVC_CHECK"); + break; + + case ACTION_OPCODE_BFD_MSG: + ds_put_cstr(&opc_str, "BFD_MSG"); + break; + + default: + ds_put_format(&opc_str, "unrecognized(%"PRIu32")", + ovnact_opc); + break; + } + return ds_steal_cstr(&opc_str); +} diff --git a/tests/ovn.at b/tests/ovn.at index a4ed03041..9ec62e321 100644 --- a/tests/ovn.at +++ b/tests/ovn.at @@ -18283,6 +18283,8 @@ ovs-vsctl -- add-port br-int hv1-vif3 -- \ options:rxq_pcap=hv1/vif3-rx.pcap \ ofport-request=3 +ovs-appctl -t ovn-controller vlog/set dbg + sim_add hv2 as hv2 ovs-vsctl add-br br-phys @@ -18473,6 +18475,8 @@ wait_row_count Port_Binding 1 logical_port=sw0-vir chassis=$hv1_ch_uuid check_row_count Port_Binding 1 logical_port=sw0-vir virtual_parent=sw0-p1 wait_for_ports_up sw0-vir check ovn-nbctl --wait=hv sync +AT_CHECK([test 2 = `cat hv1/ovn-controller.log | grep "pinctrl received packet-in" | \ +grep opcode=BIND_VPORT | grep OF_Table_ID=24 | wc -l`]) wait_row_count Port_Binding 1 logical_port=sw0-vir6 chassis=$hv1_ch_uuid check_row_count Port_Binding 1 logical_port=sw0-vir6 virtual_parent=sw0-p1 @@ -21339,6 +21343,10 @@ list mac_binding], [0], [lr0-sw0 AT_CHECK([test 1 = `cat hv1/ovn-controller.log | grep NXT_PACKET_IN2 | \ grep table_id=10 | wc -l`]) + +AT_CHECK([test 1 = `cat hv1/ovn-controller.log | grep "pinctrl received packet-in" | \ +grep opcode=PUT_ARP | grep OF_Table_ID=10 | wc -l`]) + AT_CHECK([test 1 = `as hv1 ovs-ofctl dump-flows br-int table=10 | grep arp | \ grep controller | grep -v n_packets=0 | wc -l`])
Improve packet-in debuggability within pinctrl module by printing basic details about each received packet-in message, those messages will be printed to the logs only when DBG log level is enabled. Also, add two coverage counters that will indicate the total packet-in messages that were received and the number of times that the pinctrl main thread was notified to handle a change in the local DBs, those counters can be used by the user as an indicator to enable the DBG logs level and see more details about the received packet-in in the logs. Reported-at: https://bugzilla.redhat.com/show_bug.cgi?id=1821965 Signed-off-by: Mohammad Heib <mheib@redhat.com> --- controller/pinctrl.c | 39 ++++++++++++++ include/ovn/actions.h | 1 + lib/actions.c | 123 ++++++++++++++++++++++++++++++++++++++++++ tests/ovn.at | 8 +++ 4 files changed, 171 insertions(+)