Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

RTP Engine doesn't send audio on NAT scenario with Re-INVITE #817

Closed
JRequeijo opened this issue Jul 23, 2019 · 15 comments
Closed

RTP Engine doesn't send audio on NAT scenario with Re-INVITE #817

JRequeijo opened this issue Jul 23, 2019 · 15 comments

Comments

@JRequeijo
Copy link

Hello,
I have a NAT environment with RTPEngine + Kamailio + Asterisk.

The system components IP addresses are:

  • Kamailio:
    • private: 10.51.0.190
    • public: 52.164.XXX.XXX
  • RTPEngine:
    • private: 10.51.0.35
    • public: 13.74.XXX.XXX
  • Asterisk:
    • private: 10.51.0.15

NOTE: Understand the XXX in the addresses as "masks" of my public IPs for confidentiality purposes.

So Asterisk is only accessible internally through its private IP by Kamailio and RTPEngine.
All the calls enter the system via Kamailio and are forwarded to Asterisk.
All the audio enters and leaves the system via RTPEngine.

When a call is made between 2 peers, the audio between them INITIALLY flows through both RTPEngine and Asterisk, i.e.:

  • the 1st peer sends audio to RTPEngine ( 1st peer -> RTPEngine )
  • RTPEngine forwards the audio to Asterisk ( RTPEngine -> Asterisk )
  • Asterisk connects both call legs, so it forwards the audio back to RTPEngine, for the 2nd call leg ( Asterisk -> RTPEngine )
  • RTPEngine redirects the 2nd call leg audio to the 2nd peer ( RTPEngine -> 2nd peer )

So the complete audio flow is:

  • 1st peer -> RTPEngine -> Asterisk -> RTPEngine -> 2nd peer.

NOTE: all the audio between the peers and RTPEngine flows through the RTPEngine's public address. All the audio between Asterisk and RTPEngine leaves Asterisk through its private address (10.51.0.15) and enters RTPEngine through its public address 13.74.XXX.XXX.

After the call is established between the 2 peers, Asterisk will "delegate" the audio flow only to RTPEngine, sending Re-INVITES to the peers, re-negotiating the audio endpoints.
The audio flow is therefore changed to:

  • the 1st peer sends audio to RTPEngine ( 1st peer -> RTPEngine )
  • RTPEngine redirects the 1st peer's audio to the 2nd peer's audio port (all of this internally: RTPEngine -> RTPEngine).
  • RTPEngine sends the audio it is receiving on the 2nd peer's audio port to the 2nd peer ( RTPEngine -> 2nd peer )

Up to this point everything works fine EVERY time.

PROBLEM:
From this point on, when Asterisk needs to play some file or to record the call legs, it re-negotiates the audio endpoints again with re-INVITES, so the final flow becomes equal to the initial one, i.e.:

  • 1st peer -> RTPEngine -> Asterisk -> RTPEngine -> 2nd peer

In this step the problem occurs, because sometimes (ONLY SOMETIMES), RTPEngine mixes up the IP addresses in the 2nd re-negotiation and, in the end, it reaches a state where it doesn't send any audio to Asterisk at all.

What I can see on RTPEngine's log files is:

CASE 1 WHERE EVERYTHING WORKS FINE:

[1563818504.000126] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: Call branch '8b08ff3d' (via-branch '') deleted, no more branches remaining
[1563818504.000148] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: Call branch 'as1742143d' (via-branch '') deleted, no more branches remaining
[1563818504.004672] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: Final packet stats:
[1563818504.004688] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- Tag 'as1742143d', created 0:51 ago for branch '', in dialogue with 'a6c87b48'
[1563818504.004696] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.004702] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40178 <>     13.79.XXX.XXX:9922 , SSRC 2c2e6151, 847 p, 143764 b, 12 e, 31 ts
[1563818504.004707] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40179 <>      10.51.0.15:15041 (RTCP), SSRC 4ffc4522, 2 p, 200 b, 0 e, 45 ts
[1563818504.004710] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- Tag 'a6c87b48', created 0:51 ago for branch '', in dialogue with 'as1742143d'
[1563818504.004714] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.004720] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40156 <>    213.30.XXX.XXX:4219 , SSRC 1f0939fd, 871 p, 149812 b, 0 e, 31 ts
[1563818504.004726] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40157 <>    213.30.XXX.XXX:19610 (RTCP), SSRC 1f0939fd, 5 p, 356 b, 0 e, 31 ts
[1563818504.004736] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- SSRC 1f0939fd
[1563818504.004741] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563818504.004809] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004824] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004839] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004844] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.008535] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: Final packet stats:
[1563818504.008563] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- Tag '8b08ff3d', created 0:51 ago for branch '', in dialogue with 'as7d73e65e'
[1563818504.008570] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.008575] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40140 <>    213.30.XXX.XXX:34961, SSRC 4ffc4522, 851 p, 144452 b, 12 e, 31 ts
[1563818504.008580] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40141 <>    213.30.XXX.XXX:35171 (RTCP), SSRC 4ffc4522, 4 p, 360 b, 0 e, 31 ts
[1563818504.008583] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- Tag 'as7d73e65e', created 0:51 ago for branch '', in dialogue with '8b08ff3d'
[1563818504.008587] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.008591] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40118 <>      10.51.0.15:18384, SSRC 561a2ae3, 860 p, 147920 b, 0 e, 31 ts
[1563818504.008595] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40119 <>      10.51.0.15:18385 (RTCP), SSRC 1f0939fd, 3 p, 236 b, 0 e, 38 ts
[1563818504.008600] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- SSRC 1f0939fd
[1563818504.008604] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:08), highest MOS 4.3 (at 0:08)
[1563818504.008684] DEBUG: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: __free_ssrc_handler
[1563818504.008700] DEBUG: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: __free_ssrc_handler

