| Message ID | 20211118105406.508257-1-mheib@redhat.com |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [ovs-dev] 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 | fail | github build: failed |
On Thu, Nov 18, 2021 at 5:55 AM Mohammad Heib <mheib@redhat.com> 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 | 66 ++++++++++++++++++++++++++++++++++++++++++++ > tests/ovn.at | 8 ++++++ > 2 files changed, 74 insertions(+) > > diff --git a/controller/pinctrl.c b/controller/pinctrl.c > index ae5320e09..38bda2a89 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; > @@ -3073,6 +3075,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > { > static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); > > + struct ds pin_str = DS_EMPTY_INITIALIZER; > struct ofputil_packet_in pin; > struct ofpbuf continuation; > enum ofperr error = ofputil_decode_packet_in(msg, true, NULL, NULL, &pin, > @@ -3099,18 +3102,22 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > dp_packet_use_const(&packet, pin.packet, pin.packet_len); > struct flow headers; > flow_extract(&packet, &headers); > + ds_put_cstr(&pin_str, "pinctrl received packet-in | opcode="); > > switch (ntohl(ah->opcode)) { > case ACTION_OPCODE_ARP: > + ds_put_cstr(&pin_str, "ARP"); > pinctrl_handle_arp(swconn, &headers, &packet, &pin.flow_metadata, > &userdata); > break; > case ACTION_OPCODE_IGMP: > + ds_put_cstr(&pin_str, "IGMP"); > pinctrl_ip_mcast_handle(swconn, &headers, &packet, &pin.flow_metadata, > &userdata); > break; > > case ACTION_OPCODE_PUT_ARP: > + ds_put_cstr(&pin_str, "PUT_ARP"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, > true); > @@ -3118,21 +3125,25 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > break; > > case ACTION_OPCODE_PUT_DHCP_OPTS: > + ds_put_cstr(&pin_str, "PUT_DHCP_OPTS"); > pinctrl_handle_put_dhcp_opts(swconn, &packet, &pin, &headers, > &userdata, &continuation); > break; > > case ACTION_OPCODE_ND_NA: > + ds_put_cstr(&pin_str, "ND_NA"); > pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, > false); > break; > > case ACTION_OPCODE_ND_NA_ROUTER: > + ds_put_cstr(&pin_str, "ND_NA_ROUTER"); > pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, > true); > break; > > case ACTION_OPCODE_PUT_ND: > + ds_put_cstr(&pin_str, "PUT_ND"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, > false); > @@ -3140,17 +3151,20 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > break; > > case ACTION_OPCODE_PUT_FDB: > + ds_put_cstr(&pin_str, "PUT_FDB"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_put_fdb(&pin.flow_metadata.flow, &headers); > ovs_mutex_unlock(&pinctrl_mutex); > break; > > case ACTION_OPCODE_PUT_DHCPV6_OPTS: > + ds_put_cstr(&pin_str, "PUT_DHCPV6_OPTS"); > pinctrl_handle_put_dhcpv6_opts(swconn, &packet, &pin, &userdata, > &continuation); > break; > > case ACTION_OPCODE_DNS_LOOKUP: > + ds_put_cstr(&pin_str, "DNS_LOOKUP"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_dns_lookup(swconn, &packet, &pin, &userdata, > &continuation); > @@ -3158,63 +3172,83 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > break; > > case ACTION_OPCODE_LOG: > + ds_put_cstr(&pin_str, "LOG"); > handle_acl_log(&headers, &userdata); > break; > > case ACTION_OPCODE_PUT_ND_RA_OPTS: > + ds_put_cstr(&pin_str, "PUT_ND_RA_OPTS"); > pinctrl_handle_put_nd_ra_opts(swconn, &headers, &packet, &pin, > &userdata, &continuation); > break; > > case ACTION_OPCODE_ND_NS: > + ds_put_cstr(&pin_str, "ND_NS"); > pinctrl_handle_nd_ns(swconn, &headers, &packet, &pin.flow_metadata, > &userdata); > break; > > case ACTION_OPCODE_ICMP: > + ds_put_cstr(&pin_str, "ICMP"); > pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, > &userdata, true, false); > break; > > case ACTION_OPCODE_ICMP4_ERROR: > case ACTION_OPCODE_ICMP6_ERROR: > + if (ntohl(ah->opcode) == ACTION_OPCODE_ICMP4_ERROR) { > + ds_put_cstr(&pin_str, "ICMP4_ERROR"); > + } else { > + ds_put_cstr(&pin_str, "ICMP6_ERROR"); > + } > pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, > &userdata, false, false); > break; > > case ACTION_OPCODE_TCP_RESET: > + ds_put_cstr(&pin_str, "TCP_RESET"); > pinctrl_handle_tcp_reset(swconn, &headers, &packet, &pin.flow_metadata, > &userdata, false); > break; > > case ACTION_OPCODE_SCTP_ABORT: > + ds_put_cstr(&pin_str, "SCTP_ABORT"); > pinctrl_handle_sctp_abort(swconn, &headers, &packet, > &pin.flow_metadata, &userdata, false); > break; > > case ACTION_OPCODE_REJECT: > + ds_put_cstr(&pin_str, "REJECT"); > pinctrl_handle_reject(swconn, &headers, &packet, &pin.flow_metadata, > &userdata); > break; > > case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: > case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: > + if (ntohl(ah->opcode) == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { > + ds_put_cstr(&pin_str, "PUT_ICMP4_FRAG_MTU"); > + } else { > + ds_put_cstr(&pin_str, "PUT_ICMP6_FRAG_MTU"); > + } > pinctrl_handle_put_icmp_frag_mtu(swconn, &headers, &packet, &pin, > &userdata, &continuation); > break; > > case ACTION_OPCODE_EVENT: > + ds_put_cstr(&pin_str, "EVENT"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_event(&userdata); > ovs_mutex_unlock(&pinctrl_mutex); > break; > > case ACTION_OPCODE_BIND_VPORT: > + ds_put_cstr(&pin_str, "BIND_VPORT"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_bind_vport(&pin.flow_metadata.flow, &userdata); > ovs_mutex_unlock(&pinctrl_mutex); > break; > case ACTION_OPCODE_DHCP6_SERVER: > + ds_put_cstr(&pin_str, "DHCP6_SERVER"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_dhcp6_server(swconn, &headers, &packet, > &pin.flow_metadata); > @@ -3222,6 +3256,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > break; > > case ACTION_OPCODE_HANDLE_SVC_CHECK: > + ds_put_cstr(&pin_str, "HANDLE_SVC_CHECK"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_svc_check(swconn, &headers, &packet, > &pin.flow_metadata); > @@ -3229,16 +3264,45 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > break; > > case ACTION_OPCODE_BFD_MSG: > + ds_put_cstr(&pin_str, "BFD_MSG"); > ovs_mutex_lock(&pinctrl_mutex); > pinctrl_handle_bfd_msg(swconn, &headers, &packet); > ovs_mutex_unlock(&pinctrl_mutex); > break; > > default: > + ds_put_format(&pin_str, "unrecognized(%"PRIu32")", > + ntohl(ah->opcode)); > VLOG_WARN_RL(&rl, "unrecognized packet-in opcode %"PRIu32, > ntohl(ah->opcode)); > break; > } > + > + Thanks for the patch. I've one comment. When log level is NOT DBG, then this patch would unnecessarily build the "pin_str" dynamic string. I'd suggest adding another switch inside the below if (VLOG_IS_DBG_ENABLED) {} and set the opcode string in the "pin_str". What do you think ? Thanks Numan > + if (VLOG_IS_DBG_ENABLED()) { > + 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); > } > > /* Called with in the pinctrl_handler thread context. */ > @@ -3256,6 +3320,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()) { > @@ -3280,6 +3345,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/tests/ovn.at b/tests/ovn.at > index ae832918c..02e64b7b4 100644 > --- a/tests/ovn.at > +++ b/tests/ovn.at > @@ -18019,6 +18019,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 > @@ -18209,6 +18211,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 > @@ -21075,6 +21079,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`]) > > -- > 2.26.3 > > _______________________________________________ > dev mailing list > dev@openvswitch.org > https://mail.openvswitch.org/mailman/listinfo/ovs-dev >
On 11/29/21 10:39 PM, Numan Siddique wrote: > On Thu, Nov 18, 2021 at 5:55 AM Mohammad Heib <mheib@redhat.com> 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 | 66 ++++++++++++++++++++++++++++++++++++++++++++ >> tests/ovn.at | 8 ++++++ >> 2 files changed, 74 insertions(+) >> >> diff --git a/controller/pinctrl.c b/controller/pinctrl.c >> index ae5320e09..38bda2a89 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; >> @@ -3073,6 +3075,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> { >> static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); >> >> + struct ds pin_str = DS_EMPTY_INITIALIZER; >> struct ofputil_packet_in pin; >> struct ofpbuf continuation; >> enum ofperr error = ofputil_decode_packet_in(msg, true, NULL, NULL, &pin, >> @@ -3099,18 +3102,22 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> dp_packet_use_const(&packet, pin.packet, pin.packet_len); >> struct flow headers; >> flow_extract(&packet, &headers); >> + ds_put_cstr(&pin_str, "pinctrl received packet-in | opcode="); >> >> switch (ntohl(ah->opcode)) { >> case ACTION_OPCODE_ARP: >> + ds_put_cstr(&pin_str, "ARP"); >> pinctrl_handle_arp(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata); >> break; >> case ACTION_OPCODE_IGMP: >> + ds_put_cstr(&pin_str, "IGMP"); >> pinctrl_ip_mcast_handle(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata); >> break; >> >> case ACTION_OPCODE_PUT_ARP: >> + ds_put_cstr(&pin_str, "PUT_ARP"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, >> true); >> @@ -3118,21 +3125,25 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> break; >> >> case ACTION_OPCODE_PUT_DHCP_OPTS: >> + ds_put_cstr(&pin_str, "PUT_DHCP_OPTS"); >> pinctrl_handle_put_dhcp_opts(swconn, &packet, &pin, &headers, >> &userdata, &continuation); >> break; >> >> case ACTION_OPCODE_ND_NA: >> + ds_put_cstr(&pin_str, "ND_NA"); >> pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, >> false); >> break; >> >> case ACTION_OPCODE_ND_NA_ROUTER: >> + ds_put_cstr(&pin_str, "ND_NA_ROUTER"); >> pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, >> true); >> break; >> >> case ACTION_OPCODE_PUT_ND: >> + ds_put_cstr(&pin_str, "PUT_ND"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, >> false); >> @@ -3140,17 +3151,20 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> break; >> >> case ACTION_OPCODE_PUT_FDB: >> + ds_put_cstr(&pin_str, "PUT_FDB"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_put_fdb(&pin.flow_metadata.flow, &headers); >> ovs_mutex_unlock(&pinctrl_mutex); >> break; >> >> case ACTION_OPCODE_PUT_DHCPV6_OPTS: >> + ds_put_cstr(&pin_str, "PUT_DHCPV6_OPTS"); >> pinctrl_handle_put_dhcpv6_opts(swconn, &packet, &pin, &userdata, >> &continuation); >> break; >> >> case ACTION_OPCODE_DNS_LOOKUP: >> + ds_put_cstr(&pin_str, "DNS_LOOKUP"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_dns_lookup(swconn, &packet, &pin, &userdata, >> &continuation); >> @@ -3158,63 +3172,83 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> break; >> >> case ACTION_OPCODE_LOG: >> + ds_put_cstr(&pin_str, "LOG"); >> handle_acl_log(&headers, &userdata); >> break; >> >> case ACTION_OPCODE_PUT_ND_RA_OPTS: >> + ds_put_cstr(&pin_str, "PUT_ND_RA_OPTS"); >> pinctrl_handle_put_nd_ra_opts(swconn, &headers, &packet, &pin, >> &userdata, &continuation); >> break; >> >> case ACTION_OPCODE_ND_NS: >> + ds_put_cstr(&pin_str, "ND_NS"); >> pinctrl_handle_nd_ns(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata); >> break; >> >> case ACTION_OPCODE_ICMP: >> + ds_put_cstr(&pin_str, "ICMP"); >> pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata, true, false); >> break; >> >> case ACTION_OPCODE_ICMP4_ERROR: >> case ACTION_OPCODE_ICMP6_ERROR: >> + if (ntohl(ah->opcode) == ACTION_OPCODE_ICMP4_ERROR) { >> + ds_put_cstr(&pin_str, "ICMP4_ERROR"); >> + } else { >> + ds_put_cstr(&pin_str, "ICMP6_ERROR"); >> + } >> pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata, false, false); >> break; >> >> case ACTION_OPCODE_TCP_RESET: >> + ds_put_cstr(&pin_str, "TCP_RESET"); >> pinctrl_handle_tcp_reset(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata, false); >> break; >> >> case ACTION_OPCODE_SCTP_ABORT: >> + ds_put_cstr(&pin_str, "SCTP_ABORT"); >> pinctrl_handle_sctp_abort(swconn, &headers, &packet, >> &pin.flow_metadata, &userdata, false); >> break; >> >> case ACTION_OPCODE_REJECT: >> + ds_put_cstr(&pin_str, "REJECT"); >> pinctrl_handle_reject(swconn, &headers, &packet, &pin.flow_metadata, >> &userdata); >> break; >> >> case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: >> case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: >> + if (ntohl(ah->opcode) == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { >> + ds_put_cstr(&pin_str, "PUT_ICMP4_FRAG_MTU"); >> + } else { >> + ds_put_cstr(&pin_str, "PUT_ICMP6_FRAG_MTU"); >> + } >> pinctrl_handle_put_icmp_frag_mtu(swconn, &headers, &packet, &pin, >> &userdata, &continuation); >> break; >> >> case ACTION_OPCODE_EVENT: >> + ds_put_cstr(&pin_str, "EVENT"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_event(&userdata); >> ovs_mutex_unlock(&pinctrl_mutex); >> break; >> >> case ACTION_OPCODE_BIND_VPORT: >> + ds_put_cstr(&pin_str, "BIND_VPORT"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_bind_vport(&pin.flow_metadata.flow, &userdata); >> ovs_mutex_unlock(&pinctrl_mutex); >> break; >> case ACTION_OPCODE_DHCP6_SERVER: >> + ds_put_cstr(&pin_str, "DHCP6_SERVER"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_dhcp6_server(swconn, &headers, &packet, >> &pin.flow_metadata); >> @@ -3222,6 +3256,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> break; >> >> case ACTION_OPCODE_HANDLE_SVC_CHECK: >> + ds_put_cstr(&pin_str, "HANDLE_SVC_CHECK"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_svc_check(swconn, &headers, &packet, >> &pin.flow_metadata); >> @@ -3229,16 +3264,45 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) >> break; >> >> case ACTION_OPCODE_BFD_MSG: >> + ds_put_cstr(&pin_str, "BFD_MSG"); >> ovs_mutex_lock(&pinctrl_mutex); >> pinctrl_handle_bfd_msg(swconn, &headers, &packet); >> ovs_mutex_unlock(&pinctrl_mutex); >> break; >> >> default: >> + ds_put_format(&pin_str, "unrecognized(%"PRIu32")", >> + ntohl(ah->opcode)); >> VLOG_WARN_RL(&rl, "unrecognized packet-in opcode %"PRIu32, >> ntohl(ah->opcode)); >> break; >> } >> + >> + Hi Numan, > Thanks for the patch. I've one comment. > > When log level is NOT DBG, then this patch would unnecessarily build > the "pin_str" dynamic string. > > I'd suggest adding another switch inside the below if (VLOG_IS_DBG_ENABLED) {} > and set the opcode string in the "pin_str". > > What do you think ? yes, i fully agree with you that in most cases we build pin_str but didn't use it. but I'm not sure about adding another switch inside the if (VLOG_IS_DBG_ENABLED) {} because that will be more duplicating code. i also was thinking about maybe I can add function ovnact_op_to_string to lib/actions.c and there I can add the switch or case what do you think? Thank you > > Thanks > Numan > > >> + if (VLOG_IS_DBG_ENABLED()) { >> + 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); >> } >> >> /* Called with in the pinctrl_handler thread context. */ >> @@ -3256,6 +3320,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()) { >> @@ -3280,6 +3345,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/tests/ovn.at b/tests/ovn.at >> index ae832918c..02e64b7b4 100644 >> --- a/tests/ovn.at >> +++ b/tests/ovn.at >> @@ -18019,6 +18019,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 >> @@ -18209,6 +18211,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 >> @@ -21075,6 +21079,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`]) >> >> -- >> 2.26.3 >> >> _______________________________________________ >> dev mailing list >> dev@openvswitch.org >> https://mail.openvswitch.org/mailman/listinfo/ovs-dev >>
On Tue, Nov 30, 2021 at 6:24 AM Mohammad Heib <mheib@redhat.com> wrote: > > > On 11/29/21 10:39 PM, Numan Siddique wrote: > > On Thu, Nov 18, 2021 at 5:55 AM Mohammad Heib <mheib@redhat.com> 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 | 66 ++++++++++++++++++++++++++++++++++++++++++++ > >> tests/ovn.at | 8 ++++++ > >> 2 files changed, 74 insertions(+) > >> > >> diff --git a/controller/pinctrl.c b/controller/pinctrl.c > >> index ae5320e09..38bda2a89 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; > >> @@ -3073,6 +3075,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> { > >> static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); > >> > >> + struct ds pin_str = DS_EMPTY_INITIALIZER; > >> struct ofputil_packet_in pin; > >> struct ofpbuf continuation; > >> enum ofperr error = ofputil_decode_packet_in(msg, true, NULL, NULL, &pin, > >> @@ -3099,18 +3102,22 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> dp_packet_use_const(&packet, pin.packet, pin.packet_len); > >> struct flow headers; > >> flow_extract(&packet, &headers); > >> + ds_put_cstr(&pin_str, "pinctrl received packet-in | opcode="); > >> > >> switch (ntohl(ah->opcode)) { > >> case ACTION_OPCODE_ARP: > >> + ds_put_cstr(&pin_str, "ARP"); > >> pinctrl_handle_arp(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata); > >> break; > >> case ACTION_OPCODE_IGMP: > >> + ds_put_cstr(&pin_str, "IGMP"); > >> pinctrl_ip_mcast_handle(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata); > >> break; > >> > >> case ACTION_OPCODE_PUT_ARP: > >> + ds_put_cstr(&pin_str, "PUT_ARP"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, > >> true); > >> @@ -3118,21 +3125,25 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> break; > >> > >> case ACTION_OPCODE_PUT_DHCP_OPTS: > >> + ds_put_cstr(&pin_str, "PUT_DHCP_OPTS"); > >> pinctrl_handle_put_dhcp_opts(swconn, &packet, &pin, &headers, > >> &userdata, &continuation); > >> break; > >> > >> case ACTION_OPCODE_ND_NA: > >> + ds_put_cstr(&pin_str, "ND_NA"); > >> pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, > >> false); > >> break; > >> > >> case ACTION_OPCODE_ND_NA_ROUTER: > >> + ds_put_cstr(&pin_str, "ND_NA_ROUTER"); > >> pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, > >> true); > >> break; > >> > >> case ACTION_OPCODE_PUT_ND: > >> + ds_put_cstr(&pin_str, "PUT_ND"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, > >> false); > >> @@ -3140,17 +3151,20 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> break; > >> > >> case ACTION_OPCODE_PUT_FDB: > >> + ds_put_cstr(&pin_str, "PUT_FDB"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_put_fdb(&pin.flow_metadata.flow, &headers); > >> ovs_mutex_unlock(&pinctrl_mutex); > >> break; > >> > >> case ACTION_OPCODE_PUT_DHCPV6_OPTS: > >> + ds_put_cstr(&pin_str, "PUT_DHCPV6_OPTS"); > >> pinctrl_handle_put_dhcpv6_opts(swconn, &packet, &pin, &userdata, > >> &continuation); > >> break; > >> > >> case ACTION_OPCODE_DNS_LOOKUP: > >> + ds_put_cstr(&pin_str, "DNS_LOOKUP"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_dns_lookup(swconn, &packet, &pin, &userdata, > >> &continuation); > >> @@ -3158,63 +3172,83 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> break; > >> > >> case ACTION_OPCODE_LOG: > >> + ds_put_cstr(&pin_str, "LOG"); > >> handle_acl_log(&headers, &userdata); > >> break; > >> > >> case ACTION_OPCODE_PUT_ND_RA_OPTS: > >> + ds_put_cstr(&pin_str, "PUT_ND_RA_OPTS"); > >> pinctrl_handle_put_nd_ra_opts(swconn, &headers, &packet, &pin, > >> &userdata, &continuation); > >> break; > >> > >> case ACTION_OPCODE_ND_NS: > >> + ds_put_cstr(&pin_str, "ND_NS"); > >> pinctrl_handle_nd_ns(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata); > >> break; > >> > >> case ACTION_OPCODE_ICMP: > >> + ds_put_cstr(&pin_str, "ICMP"); > >> pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata, true, false); > >> break; > >> > >> case ACTION_OPCODE_ICMP4_ERROR: > >> case ACTION_OPCODE_ICMP6_ERROR: > >> + if (ntohl(ah->opcode) == ACTION_OPCODE_ICMP4_ERROR) { > >> + ds_put_cstr(&pin_str, "ICMP4_ERROR"); > >> + } else { > >> + ds_put_cstr(&pin_str, "ICMP6_ERROR"); > >> + } > >> pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata, false, false); > >> break; > >> > >> case ACTION_OPCODE_TCP_RESET: > >> + ds_put_cstr(&pin_str, "TCP_RESET"); > >> pinctrl_handle_tcp_reset(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata, false); > >> break; > >> > >> case ACTION_OPCODE_SCTP_ABORT: > >> + ds_put_cstr(&pin_str, "SCTP_ABORT"); > >> pinctrl_handle_sctp_abort(swconn, &headers, &packet, > >> &pin.flow_metadata, &userdata, false); > >> break; > >> > >> case ACTION_OPCODE_REJECT: > >> + ds_put_cstr(&pin_str, "REJECT"); > >> pinctrl_handle_reject(swconn, &headers, &packet, &pin.flow_metadata, > >> &userdata); > >> break; > >> > >> case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: > >> case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: > >> + if (ntohl(ah->opcode) == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { > >> + ds_put_cstr(&pin_str, "PUT_ICMP4_FRAG_MTU"); > >> + } else { > >> + ds_put_cstr(&pin_str, "PUT_ICMP6_FRAG_MTU"); > >> + } > >> pinctrl_handle_put_icmp_frag_mtu(swconn, &headers, &packet, &pin, > >> &userdata, &continuation); > >> break; > >> > >> case ACTION_OPCODE_EVENT: > >> + ds_put_cstr(&pin_str, "EVENT"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_event(&userdata); > >> ovs_mutex_unlock(&pinctrl_mutex); > >> break; > >> > >> case ACTION_OPCODE_BIND_VPORT: > >> + ds_put_cstr(&pin_str, "BIND_VPORT"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_bind_vport(&pin.flow_metadata.flow, &userdata); > >> ovs_mutex_unlock(&pinctrl_mutex); > >> break; > >> case ACTION_OPCODE_DHCP6_SERVER: > >> + ds_put_cstr(&pin_str, "DHCP6_SERVER"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_dhcp6_server(swconn, &headers, &packet, > >> &pin.flow_metadata); > >> @@ -3222,6 +3256,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> break; > >> > >> case ACTION_OPCODE_HANDLE_SVC_CHECK: > >> + ds_put_cstr(&pin_str, "HANDLE_SVC_CHECK"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_svc_check(swconn, &headers, &packet, > >> &pin.flow_metadata); > >> @@ -3229,16 +3264,45 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) > >> break; > >> > >> case ACTION_OPCODE_BFD_MSG: > >> + ds_put_cstr(&pin_str, "BFD_MSG"); > >> ovs_mutex_lock(&pinctrl_mutex); > >> pinctrl_handle_bfd_msg(swconn, &headers, &packet); > >> ovs_mutex_unlock(&pinctrl_mutex); > >> break; > >> > >> default: > >> + ds_put_format(&pin_str, "unrecognized(%"PRIu32")", > >> + ntohl(ah->opcode)); > >> VLOG_WARN_RL(&rl, "unrecognized packet-in opcode %"PRIu32, > >> ntohl(ah->opcode)); > >> break; > >> } > >> + > >> + > > Hi Numan, > > > Thanks for the patch. I've one comment. > > > > When log level is NOT DBG, then this patch would unnecessarily build > > the "pin_str" dynamic string. > > > > I'd suggest adding another switch inside the below if (VLOG_IS_DBG_ENABLED) {} > > and set the opcode string in the "pin_str". > > > > What do you think ? > yes, i fully agree with you that in most cases we build pin_str but > didn't use it. > but I'm not sure about adding another switch inside the if > (VLOG_IS_DBG_ENABLED) {} > because that will be more duplicating code. > i also was thinking about maybe I can add function ovnact_op_to_string > to lib/actions.c and there > I can add the switch or case what do you think? ovnact_op_to_string () sounds good to me. Numan > > Thank you > > > > > Thanks > > Numan > > > > > >> + if (VLOG_IS_DBG_ENABLED()) { > >> + 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); > >> } > >> > >> /* Called with in the pinctrl_handler thread context. */ > >> @@ -3256,6 +3320,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()) { > >> @@ -3280,6 +3345,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/tests/ovn.at b/tests/ovn.at > >> index ae832918c..02e64b7b4 100644 > >> --- a/tests/ovn.at > >> +++ b/tests/ovn.at > >> @@ -18019,6 +18019,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 > >> @@ -18209,6 +18211,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 > >> @@ -21075,6 +21079,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`]) > >> > >> -- > >> 2.26.3 > >> > >> _______________________________________________ > >> dev mailing list > >> dev@openvswitch.org > >> https://mail.openvswitch.org/mailman/listinfo/ovs-dev > >> > _______________________________________________ > dev mailing list > dev@openvswitch.org > https://mail.openvswitch.org/mailman/listinfo/ovs-dev >
diff --git a/controller/pinctrl.c b/controller/pinctrl.c index ae5320e09..38bda2a89 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; @@ -3073,6 +3075,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) { static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); + struct ds pin_str = DS_EMPTY_INITIALIZER; struct ofputil_packet_in pin; struct ofpbuf continuation; enum ofperr error = ofputil_decode_packet_in(msg, true, NULL, NULL, &pin, @@ -3099,18 +3102,22 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) dp_packet_use_const(&packet, pin.packet, pin.packet_len); struct flow headers; flow_extract(&packet, &headers); + ds_put_cstr(&pin_str, "pinctrl received packet-in | opcode="); switch (ntohl(ah->opcode)) { case ACTION_OPCODE_ARP: + ds_put_cstr(&pin_str, "ARP"); pinctrl_handle_arp(swconn, &headers, &packet, &pin.flow_metadata, &userdata); break; case ACTION_OPCODE_IGMP: + ds_put_cstr(&pin_str, "IGMP"); pinctrl_ip_mcast_handle(swconn, &headers, &packet, &pin.flow_metadata, &userdata); break; case ACTION_OPCODE_PUT_ARP: + ds_put_cstr(&pin_str, "PUT_ARP"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, true); @@ -3118,21 +3125,25 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) break; case ACTION_OPCODE_PUT_DHCP_OPTS: + ds_put_cstr(&pin_str, "PUT_DHCP_OPTS"); pinctrl_handle_put_dhcp_opts(swconn, &packet, &pin, &headers, &userdata, &continuation); break; case ACTION_OPCODE_ND_NA: + ds_put_cstr(&pin_str, "ND_NA"); pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, false); break; case ACTION_OPCODE_ND_NA_ROUTER: + ds_put_cstr(&pin_str, "ND_NA_ROUTER"); pinctrl_handle_nd_na(swconn, &headers, &pin.flow_metadata, &userdata, true); break; case ACTION_OPCODE_PUT_ND: + ds_put_cstr(&pin_str, "PUT_ND"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_put_mac_binding(&pin.flow_metadata.flow, &headers, false); @@ -3140,17 +3151,20 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) break; case ACTION_OPCODE_PUT_FDB: + ds_put_cstr(&pin_str, "PUT_FDB"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_put_fdb(&pin.flow_metadata.flow, &headers); ovs_mutex_unlock(&pinctrl_mutex); break; case ACTION_OPCODE_PUT_DHCPV6_OPTS: + ds_put_cstr(&pin_str, "PUT_DHCPV6_OPTS"); pinctrl_handle_put_dhcpv6_opts(swconn, &packet, &pin, &userdata, &continuation); break; case ACTION_OPCODE_DNS_LOOKUP: + ds_put_cstr(&pin_str, "DNS_LOOKUP"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_dns_lookup(swconn, &packet, &pin, &userdata, &continuation); @@ -3158,63 +3172,83 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) break; case ACTION_OPCODE_LOG: + ds_put_cstr(&pin_str, "LOG"); handle_acl_log(&headers, &userdata); break; case ACTION_OPCODE_PUT_ND_RA_OPTS: + ds_put_cstr(&pin_str, "PUT_ND_RA_OPTS"); pinctrl_handle_put_nd_ra_opts(swconn, &headers, &packet, &pin, &userdata, &continuation); break; case ACTION_OPCODE_ND_NS: + ds_put_cstr(&pin_str, "ND_NS"); pinctrl_handle_nd_ns(swconn, &headers, &packet, &pin.flow_metadata, &userdata); break; case ACTION_OPCODE_ICMP: + ds_put_cstr(&pin_str, "ICMP"); pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, &userdata, true, false); break; case ACTION_OPCODE_ICMP4_ERROR: case ACTION_OPCODE_ICMP6_ERROR: + if (ntohl(ah->opcode) == ACTION_OPCODE_ICMP4_ERROR) { + ds_put_cstr(&pin_str, "ICMP4_ERROR"); + } else { + ds_put_cstr(&pin_str, "ICMP6_ERROR"); + } pinctrl_handle_icmp(swconn, &headers, &packet, &pin.flow_metadata, &userdata, false, false); break; case ACTION_OPCODE_TCP_RESET: + ds_put_cstr(&pin_str, "TCP_RESET"); pinctrl_handle_tcp_reset(swconn, &headers, &packet, &pin.flow_metadata, &userdata, false); break; case ACTION_OPCODE_SCTP_ABORT: + ds_put_cstr(&pin_str, "SCTP_ABORT"); pinctrl_handle_sctp_abort(swconn, &headers, &packet, &pin.flow_metadata, &userdata, false); break; case ACTION_OPCODE_REJECT: + ds_put_cstr(&pin_str, "REJECT"); pinctrl_handle_reject(swconn, &headers, &packet, &pin.flow_metadata, &userdata); break; case ACTION_OPCODE_PUT_ICMP4_FRAG_MTU: case ACTION_OPCODE_PUT_ICMP6_FRAG_MTU: + if (ntohl(ah->opcode) == ACTION_OPCODE_PUT_ICMP4_FRAG_MTU) { + ds_put_cstr(&pin_str, "PUT_ICMP4_FRAG_MTU"); + } else { + ds_put_cstr(&pin_str, "PUT_ICMP6_FRAG_MTU"); + } pinctrl_handle_put_icmp_frag_mtu(swconn, &headers, &packet, &pin, &userdata, &continuation); break; case ACTION_OPCODE_EVENT: + ds_put_cstr(&pin_str, "EVENT"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_event(&userdata); ovs_mutex_unlock(&pinctrl_mutex); break; case ACTION_OPCODE_BIND_VPORT: + ds_put_cstr(&pin_str, "BIND_VPORT"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_bind_vport(&pin.flow_metadata.flow, &userdata); ovs_mutex_unlock(&pinctrl_mutex); break; case ACTION_OPCODE_DHCP6_SERVER: + ds_put_cstr(&pin_str, "DHCP6_SERVER"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_dhcp6_server(swconn, &headers, &packet, &pin.flow_metadata); @@ -3222,6 +3256,7 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) break; case ACTION_OPCODE_HANDLE_SVC_CHECK: + ds_put_cstr(&pin_str, "HANDLE_SVC_CHECK"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_svc_check(swconn, &headers, &packet, &pin.flow_metadata); @@ -3229,16 +3264,45 @@ process_packet_in(struct rconn *swconn, const struct ofp_header *msg) break; case ACTION_OPCODE_BFD_MSG: + ds_put_cstr(&pin_str, "BFD_MSG"); ovs_mutex_lock(&pinctrl_mutex); pinctrl_handle_bfd_msg(swconn, &headers, &packet); ovs_mutex_unlock(&pinctrl_mutex); break; default: + ds_put_format(&pin_str, "unrecognized(%"PRIu32")", + ntohl(ah->opcode)); VLOG_WARN_RL(&rl, "unrecognized packet-in opcode %"PRIu32, ntohl(ah->opcode)); break; } + + + if (VLOG_IS_DBG_ENABLED()) { + 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); } /* Called with in the pinctrl_handler thread context. */ @@ -3256,6 +3320,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()) { @@ -3280,6 +3345,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/tests/ovn.at b/tests/ovn.at index ae832918c..02e64b7b4 100644 --- a/tests/ovn.at +++ b/tests/ovn.at @@ -18019,6 +18019,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 @@ -18209,6 +18211,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 @@ -21075,6 +21079,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 | 66 ++++++++++++++++++++++++++++++++++++++++++++ tests/ovn.at | 8 ++++++ 2 files changed, 74 insertions(+)