Delay with SRTP negotiation on remote side

[ovoshlook]

Hi.

I using rm4.4 version + kamialio 4.4.0 When make call from WSS to WSS have long time one side media Remote part hears and see caller but caller not see of hears remote party too long (sometimes 20 seconds delay)

At this time i look at the logs

SRTP output wanted but no crypto was negotiated

After some delay audio and video starts at the both sides

I tried to make changes at the config part but nothing helps to remove this delay.

i use config at the kamailio like this rtpengine_manage("force trust-address replace-origin replace-session-connection ICE=force")

and starts rtpengine with rtpengine -f --interface=intip!extip --listen-udp=127.0.0.1:7723 --listen-ng=127.0.0.1:7724 --tos=184 --pidfile=/var/run/rtpengine.pid

Thks for answer

[ovoshlook]

TRied DTLS=passive suppose - no effect

[ovoshlook]

Did some tests. Issue happens only with WSS-to-WSS calls, No media from remote party only. Caller party always send media and it runs at the remote side fine.

sometimes it is no any delay. Only one side media I suppose it is because RTP from remote part sends as not encrypted because at the RTP log i see RTP at the both sides.

Also at the calls from WSS to SIP no troubles with 2 sides media. All works fine.

There are log of rtpengine log-level = 7

With some small entries of kamailio log (just for understanding which method or reply was before) rtpeingine config at the kamailio rtpengine_manage("force trust-address replace-origin replace-session-connection DTLS=passive ICE=force");

rtpengine output log.txt

[ovoshlook]

One more update Set at he UAC side manually ICE server ip as my server ip and changed setting at the rtpengine

rtpengine_manage("force trust-address replace-origin replace-session-connection"); i.e using rtpengine without ICE forcing

This resolved issue

But anyway it istrange to get this issue when rtpengine changes ICE servers by itself

Will not closing this issue because it exists with ICE hndling on rtpengine

[rfuchs]

How long of a delay are you experiencing? From the log you posted, the far side DTLS is established at 03:30:16, only 2 seconds after the call started. Media should have started flowing at that point.

[ovoshlook]

At the most of time it is more than 30 seconds As i said before after i deleted ICE=force and added stun servers to endpoints config it works fast.

And also at the call form log only one side media was.

[rfuchs]

So in the call log you posted, at what point did media start flowing?

[ovoshlook]

I always have media at the remote point means that callee hear and see caller but caller not hear and see callee

[ovoshlook]

Hi. Any ideas about this? I can give you as many logs as it needs. For now it not rewrites ice candidates. Just adding new one. But i suppose that will be better to delete not needed candidates and make it works with this functionality.

[ovoshlook]

Hi. For another project have same issue. Audio calls goes well but VIDEO calls can hav delay in 30 seconds and more

Also it makes strange thing: I have one way audio and video till video not started.

For example i calling form A point to B point B point accept call and have Audio and Video flow from the point A but point A have no any media flow.

I use folloving scheme (Call from A to B) WSphone(A)->(1-st leg)-> kamailio+rtpeinge->(2-nd leg->)asterisk asterisk ->(3-st leg)-> kamailio+rtpeinge->(4-th leg)->WSphone(B)

rtpengine (with kamailio) an asteirsk uses same server But connection made thoufh external interface. not local (it is made because in a production scheme asteirsk will be in a different server, but actuaaly it is does not have any matter, just for understanding topology)

So at the logs after call i see next things

First call from point A to asterisk (first leg and second leg)