CASE 2 WHERE EVERYTHING WORKS FINE:

[1563818414.000065] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: Call branch 'as0b23082f' (via-branch '') deleted, no more branches remaining
[1563818414.000087] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: Call branch 'f6bc9b29' (via-branch '') deleted, no more branches remaining
[1563818414.004062] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: Final packet stats:
[1563818414.004083] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- Tag 'f6bc9b29', created 1:26 ago for branch '', in dialogue with 'as4c93f451'
[1563818414.004094] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.004105] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40068 <>    213.30.XXX.XXX:37352, SSRC 15f0614f, 2656 p, 454912 b, 12 e, 30 ts
[1563818414.004112] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40069 <>    213.30.XXX.XXX:57918 (RTCP), SSRC 15f0614f, 5 p, 460 b, 0 e, 30 ts
[1563818414.004118] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- Tag 'as4c93f451', created 1:26 ago for branch '', in dialogue with 'f6bc9b29'
[1563818414.004124] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.004130] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40050 <>     13.79.XXX.XXX:9920 , SSRC 7156043a, 2598 p, 446856 b, 0 e, 30 ts
[1563818414.004137] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40051 <>      10.51.0.15:18907 (RTCP), SSRC 59920cba, 14 p, 1168 b, 0 e, 36 ts
[1563818414.004141] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- SSRC 59920cba
[1563818414.004146] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:05), highest MOS 4.3 (at 0:05)
[1563818414.004150] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- SSRC 15f0614f
[1563818414.004154] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:12), highest MOS 4.3 (at 0:12)
[1563818414.004445] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004525] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004659] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004805] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.008342] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: Final packet stats:
[1563818414.008357] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- Tag 'as0b23082f', created 1:26 ago for branch '', in dialogue with '4a42481a'
[1563818414.008393] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.008401] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40098 <>     13.79.XXX.XXX:9921 , SSRC 577a7ea2, 2652 p, 454224 b, 12 e, 30 ts
[1563818414.008408] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40099 <>      10.51.0.15:13267 (RTCP), SSRC 15f0614f, 3 p, 300 b, 0 e, 67 ts
[1563818414.008413] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- Tag '4a42481a', created 1:26 ago for branch '', in dialogue with 'as0b23082f'
[1563818414.008419] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.008426] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40078 <>    213.30.XXX.XXX:20400, SSRC 59920cba, 2610 p, 448920 b, 0 e, 30 ts
[1563818414.008433] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40079 <>    213.30.XXX.XXX:11387 (RTCP), SSRC 59920cba, 16 p, 1288 b, 0 e, 30 ts
[1563818414.008442] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- SSRC 59920cba
[1563818414.009208] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:05), highest MOS 4.3 (at 0:05)
[1563818414.009226] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- SSRC 15f0614f
[1563818414.009231] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:12), highest MOS 4.3 (at 0:12)
[1563818414.009351] DEBUG: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: __free_ssrc_handler
[1563818414.009366] DEBUG: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: __free_ssrc_handler

CASE 3 WHERE PROBLEM OCCURS:

