[SR-Users] RTPEngine UDP receive queue issue

Richard Fuchs rfuchs at sipwise.com
Tue Aug 7 15:18:06 CEST 2018


On 2018-08-06 21:17, Alex Balashov wrote:
>  From the 5.1 TB transferred on the 'lo' interface (RTPEngine running on
> same host as Kamailio):
>
> lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
>          inet 127.0.0.1  netmask 255.0.0.0
>          inet6 ::1  prefixlen 128  scopeid 0x10<host>
>          loop  txqueuelen 1  (Local Loopback)
>          RX packets 27694476978  bytes 5678003789723 (5.1 TiB)
>          RX errors 0  dropped 0  overruns 0  frame 0
>          TX packets 27694476978  bytes 5678003789723 (5.1 TiB)
>          TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
>
> ... I would surmise that this is some sort of loop / infinite loop
> condition, but I can't quite put my finger on what it is.
>
>  From an RTPEngine logging standpoint, the scenario begins looking rather
> normally:
>
> Aug  6 18:11:04 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Received command 'offer' from 127.0.0.1:48525
> Aug  6 18:11:04 gw1 rtpengine[25476]: NOTICE: [1074537188_44545952 at 20.20.20.20]: Creating new call
> Aug  6 18:11:04 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: offer time = 0.000865 sec
> Aug  6 18:11:04 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Replying to 'offer' from 127.0.0.1:48525
> Aug  6 18:11:14 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Received command 'answer' from 127.0.0.1:58668
> Aug  6 18:11:14 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: answer time = 0.000123 sec
> Aug  6 18:11:14 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Replying to 'answer' from 127.0.0.1:58668
> Aug  6 18:11:18 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20 port 61666]: Confirmed peer address as 2.2.2.2:38236
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Received command 'offer' from 127.0.0.1:50995
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: offer time = 0.000082 sec
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Replying to 'offer' from 127.0.0.1:50995
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Received command 'offer' from 127.0.0.1:47321
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: offer time = 0.000151 sec
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20]: Replying to 'offer' from 127.0.0.1:47321
> Aug  6 18:11:23 gw1 rtpengine[25476]: INFO: [1074537188_44545952 at 20.20.20.20 port 61666]: Switching local interface to 1.1.1.1:61666
> Aug  6 18:11:23 gw1 rtpengine[25476]: ERR: [1074537188_44545952 at 20.20.20.20 port 61666]: Too many packets in UDP receive queue (more than 50), aborting loop. Dropped packets possible
> [... ad nauseum... ]
>
> The only thing unusual about it from a SIP perspective is that it
> involves an SRTP endpoint and several reinvites which don't seem to be
> handled as one would expect:
>
> Aug  6 18:11:04 gw1 /usr/local/sbin/kamailio[22070]: INFO: [R-INBOUND-ROUTE-BRANCH:1074537188_44545952 at 2.2.2.2] Relaying media through RTPEngine
> Aug  6 18:11:04 gw1 /usr/local/sbin/kamailio[22070]: INFO: [R-INBOUND-ROUTE-BRANCH:1074537188_44545952 at 2.2.2.2] -> Forcing Secure RTP (SRTP) profile in offer
> Aug  6 18:11:04 gw1 /usr/local/sbin/kamailio[22233]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '100 Trying' from 3.3.3.3:54246
> Aug  6 18:11:04 gw1 /usr/local/sbin/kamailio[22233]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '180 Ringing' from 3.3.3.3:54246
> Aug  6 18:11:14 gw1 /usr/local/sbin/kamailio[22258]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 3.3.3.3:54246
> Aug  6 18:11:14 gw1 /usr/local/sbin/kamailio[22258]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:14 gw1 /usr/local/sbin/kamailio[22112]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 2.2.2.2:5060
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22263]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Re-invite received on rtpengine'd call -- updating RTPEngine
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22068]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Re-invite received on rtpengine'd call -- updating RTPEngine
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22074]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '100 Trying' from 1.1.1.1:5060
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22057]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '100 Trying' from 2.2.2.2:5060
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22070]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 2.2.2.2:5060
> Aug  6 18:11:23 gw1 /usr/local/sbin/kamailio[22070]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22065]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 2.2.2.2:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22065]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22104]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22104]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22088]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 2.2.2.2:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22088]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22118]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22118]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22100]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 2.2.2.2:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22100]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22116]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22116]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22094]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] Reply '200 OK' from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22094]: INFO: [R-MAIN-REPLY:1074537188_44545952 at 2.2.2.2] -> Reply contains SDP;  diverting through RTPEngine
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22263]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 3.3.3.3:54246
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22090]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22263]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 3.3.3.3:54246
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22263]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 3.3.3.3:54246
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22074]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22068]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 1.1.1.1:5060
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22263]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 3.3.3.3:54246
> Aug  6 18:11:27 gw1 /usr/local/sbin/kamailio[22098]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> Other sequential ACK received from 1.1.1.1:5060
> Aug  6 18:11:58 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 3.3.3.3:54246
> Aug  6 18:11:58 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22104]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 1.1.1.1:5060
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22104]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 3.3.3.3:54246
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 3.3.3.3:54246
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 3.3.3.3:54246
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE (hangup) received from 3.3.3.3:54246
> Aug  6 18:12:02 gw1 /usr/local/sbin/kamailio[22211]: INFO: [R-MAIN:1074537188_44545952 at 2.2.2.2] -> BYE received - tearing down rtpengine session
>
> But while this signalling chronology is anomalous, it doesn't explain a
> continuous queue overflow of some kind which lasted several hours?

This can happen if the output SDP (rewritten by rtpengine) is fed back 
into rtpengine as an input SDP for the same call/branch. Then rtpengine 
will start looping media back to itself. There are some safeguards in 
the code to prevent this from happening, but if the underlying 
signalling is broken, it can still happen.

Cheers



More information about the sr-users mailing list