[1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: ------ Media #1 (audio over RTP/SAVPF) using opus/48000/2 [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30170 <> A.po.int.ip:51918, 244 p, 22944 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30171 <> A.po.int.ip:51920 (RTCP), 4 p, 196 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: ------ Media #2 (video over RTP/SAVPF) using VP8/90000 [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30200 <> A.po.int.ip:51922, 209 p, 164499 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30201 <> A.po.int.ip:51924 (RTCP), 129 p, 4292 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --- Tag 'as76205e6a', created 0:39 ago for branch '', in dialogue with '5aalmrbaek' [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: ------ Media #1 (audio over RTP/AVP) using opus/48000/2 [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30156 <> my.ser.ver.ip:29236, 242 p, 23861 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30157 <> my.ser.ver.ip:29237 (RTCP), 0 p, 0 b, 0 e, 1473403340 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: ------ Media #2 (video over RTP/AVP) using VP8/90000 [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30184 <> my.ser.ver.ip:27252, 148 p, 152972 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [ga5c8qb2uaasr42j63h4]: --------- Port my.ser.ver.ip:30185 <> my.ser.ver.ip:27253 (RTCP), 0 p, 0 b, 0 e, 1473403340 last_packet

call from asterisk to point B (3-d leg and 4-th leg)

[1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: ------ Media #1 (audio over RTP/AVP) using opus/48000/2 [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30238 <> my.ser.ver.ip:29958, 239 p, 24902 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30239 <> my.ser.ver.ip:29959 (RTCP), 0 p, 0 b, 0 e, 1473403340 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: ------ Media #2 (video over RTP/AVP) using VP8/90000 [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30264 <> my.ser.ver.ip:40374, 205 p, 163663 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30265 <> my.ser.ver.ip:40375 (RTCP), 0 p, 0 b, 0 e, 1473403340 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --- Tag 'fgl9f33gf0', created 0:39 ago for branch '', in dialogue with 'as5f26dbd9' [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: ------ Media #1 (audio over RTP/SAVPF) using opus/48000/2 [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30218 <> B.po.int.ip:26138, 242 p, 21481 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30219 <> B.po.int.ip:30161 (RTCP), 4 p, 188 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: ------ Media #2 (video over RTP/SAVPF) using VP8/90000 [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30246 <> B.po.int.ip:31174, 198 p, 163302 b, 0 e, 1473403349 last_packet [1473403379.000108] INFO: [7742bfcf0e9570ab6d7d40a52cd4cd4a@my.ser.ver.ip:5999]: --------- Port my.ser.ver.ip:30247 <> B.po.int.ip:59057 (RTCP), 12 p, 540 b, 0 e, 1473403349 last_packet

As i see there is no any lost pakets and errors

and all packets going through

but at the asteirsk log i see that

Sent RTP P2P packet to my.ser.ver.ip:30238 (type 107, len 000102) Sent RTP P2P packet to my.ser.ver.ip:30156 (type 111, len 000071) Sent RTP P2P packet to my.ser.ver.ip:30238 (type 107, len 000079)

when packets sended from asterisk to rtpengine they have no response

So it looks like that asterisk have no response from rtpengine when sending him any IP.

Also i checked at th ewebphone side but it sending pakents. So at this side no trouble...

If you have some time plz help me to understand what is going wrong because i can not understand root of the problem there. all logs looks fine and this is confusing me.

Thank you.

[ovoshlook]

Also dont saw your message

So in the call log you posted, at what point did media start flowing?

Actually i dont have some point in logs from dialog starting. THat was strange for me because with voice issues for example i saw that SRTP negotiated but crypto wanted and etc staff. but here was not any staff in logs...

[vance-od]

Hi! about this point:

Also it makes strange thing: I have one way audio and video till video not started.

In webrtc, audio will not start playing - until video is started (if call audio+video negotiated) Some time ago I encountered this issue, and found this explanation in webrtc bug tracker (currently cannot find the link) This is if I understand your case correctly cheers!

[ovoshlook]

Oh. Thanks for information My case is little bit different. I needto understand why i have only one side at this.

So this problems looks like some troulbe happens and video can not be started immpediatly

But i can not understand what trouble happens with video

[vance-od]

You should start checking tcpdump of your call. Firstly analize the sdp in every point (and make a map with ip:port in every point, Than check that media packets go through all your intermediate points (when I made such map, I analysed the ngrep output on port where Kamailio<->Rtpengine are speaking via NG protocol, it is a way how to get all SDP in one place, and it make analyse faster)

Check also that RTCP packets are sent correctly (and transparently). It may be the case that some RTCP packet is lost/incorrectly transmitted. We also had a case when video started after some time, and the issue was in RTCP relay through Asterisk.

Have a good luck and be patient!

[ovoshlook]

Hm! THanks! Will try and will send there all results.

[ovoshlook]

checked SDP and etc (once again, because begfore already checked) It is correct. so last thing that can be is RTCP.

@vance-od how you route RTCP for this staff? As i know asterisk can not disable RTCP. only if chage way to use RTP with directmedia=yes. Then RTP will need to relaying directly between endpoints.

Also I had simular trouble with arch without asterisk. That was resolved on rtpengine by removing ICE=force (above at the issue topic)

[vance-od]

with RTCP nothing unusual, the problem that we had - was that asterisk did not sent rtcp in some of the cases (do not remember more details) My idea was - to check is it OK with RTCP relay

[ovoshlook]

Guys thanks for your advices. At the FreeSwitch instead Asterisk it looks like going ok. So it is a trouble of Asterisk and, suppose RTCP. If you will help going deeper to this trouble from side of rtpengine (for understand whats wrong for rtpengine here) we will can close big part of this issue.

Will not close for waintig your answers here

[vance-od]

Did you checked RTCP sending in tcpdump?

[rfuchs]

Video might depend on RTP/AVPF being used instead of RTP/AVP on the unencrypted side. RTP/AVP does not send RTCP feedback messages and RTP/SAVPF might depend on them.

[ovoshlook]

@vance-od Not yet. Must finish task urgent. Didnot have time for it. but i will do it in a next some days.

@rfuchs I build syste as transcoder from webRTC to sip and back. But i suppose that it is something strange on the RTPACVP leg from asteirsk to rtpengine side because as i said before there are one way RTP packets only from asterisk when call established. I think it is something wrong at them and thats why rtpenigne dont want to continiue RTP dialog

May be if it possible to create deepest logs (hight than 7 level)?