Sporadic one-way-audio with mr13.5

[SipSeb]

rtpengine version the issue has been seen with

13.5.1.3+0~mr13.5.1.3

Used distribution and its version

Ubuntu 24

Linux kernel version used

6.8.0-90-generic

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

x86_64

Expected behaviour you didn't see

rtpengine should forward all packets

Unexpected behaviour you saw

We have an rtpengine running converting vom srtp to rtp and vice-versa. We have been running version 10.5.x for months without problems. After updating to 13.5.1.3, we got customer complaints about sporadic one-way-audio, where it's always the srtp side that does not hear anything. Attached are two graphs with the rtpengine_packet_errors_total metric before and after the upgrade, and again before and after downgrading to 10.5.x again. You can see, there were virtually no errors with kernel streams before the upgrade, and there are a lot of errors with kernel streams.
In the logs we don't see anything that we can relate to these errors. There have always been errors, and on some affected calls rtpengine logs an error, which we also see for working calls, so we can't provide useful logs.

rtpengine gets controlled by Kamailio (currently version 5.8.x).

Upgrade:

Downgrade:

Just to get an idea about the traffic of those machines:

Steps to reproduce the problem

No response

Additional program output to the terminal or logs illustrating the issue

Anything else?

There was a change from iptables to nftables when updating from 10.x to 13.x, but in general, it is working, there are just sporadic one-way-audio issues. The next call always works.

[rfuchs]

I'm afraid this isn't a useful issue report without any kind of clue as to what's causing these errors or what is actually happening in the affected calls

[SipSeb]

@rfuchs Any idea how to get closer to identifiying the reason for this? I'm happy to help. Unfortunately, I'm afraid setting the rtpengine log level to 7 will let our logging system explode.

[rfuchs]

@rfuchs Any idea how to get closer to identifiying the reason for this? I'm happy to help. Unfortunately, I'm afraid setting the rtpengine log level to 7 will let our logging system explode.

Setting the log level to 7 for only specific logging subsections should be enough and shouldn't be too intrusive. crypto and srtp have their own log levels, as does dtls if that's applicable. control can also be useful as you get to see the full SDPs.

Or get a better logging system 😁

[SipSeb]

After I found the "debug" flag to enable full debug logging for one specific call, I can provide more information.

First a bit about the setup

• Host OS is Ubuntu Noble
• rtpengine is running together with Kamailio in a podman container using Ubuntu Noble as well, with host networking.
• Kernel module is included in the host and activated correctly, rtpengine communicates with it.
• Communications through the proxies go from encrypted (external) clients to unencrypted (internal) Asterisk pbxes.
• When updating from a container with rtpengine 10.5.x to 13.5.x, we exchanged the host os image (a slightly newer Noble) with the new kernel module, everything else stayed the same.
• The update included a switch from iptables to nftables

Problem description

• When the problem happens, rtpengine always reports that there are no packets coming from the internal side.
• a pcap running on the pbx and the proxy hosts show that there are RTP packets flowing between these hosts with the affected ports.
• Debug log shows that it successfully opens the affected port.
• It kernelizes the stream from outside to inside, but it never shows packets received on the internal port in failure cases. I see matching log lines ("Handling packet on: ...") in successful calls - and later the "kernelizing media stream" messages for this direction, in the failed calls they are missing.
• We have an automated call tester placing calls regularly, and sometimes it happens twice only few minutes apart, sometimes the tester is not affected for hours. It happened twice last night, in a period where there are no or only a handful of calls most of the time, so it is not a problem with high traffic.
• The prometheus stats clearly show the calls as "one-way-audio" in the metrics. The packet error metrics increase for these calls, too.

Idea: Maybe the port is stuck in kernel module

• Did a cat /proc/rtpengine/1/list and inspected this.
• Found lines like this:

local inet4 100.101.15.1:33724
    expect inet4 100.98.177.148:12264
    src mismatch action: drop
    stats:               352786 bytes,                 2075 packets,       30517632991529 errors

