memory corruption in pkt_alloc

[eyuval]

When pkt_alloc is called with a timeout (CLONE_TIMEOUT=100ms) and there is no free buffer, k_mem_slab_alloc returns a 0 value (OK) but the returned pkt is NULL. Since afterwards the pkt pointer is not checked it results in memory corruption.

I encountered this problem in the following scenario: I have a multicast listener (mdns ipv4) and bombard the device with multicast traffic for this listener, the aim being to exhaust the pkt buffer pool. From the code (net_conn_input) I see that multicast packets are cloned as follows:
mcast_pkt = net_pkt_clone(pkt, CLONE_TIMEOUT);

This eventually calls pkt_alloc, which calls k_mem_slab_alloc. When the slab is exhausted and because our timeout is not K_NO_WAIT, the function k_mem_slab_alloc returns a return code of zero but also a NULL pkt.

[jukkar]

Thanks for the analysis. I checked the net_pkt_clone() call in connection.c and at least it is checking the return value. Can you point me to the line where you found the issue?

[eyuval]

The problem happens in function pkt_alloc in subsys/net/ip/net_pkt.c, called with CLONE_TIME. The function calls k_mem_slab_alloc, which in my case returns 0, indicating success but the pkt pointer is NULL. Because pkt_alloc relies on the return code it does not check the pkt pointer and uses the returned NULL in the subsequent call to memset(pkt, 0, sizeof(struct net_pkt));. I reconstruct the problem under heavy multicast traffic, which causes a lot of packet cloning and finally apparently the exhaustion of the packet buffers. The strange thing for me is the function k_mem_slab_alloc:
The problematic code (below) somehow assumes that _current->base.swap_data; has a valid memory pointer. Shouldn't the logic be somewhat like: return *mem ? result : -ENOMEM

/* wait for a free block or timeout */
	result = z_pend_curr(&lock, key, &slab->wait_q, timeout);
	if (result == 0) {
		*mem = _current->base.swap_data;
	}
	return result;

[jukkar]

Ok, this seems to indicate issue in k_mem_slab_alloc() if 0 is returned but the returned memory pointer is NULL.
Assigning to @andyross for analysis.

[dcpleung]

Are you also using k_mbox_*(), k_stack_*(), k_pipes_*(), k_queue_*(), or k_msgq_*()? These also touch base.swap_data.

[eyuval]

yes, we at least use also the k_msgq , work queues and threads

[dcpleung]

Could you provide something that can reproduce the issue via QEMU (which will help with debugging)? Just by looking at the code, mem slab should not return a null pointer in k_mem_slab_alloc() unless a null pointer is being freed in k_mem_slab_free(). I also made a mock up to test alloc/free with timeouts but it ran for hours without returning pointers outside the mem slab block. So anything that can help us to reproduce the issue would be very helpful.

[eyuval]

Sorry, I do not have the resources to reproduce this, except the scenario I described. Could it be, that there simply was no call to k_mem_slab_free in the given timeout? Another possible direction for me is, that our bsp code (aarch64) somehow messes things up.

[dcpleung]

It should return -EAGAIN if alloc times out (as set in kernel/include/kswap.h, line 99 when the allocating thread first is being swapped out).

I ran my mock-up app with qemu_cortex_a53 for all morning without any issue, but this is missing a lot of interactions that exist in your app.

[dcpleung]

Another thing, is it always happening to the same thread? If so, maybe you can setup a watch point to catch when the thread's base.swap_data is set to zero. k_mem_slab_free() should not set it to zero, or else it would be freeing a null pointer. The k_msgq may be setting it to zero, depending on your app.

[andyross]

Looks like #29615 was submitted to manage exactly the same issue. That's more of a workaround than a fix, though.

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[krish2718]

I am seeing this issue with latest Zephyr (e1e06d05fa + some cherry-picked fixes), its quite easy to reproduce and my test case is below:

Test

• Zperf is running UDP download over Wi-Fi and iperf client pumping at 50Mbps, the throughput reported is ~15Mbps
• In the background, a separate thread is running a command to get some driver stats, this command causes the RX queue to be full as it blocks the
  driver. Running it 4/5 times is enough

Context

• Driver is using net_pkt_rx_alloc_with_buffer with 100ms timeout, when this fails net_pkt_clone also fails as described
  above
• Disable timeout fixes the issue (net_pkt_rx_alloc_with_buffer with K_NO_WAIT)
• The fix suggested in this thread didn't help, as in the driver we do check for pkt not just the return value.

Ozone callstack:

[00:00:52.087,463] <err> net_pkt: Data buffer (1498) allocation failed.
[00:00:52.087,493] <wrn> net_conn: pkt cloning failed, pkt 0x20066df4 dropped
[00:00:52.187,744] <err> net_pkt: Data buffer (1498) allocation failed.
[00:00:52.187,744] <wrn> net_conn: pkt cloning failed, pkt 0x20067168 dropped
[00:00:52.288,024] <err> net_pkt: Data buffer (1498) allocation failed.
[00:00:52.288,024] <wrn> net_conn: pkt cloning failed, pkt 0x200671ac dropped
[00:03:38.462,005] <err> os: ***** BUS FAULT *****
[00:03:38.462,005] <err> os:   Precise data bus error
[00:03:38.462,005] <err> os:   BFAR Address: 0xffffff73
[00:03:38.462,036] <err> os: r0/a1:  0xffffff65  r1/a2:  0x20003700  r2/a3:  0x20003760
[00:03:38.462,036] <err> os: r3/a4:  0x20011338 r12/ip:  0x00006f4c r14/lr:  0x0006c6c7
[00:03:38.462,036] <err> os:  xpsr:  0xa1000000
[00:03:38.462,036] <err> os: Faulting instruction address (r15/pc): 0x0006c33a
[00:03:38.462,066] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:03:38.462,066] <err> os: Current thread: 0x20003700

This varies but I see two callstacks consistently, none of them are directly related to the code.

• z_impl_zsock_select....->z_sched_prio_cmp (thread1 pointer is corrupted, thread2 is the background thread)
• z_impl_k_poll->register_events...->clear_event_registrations...->sys_dlist_remove (list is corrupted)

Enabling all network debugs was unhelpful.

This looks like the some thread switching while we wait for network buffers to be free is causing the issue, for now not using timeout works well, so, proceeding with that . I can provide any details needed.

@rlubos @carlescufi please re-open the issue or let me know if you need me to raise a new bug.

[rlubos]

@krish2718 I'd rather open a new issue, instead of resurrecting an over 2-year-old report. However - I think'll be really difficult to help here, w/o providing some way to reproduce the issue, ideally in a form of a minimal sample or test to run in a simulated environment.
Also, please note, that based on my past experiences, I'm more inclined to believe that such kernel misbehaviors, are most likely a result of some external memory corruption (stack overflows etc.) rather than a problem within the kernel itself.