[1563871689.000084] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: Call branch 'as05cd1c2b' (via-branch '') deleted, no more branches remaining
[1563871689.000121] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: Call branch '4db20504' (via-branch '') deleted, no more branches remaining
[1563871689.003790] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: Final packet stats:
[1563871689.003817] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag '4db20504', created 1:25 ago for branch '', in dialogue with 'as21c0243c'
[1563871689.003859] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003871] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40262 <>    213.30.XXX.XXX:28295, SSRC 7697168c, 2572 p, 442384 b, 0 e, 31 ts
[1563871689.003884] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40263 <>    213.30.XXX.XXX:38017 (RTCP), SSRC 7697168c, 3 p, 188 b, 0 e, 44 ts
[1563871689.003889] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag 'as21c0243c', created 1:25 ago for branch '', in dialogue with '4db20504'
[1563871689.003904] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003911] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40246 <>   13.74.XXX.XXX:40294, SSRC 6ecf5cb6, 2585 p, 444620 b, 0 e, 31 ts
[1563871689.003917] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40247 <>      10.51.0.15:13439 (RTCP), SSRC 6ecf5cb6, 3 p, 236 b, 0 e, 72 ts
[1563871689.003921] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- SSRC 6ecf5cb6
[1563871689.003926] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563871689.004059] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004071] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004085] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004091] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.007129] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: Final packet stats:
[1563871689.007147] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- Tag 'as05cd1c2b', created 1:25 ago for branch '', in dialogue with '567c7e5a'
[1563871689.007157] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.007201] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40294 <>   13.74.XXX.XXX:40246, SSRC 7697168c, 2572 p, 442384 b, 0 e, 31 ts
[1563871689.007225] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40295 <>      10.51.0.15:10101 (RTCP), SSRC 7697168c, 2 p, 176 b, 0 e, 80 ts
[1563871689.007232] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- Tag '567c7e5a', created 1:25 ago for branch '', in dialogue with 'as05cd1c2b'
[1563871689.007239] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.007245] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40282 <>    213.30.XXX.XXX:13909, SSRC 6ecf5cb6, 2588 p, 445136 b, 0 e, 31 ts
[1563871689.007251] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40283 <>    213.30.XXX.XXX:11724 (RTCP), SSRC 6ecf5cb6, 15 p, 1168 b, 0 e, 31 ts
[1563871689.007260] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- SSRC 6ecf5cb6
[1563871689.007275] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563871689.007330] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007344] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007373] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007389] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler

So I see that, in case 3 (when the problem happens), RTPEngine tries to send audio to it public IP (13.74.XXX.XXX) after the re-negotiation, i.e.:

[1563871689.003889] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag 'as21c0243c', created 1:25 ago for branch '', in dialogue with '4db20504'
[1563871689.003904] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003911] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40246 <>   13.74.XXX.XXX:40294, SSRC 6ecf5cb6, 2585 p, 444620 b, 0 e, 31 ts
[1563871689.003917] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40247 <>      10.51.0.15:13439 (RTCP), SSRC 6ecf5cb6, 3 p, 236 b, 0 e, 72 ts
[1563871689.003921] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- SSRC 6ecf5cb6

instead of sending it to the private IP of Asterisk, as request by Asterisk in the re-negotiation.

What is also stranger is:

  • The RTCP is always correctly re-negotiated, i.e. the RTCP is always being sent to Asterisk's private IP (10.51.0.15), for both the problematic and the correct cases.
  • In the cases that everything works fine, I see that RTP is actually sent to a strange IP (13.79.XXX.XXX), for just one of the call legs on case 1 or for both call legs in case 2.
    The IP (13.79.XXX.XXX) actually belongs to another application/component of my system that is not even related to SIP or telephony, but somehow RTPEngine is picking it up from the network.

Can anyone help to explain what may be happening on RTPEngine so that (ONLY SOMETIMES) it sends audio to its public IP after the re-negotiation, instead of sending it to Asterisk?

The RTPEngine's configuration file is:

[rtpengine]
table = -1
interface = 10.51.0.35!13.74.XXX.XXX
listen-ng = 10.51.0.35:2222
timeout = 60
silent-timeout = 3600
tos = 184
pidfile = /var/run/ngcp-rtpengine-daemon.pid
port-min = 40000
port-max = 60000
redis = XXXXXXXXXXXXXXXX:6379/5
log-level = 7
log-stderr = true

The flags that Kamailio passes to RTPEngine through rtpengine_manage() are:

replace-origin replace-session-connection strict-source port-latching codec-strip-telephone-event codec-mask-all codec-offer-telephone-event codec-transcode-PCMA RTP/AVP rtcp-mux-demux ICE=remove
@rfuchs
Copy link
Member

rfuchs commented Jul 23, 2019

I suspect this is a case of the peer address learning feature interfering with the endpoint switching. Check your logs for lines Confirmed peer address as ... You will probably find that in some cases, it learns the wrong (old) address. This is because when switching endpoints like this, depending on the timing involved, rtpengine can still receive audio from the old address after the re-invite and will use the source address as a newly learned, corrected endpoint address.

If you don't require the peer address learning feature (e.g. none of your clients are behind NAT and the addresses in the SDP are always correct), you can use the asymmetric flag to disable it.

@JRequeijo
Copy link
Author

Hi rfuchs, and thanks for the quick reply!

I also had exactly the same thinking as you described, but what I see is that the IPs in the lines with Confirmed peer address as not always make sense perfect sense with the actual result, i.e.:

  • sometimes I see that the only IPs that appear on those lines are the public IP of RTPEngine and the public IP of the peers, and the problem occurs - which makes sense, as the private IP of Asterisk never appears on those lines.
  • other times I see that firstly the IPs on those lines are the RTPEngine public and the peers public, and then some time later, appears that "strange" IP 13.79.XXX.XXX that doesn't belong neither to Asterisk, Kamailio, RTPEngine nor the peers, but the problem doesn't occur (audio flows perfectly), which I think is strange, as the Asterisk's IP never appears on those lines.
  • finally, on other examples, I also see that the only IPs that appear on those lines are the public IP of RTPEngine and the public IP of the peers, and the problem never occurs, which I also think is strange for the same reasons as before.

