[dpdk-dev] [PATCH] app/testpmd: fix testpmd packets dump overlapping

[Ferruh Yigit]

On 11/12/2020 8:36 AM, Jiawei Wang wrote:
> When testpmd enabled the verbosity for the received packets, if two packets
> was received at the same time, for example, sampling packet and normal
> packet, the dump output of these packets may be overlapping due to multiple
> core handled the multiple queues simultaneously.
> 

Hi Jiawei,

Is the problem observer only when having sampling? Do you observe the problem 
when multiple cores Rx?

> The patch uses one string buffer that collects all the packet dump output
> into this buffer and then printout it at last, that guarantee to printout
> separately the dump output per packet.
> 
> Fixes: d862c45 ("app/testpmd: move dumping packets to a separate function")
> 
> Signed-off-by: Jiawei Wang <jiaweiw at nvidia.com>
> ---
>   app/test-pmd/util.c | 238 ++++++++++++++++++++++++++++++++++++++--------------
>   1 file changed, 177 insertions(+), 61 deletions(-)
> 
> diff --git a/app/test-pmd/util.c b/app/test-pmd/util.c
> index 649bf8f..47b75b0 100644
> --- a/app/test-pmd/util.c
> +++ b/app/test-pmd/util.c
> @@ -12,15 +12,20 @@
>   #include <rte_vxlan.h>
>   #include <rte_ethdev.h>
>   #include <rte_flow.h>
> +#include <rte_log.h>
>   
>   #include "testpmd.h"
>   
> -static inline void
> -print_ether_addr(const char *what, const struct rte_ether_addr *eth_addr)
> +#define MAX_STRING_LEN 8192
> +
> +static inline int
> +print_ether_addr(const char *what, const struct rte_ether_addr *eth_addr,
> +		 char print_buf[], int buf_size)
>   {
>   	char buf[RTE_ETHER_ADDR_FMT_SIZE];
> +
>   	rte_ether_format_addr(buf, RTE_ETHER_ADDR_FMT_SIZE, eth_addr);
> -	printf("%s%s", what, buf);
> +	return snprintf(print_buf, buf_size, "%s%s", what, buf);
>   }
>   
>   static inline bool
> @@ -74,13 +79,18 @@
>   	uint32_t vx_vni;
>   	const char *reason;
>   	int dynf_index;
> +	int buf_size = MAX_STRING_LEN * nb_pkts;
> +	char print_buf[buf_size];

This is a large value to allocate from stack, specially with larger burst size. 
Allocating from heap is an option but it has a cost.

So what do you think print per packet, instead of print per burst? This also 
prevents display latency of the packet log.

> +	int cur_len = 0;
>   
> +	memset(print_buf, 0, sizeof(print_buf));
>   	if (!nb_pkts)
>   		return;
> -	printf("port %u/queue %u: %s %u packets\n",
> -		port_id, queue,
> -	       is_rx ? "received" : "sent",
> -	       (unsigned int) nb_pkts);
> +	cur_len += snprintf(print_buf + cur_len, buf_size - cur_len,
> +			    "port %u/queue %u: %s %u packets\n",
> +			    port_id, queue,
> +			    is_rx ? "received" : "sent",
> +			    (unsigned int) nb_pkts);
>   	for (i = 0; i < nb_pkts; i++) {
>   		int ret;
>   		struct rte_flow_error error;
> @@ -93,95 +103,183 @@
>   		is_encapsulation = RTE_ETH_IS_TUNNEL_PKT(packet_type);
>   		ret = rte_flow_get_restore_info(port_id, mb, &info, &error);
>   		if (!ret) {
> -			printf("restore info:");
> +			cur_len += snprintf(print_buf + cur_len,
> +					    buf_size - cur_len,
> +					    "restore info:");

This is not safe.
'snprintf' returns size of the required buffer size, not written chars, this can 
make "buf_size - cur_len" a negative value at some point, and since 'size' type 
is unsigned negative value will be converted into a very large number and this 
will corrupt the stack.

<...>

> +	if (cur_len >= buf_size)
> +		TESTPMD_LOG(ERR, "no enough buffer (size: %d) to store "
> +			    "the current dump output (size: %d)\n",
> +			    buf_size, cur_len);

Instead of this error log, which I believe not very useful, why not append some 
chars at the end of the actual buffer to say it is truncated, something like

  if (truncated)
    TESTPMD_LOG(INFO, "%s ...", print_buf);
  else
    TESTPMD_LOG(INFO, "%s", print_buf);