• This was the port of one of the last failed calls.
• AI says, there are 41 ports that need to be cleaned up in the kernel module. I assume, calls being assigned one of those 41 ports will have one-way audio every time.
• The host with an older rtpengine does not show this behavior. However, the command lines differ slightly, because we implemented an rtpbleed fix in-between.
• Old:

rtpengine --table=1 --interface=priv/100.102.14.1 --interface=pub/100.68.2.14![REDACTED] --interface=pub6/2a05:d014:cda:9302:affe:affe:affe::1 --listen-ng=127.0.0.1:22222 --listen-cli=127.0.0.1:9900 --listen-http=127.0.0.1:9901 --delete-delay=3 --tos=184 -m 30000 -M 35000 -f -L 4

• New:

 rtpengine --table=1 --interface=priv/100.101.15.1 --interface=pub/100.68.1.15![REDACTED] --interface=pub6/2a05:d014:cda:9301:2b93:cafe:cafe::1 --listen-ng=127.0.0.1:22222 --listen-cli=127.0.0.1:9900 --listen-http=127.0.0.1:9901 --delete-delay=3 --endpoint-learning=heuristic --tos=184 --nftables-chain= -m 30000 -M 35000 -f -L 4

• Also, we added the strict-source flag to the rtpengine_manage() call.
• The old rtpengine kernel list is missing the src mismatch action: drop line, which apparently is a result of either the strict-source flag or the heuristic command line parameter.
• rtpengine does not know anything about those sessions with the high kernel error count anymore, the oldest session is from about 5h ago (as time of inspecting).

Last log lines

There are lines that exist only on the host with the new rtpengine.

[core] Failed to push relay stream destination to kernel: No such file or directory
[core] Failed to push relay stream to kernel: File exists
[core] Failed to push relay stream destination to kernel: Device or resource busy

However, when inspecting the call-ids for which these messages get logged, I see calls being multiple minutes long, so I would assume that these log lines aren't a clear indicator for broken calls.

Conclusion

It seems that there is a bug somewhere in cleanup. There may be cases where calls are not hung up correctly. rtpengine seems to clean up these calls internally, but in certain cases the ports stay activated in the kernel module. And because of the new flags or command line parameters, they cannot be overwritten. Maybe this cleanup problem has always been there but has not had an effect before. (Can't proof this, though.)

[rfuchs]

30517632991529 errors

This is an extremely high number. In fact it is so high that I'm seriously doubting its validity. Are you sure that the version of the kernel module in use is an exact match to the version of rtpengine in use?

[SipSeb]

Yes. Just compared host and container images, and when we first updated, they had the exact same build number from our build system. So they must match.

[rfuchs]

Do you see those insane numbers with other calls? Are they changing/increasing?

[rfuchs]

And do you see any messages Failed to delete relay stream from kernel appear in the log?

[SipSeb]

And do you see any messages Failed to delete relay stream from kernel appear in the log?

Yes.

[core] Failed to delete relay stream from kernel: No such file or directory

[SipSeb]

Do you see those insane numbers with other calls? Are they changing/increasing?

I just dumped the status again. And for the same port as above, the number has changed.

local inet4 100.101.15.1:33724
    expect inet4 100.98.177.148:12264
    src mismatch action: drop
    stats:                    0 bytes,                    0 packets,      206158430208908 errors

Could be some kind of counter wraparound or similar.

[SipSeb]

Is there a command to remove single ports/streams from kernel by hand? Via /proc file system?

[rfuchs]

And do you see any messages Failed to delete relay stream from kernel appear in the log?

Yes.

[core] Failed to delete relay stream from kernel: No such file or directory

Any way you can correlate/confirm that these are the same ones that are left over?

[rfuchs]

Is there a command to remove single ports/streams from kernel by hand? Via /proc file system?

No, other than restarting the daemon and resetting the entire table