What seems even stranger to me is: if the problem happens because of the address learning feature, doesn't RTPEngine should be able to understand that it is sending audio to itself before the re-negotiation is requested, and then, after asterisk requests the re-negotiation, it needs to "forget" that "old"/learned IP address (which is actually its own) and start sending audio to the new address that is requested on the re-negotiation (which is the correct asterisk's address)?

I also failed to mention but I really need the address learning feature because I can't assure that my clients will never be behind NAT.
Before opening this issue, I found this one, and I actually tried to use the asymmetric flag as you also mention. When I did that, I end up with no audio at all flowing correctly in the system, so I concluded that, in my specific environment, that flag only makes things worse.

@rfuchs
Copy link
Member

rfuchs commented Jul 23, 2019

Unfortunately there's no way to support both NAT detection AND dynamic endpoint switching at the same time. Rtpengine sending audio to itself is actually a valid use case. And rtpengine does "forget" the old learned address after receiving a signalling event, but I suspect that in your case, it then still receives some audio packets from the old endpoint, and possibly also audio packets from the new endpoint, and has no of distinguishing the two, and so will learn the address if whichever packet is received last just before the learning timeout kicks in. The only thing you can try is to increase the length of time that rtpengine waits after a signalling event before committing to a learned address. This is not configurable but you can change it in the code at https://github.com/sipwise/rtpengine/blob/master/daemon/media_socket.c#L1579

@ecarruda
Copy link

Hello,
I have a NAT environment with RTPEngine + Kamailio + Asterisk.

The system components IP addresses are:

  • Kamailio:

    • private: 10.51.0.190
    • public: 52.164.XXX.XXX
  • RTPEngine:

    • private: 10.51.0.35
    • public: 13.74.XXX.XXX
  • Asterisk:

    • private: 10.51.0.15

NOTE: Understand the XXX in the addresses as "masks" of my public IPs for confidentiality purposes.

So Asterisk is only accessible internally through its private IP by Kamailio and RTPEngine.
All the calls enter the system via Kamailio and are forwarded to Asterisk.
All the audio enters and leaves the system via RTPEngine.

When a call is made between 2 peers, the audio between them INITIALLY flows through both RTPEngine and Asterisk, i.e.:

  • the 1st peer sends audio to RTPEngine ( 1st peer -> RTPEngine )
  • RTPEngine forwards the audio to Asterisk ( RTPEngine -> Asterisk )
  • Asterisk connects both call legs, so it forwards the audio back to RTPEngine, for the 2nd call leg ( Asterisk -> RTPEngine )
  • RTPEngine redirects the 2nd call leg audio to the 2nd peer ( RTPEngine -> 2nd peer )

So the complete audio flow is:

  • 1st peer -> RTPEngine -> Asterisk -> RTPEngine -> 2nd peer.

NOTE: all the audio between the peers and RTPEngine flows through the RTPEngine's public address. All the audio between Asterisk and RTPEngine leaves Asterisk through its private address (10.51.0.15) and enters RTPEngine through its public address 13.74.XXX.XXX.

After the call is established between the 2 peers, Asterisk will "delegate" the audio flow only to RTPEngine, sending Re-INVITES to the peers, re-negotiating the audio endpoints.
The audio flow is therefore changed to:

  • the 1st peer sends audio to RTPEngine ( 1st peer -> RTPEngine )
  • RTPEngine redirects the 1st peer's audio to the 2nd peer's audio port (all of this internally: RTPEngine -> RTPEngine).
  • RTPEngine sends the audio it is receiving on the 2nd peer's audio port to the 2nd peer ( RTPEngine -> 2nd peer )

Up to this point everything works fine EVERY time.

PROBLEM:
From this point on, when Asterisk needs to play some file or to record the call legs, it re-negotiates the audio endpoints again with re-INVITES, so the final flow becomes equal to the initial one, i.e.:

  • 1st peer -> RTPEngine -> Asterisk -> RTPEngine -> 2nd peer

In this step the problem occurs, because sometimes (ONLY SOMETIMES), RTPEngine mixes up the IP addresses in the 2nd re-negotiation and, in the end, it reaches a state where it doesn't send any audio to Asterisk at all.

What I can see on RTPEngine's log files is:

CASE 1 WHERE EVERYTHING WORKS FINE:

[1563818504.000126] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: Call branch '8b08ff3d' (via-branch '') deleted, no more branches remaining
[1563818504.000148] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: Call branch 'as1742143d' (via-branch '') deleted, no more branches remaining
[1563818504.004672] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: Final packet stats:
[1563818504.004688] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- Tag 'as1742143d', created 0:51 ago for branch '', in dialogue with 'a6c87b48'
[1563818504.004696] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.004702] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40178 <>     13.79.XXX.XXX:9922 , SSRC 2c2e6151, 847 p, 143764 b, 12 e, 31 ts
[1563818504.004707] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40179 <>      10.51.0.15:15041 (RTCP), SSRC 4ffc4522, 2 p, 200 b, 0 e, 45 ts
[1563818504.004710] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- Tag 'a6c87b48', created 0:51 ago for branch '', in dialogue with 'as1742143d'
[1563818504.004714] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.004720] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40156 <>    213.30.XXX.XXX:4219 , SSRC 1f0939fd, 871 p, 149812 b, 0 e, 31 ts
[1563818504.004726] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --------- Port      10.51.0.35:40157 <>    213.30.XXX.XXX:19610 (RTCP), SSRC 1f0939fd, 5 p, 356 b, 0 e, 31 ts
[1563818504.004736] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: --- SSRC 1f0939fd
[1563818504.004741] INFO: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563818504.004809] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004824] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004839] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.004844] DEBUG: [3db231af6dcd27d310fd10c523c3897f@10.51.0.15:5080]: __free_ssrc_handler
[1563818504.008535] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: Final packet stats:
[1563818504.008563] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- Tag '8b08ff3d', created 0:51 ago for branch '', in dialogue with 'as7d73e65e'
[1563818504.008570] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.008575] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40140 <>    213.30.XXX.XXX:34961, SSRC 4ffc4522, 851 p, 144452 b, 12 e, 31 ts
[1563818504.008580] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40141 <>    213.30.XXX.XXX:35171 (RTCP), SSRC 4ffc4522, 4 p, 360 b, 0 e, 31 ts
[1563818504.008583] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- Tag 'as7d73e65e', created 0:51 ago for branch '', in dialogue with '8b08ff3d'
[1563818504.008587] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818504.008591] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40118 <>      10.51.0.15:18384, SSRC 561a2ae3, 860 p, 147920 b, 0 e, 31 ts
[1563818504.008595] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --------- Port      10.51.0.35:40119 <>      10.51.0.15:18385 (RTCP), SSRC 1f0939fd, 3 p, 236 b, 0 e, 38 ts
[1563818504.008600] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: --- SSRC 1f0939fd
[1563818504.008604] INFO: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:08), highest MOS 4.3 (at 0:08)
[1563818504.008684] DEBUG: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: __free_ssrc_handler
[1563818504.008700] DEBUG: [98845NWI0YzgwMmM1NjVhMDU4MmQzMDZjNmYwZGNlOGJkMTc]: __free_ssrc_handler

CASE 2 WHERE EVERYTHING WORKS FINE:

[1563818414.000065] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: Call branch 'as0b23082f' (via-branch '') deleted, no more branches remaining
[1563818414.000087] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: Call branch 'f6bc9b29' (via-branch '') deleted, no more branches remaining
[1563818414.004062] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: Final packet stats:
[1563818414.004083] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- Tag 'f6bc9b29', created 1:26 ago for branch '', in dialogue with 'as4c93f451'
[1563818414.004094] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.004105] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40068 <>    213.30.XXX.XXX:37352, SSRC 15f0614f, 2656 p, 454912 b, 12 e, 30 ts
[1563818414.004112] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40069 <>    213.30.XXX.XXX:57918 (RTCP), SSRC 15f0614f, 5 p, 460 b, 0 e, 30 ts
[1563818414.004118] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- Tag 'as4c93f451', created 1:26 ago for branch '', in dialogue with 'f6bc9b29'
[1563818414.004124] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.004130] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40050 <>     13.79.XXX.XXX:9920 , SSRC 7156043a, 2598 p, 446856 b, 0 e, 30 ts
[1563818414.004137] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --------- Port      10.51.0.35:40051 <>      10.51.0.15:18907 (RTCP), SSRC 59920cba, 14 p, 1168 b, 0 e, 36 ts
[1563818414.004141] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- SSRC 59920cba
[1563818414.004146] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:05), highest MOS 4.3 (at 0:05)
[1563818414.004150] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: --- SSRC 15f0614f
[1563818414.004154] INFO: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:12), highest MOS 4.3 (at 0:12)
[1563818414.004445] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004525] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004659] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.004805] DEBUG: [98845YjI2OWM1MTIzZDRhZDU0ZjBhMGNiYzJlOGM4M2Q4NzE]: __free_ssrc_handler
[1563818414.008342] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: Final packet stats:
[1563818414.008357] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- Tag 'as0b23082f', created 1:26 ago for branch '', in dialogue with '4a42481a'
[1563818414.008393] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.008401] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40098 <>     13.79.XXX.XXX:9921 , SSRC 577a7ea2, 2652 p, 454224 b, 12 e, 30 ts
[1563818414.008408] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40099 <>      10.51.0.15:13267 (RTCP), SSRC 15f0614f, 3 p, 300 b, 0 e, 67 ts
[1563818414.008413] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- Tag '4a42481a', created 1:26 ago for branch '', in dialogue with 'as0b23082f'
[1563818414.008419] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563818414.008426] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40078 <>    213.30.XXX.XXX:20400, SSRC 59920cba, 2610 p, 448920 b, 0 e, 30 ts
[1563818414.008433] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --------- Port      10.51.0.35:40079 <>    213.30.XXX.XXX:11387 (RTCP), SSRC 59920cba, 16 p, 1288 b, 0 e, 30 ts
[1563818414.008442] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- SSRC 59920cba
[1563818414.009208] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:05), highest MOS 4.3 (at 0:05)
[1563818414.009226] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: --- SSRC 15f0614f
[1563818414.009231] INFO: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:12), highest MOS 4.3 (at 0:12)
[1563818414.009351] DEBUG: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: __free_ssrc_handler
[1563818414.009366] DEBUG: [550f886e6649c7000f13db805044a410@10.51.0.15:5080]: __free_ssrc_handler

