Re: [PATCH 4/4] net/colo: Match is-enabled probe to tracepoint

[Roman Bolshakov]

On Thu, Jul 16, 2020 at 09:51:27AM +0100, Daniel P. Berrangé wrote:
> Adding Stefan to CC as the trace maintainer.
> 
> On Thu, Jul 16, 2020 at 11:17:54AM +0300, Roman Bolshakov wrote:
> > Build of QEMU with dtrace fails on macOS:
> > 
> >   LINK    x86_64-softmmu/qemu-system-x86_64
> > error: probe colo_compare_miscompare doesn't exist
> > error: Could not register probes
> > ld: error creating dtrace DOF section for architecture x86_64
> > 
> > The reason of the error is explained by Adam Leventhal [1]:
> > 
> >   Note that is-enabled probes don't have the stability magic so I'm not
> >   sure how things would work if only is-enabled probes were used.
> > 
> > net/colo code uses is-enabled probes to determine if other probes should
> > be used but colo_compare_miscompare itself is not used explicitly.
> > Linker doesn't include the symbol and build fails.
> > 
> > The issue can be resolved if is-enabled probe matches the actual trace
> > point that is used inside the test.
> > 
> > 1. http://markmail.org/message/6grq2ygr5nwdwsnb
> > 
> > Fixes: f4b618360e ("colo-compare: add TCP, UDP, ICMP packet comparison")
> > Cc: Philippe Mathieu-Daudé <philmd@redhat.com>
> > Cc: Cameron Esfahani <dirty@apple.com>
> > Signed-off-by: Roman Bolshakov <r.bolshakov@yadro.com>
> > ---
> >  net/colo-compare.c    | 12 +++++++-----
> >  net/filter-rewriter.c |  8 ++++++--
> >  net/trace-events      |  2 --
> >  3 files changed, 13 insertions(+), 9 deletions(-)
> > 
> > diff --git a/net/colo-compare.c b/net/colo-compare.c
> > index 398b7546ff..9525ed703b 100644
> > --- a/net/colo-compare.c
> > +++ b/net/colo-compare.c
> > @@ -327,7 +327,7 @@ static int colo_compare_packet_payload(Packet *ppkt,
> >                                         uint16_t len)
> >  
> >  {
> > -    if (trace_event_get_state_backends(TRACE_COLO_COMPARE_MISCOMPARE)) {
> > +    if (trace_event_get_state_backends(TRACE_COLO_COMPARE_IP_INFO)) {
> >          char pri_ip_src[20], pri_ip_dst[20], sec_ip_src[20], 
> > sec_ip_dst[20];
> >  
> >          strcpy(pri_ip_src, inet_ntoa(ppkt->ip->ip_src));
> > @@ -492,7 +492,7 @@ sec:
> >          g_queue_push_head(&conn->primary_list, ppkt);
> >          g_queue_push_head(&conn->secondary_list, spkt);
> >  
> > -        if (trace_event_get_state_backends(TRACE_COLO_COMPARE_MISCOMPARE)) 
> > {
> > +        if (trace_event_get_state_backends(TRACE_COLO_COMPARE_TCP_INFO)) {
> >              qemu_hexdump((char *)ppkt->data, stderr,
> >                          "colo-compare ppkt", ppkt->size);
> >              qemu_hexdump((char *)spkt->data, stderr,
> 
> Not your fault, as this problem is pre-existing, but IMHO this block of code
> is simply broken by design. It is checking a trace event enablement state,
> and then not emitting any trace event, but instead dumping info to stderr.
> This is mis-use of the trace framework, and changing the event name fixes
> your immediate macOS bug but the code is still flawed.
> 
> Basically it is using the trace framework as a way to dynamically turn on /
> off general debugging information.
> 
> I'm not quite sure what todo to fix it, but I don't think it should be wrapped
> in any trace_event_get_state_backends() call at all.
> 
> The simplest immediate option I think is to change it to be a compile time
> debug
> 
>   // #define DEBUG_COLO_PACKETS
> 
> and then use
> 
>   #ifdef DEBUG_COLO_PACKETS
>       qemu_hexdump(...)
>   #endif
> 
> and then leave it upto the maintainer to come up with a more advanced
> solution if they want to make it runtime configurable again, but not
> abusing the trace framework.
> 


Hi Daniel,

It makes sense, compile-time define works better because the trace data
doesn't go into a trace point. I'll use that approach in v2.

> > @@ -533,7 +533,8 @@ static int colo_packet_compare_udp(Packet *spkt, Packet 
> > *ppkt)
> >                                      ppkt->size - offset)) {
> >          trace_colo_compare_udp_miscompare("primary pkt size", ppkt->size);
> >          trace_colo_compare_udp_miscompare("Secondary pkt size", 
> > spkt->size);
> > -        if (trace_event_get_state_backends(TRACE_COLO_COMPARE_MISCOMPARE)) 
> > {
> > +        if (trace_event_get_state_backends(
> > +              TRACE_COLO_COMPARE_UDP_MISCOMPARE)) {
> >              qemu_hexdump((char *)ppkt->data, stderr, "colo-compare pri 
> > pkt",
> >                           ppkt->size);
> >              qemu_hexdump((char *)spkt->data, stderr, "colo-compare sec 
> > pkt",
> 
> Same brokenness
> 
> > @@ -576,7 +577,8 @@ static int colo_packet_compare_icmp(Packet *spkt, 
> > Packet *ppkt)
> >                                             ppkt->size);
> >          trace_colo_compare_icmp_miscompare("Secondary pkt size",
> >                                             spkt->size);
> > -        if (trace_event_get_state_backends(TRACE_COLO_COMPARE_MISCOMPARE)) 
> > {
> > +        if (trace_event_get_state_backends(
> > +              TRACE_COLO_COMPARE_ICMP_MISCOMPARE)) {
> >              qemu_hexdump((char *)ppkt->data, stderr, "colo-compare pri 
> > pkt",
> >                           ppkt->size);
> >              qemu_hexdump((char *)spkt->data, stderr, "colo-compare sec 
> > pkt",
> 
> Same brokenness
> 
> > @@ -597,7 +599,7 @@ static int colo_packet_compare_other(Packet *spkt, 
> > Packet *ppkt)
> >      uint16_t offset = ppkt->vnet_hdr_len;
> >  
> >      trace_colo_compare_main("compare other");
> > -    if (trace_event_get_state_backends(TRACE_COLO_COMPARE_MISCOMPARE)) {
> > +    if (trace_event_get_state_backends(TRACE_COLO_COMPARE_IP_INFO)) {
> >          char pri_ip_src[20], pri_ip_dst[20], sec_ip_src[20], 
> > sec_ip_dst[20];
> >  
> >          strcpy(pri_ip_src, inet_ntoa(ppkt->ip->ip_src));
> > diff --git a/net/filter-rewriter.c b/net/filter-rewriter.c
> > index 1aaad101b6..ff04165cc4 100644
> > --- a/net/filter-rewriter.c
> > +++ b/net/filter-rewriter.c
> > @@ -76,7 +76,9 @@ static int handle_primary_tcp_pkt(RewriterState *rf,
> >      struct tcp_hdr *tcp_pkt;
> >  
> >      tcp_pkt = (struct tcp_hdr *)pkt->transport_header;
> > -    if (trace_event_get_state_backends(TRACE_COLO_FILTER_REWRITER_DEBUG)) {
> > +    if 
> > (trace_event_get_state_backends(TRACE_COLO_FILTER_REWRITER_PKT_INFO) ||
> > +        trace_event_get_state_backends(
> > +          TRACE_COLO_FILTER_REWRITER_CONN_OFFSET)) {
> >          trace_colo_filter_rewriter_pkt_info(__func__,
> >                      inet_ntoa(pkt->ip->ip_src), inet_ntoa(pkt->ip->ip_dst),
> >                      ntohl(tcp_pkt->th_seq), ntohl(tcp_pkt->th_ack),
> 
> Since there are two separate trace events here, each should be wrapped with
> its own check. IOW, two completely separate if (...) trace(..); blocks
> 


Agreed, I'll do that, thanks!

> > @@ -180,7 +182,9 @@ static int handle_secondary_tcp_pkt(RewriterState *rf,
> >  
> >      tcp_pkt = (struct tcp_hdr *)pkt->transport_header;
> >  
> > -    if (trace_event_get_state_backends(TRACE_COLO_FILTER_REWRITER_DEBUG)) {
> > +    if 
> > (trace_event_get_state_backends(TRACE_COLO_FILTER_REWRITER_PKT_INFO) ||
> > +        trace_event_get_state_backends(
> > +          TRACE_COLO_FILTER_REWRITER_CONN_OFFSET)) {
> >          trace_colo_filter_rewriter_pkt_info(__func__,
> >                      inet_ntoa(pkt->ip->ip_src), inet_ntoa(pkt->ip->ip_dst),
> >                      ntohl(tcp_pkt->th_seq), ntohl(tcp_pkt->th_ack),
> 
> Same here.
> 
> 

Best regards,
Roman