Re: [vpp-dev] how to allocate new buffer correctly

2021-01-18 Thread Stanislav Zaikin
Hi Matthew,

Many thanks for opening my eyes. Now everything is perfectly clear for me.

On Mon, 18 Jan 2021 at 18:10, Matthew Smith  wrote:

>
> Hi Stanislav,
>
> As you noted, vlib_buffer_validate_alloc_free() is the only place that
> would change the "known state" of a buffer. All of the calls to that
> function are in vlib/buffer_funcs.h in inline functions in conditional
> blocks with a condition like 'if (CLIB_DEBUG > 0)'. One of those calls is
> made when vlib_buffer_alloc() is called - it
> calls vlib_buffer_alloc_on_numa() which calls vlib_buffer_alloc_from_pool()
> which has several invocations of vlib_buffer_validate_alloc_free() which
> all look like this:
>
>   if (CLIB_DEBUG > 0)
> vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
>  VLIB_BUFFER_KNOWN_FREE);
>
> Since these calls occur in inline functions and are only made when
> CLIB_DEBUG is defined as a value greater than 0, it seems like the issue is
> probably that VPP and the router plugin are being built with CLIB_DEBUG
> defined to different values - one of them is being built with CLIB_DEBUG ==
> 0 and one of them is built with CLIB_DEBUG > 0. Since your backtrace
> shows vlib_buffer_validate_alloc_free() being called from one of the VPP
> virtio nodes, that suggests that VPP was built with CLIB_DEBUG > 0. You are
> probably building the router plugin without explicitly defining a value for
> CLIB_DEBUG so it is ending up defined to 0. To remedy the issue, you could
> either build VPP with CLIB_DEBUG set to 0 (run 'make build-release' instead
> of 'make build') or explicitly define CLIB_DEBUG when you build the router
> plugin.
>
> -Matt
>
>
> On Sat, Jan 16, 2021 at 5:50 AM Stanislav Zaikin 
> wrote:
>
>> I've dug more into this issue. And I noticed strange thing:
>>
>> 187  {
>> (gdb) next
>> 188tap_inject_main_t * im = tap_inject_get_main ();
>> (gdb)
>> 190u32 bi = ~0;
>> (gdb)
>> 194sw_if_index = tap_inject_lookup_sw_if_index_from_tap_fd (fd);
>> (gdb)
>> 195if (sw_if_index == ~0)
>> (gdb)
>> 199if( vlib_buffer_alloc (vm, , 1) != 1 )
>> (gdb)
>> 202b = vlib_get_buffer (vm, bi);
>> (gdb)
>> 207n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
>> (gdb)
>> 208if (n_bytes < 0)
>> (gdb) print b
>> $31 = (vlib_buffer_t *) 0x10027db5c0
>> (gdb) print *b
>> $32 = {{cacheline0 = 0x10027db5c0 "", current_data = 0, current_length = 0, 
>> flags = 0, flow_id = 0, ref_count = 1 '\001', buffer_pool_index = 0 '\000', 
>> error = 0, next_buffer = 0, {current_config_index = 0,
>>   punt_reason = 0}, opaque = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
>> template_end = 0x10027db600 "", second_half = 0x10027db600 "", trace_handle 
>> = 0, total_length_not_including_first_buffer = 0, opaque2 = {
>>   0 }, headroom = 0x10027db640 "", pre_data = '\000' 
>> , "\001", data = 0x10027db6c0 "33"}}
>> (gdb) print bi
>> $33 = 653015
>> (gdb) call vlib_buffer_is_known (vm, bi)
>> $34 = VLIB_BUFFER_KNOWN_FREE
>>
>> For some reason the allocated buffer was marked as free. The only function 
>> that could change its state is vlib_buffer_validate_alloc_free.
>>
>> always_inline __clib_warn_unused_result u32
>> vlib_buffer_alloc_from_pool (vlib_main_t * vm, u32 * buffers, u32
>> n_buffers,
>> u8 buffer_pool_index)
>> {
>> /* omit */
>> if (CLIB_DEBUG > 0)
>> vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
>> VLIB_BUFFER_KNOWN_FREE);
>> return n_buffers;
>>
>> But there's another strange issue. I've tried to debug it with gdb and
>> sometimes vlib_buffer_validate_alloc_free isn't calling for some reason:
>>
>> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool 
>> (buffer_pool_index=0 '\000', n_buffers=1, buffers=0x7fffafc727e0, 
>> vm=0x76d67bc0 )
>> at /usr/include/vlib/buffer_funcs.h:569
>> 569vlib_buffer_main_t *bm = vm->buffer_main;
>> (gdb) next
>> 585bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
>> (gdb)
>> 586bpt = vec_elt_at_index (bp->threads, vm->thread_index);
>> (gdb)
>> 588dst = buffers;
>> (gdb)
>> 589n_left = n_buffers;
>> (gdb)
>> 590len = bpt->n_cached;
>> (gdb)
>> 593if (len >= n_buffers)
>> (gdb)
>> 595src = bpt->cached_buffers + len - n_buffers;
>> (gdb)
>> 596vlib_buffer_copy_indices (dst, src, n_buffers);
>> (gdb)
>> 597bpt->n_cached -= n_buffers;
>> (gdb)
>> 602return n_buffers;
>> (gdb) nextvlib_buffer_alloc_on_numa (numa_node=0, n_buffers=1, 
>> buffers=0x7fffafc727e0, vm=0x76d67bc0 ) at 
>> /usr/include/vlib/buffer_funcs.h:664
>> 664return vlib_buffer_alloc_from_pool (vm, buffers, n_buffers, index);
>> (gdb) cont
>> Continuing.
>> [New Thread 0x7fffacc9b700 (LWP 127836)]
>> [Thread 0x7fffacc9b700 (LWP 127836) exited]
>>
>> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool 
>> (vm=0x76d67bc0 , buffers=0x7fffb74e4dfc, n_buffers=64, 
>> buffer_pool_index=0 '\000')
>> at 

Re: [vpp-dev] how to allocate new buffer correctly

2021-01-18 Thread Matthew Smith via lists.fd.io
Hi Stanislav,

As you noted, vlib_buffer_validate_alloc_free() is the only place that
would change the "known state" of a buffer. All of the calls to that
function are in vlib/buffer_funcs.h in inline functions in conditional
blocks with a condition like 'if (CLIB_DEBUG > 0)'. One of those calls is
made when vlib_buffer_alloc() is called - it
calls vlib_buffer_alloc_on_numa() which calls vlib_buffer_alloc_from_pool()
which has several invocations of vlib_buffer_validate_alloc_free() which
all look like this:

  if (CLIB_DEBUG > 0)
vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
 VLIB_BUFFER_KNOWN_FREE);

Since these calls occur in inline functions and are only made when
CLIB_DEBUG is defined as a value greater than 0, it seems like the issue is
probably that VPP and the router plugin are being built with CLIB_DEBUG
defined to different values - one of them is being built with CLIB_DEBUG ==
0 and one of them is built with CLIB_DEBUG > 0. Since your backtrace
shows vlib_buffer_validate_alloc_free() being called from one of the VPP
virtio nodes, that suggests that VPP was built with CLIB_DEBUG > 0. You are
probably building the router plugin without explicitly defining a value for
CLIB_DEBUG so it is ending up defined to 0. To remedy the issue, you could
either build VPP with CLIB_DEBUG set to 0 (run 'make build-release' instead
of 'make build') or explicitly define CLIB_DEBUG when you build the router
plugin.

-Matt


On Sat, Jan 16, 2021 at 5:50 AM Stanislav Zaikin  wrote:

> I've dug more into this issue. And I noticed strange thing:
>
> 187   {
> (gdb) next
> 188 tap_inject_main_t * im = tap_inject_get_main ();
> (gdb)
> 190 u32 bi = ~0;
> (gdb)
> 194 sw_if_index = tap_inject_lookup_sw_if_index_from_tap_fd (fd);
> (gdb)
> 195 if (sw_if_index == ~0)
> (gdb)
> 199 if( vlib_buffer_alloc (vm, , 1) != 1 )
> (gdb)
> 202 b = vlib_get_buffer (vm, bi);
> (gdb)
> 207 n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
> (gdb)
> 208 if (n_bytes < 0)
> (gdb) print b
> $31 = (vlib_buffer_t *) 0x10027db5c0
> (gdb) print *b
> $32 = {{cacheline0 = 0x10027db5c0 "", current_data = 0, current_length = 0, 
> flags = 0, flow_id = 0, ref_count = 1 '\001', buffer_pool_index = 0 '\000', 
> error = 0, next_buffer = 0, {current_config_index = 0,
>   punt_reason = 0}, opaque = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, template_end 
> = 0x10027db600 "", second_half = 0x10027db600 "", trace_handle = 0, 
> total_length_not_including_first_buffer = 0, opaque2 = {
>   0 }, headroom = 0x10027db640 "", pre_data = '\000' 
> , "\001", data = 0x10027db6c0 "33"}}
> (gdb) print bi
> $33 = 653015
> (gdb) call vlib_buffer_is_known (vm, bi)
> $34 = VLIB_BUFFER_KNOWN_FREE
>
> For some reason the allocated buffer was marked as free. The only function 
> that could change its state is vlib_buffer_validate_alloc_free.
>
> always_inline __clib_warn_unused_result u32
> vlib_buffer_alloc_from_pool (vlib_main_t * vm, u32 * buffers, u32
> n_buffers,
> u8 buffer_pool_index)
> {
> /* omit */
> if (CLIB_DEBUG > 0)
> vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
> VLIB_BUFFER_KNOWN_FREE);
> return n_buffers;
>
> But there's another strange issue. I've tried to debug it with gdb and
> sometimes vlib_buffer_validate_alloc_free isn't calling for some reason:
>
> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool 
> (buffer_pool_index=0 '\000', n_buffers=1, buffers=0x7fffafc727e0, 
> vm=0x76d67bc0 )
> at /usr/include/vlib/buffer_funcs.h:569
> 569 vlib_buffer_main_t *bm = vm->buffer_main;
> (gdb) next
> 585 bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
> (gdb)
> 586 bpt = vec_elt_at_index (bp->threads, vm->thread_index);
> (gdb)
> 588 dst = buffers;
> (gdb)
> 589 n_left = n_buffers;
> (gdb)
> 590 len = bpt->n_cached;
> (gdb)
> 593 if (len >= n_buffers)
> (gdb)
> 595 src = bpt->cached_buffers + len - n_buffers;
> (gdb)
> 596 vlib_buffer_copy_indices (dst, src, n_buffers);
> (gdb)
> 597 bpt->n_cached -= n_buffers;
> (gdb)
> 602 return n_buffers;
> (gdb) nextvlib_buffer_alloc_on_numa (numa_node=0, n_buffers=1, 
> buffers=0x7fffafc727e0, vm=0x76d67bc0 ) at 
> /usr/include/vlib/buffer_funcs.h:664
> 664 return vlib_buffer_alloc_from_pool (vm, buffers, n_buffers, index);
> (gdb) cont
> Continuing.
> [New Thread 0x7fffacc9b700 (LWP 127836)]
> [Thread 0x7fffacc9b700 (LWP 127836) exited]
>
> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool 
> (vm=0x76d67bc0 , buffers=0x7fffb74e4dfc, n_buffers=64, 
> buffer_pool_index=0 '\000')
> at /home/zstas/vpp/src/vlib/buffer_funcs.h:569
> 569 vlib_buffer_main_t *bm = vm->buffer_main;
> (gdb) next
> 585 bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
> (gdb)
> 586 bpt = vec_elt_at_index (bp->threads, vm->thread_index);
> (gdb)
> 588 dst = buffers;
> (gdb)
> 589 

Re: [vpp-dev] how to allocate new buffer correctly

2021-01-18 Thread Benoit Ganne (bganne) via lists.fd.io
Hi Stanislas,

All I can say is the buffer management routine are widely used & tested so 
chances are the bug comes from your code but it is hard to guess what is 
happening without looking into it. If you can share it, we can have a quick 
look to see if we can spot any obvious error there.
By the way, if you are looking at using a TAP device, VPP already has an 
optimized driver for it, see src/vnet/devices/tap and 'create tap ...' commands.

Best
ben

> -Original Message-
> From: vpp-dev@lists.fd.io  On Behalf Of Stanislav
> Zaikin
> Sent: samedi 16 janvier 2021 12:50
> To: vpp-dev 
> Subject: Re: [vpp-dev] how to allocate new buffer correctly
> 
> I've dug more into this issue. And I noticed strange thing:
> 187   {
> (gdb) next
> 188 tap_inject_main_t * im = tap_inject_get_main ();
> (gdb)
> 190 u32 bi = ~0;
> (gdb)
> 194 sw_if_index = tap_inject_lookup_sw_if_index_from_tap_fd (fd);
> (gdb)
> 195 if (sw_if_index == ~0)
> (gdb)
> 199 if( vlib_buffer_alloc (vm, , 1) != 1 )
> (gdb)
> 202 b = vlib_get_buffer (vm, bi);
> (gdb)
> 207 n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size
> (vm));
> (gdb)
> 208 if (n_bytes < 0)
> (gdb) print b
> $31 = (vlib_buffer_t *) 0x10027db5c0
> (gdb) print *b
> $32 = {{cacheline0 = 0x10027db5c0 "", current_data = 0, current_length =
> 0, flags = 0, flow_id = 0, ref_count = 1 '\001', buffer_pool_index = 0
> '\000', error = 0, next_buffer = 0, {current_config_index = 0,
>   punt_reason = 0}, opaque = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
> template_end = 0x10027db600 "", second_half = 0x10027db600 "",
> trace_handle = 0, total_length_not_including_first_buffer = 0, opaque2 = {
>   0 }, headroom = 0x10027db640 "", pre_data = '\000'
> , "\001", data = 0x10027db6c0 "33"}}
> (gdb) print bi
> $33 = 653015
> (gdb) call vlib_buffer_is_known (vm, bi)
> $34 = VLIB_BUFFER_KNOWN_FREE
> 
> For some reason the allocated buffer was marked as free. The only function
> that could change its state is vlib_buffer_validate_alloc_free.
> 
> 
> always_inline __clib_warn_unused_result u32
> vlib_buffer_alloc_from_pool (vlib_main_t * vm, u32 * buffers, u32
> n_buffers,
> u8 buffer_pool_index)
> {
> /* omit */
> if (CLIB_DEBUG > 0)
> vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
> VLIB_BUFFER_KNOWN_FREE);
> return n_buffers;
> 
> 
> But there's another strange issue. I've tried to debug it with gdb and
> sometimes vlib_buffer_validate_alloc_free isn't calling for some reason:
> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool
> (buffer_pool_index=0 '\000', n_buffers=1, buffers=0x7fffafc727e0,
> vm=0x76d67bc0 )
> at /usr/include/vlib/buffer_funcs.h:569
> 569 vlib_buffer_main_t *bm = vm->buffer_main;
> (gdb) next
> 585 bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
> (gdb)
> 586 bpt = vec_elt_at_index (bp->threads, vm->thread_index);
> (gdb)
> 588 dst = buffers;
> (gdb)
> 589 n_left = n_buffers;
> (gdb)
> 590 len = bpt->n_cached;
> (gdb)
> 593 if (len >= n_buffers)
> (gdb)
> 595 src = bpt->cached_buffers + len - n_buffers;
> (gdb)
> 596 vlib_buffer_copy_indices (dst, src, n_buffers);
> (gdb)
> 597 bpt->n_cached -= n_buffers;
> (gdb)
> 602 return n_buffers;
> (gdb) next
> vlib_buffer_alloc_on_numa (numa_node=0, n_buffers=1,
> buffers=0x7fffafc727e0, vm=0x76d67bc0 ) at
> /usr/include/vlib/buffer_funcs.h:664
> 664 return vlib_buffer_alloc_from_pool (vm, buffers, n_buffers,
> index);
> (gdb) cont
> Continuing.
> [New Thread 0x7fffacc9b700 (LWP 127836)]
> [Thread 0x7fffacc9b700 (LWP 127836) exited]
> 
> Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool
> (vm=0x76d67bc0 , buffers=0x7fffb74e4dfc,
> n_buffers=64, buffer_pool_index=0 '\000')
> at /home/zstas/vpp/src/vlib/buffer_funcs.h:569
> 569 vlib_buffer_main_t *bm = vm->buffer_main;
> (gdb) next
> 585 bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
> (gdb)
> 586 bpt = vec_elt_at_index (bp->threads, vm->thread_index);
> (gdb)
> 588 dst = buffers;
> (gdb)
> 589 n_left = n_buffers;
> (gdb)
> 590 len = bpt->n_cached;
> (gdb)
> 593 if (len >= n_buffers)
> (gdb)
> 595 src = bpt->cached_buffers + len - n_buffers;
> (gdb)
> 596 vlib_buffer_copy_indices (dst, src, n_buffers);
> (gdb)
> 597 bpt->n_cached -= n_buffers;
> (gdb)
> 600   vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
> (gdb)
>

Re: [vpp-dev] how to allocate new buffer correctly

2021-01-16 Thread Stanislav Zaikin
I've dug more into this issue. And I noticed strange thing:

187 {
(gdb) next
188   tap_inject_main_t * im = tap_inject_get_main ();
(gdb)
190   u32 bi = ~0;
(gdb)
194   sw_if_index = tap_inject_lookup_sw_if_index_from_tap_fd (fd);
(gdb)
195   if (sw_if_index == ~0)
(gdb)
199   if( vlib_buffer_alloc (vm, , 1) != 1 )
(gdb)
202   b = vlib_get_buffer (vm, bi);
(gdb)
207   n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
(gdb)
208   if (n_bytes < 0)
(gdb) print b
$31 = (vlib_buffer_t *) 0x10027db5c0
(gdb) print *b
$32 = {{cacheline0 = 0x10027db5c0 "", current_data = 0, current_length
= 0, flags = 0, flow_id = 0, ref_count = 1 '\001', buffer_pool_index =
0 '\000', error = 0, next_buffer = 0, {current_config_index = 0,
  punt_reason = 0}, opaque = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0},
template_end = 0x10027db600 "", second_half = 0x10027db600 "",
trace_handle = 0, total_length_not_including_first_buffer = 0, opaque2
= {
  0 }, headroom = 0x10027db640 "", pre_data =
'\000' , "\001", data = 0x10027db6c0 "33"}}
(gdb) print bi
$33 = 653015
(gdb) call vlib_buffer_is_known (vm, bi)
$34 = VLIB_BUFFER_KNOWN_FREE

For some reason the allocated buffer was marked as free. The only
function that could change its state is
vlib_buffer_validate_alloc_free.

always_inline __clib_warn_unused_result u32
vlib_buffer_alloc_from_pool (vlib_main_t * vm, u32 * buffers, u32 n_buffers,
u8 buffer_pool_index)
{
/* omit */
if (CLIB_DEBUG > 0)
vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
VLIB_BUFFER_KNOWN_FREE);
return n_buffers;

But there's another strange issue. I've tried to debug it with gdb and
sometimes vlib_buffer_validate_alloc_free isn't calling for some reason:

Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool
(buffer_pool_index=0 '\000', n_buffers=1, buffers=0x7fffafc727e0,
vm=0x76d67bc0 )
at /usr/include/vlib/buffer_funcs.h:569
569   vlib_buffer_main_t *bm = vm->buffer_main;
(gdb) next
585   bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
(gdb)
586   bpt = vec_elt_at_index (bp->threads, vm->thread_index);
(gdb)
588   dst = buffers;
(gdb)
589   n_left = n_buffers;
(gdb)
590   len = bpt->n_cached;
(gdb)
593   if (len >= n_buffers)
(gdb)
595   src = bpt->cached_buffers + len - n_buffers;
(gdb)
596   vlib_buffer_copy_indices (dst, src, n_buffers);
(gdb)
597   bpt->n_cached -= n_buffers;
(gdb)
602   return n_buffers;
(gdb) nextvlib_buffer_alloc_on_numa (numa_node=0, n_buffers=1,
buffers=0x7fffafc727e0, vm=0x76d67bc0 ) at
/usr/include/vlib/buffer_funcs.h:664
664   return vlib_buffer_alloc_from_pool (vm, buffers, n_buffers, index);
(gdb) cont
Continuing.
[New Thread 0x7fffacc9b700 (LWP 127836)]
[Thread 0x7fffacc9b700 (LWP 127836) exited]

Thread 1 "vpp_main" hit Breakpoint 1, vlib_buffer_alloc_from_pool
(vm=0x76d67bc0 , buffers=0x7fffb74e4dfc,
n_buffers=64, buffer_pool_index=0 '\000')
at /home/zstas/vpp/src/vlib/buffer_funcs.h:569
569   vlib_buffer_main_t *bm = vm->buffer_main;
(gdb) next
585   bp = vec_elt_at_index (bm->buffer_pools, buffer_pool_index);
(gdb)
586   bpt = vec_elt_at_index (bp->threads, vm->thread_index);
(gdb)
588   dst = buffers;
(gdb)
589   n_left = n_buffers;
(gdb)
590   len = bpt->n_cached;
(gdb)
593   if (len >= n_buffers)
(gdb)
595   src = bpt->cached_buffers + len - n_buffers;
(gdb)
596   vlib_buffer_copy_indices (dst, src, n_buffers);
(gdb)
597   bpt->n_cached -= n_buffers;
(gdb) *600  vlib_buffer_validate_alloc_free (vm, buffers, n_buffers,
*(gdb)
602   return n_buffers;
(gdb)
648 }
(gdb) cont

I have no idea why in the first run vlib_buffer_validate_alloc_free
hadn't been called (second run was ok). Because there is the same code
according to debug info in gdb.

I hope you'll point me where I'm wrong.


On Sat, 16 Jan 2021 at 12:07, Stanislav Zaikin via lists.fd.io  wrote:

> Hello Damjan,
> Thanks for the response.
>
> Nothing special happens, I just want to send this packet to another
> interface.
> Interface TX is just a regular VPP node (TX for tapv2/virtio). This packet
> went to error-node because the interface was down. But if I set interface
> up, everything looks just the same (error on freeing this buffer):
>
> (gdb) bt
> #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> #1  0x76936859 in __GI_abort () at abort.c:79
> #2  0x76bd73bf in os_panic () at 
> /home/zstas/vpp/src/vppinfra/unix-misc.c:177
> #3  0x76b37ea4 in debugger () at 
> /home/zstas/vpp/src/vppinfra/error.c:84
> #4  0x76b38295 in _clib_error (how_to_die=2, 
> function_name=0x76d39c40 <__FUNCTION__.16> 
> "vlib_buffer_validate_alloc_free", line_number=366, fmt=0x76d3974a "%s %U 
> buffer 0x%x")
> at /home/zstas/vpp/src/vppinfra/error.c:143
> #5  0x76c644fc in vlib_buffer_validate_alloc_free 

Re: [vpp-dev] how to allocate new buffer correctly

2021-01-16 Thread Stanislav Zaikin
Hello Damjan,
Thanks for the response.

Nothing special happens, I just want to send this packet to another
interface.
Interface TX is just a regular VPP node (TX for tapv2/virtio). This packet
went to error-node because the interface was down. But if I set interface
up, everything looks just the same (error on freeing this buffer):

(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x76936859 in __GI_abort () at abort.c:79
#2  0x76bd73bf in os_panic () at
/home/zstas/vpp/src/vppinfra/unix-misc.c:177
#3  0x76b37ea4 in debugger () at /home/zstas/vpp/src/vppinfra/error.c:84
#4  0x76b38295 in _clib_error (how_to_die=2,
function_name=0x76d39c40 <__FUNCTION__.16>
"vlib_buffer_validate_alloc_free", line_number=366, fmt=0x76d3974a
"%s %U buffer 0x%x")
at /home/zstas/vpp/src/vppinfra/error.c:143
#5  0x76c644fc in vlib_buffer_validate_alloc_free
(vm=0x76d67bc0 , buffers=0x7fffafc730b0,
n_buffers=1, expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
at /home/zstas/vpp/src/vlib/buffer.c:366
#6  0x76f753ec in vlib_buffer_pool_put (vm=0x76d67bc0
, buffer_pool_index=0 '\000',
buffers=0x7fffafc730b0, n_buffers=1) at
/home/zstas/vpp/src/vlib/buffer_funcs.h:754
#7  0x76f75c29 in vlib_buffer_free_inline (vm=0x76d67bc0
, buffers=0x7fffb74f0044, n_buffers=0, maybe_next=1)
at /home/zstas/vpp/src/vlib/buffer_funcs.h:924
#8  0x76f75c79 in vlib_buffer_free (vm=0x76d67bc0
, buffers=0x7fffb74f0040, n_buffers=1) at
/home/zstas/vpp/src/vlib/buffer_funcs.h:943
#9  0x76f75d1a in vlib_buffer_free_from_ring
(vm=0x76d67bc0 , ring=0x7fffb74f0040, start=0,
ring_size=256, n_buffers=1) at
/home/zstas/vpp/src/vlib/buffer_funcs.h:991
#10 0x76f79af4 in virtio_free_used_device_desc_split
(vm=0x76d67bc0 , vring=0x7fffb75ab540,
node_index=679) at
/home/zstas/vpp/src/vnet/devices/virtio/device.c:200
#11 0x76f79dc2 in virtio_free_used_device_desc
(vm=0x76d67bc0 , vring=0x7fffb75ab540,
node_index=679, packed=0) at
/home/zstas/vpp/src/vnet/devices/virtio/device.c:277
#12 0x76f7baed in virtio_device_class_tx_fn_hsw
(vm=0x76d67bc0 , node=0x7fffb6b73800,
frame=0x7fffb96ff8c0) at
/home/zstas/vpp/src/vnet/devices/virtio/device.c:1017
#13 0x76cba2e2 in dispatch_node (vm=0x76d67bc0
, node=0x7fffb6b73800, type=VLIB_NODE_TYPE_INTERNAL,
dispatch_state=VLIB_NODE_STATE_POLLING, frame=0x7fffb96ff8c0,
last_time_stamp=1108992938029) at /home/zstas/vpp/src/vlib/main.c:1223
#14 0x76cbaa19 in dispatch_pending_node (vm=0x76d67bc0
, pending_frame_index=1,
last_time_stamp=1108992938029) at /home/zstas/vpp/src/vlib/main.c:1384
#15 0x76cbcdd3 in vlib_main_or_worker_loop (vm=0x76d67bc0
, is_main=1) at /home/zstas/vpp/src/vlib/main.c:1912
#16 0x76cbd848 in vlib_main_loop (vm=0x76d67bc0
) at /home/zstas/vpp/src/vlib/main.c:2040
#17 0x76cbe66b in vlib_main (vm=0x76d67bc0
, input=0x7fffafc73fb0) at
/home/zstas/vpp/src/vlib/main.c:2286
#18 0x76d29ac5 in thread0 (arg=140737334639552) at
/home/zstas/vpp/src/vlib/unix/main.c:670
#19 0x76b56f10 in clib_calljmp () at
/home/zstas/vpp/src/vppinfra/longjmp.S:123
#20 0x7fffd150 in ?? ()
#21 0x76d2a095 in vlib_unix_main (argc=28,
argv=0x55631e50) at /home/zstas/vpp/src/vlib/unix/main.c:747
#22 0xcd8b in main (argc=28, argv=0x55631e50) at
/home/zstas/vpp/src/vpp/vnet/main.c:338


On Fri, 15 Jan 2021 at 19:57, Damjan Marion  wrote:

>
> This looks right (except the wrong assumption that vlib_get_frame_to_node
> will give you empty frame).
>
>
> What happens between this code and error-drop node? Is interface TX also
> your custom code?
>
> —
> Damjan
>
>
> On 15.01.2021., at 17:03, Stanislav Zaikin  wrote:
>
> Hello,
>
> I'm trying to reincarnate router plugin. But I stuck with a pretty simple
> thing, when I need to allocate a buffer to store a packet from a tap
> device, everything is going well. But when the next node decides to free
> this buffer I get a clib_error.
>
> Basically, code is pretty simple and straightforward:
> u32 bi = ~0;
> vlib_buffer_t * b;
>
> if( vlib_buffer_alloc (vm, , 1) != 1 )
> //err handling
>
> b = vlib_get_buffer (vm, bi);
> VLIB_BUFFER_TRACE_TRAJECTORY_INIT(b);
>
> n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
> // err handling
>
> b->current_length = n_bytes;
> vnet_buffer (b)->sw_if_index[VLIB_RX] = sw_if_index;
> vnet_buffer (b)->sw_if_index[VLIB_TX] = sw_if_index;
>
> vnet_hw_interface_t * hw;
> vlib_frame_t * new_frame;
> u32 * to_next;
>
> hw = vnet_get_hw_interface (vnet_get_main (), sw_if_index);
>
> new_frame = vlib_get_frame_to_node (vm, hw->output_node_index);
> to_next = vlib_frame_vector_args (new_frame);
> to_next[0] = bi;
> new_frame->n_vectors = 1;
>
> vlib_put_frame_to_node (vm, hw->output_node_index, new_frame);
>
> Error looks like:
>
> gdb) bt
> #0  __GI_raise (sig=sig@entry=6) at 

Re: [vpp-dev] how to allocate new buffer correctly

2021-01-15 Thread Damjan Marion via lists.fd.io

This looks right (except the wrong assumption that vlib_get_frame_to_node will 
give you empty frame).


What happens between this code and error-drop node? Is interface TX also your 
custom code?

— 
Damjan


> On 15.01.2021., at 17:03, Stanislav Zaikin  wrote:
> 
> Hello,
> 
> I'm trying to reincarnate router plugin. But I stuck with a pretty simple 
> thing, when I need to allocate a buffer to store a packet from a tap device, 
> everything is going well. But when the next node decides to free this buffer 
> I get a clib_error.
> 
> Basically, code is pretty simple and straightforward:
> u32 bi = ~0;
> vlib_buffer_t * b;
> 
> if( vlib_buffer_alloc (vm, , 1) != 1 )
> //err handling
> 
> b = vlib_get_buffer (vm, bi);
> VLIB_BUFFER_TRACE_TRAJECTORY_INIT(b);
> 
> n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
> // err handling
> 
> b->current_length = n_bytes;
> vnet_buffer (b)->sw_if_index[VLIB_RX] = sw_if_index;
> vnet_buffer (b)->sw_if_index[VLIB_TX] = sw_if_index;
> 
> vnet_hw_interface_t * hw;
> vlib_frame_t * new_frame;
> u32 * to_next;
> 
> hw = vnet_get_hw_interface (vnet_get_main (), sw_if_index);
> 
> new_frame = vlib_get_frame_to_node (vm, hw->output_node_index);
> to_next = vlib_frame_vector_args (new_frame);
> to_next[0] = bi;
> new_frame->n_vectors = 1;
> 
> vlib_put_frame_to_node (vm, hw->output_node_index, new_frame);
> 
> Error looks like:
> gdb) bt
> #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> #1  0x76936859 in __GI_abort () at abort.c:79
> #2  0x76bd73bf in os_panic () at 
> /home/zstas/vpp/src/vppinfra/unix-misc.c:177
> #3  0x76b37ea4 in debugger () at 
> /home/zstas/vpp/src/vppinfra/error.c:84
> #4  0x76b38295 in _clib_error (how_to_die=2, 
> function_name=0x76d39c40 <__FUNCTION__.16> 
> "vlib_buffer_validate_alloc_free", line_number=366, fmt=0x76d3974a "%s %U 
> buffer 0x%x")
> at /home/zstas/vpp/src/vppinfra/error.c:143
> #5  0x76c644fc in vlib_buffer_validate_alloc_free (vm=0x76d67bc0 
> , buffers=0x7fffafc725f0, n_buffers=1, 
> expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
> at /home/zstas/vpp/src/vlib/buffer.c:366
> #6  0x76c4a08c in vlib_buffer_pool_put (vm=0x76d67bc0 
> , buffer_pool_index=0 '\000', buffers=0x7fffafc725f0, 
> n_buffers=1) at /home/zstas/vpp/src/vlib/buffer_funcs.h:754
> #7  0x76c4a8c9 in vlib_buffer_free_inline (vm=0x76d67bc0 
> , buffers=0x7fffb6b37ed4, n_buffers=0, maybe_next=1) at 
> /home/zstas/vpp/src/vlib/buffer_funcs.h:924
> #8  0x76c4a919 in vlib_buffer_free (vm=0x76d67bc0 
> , buffers=0x7fffb6b37ed0, n_buffers=1) at 
> /home/zstas/vpp/src/vlib/buffer_funcs.h:943
> #9  0x76c4b3b5 in process_drop_punt (vm=0x76d67bc0 
> , node=0x7fffb6b772c0, frame=0x7fffb6b37ec0, 
> disposition=ERROR_DISPOSITION_DROP) at /home/zstas/vpp/src/vlib/drop.c:231
> #10 0x76c4b4bf in error_drop_node_fn_hsw (vm=0x76d67bc0 
> , node=0x7fffb6b772c0, frame=0x7fffb6b37ec0) at 
> /home/zstas/vpp/src/vlib/drop.c:247
> #11 0x76cba2e2 in dispatch_node (vm=0x76d67bc0 
> , node=0x7fffb6b772c0, type=VLIB_NODE_TYPE_INTERNAL, 
> dispatch_state=VLIB_NODE_STATE_POLLING, frame=0x7fffb6b37ec0, 
> last_time_stamp=77969722318942) at /home/zstas/vpp/src/vlib/main.c:1223
> #12 0x76cbaa19 in dispatch_pending_node (vm=0x76d67bc0 
> , pending_frame_index=2, last_time_stamp=77969722318942) at 
> /home/zstas/vpp/src/vlib/main.c:1384
> #13 0x76cbcdd3 in vlib_main_or_worker_loop (vm=0x76d67bc0 
> , is_main=1) at /home/zstas/vpp/src/vlib/main.c:1912
> #14 0x76cbd848 in vlib_main_loop (vm=0x76d67bc0 
> ) at /home/zstas/vpp/src/vlib/main.c:2040
> #15 0x76cbe66b in vlib_main (vm=0x76d67bc0 , 
> input=0x7fffafc73fb0) at /home/zstas/vpp/src/vlib/main.c:2286
> #16 0x76d29ac5 in thread0 (arg=140737334639552) at 
> /home/zstas/vpp/src/vlib/unix/main.c:670
> #17 0x76b56f10 in clib_calljmp () at 
> /home/zstas/vpp/src/vppinfra/longjmp.S:123
> #18 0x7fffd150 in ?? ()
> #19 0x76d2a095 in vlib_unix_main (argc=28, argv=0x55631e50) at 
> /home/zstas/vpp/src/vlib/unix/main.c:747
> #20 0xcd8b in main (argc=28, argv=0x55631e50) at 
> /home/zstas/vpp/src/vpp/vnet/main.c:338
> Buffer index seems right:
> Thread 1 "vpp_main" hit Breakpoint 1, tap_rx (vm=0x76d67bc0 
> , node=0x7fffb6a75d00, f=0x0, fd=23) at 
> router/tap_inject_node.c:187
> warning: Source file is more recent than executable.
> (gdb) info locals
> im = 0x7fffb002b7c0 
> sw_if_index = 1
> bi = 653093
> b = 0x10027dc940
> n_bytes = 90
> __FUNCTION__ = "tap_rx"
> /* later */
> Thread 1 "vpp_main" received signal SIGABRT, Aborted.
> __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> 50../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> (gdb) bt
> #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
> #1  