CASE 3 WHERE PROBLEM OCCURS:

[1563871689.000084] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: Call branch 'as05cd1c2b' (via-branch '') deleted, no more branches remaining
[1563871689.000121] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: Call branch '4db20504' (via-branch '') deleted, no more branches remaining
[1563871689.003790] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: Final packet stats:
[1563871689.003817] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag '4db20504', created 1:25 ago for branch '', in dialogue with 'as21c0243c'
[1563871689.003859] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003871] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40262 <>    213.30.XXX.XXX:28295, SSRC 7697168c, 2572 p, 442384 b, 0 e, 31 ts
[1563871689.003884] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40263 <>    213.30.XXX.XXX:38017 (RTCP), SSRC 7697168c, 3 p, 188 b, 0 e, 44 ts
[1563871689.003889] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag 'as21c0243c', created 1:25 ago for branch '', in dialogue with '4db20504'
[1563871689.003904] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003911] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40246 <>   13.74.XXX.XXX:40294, SSRC 6ecf5cb6, 2585 p, 444620 b, 0 e, 31 ts
[1563871689.003917] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40247 <>      10.51.0.15:13439 (RTCP), SSRC 6ecf5cb6, 3 p, 236 b, 0 e, 72 ts
[1563871689.003921] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- SSRC 6ecf5cb6
[1563871689.003926] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563871689.004059] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004071] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004085] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.004091] DEBUG: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: __free_ssrc_handler
[1563871689.007129] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: Final packet stats:
[1563871689.007147] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- Tag 'as05cd1c2b', created 1:25 ago for branch '', in dialogue with '567c7e5a'
[1563871689.007157] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.007201] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40294 <>   13.74.XXX.XXX:40246, SSRC 7697168c, 2572 p, 442384 b, 0 e, 31 ts
[1563871689.007225] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40295 <>      10.51.0.15:10101 (RTCP), SSRC 7697168c, 2 p, 176 b, 0 e, 80 ts
[1563871689.007232] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- Tag '567c7e5a', created 1:25 ago for branch '', in dialogue with 'as05cd1c2b'
[1563871689.007239] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.007245] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40282 <>    213.30.XXX.XXX:13909, SSRC 6ecf5cb6, 2588 p, 445136 b, 0 e, 31 ts
[1563871689.007251] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --------- Port      10.51.0.35:40283 <>    213.30.XXX.XXX:11724 (RTCP), SSRC 6ecf5cb6, 15 p, 1168 b, 0 e, 31 ts
[1563871689.007260] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: --- SSRC 6ecf5cb6
[1563871689.007275] INFO: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: ------ Average MOS 4.3, lowest MOS 4.3 (at 0:07), highest MOS 4.3 (at 0:07)
[1563871689.007330] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007344] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007373] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler
[1563871689.007389] DEBUG: [18fe0c116bbb0719242748292490652e@10.51.0.15:5080]: __free_ssrc_handler

So I see that, in case 3 (when the problem happens), RTPEngine tries to send audio to it public IP (13.74.XXX.XXX) after the re-negotiation, i.e.:

[1563871689.003889] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- Tag 'as21c0243c', created 1:25 ago for branch '', in dialogue with '4db20504'
[1563871689.003904] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: ------ Media #1 (audio over RTP/AVP) using PCMA/8000
[1563871689.003911] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40246 <>   13.74.XXX.XXX:40294, SSRC 6ecf5cb6, 2585 p, 444620 b, 0 e, 31 ts
[1563871689.003917] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --------- Port      10.51.0.35:40247 <>      10.51.0.15:13439 (RTCP), SSRC 6ecf5cb6, 3 p, 236 b, 0 e, 72 ts
[1563871689.003921] INFO: [97566MWUzNWRlNjNlZDQ4ODk1OTYxYTZkY2RhYmFlMjM4MmY]: --- SSRC 6ecf5cb6

instead of sending it to the private IP of Asterisk, as request by Asterisk in the re-negotiation.

What is also stranger is:

  • The RTCP is always correctly re-negotiated, i.e. the RTCP is always being sent to Asterisk's private IP (10.51.0.15), for both the problematic and the correct cases.
  • In the cases that everything works fine, I see that RTP is actually sent to a strange IP (13.79.XXX.XXX), for just one of the call legs on case 1 or for both call legs in case 2.
    The IP (13.79.XXX.XXX) actually belongs to another application/component of my system that is not even related to SIP or telephony, but somehow RTPEngine is picking it up from the network.

