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, &bi, 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 <repeats 14 times>}, headroom = 0x10027db640 "", pre_data =
'\000' <repeats 126 times>, "\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=0x7ffff6d67bc0 <vlib_global_main>)
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=0x7ffff6d67bc0 <vlib_global_main>) 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=0x7ffff6d67bc0 <vlib_global_main>, 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 <zstaseg=
gmail....@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 0x00007ffff6936859 in __GI_abort () at abort.c:79
> #2 0x00007ffff6bd73bf in os_panic () at
> /home/zstas/vpp/src/vppinfra/unix-misc.c:177
> #3 0x00007ffff6b37ea4 in debugger () at
> /home/zstas/vpp/src/vppinfra/error.c:84
> #4 0x00007ffff6b38295 in _clib_error (how_to_die=2,
> function_name=0x7ffff6d39c40 <__FUNCTION__.16>
> "vlib_buffer_validate_alloc_free", line_number=366, fmt=0x7ffff6d3974a "%s %U
> buffer 0x%x")
> at /home/zstas/vpp/src/vppinfra/error.c:143
> #5 0x00007ffff6c644fc in vlib_buffer_validate_alloc_free (vm=0x7ffff6d67bc0
> <vlib_global_main>, buffers=0x7fffafc730b0, n_buffers=1,
> expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
> at /home/zstas/vpp/src/vlib/buffer.c:366
> #6 0x00007ffff6f753ec in vlib_buffer_pool_put (vm=0x7ffff6d67bc0
> <vlib_global_main>, buffer_pool_index=0 '\000', buffers=0x7fffafc730b0,
> n_buffers=1) at /home/zstas/vpp/src/vlib/buffer_funcs.h:754
> #7 0x00007ffff6f75c29 in vlib_buffer_free_inline (vm=0x7ffff6d67bc0
> <vlib_global_main>, buffers=0x7fffb74f0044, n_buffers=0, maybe_next=1) at
> /home/zstas/vpp/src/vlib/buffer_funcs.h:924
> #8 0x00007ffff6f75c79 in vlib_buffer_free (vm=0x7ffff6d67bc0
> <vlib_global_main>, buffers=0x7fffb74f0040, n_buffers=1) at
> /home/zstas/vpp/src/vlib/buffer_funcs.h:943
> #9 0x00007ffff6f75d1a in vlib_buffer_free_from_ring (vm=0x7ffff6d67bc0
> <vlib_global_main>, ring=0x7fffb74f0040, start=0, ring_size=256, n_buffers=1)
> at /home/zstas/vpp/src/vlib/buffer_funcs.h:991
> #10 0x00007ffff6f79af4 in virtio_free_used_device_desc_split
> (vm=0x7ffff6d67bc0 <vlib_global_main>, vring=0x7fffb75ab540, node_index=679)
> at /home/zstas/vpp/src/vnet/devices/virtio/device.c:200
> #11 0x00007ffff6f79dc2 in virtio_free_used_device_desc (vm=0x7ffff6d67bc0
> <vlib_global_main>, vring=0x7fffb75ab540, node_index=679, packed=0) at
> /home/zstas/vpp/src/vnet/devices/virtio/device.c:277
> #12 0x00007ffff6f7baed in virtio_device_class_tx_fn_hsw (vm=0x7ffff6d67bc0
> <vlib_global_main>, node=0x7fffb6b73800, frame=0x7fffb96ff8c0) at
> /home/zstas/vpp/src/vnet/devices/virtio/device.c:1017
> #13 0x00007ffff6cba2e2 in dispatch_node (vm=0x7ffff6d67bc0
> <vlib_global_main>, 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 0x00007ffff6cbaa19 in dispatch_pending_node (vm=0x7ffff6d67bc0
> <vlib_global_main>, pending_frame_index=1, last_time_stamp=1108992938029) at
> /home/zstas/vpp/src/vlib/main.c:1384
> #15 0x00007ffff6cbcdd3 in vlib_main_or_worker_loop (vm=0x7ffff6d67bc0
> <vlib_global_main>, is_main=1) at /home/zstas/vpp/src/vlib/main.c:1912
> #16 0x00007ffff6cbd848 in vlib_main_loop (vm=0x7ffff6d67bc0
> <vlib_global_main>) at /home/zstas/vpp/src/vlib/main.c:2040
> #17 0x00007ffff6cbe66b in vlib_main (vm=0x7ffff6d67bc0 <vlib_global_main>,
> input=0x7fffafc73fb0) at /home/zstas/vpp/src/vlib/main.c:2286
> #18 0x00007ffff6d29ac5 in thread0 (arg=140737334639552) at
> /home/zstas/vpp/src/vlib/unix/main.c:670
> #19 0x00007ffff6b56f10 in clib_calljmp () at
> /home/zstas/vpp/src/vppinfra/longjmp.S:123
> #20 0x00007fffffffd150 in ?? ()
> #21 0x00007ffff6d2a095 in vlib_unix_main (argc=28, argv=0x555555631e50) at
> /home/zstas/vpp/src/vlib/unix/main.c:747
> #22 0x000055555555cd8b in main (argc=28, argv=0x555555631e50) at
> /home/zstas/vpp/src/vpp/vnet/main.c:338
>
>
> On Fri, 15 Jan 2021 at 19:57, Damjan Marion <dmar...@me.com> 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 <zsta...@gmail.com> 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, &bi, 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 0x00007ffff6936859 in __GI_abort () at abort.c:79
>> #2 0x00007ffff6bd73bf in os_panic () at
>> /home/zstas/vpp/src/vppinfra/unix-misc.c:177
>> #3 0x00007ffff6b37ea4 in debugger () at
>> /home/zstas/vpp/src/vppinfra/error.c:84
>> #4 0x00007ffff6b38295 in _clib_error (how_to_die=2,
>> function_name=0x7ffff6d39c40 <__FUNCTION__.16>
>> "vlib_buffer_validate_alloc_free", line_number=366, fmt=0x7ffff6d3974a "%s
>> %U buffer 0x%x")
>> at /home/zstas/vpp/src/vppinfra/error.c:143
>> #5 0x00007ffff6c644fc in vlib_buffer_validate_alloc_free (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffers=0x7fffafc725f0, n_buffers=1,
>> expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
>> at /home/zstas/vpp/src/vlib/buffer.c:366
>> #6 0x00007ffff6c4a08c in vlib_buffer_pool_put (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffer_pool_index=0 '\000', buffers=0x7fffafc725f0,
>> n_buffers=1) at /home/zstas/vpp/src/vlib/buffer_funcs.h:754
>> #7 0x00007ffff6c4a8c9 in vlib_buffer_free_inline (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffers=0x7fffb6b37ed4, n_buffers=0, maybe_next=1) at
>> /home/zstas/vpp/src/vlib/buffer_funcs.h:924
>> #8 0x00007ffff6c4a919 in vlib_buffer_free (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffers=0x7fffb6b37ed0, n_buffers=1) at
>> /home/zstas/vpp/src/vlib/buffer_funcs.h:943
>> #9 0x00007ffff6c4b3b5 in process_drop_punt (vm=0x7ffff6d67bc0
>> <vlib_global_main>, node=0x7fffb6b772c0, frame=0x7fffb6b37ec0,
>> disposition=ERROR_DISPOSITION_DROP) at /home/zstas/vpp/src/vlib/drop.c:231
>> #10 0x00007ffff6c4b4bf in error_drop_node_fn_hsw (vm=0x7ffff6d67bc0
>> <vlib_global_main>, node=0x7fffb6b772c0, frame=0x7fffb6b37ec0) at
>> /home/zstas/vpp/src/vlib/drop.c:247
>> #11 0x00007ffff6cba2e2 in dispatch_node (vm=0x7ffff6d67bc0
>> <vlib_global_main>, 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 0x00007ffff6cbaa19 in dispatch_pending_node (vm=0x7ffff6d67bc0
>> <vlib_global_main>, pending_frame_index=2, last_time_stamp=77969722318942)
>> at /home/zstas/vpp/src/vlib/main.c:1384
>> #13 0x00007ffff6cbcdd3 in vlib_main_or_worker_loop (vm=0x7ffff6d67bc0
>> <vlib_global_main>, is_main=1) at /home/zstas/vpp/src/vlib/main.c:1912
>> #14 0x00007ffff6cbd848 in vlib_main_loop (vm=0x7ffff6d67bc0
>> <vlib_global_main>) at /home/zstas/vpp/src/vlib/main.c:2040
>> #15 0x00007ffff6cbe66b in vlib_main (vm=0x7ffff6d67bc0 <vlib_global_main>,
>> input=0x7fffafc73fb0) at /home/zstas/vpp/src/vlib/main.c:2286
>> #16 0x00007ffff6d29ac5 in thread0 (arg=140737334639552) at
>> /home/zstas/vpp/src/vlib/unix/main.c:670
>> #17 0x00007ffff6b56f10 in clib_calljmp () at
>> /home/zstas/vpp/src/vppinfra/longjmp.S:123
>> #18 0x00007fffffffd150 in ?? ()
>> #19 0x00007ffff6d2a095 in vlib_unix_main (argc=28, argv=0x555555631e50) at
>> /home/zstas/vpp/src/vlib/unix/main.c:747
>> #20 0x000055555555cd8b in main (argc=28, argv=0x555555631e50) at
>> /home/zstas/vpp/src/vpp/vnet/main.c:338
>>
>> Buffer index seems right:
>>
>> Thread 1 "vpp_main" hit Breakpoint 1, tap_rx (vm=0x7ffff6d67bc0
>> <vlib_global_main>, 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 <tap_inject_main>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 0x00007ffff6936859 in __GI_abort () at abort.c:79
>> #2 0x00007ffff6bd73bf in os_panic () at
>> /home/zstas/vpp/src/vppinfra/unix-misc.c:177
>> #3 0x00007ffff6b37ea4 in debugger () at
>> /home/zstas/vpp/src/vppinfra/error.c:84
>> #4 0x00007ffff6b38295 in _clib_error (how_to_die=2,
>> function_name=0x7ffff6d39c40 <__FUNCTION__.16>
>> "vlib_buffer_validate_alloc_free", line_number=366, fmt=0x7ffff6d3974a "%s
>> %U buffer 0x%x")
>> at /home/zstas/vpp/src/vppinfra/error.c:143
>> #5 0x00007ffff6c644fc in vlib_buffer_validate_alloc_free (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffers=0x7fffafc725f0, n_buffers=1,
>> expected_state=VLIB_BUFFER_KNOWN_ALLOCATED)
>> at /home/zstas/vpp/src/vlib/buffer.c:366
>> #6 0x00007ffff6c4a08c in vlib_buffer_pool_put (vm=0x7ffff6d67bc0
>> <vlib_global_main>, buffer_pool_index=0 '\000', buffers=0x7fffafc725f0,
>> n_buffers=1) at /home/zstas/vpp/src/vlib/buffer_funcs.h:754
>> /* omit */
>> (gdb) select 6
>> (gdb) print buffers[0]
>> $6 = 653093
>>
>> Maybe I need to set some flags on the allocated buffer? Or what else am I
>> missing?
>>
>> --
>> Best regards
>> Stanislav Zaikin
>>
>>
>>
>>
>>
>
> --
> Best regards
> Stanislav Zaikin
>
>
>
>
--
Best regards
Stanislav Zaikin
-=-=-=-=-=-=-=-=-=-=-=-
Links: You receive all messages sent to this group.
View/Reply Online (#18527): https://lists.fd.io/g/vpp-dev/message/18527
Mute This Topic: https://lists.fd.io/mt/79705076/21656
Group Owner: vpp-dev+ow...@lists.fd.io
Unsubscribe: https://lists.fd.io/g/vpp-dev/unsub [arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
