sipwise / rtpengine

The Sipwise media proxy for Kamailio
GNU General Public License v3.0
763 stars 360 forks source link

System hard lock or kernel call traces generated when using rx-gro-list or rx-udp-gro-forwarding offloads #1792

Closed rrb3942 closed 4 months ago

rrb3942 commented 5 months ago

rtpengine version the issue has been seen with

12.2.1.1-1~bpo12+1

Used distribution and its version

Debian 12

Linux kernel version used

6.7.1-zabbly+

CPU architecture issue was seen on (see uname -m)

x86_64

Expected behaviour you didn't see

No kernel traces and system no system hard locks.

Unexpected behaviour you saw

When using rx-udp-gro-forwarding network offloading kernel call traces are generated when the kernel module is in use.

If rx-gro-list is enabled the system encounters a full hard lock with no output to the log or console and requires a power reset.

These problems only seem to occur for rtpengine, other applications do not trigger the same behavior. I suspect something in the kernel module is not playing nice we these offloads.

Steps to reproduce the problem

Enable rx-gro-list and/or rx-udp-gro-forwarding offloading on the underlying networking device and any bonds and make sure the rtpengine kernel module is in use.

ethtool -K $IFACE rx-gro-list on ethtool -K $IFACE rx-udp-gro-forwarding on

Run some calls through rtpengine.

Additional program output to the terminal or logs illustrating the issue

Anything else?

We have also encountered the hard lock on Debian 12 systems running kernel 6.1 and rtpengine 12.1 using Intel nics when rx-gro-list is enabled.

The problem is more apparent at higher volumes, but can also be triggered at low volumes.

In some of my testing I could trigger it with a single call by placing a call on and off hold music, even if no SIP signaling was involved, so timing of the RTP packets may be a factor.

Attached are some call traces from kernel 6.7 Kernel Trace.txt

We found rx-gro-list and rx-udp-gro-forwarding to be beneficial in some small packet UDP testing and wanted to measure it's impact on rtpengine when we encountered these issues.

rfuchs commented 5 months ago

I don't really have a way to test this myself. Have a look at https://github.com/sipwise/rtpengine/compare/rfuchs/gh1792 - you would need all 3 commits.

rrb3942 commented 5 months ago

Using 12.2.1.2 with those patches and limited testing:

rx-udp-gro-forwarding does not appear to be causing call traces any more, so it looks like this is working.

rx-gro-list is still causing a full kernel hard lock with no output to logs or console. Not sure how to debug this further to get more detail.

It appears I can reproduce this on demand, so if you know how to coax the kernel into producing some useful debug information instead of just hard locking it should be pretty easy get more details.

I believe virtio nics support these offloads, so it may also be testable inside a vm?

rfuchs commented 5 months ago

I believe virtio nics support these offloads, so it may also be testable inside a vm?

They certainly seem to, but at least in virtualbox I can reproduce neither of these issues with the two offloading options enabled, neither with a virtual pro1000 nor the virtio interface.

It appears I can reproduce this on demand, so if you know how to coax the kernel into producing some useful debug information instead of just hard locking it should be pretty easy get more details.

Very hard to say without knowing where the lockup would be. The strange thing is that either of these offloading options seem to relate to RX, and rtpengine doesn't do anything special with packets it receives.

The first thing you can do is add a few printk(KERN_ERR ...) (or possibly a higher log level) messages throughout the code, starting with the entry point rtpengine46() (or possibly even rtpengine4()), and then use these to see how far it gets, hoping that the messages make it to the console before it locks up.

rrb3942 commented 5 months ago

Managed to get a serial console attached and a call trace!

Looks like something is causing a null pointer.

rx-gro-list-trace.txt

They certainly seem to, but at least in virtualbox I can reproduce neither of these issues with the two offloading options enabled, neither with a virtual pro1000 nor the virtio interface

Putting a call on/off hold seems to be the trick for me to trigger it at low volumes. It doesn't always trigger, so it might also be timing related to rtp packets in a single stream?

rrb3942 commented 5 months ago

It's possible rx-gro-list is just bugged.

https://lore.kernel.org/netdev/e7e49ed5-09e2-da48-002d-c7eccc9f9451@intel.com/

rfuchs commented 5 months ago

It's possible rx-gro-list is just bugged.

https://lore.kernel.org/netdev/e7e49ed5-09e2-da48-002d-c7eccc9f9451@intel.com/

That certainly would make my life easier 😅

Should be fairly simple to verify this. Run rtpengine without the kernel module and see what happens.

Alternatively try a different kernel.

rrb3942 commented 5 months ago

Without the kernel module and rx-gro-list on I can't seem to trigger the issue.

I also confirmed that the kernel version I'm running does contain the fix from that mailing list thread. So it may have been a red herring.

I'm not sure if this is a rx-gro-list kernel issue or an rtpengine issue.

With your patches rx-udp-gro-forwarding on seems good, but I have only done lab testing so far.

rfuchs commented 5 months ago

Could also be that this is something specific to the mlx5 driver.

The call trace is useful, but it's hard to identify the exact instruction that caused the page fault. Are you able to give me the disassembly of __udp_gso_segment of the kernel matching that call trace? Or is this from a stock Ubuntu kernel?

rrb3942 commented 5 months ago

Kernel is from: https://github.com/zabbly/linux

cat System.map-6.7.4-zabbly+ | grep udp_gso_segment ffffffff81f1eb10 T pfx_udp_gso_segment ffffffff81f1eb20 T __udp_gso_segment ffffffff82ade6e8 r _ksymtabudp_gso_segment

grep -n ffffffff81f1eb20 disassembled-vmlinuz.asm 4854737:ffffffff81f1eb20: e8 8b b8 18 ff call 0xffffffff810aa3b0 4855589:ffffffff81f1f81f: e8 fc f2 ff ff call 0xffffffff81f1eb20 5079948:ffffffff81fdedbd: e8 5e fd f3 ff call 0xffffffff81f1eb20

I've attached the output of

tail -n +4854737 disassembled-vmlinuz.asm | head -n 200

udp_gso_segment.txt

Let me know if that is what you needed or if it got truncated.

I'm running this on debian. I could try going back to the 6.1 kernel and getting a new trace, but that might not have the other rx-gro-list fixes already.

I can also try re-spinning the system as ubuntu if needed.

rfuchs commented 4 months ago

I was able to track this down to __udpv4_gso_segment_list_csum(), specifically these lines:

    if ((udp_hdr(seg)->dest == udp_hdr(seg->next)->dest) &&
        (udp_hdr(seg)->source == udp_hdr(seg->next)->source) &&
        (ip_hdr(seg)->daddr == ip_hdr(seg->next)->daddr) &&
        (ip_hdr(seg)->saddr == ip_hdr(seg->next)->saddr))
        return segs;

These expect seg->next to be non null, but your kernel trace shows it being null (in r13).

It turns out that skb_copy_expand() flattens the skb, leaving ->next as null, but also copies the GSO flags, which leads to this code path being entered.

So I would think that resetting the GSO flags after making a copy of the skb is the right thing to do. This is what 4c9646c does. See https://github.com/sipwise/rtpengine/compare/rfuchs/gh1792

Let me know.

rrb3942 commented 4 months ago

@rfuchs After that latest patch I can no longer trigger hard locks or any strange kernel call traces with my test scenario!