Can anyone help to explain what may be happening on RTPEngine so that (ONLY SOMETIMES) it sends audio to its public IP after the re-negotiation, instead of sending it to Asterisk?

The RTPEngine's configuration file is:

[rtpengine]
table = -1
interface = 10.51.0.35!13.74.XXX.XXX
listen-ng = 10.51.0.35:2222
timeout = 60
silent-timeout = 3600
tos = 184
pidfile = /var/run/ngcp-rtpengine-daemon.pid
port-min = 40000
port-max = 60000
redis = XXXXXXXXXXXXXXXX:6379/5
log-level = 7
log-stderr = true

The flags that Kamailio passes to RTPEngine through rtpengine_manage() are:

replace-origin replace-session-connection strict-source port-latching codec-strip-telephone-event codec-mask-all codec-offer-telephone-event codec-transcode-PCMA RTP/AVP rtcp-mux-demux ICE=remove

@JRequeijo could you solve this?

@magixyu
Copy link

magixyu commented Dec 15, 2020

@JRequeijo,

Could you please take a look #1139 and see if it is the same as yours?

Thanks,
Tristan

@JRequeijo
Copy link
Author

@ecarruda @magixyu sorry for the late reply.

I couldn't solve this issue and so I stopped using rtpengine and integrated with a commercial SBC provider that handles all the media flows.

It has been a long time since I opened this issue so I don't really recall the details to ensure if it is the same as #1139 or not. When I get some free time, I'll try to recall the details of the problem I had back then and then try to compare it with #1139.

Thanks

@sem32
Copy link

sem32 commented Jul 8, 2021

Hi @rfuchs !

I faced the similar issue like this one.
Details:
First INVITE from operator has SDP:

v=0
o=cp10 162569253227 162569253227 IN IP4 78.7.253.13
s=SIP Call
c=IN IP4 87.248.52.245
t=0 0
m=audio 34150 RTP/AVP 18 8 96
b=AS:26
a=rtpmap:18 G729/8000/1
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000/1
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=ptime:20
a=sendrecv

audio port is 34150
after few minutes we sent reINVITE to operator and it replied with SDP

v=0
o=cp10 162569253227 162569253228 IN IP4 78.7.253.13
s=SIP Call
c=IN IP4 87.248.52.242
t=0 0
m=audio 30840 RTP/AVP 18 8 96
b=AS:26
a=rtpmap:18 G729/8000/1
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000/1
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=ptime:20
a=sendrecv

RTP port has been changed from 34150 to 30840, but after offer second INVITE operator sent one RTP packet from old UDP port. Operator is waiting media from us on new port and didn't send RTP to us. But RTPengine learned to send media to old port and we have no audio issue.

RTP from OLD port (34150)
RTP from old port

RTP from NEW port (30840)
RTP from new port

I added fix of this issue (add skipping first 5 packets after answer/offer) and it works for me, but I'm interesting to deliver this change to community as well (if it's correct)
diff based on master branch commit 9ad5378