[vpp-dev] how to allocate new buffer correctly

2021-01-15 Thread Stanislav Zaikin
Hello,

I'm trying to reincarnate router plugin. But I stuck with a pretty simple
thing, when I need to allocate a buffer to store a packet from a tap
device, everything is going well. But when the next node decides to free
this buffer I get a clib_error.

Basically, code is pretty simple and straightforward:
u32 bi = ~0;
vlib_buffer_t * b;

if( vlib_buffer_alloc (vm, , 1) != 1 )
//err handling

b = vlib_get_buffer (vm, bi);
VLIB_BUFFER_TRACE_TRAJECTORY_INIT(b);

n_bytes = read (fd, b->data, vlib_buffer_get_default_data_size (vm));
// err handling

b->current_length = n_bytes;
vnet_buffer (b)->sw_if_index[VLIB_RX] = sw_if_index;
vnet_buffer (b)->sw_if_index[VLIB_TX] = sw_if_index;

vnet_hw_interface_t * hw;
vlib_frame_t * new_frame;
u32 * to_next;

hw = vnet_get_hw_interface (vnet_get_main (), sw_if_index);

new_frame = vlib_get_frame_to_node (vm, hw->output_node_index);
to_next = vlib_frame_vector_args (new_frame);
to_next[0] = bi;
new_frame->n_vectors = 1;

vlib_put_frame_to_node (vm, hw->output_node_index, new_frame);

Error looks like:

gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x76936859 in __GI_abort () at abort.c:79
#2  0x76bd73bf in os_panic () at
/home/zstas/vpp/src/vppinfra/unix-misc.c:177
#3  0x76b37ea4 in debugger () at /home/zstas/vpp/src/vppinfra/error.c:84
#4  0x76b38295 in _clib_error (how_to_die=2,
function_name=0x76d39c40 <__FUNCTION__.16>
"vlib_buffer_validate_alloc_free", line_number=366, fmt=0x76d3974a
"%s %U buffer 0x%x")
at /home/zstas/vpp/src/vppinfra/error.c:143
#5  0x76c644fc in vlib_buffer_validate_alloc_free
(vm=0x76d67bc0 , buffers=0x7fffafc725f0,
n_buffers=1, expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
at /home/zstas/vpp/src/vlib/buffer.c:366
#6  0x76c4a08c in vlib_buffer_pool_put (vm=0x76d67bc0
, buffer_pool_index=0 '\000',
buffers=0x7fffafc725f0, n_buffers=1) at
/home/zstas/vpp/src/vlib/buffer_funcs.h:754
#7  0x76c4a8c9 in vlib_buffer_free_inline (vm=0x76d67bc0
, buffers=0x7fffb6b37ed4, n_buffers=0, maybe_next=1)
at /home/zstas/vpp/src/vlib/buffer_funcs.h:924
#8  0x76c4a919 in vlib_buffer_free (vm=0x76d67bc0
, buffers=0x7fffb6b37ed0, n_buffers=1) at
/home/zstas/vpp/src/vlib/buffer_funcs.h:943
#9  0x76c4b3b5 in process_drop_punt (vm=0x76d67bc0
, node=0x7fffb6b772c0, frame=0x7fffb6b37ec0,
disposition=ERROR_DISPOSITION_DROP) at
/home/zstas/vpp/src/vlib/drop.c:231
#10 0x76c4b4bf in error_drop_node_fn_hsw (vm=0x76d67bc0
, node=0x7fffb6b772c0, frame=0x7fffb6b37ec0) at
/home/zstas/vpp/src/vlib/drop.c:247
#11 0x76cba2e2 in dispatch_node (vm=0x76d67bc0
, node=0x7fffb6b772c0, type=VLIB_NODE_TYPE_INTERNAL,
dispatch_state=VLIB_NODE_STATE_POLLING, frame=0x7fffb6b37ec0,
last_time_stamp=77969722318942) at /home/zstas/vpp/src/vlib/main.c:1223
#12 0x76cbaa19 in dispatch_pending_node (vm=0x76d67bc0
, pending_frame_index=2,
last_time_stamp=77969722318942) at
/home/zstas/vpp/src/vlib/main.c:1384
#13 0x76cbcdd3 in vlib_main_or_worker_loop (vm=0x76d67bc0
, is_main=1) at /home/zstas/vpp/src/vlib/main.c:1912
#14 0x76cbd848 in vlib_main_loop (vm=0x76d67bc0
) at /home/zstas/vpp/src/vlib/main.c:2040
#15 0x76cbe66b in vlib_main (vm=0x76d67bc0
, input=0x7fffafc73fb0) at
/home/zstas/vpp/src/vlib/main.c:2286
#16 0x76d29ac5 in thread0 (arg=140737334639552) at
/home/zstas/vpp/src/vlib/unix/main.c:670
#17 0x76b56f10 in clib_calljmp () at
/home/zstas/vpp/src/vppinfra/longjmp.S:123
#18 0x7fffd150 in ?? ()
#19 0x76d2a095 in vlib_unix_main (argc=28,
argv=0x55631e50) at /home/zstas/vpp/src/vlib/unix/main.c:747
#20 0xcd8b in main (argc=28, argv=0x55631e50) at
/home/zstas/vpp/src/vpp/vnet/main.c:338

Buffer index seems right:

Thread 1 "vpp_main" hit Breakpoint 1, tap_rx (vm=0x76d67bc0
, node=0x7fffb6a75d00, f=0x0, fd=23) at
router/tap_inject_node.c:187
warning: Source file is more recent than executable.
(gdb) info localsim = 0x7fffb002b7c0 sw_if_index =
1bi = 653093b = 0x10027dc940n_bytes = 90__FUNCTION__ = "tap_rx"

/* later */

Thread 1 "vpp_main" received signal SIGABRT, Aborted.__GI_raise
(sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50  ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x76936859 in __GI_abort () at abort.c:79
#2  0x76bd73bf in os_panic () at
/home/zstas/vpp/src/vppinfra/unix-misc.c:177
#3  0x76b37ea4 in debugger () at /home/zstas/vpp/src/vppinfra/error.c:84
#4  0x76b38295 in _clib_error (how_to_die=2,
function_name=0x76d39c40 <__FUNCTION__.16>
"vlib_buffer_validate_alloc_free", line_number=366, fmt=0x76d3974a
"%s %U buffer 0x%x")
at /home/zstas/vpp/src/vppinfra/error.c:143
#5  0x76c644fc in vlib_buffer_validate_alloc_free
(vm=0x76d67bc0 ,