--- a/daemon/call.c
+++ b/daemon/call.c
@@ -2330,6 +2330,7 @@ int monologue_offer_answer(struct call_monologue *dialogue[2], GQueue *streams,

        call->last_signal = MAX(call->last_signal, rtpe_now.tv_sec);
        call->deleted = 0;
+       call->rtp_learn_check_counter = 0;

        __C_DBG("this="STR_FORMAT" other="STR_FORMAT, STR_FMT(&monologue->tag), STR_FMT(&other_ml->tag));

diff --git a/daemon/media_socket.c b/daemon/media_socket.c
index f5b49c62..4d186577 100644
--- a/daemon/media_socket.c
+++ b/daemon/media_socket.c
@@ -1981,8 +1981,14 @@ static int media_packet_address_check(struct packet_handler_ctx *phc)

        /* wait at least 3 seconds after last signal before committing to a particular
         * endpoint address */
-       if (!phc->mp.call->last_signal || rtpe_now.tv_sec <= phc->mp.call->last_signal + 3)
-               goto update_peerinfo;
+       if (!phc->mp.call->last_signal || rtpe_now.tv_sec <= phc->mp.call->last_signal + 3) {
+               if (phc->mp.call->rtp_learn_check_counter <= 5) {
+                       phc->mp.call->rtp_learn_check_counter++;
+                       goto out;
+               } else {
+                       goto update_peerinfo;
+               }
+       }

 confirm_now:
        phc->kernelize = 1;
diff --git a/include/call.h b/include/call.h
index 0e5bde6b..a1e1490b 100644
--- a/include/call.h
+++ b/include/call.h
@@ -504,6 +504,7 @@ struct call {
        unsigned int            foreign_media:1; // for calls taken over, tracks whether we have media
        unsigned int            disable_jb:1;
        unsigned int            debug:1;
+       unsigned int            rtp_learn_check_counter;
 };

Thanks in advance

@rfuchs
Copy link
Member

rfuchs commented Jul 8, 2021

This should already be handled by the last_signal timestamp, which exists exactly for this reason. When the answer SDP is processed, the timestamp should be reset to "now" and then the endpoint learning should only happen ~3 seconds later. I'm wondering why this doesn't happen in your case?

@sem32
Copy link

sem32 commented Jul 8, 2021

exactly, you are right, but RTP packet from old port came after answer and rtpengine learned to this old port.

update_peerinfo:
	mutex_lock(&phc->mp.stream->out_lock);
	endpoint = phc->mp.stream->endpoint;
	phc->mp.stream->endpoint = *use_endpoint_confirm;
	if (memcmp(&endpoint, &phc->mp.stream->endpoint, sizeof(endpoint))) { 
		phc->unkernelize = 1;               <---- we are here in this case
		phc->update = 1;
	}

in my case operator did't send any RTP packets from the new port, it is waiting RTP from us, but rtpengine didn't send RTP to new port, because it learned to old one.
That's why skip learning for 5 first packets helped.

@rfuchs
Copy link
Member

rfuchs commented Jul 8, 2021

in my case operator did't send any RTP packets from the new port, it is waiting RTP from us, but rtpengine didn't send RTP to new port, because it learned to old one.

Ah I see, you want to suppress the learning of a new address completely for a short while, and not just the confirmation of a learned address. I feel that using a hard-coded number of packets to wait out for this is a bit of a hack and that there should be a better solution. One approach that comes to mind: Use a timer similar to last_signal and keep track of the last learned endpoint. If a received packet then matches the last learned endpoint during the wait time, ignore it for learning purposes.

sipwise-jenkins pushed a commit that referenced this issue Jul 8, 2021
This fixes a race condition: Peer sends updated SDP with new address,
but an older RTP packet from the old address is received afterwards.
Thsi triggers learning of this old address is the "correct" endpoint.
Afterwards the peer stops sending RTP until a packet to the new endpoint
is received there, which never happens because the new endpoint has been
discarded in favour of the "learned" old one.

closes #817

Change-Id: I508f465a669f03e35ddcc6e770d5e7859e57569f
@rfuchs
Copy link
Member

rfuchs commented Jul 8, 2021

So that would look something like 2ad51fa

Untested

@sem32
Copy link

sem32 commented Jul 9, 2021

Hi @rfuchs!
It works!
I added comment to your commit with small typo)

Thank you!

@rfuchs
Copy link
Member

rfuchs commented Jul 9, 2021

I added comment to your commit with small typo)

Not a typo - the bool type is valid and already in use elsewhere.

@sem32
Copy link

sem32 commented Jul 9, 2021

Ah, sorry, I use older version, without bool type

@sem32
Copy link

sem32 commented Jul 9, 2021

As for me the issue has been solved, probably make sense to close this issue...

Thank you @rfuchs, as usual :)

sipwise-jenkins pushed a commit that referenced this issue Jul 9, 2021
This fixes a race condition: Peer sends updated SDP with new address,
but an older RTP packet from the old address is received afterwards.
Thsi triggers learning of this old address is the "correct" endpoint.
Afterwards the peer stops sending RTP until a packet to the new endpoint
is received there, which never happens because the new endpoint has been
discarded in favour of the "learned" old one.

closes #817

Change-Id: I508f465a669f03e35ddcc6e770d5e7859e57569f
(cherry picked from commit 45bd10d)
sipwise-jenkins pushed a commit that referenced this issue Jul 9, 2021
This fixes a race condition: Peer sends updated SDP with new address,
but an older RTP packet from the old address is received afterwards.
Thsi triggers learning of this old address is the "correct" endpoint.
Afterwards the peer stops sending RTP until a packet to the new endpoint
is received there, which never happens because the new endpoint has been
discarded in favour of the "learned" old one.

closes #817

Change-Id: I508f465a669f03e35ddcc6e770d5e7859e57569f
(cherry picked from commit 45bd10d)
sipwise-jenkins pushed a commit that referenced this issue Jul 9, 2021
This fixes a race condition: Peer sends updated SDP with new address,
but an older RTP packet from the old address is received afterwards.
Thsi triggers learning of this old address is the "correct" endpoint.
Afterwards the peer stops sending RTP until a packet to the new endpoint
is received there, which never happens because the new endpoint has been
discarded in favour of the "learned" old one.

closes #817

Change-Id: I508f465a669f03e35ddcc6e770d5e7859e57569f
(cherry picked from commit 45bd10d)
sipwise-jenkins pushed a commit that referenced this issue Jul 9, 2021
This fixes a race condition: Peer sends updated SDP with new address,
but an older RTP packet from the old address is received afterwards.
Thsi triggers learning of this old address is the "correct" endpoint.
Afterwards the peer stops sending RTP until a packet to the new endpoint
is received there, which never happens because the new endpoint has been
discarded in favour of the "learned" old one.

closes #817

Change-Id: I508f465a669f03e35ddcc6e770d5e7859e57569f
(cherry picked from commit 45bd10d)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants