Enabling SRTP-DTLS causes Error: Inappropriate ioctl for device

[Raj]

Hello all,

I have a [SIP client] <-> Kamailio <-> Asterisk installation. Sip clients are both WebRTC and Linphone Android app. WebRTC connects via 443 while Linphone connects VIA TLS at port 5061. WebRTC as well as Linphone with TLS, but without media encryption works fine. I am testing using echo test at asterisk.

But if I enable DTLS in Linphone I am not able to hear any audio, but works fine if media encryption is set to None.  I have tried with baresip android port and when enabling DTLS the results are the same.

Difference between working and nonworking Linphone configuration is just the change in Media encryption.

From the logs I can see that the ICE negotiation fails, but could not pinpoint how and why.

In the logs I can see some entries as follows, but google search did not yield any results:

DEBUG: [VMLl-ytTLs port 16492]: [core] Error when sending message. Error: Inappropriate ioctl for device

I have uploaded full level 7 logs for both working and non working configuration at:

Working (without SRTP): https://pastebin.com/kC6HzWg4

Not Working (with SRTP): https://pastebin.com/nM86TLDH

Both logs were taken using Linphone.

rtpengine config is as follows.

[rtpengine]

table = 0

interface = internal/10.122.0.27;external/57.145.197.35

listen-ng = 127.0.0.1:22222

listen-tcp = 127.0.0.1:25060

listen-udp = 127.0.0.1:12222

listen-cli = 127.0.0.1:9900

timeout = 60

silent-timeout = 30

tos = 184

pidfile = /var/run/ngcp-rtpengine-daemon.pid

fork = yes

port-min = 16384

port-max = 19384

log-level = 7

log-facility = local5

Kamailio invokes rtpengine using the following segment:

route[RELAY] {

   xlog("L_INFO", "Do relaying\n");

   if (has_body("application/sdp")) {

     if(is_method("INVITE") && (!route(FROMASTERISK))) {

       xlog("L_INFO", "Calling RTPEngine on request side from subscriber side\n");

       rtpengine_manage("SDES-off direction=external direction=internal SIP-source-address");

     } else {

       xlog("L_INFO", "Calling RTPEngine on request side from asterisk side\n");

       rtpengine_manage("SDES-off direction=internal direction=external SIP-source-address");

     }

   }

  if (!t_relay()) {

        xlog("L_INFO", "Relay failed \n");

        sl_reply_error();

  }

  xlog("L_INFO", "Relay successful \n");

  exit;

}

I am at a loss to figure out whats wrong even after spending couple of days pouring through the logs. Any help to figure this out will be very much appreciated.

Thanks!

[Richard Fuchs]

On 21/03/2022 13.45, [EXT] Raj wrote:

Hello all,

I have a [SIP client] <-> Kamailio <-> Asterisk installation. Sip clients are both WebRTC and Linphone Android app. WebRTC connects via 443 while Linphone connects VIA TLS at port 5061. WebRTC as well as Linphone with TLS, but without media encryption works fine. I am testing using echo test at asterisk.

But if I enable DTLS in Linphone I am not able to hear any audio, but works fine if media encryption is set to None.  I have tried with baresip android port and when enabling DTLS the results are the same.

Difference between working and nonworking Linphone configuration is just the change in Media encryption.

From the logs I can see that the ICE negotiation fails, but could not pinpoint how and why.

Looks like the called party (Asterisk?) has a broken ICE implementation. You can see that all the ICE candidates of the same type in the SDP have the same priority:

Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:H9f59a2b2 1 UDP 2130706431 59.189.62.78 12586 typ host
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:Ha2f000d 1 UDP 2130706431 10.47.0.13 12586 typ host
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:Ha7a0014 1 UDP 2130706431 10.122.0.20 12586 typ host
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:H9f59a2b2 2 UDP 2130706430 59.189.62.78 12587 typ host
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:Ha2f000d 2 UDP 2130706430 10.47.0.13 12587 typ host
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: a=candidate:Ha7a0014 2 UDP 2130706430 10.122.0.20 12587 typ host

This is invalid according to the ICE RFC and breaks the ICE implementation in rtpengine which relies on the priority numbers being unique (which they should be). There's a log message indicating that:

Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: WARNING: [tR76yoVZjD]: [ice] Priority collision between candidate pairs IWMLTpmwUONDrY99:H9f59a2b2:1 and IWMLTpmwUONDrY99:Ha2f000d:1 - ICE will likely fail

On the caller side (Linphone?) the ICE candidates provided in the SDP seem unresponsive, but rtpengine learns a set of peer-reflexive candidates (with different ports - from NAT I guess) and from the log it looks like these should work. However rtpengine decides that ICE doesn't complete, even after these candidates are nominated by Linphone:

Mar 19 18:53:31 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16500]: [ice] ICE pair Xo7xC5kbNJRmjCEQ:9cd66a873258db750:1 has been nominated by peer
Mar 19 18:53:31 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16500]: [ice] ICE not completed yet and no usable candidates

This looks wrong to me and I'll have to check the code to see why this happens.

Media can flow anyway because rtpengine uses the address learned via ICE even if ICE doesn't complete successfully.

In the logs I can see some entries as follows, but google search did not yield any results:

DEBUG: [VMLl-ytTLs port 16492]: [core] Error when sending message. Error: Inappropriate ioctl for device

This is a bit of an obscure log message that simply indicates that encryption wasn't available (generally because it wasn't negotiated).

I have uploaded full level 7 logs for both working and non working configuration at:

Working (without SRTP): https://pastebin.com/kC6HzWg4

Not Working (with SRTP): https://pastebin.com/nM86TLDH

Both logs were taken using Linphone.

Fun fact: In your non-SRTP use case you actually do have SRTP on one side.

Asterisk responds with an SDP that looks like an OSRTP SDP. It lists a plain RTP transport protocol (RTP/AVPF) but also includes attributes that indicate support for for DTLS-SRTP (a=setup and a=fingerprint). This is really not correct as this is an answer SDP and an answer SDP isn't supposed to indicate OSRTP when the corresponding offer didn't also indicate OSRTP (which it didn't). So this is now two things wrong with the SDP provided by Asterisk. However rtpengine happily accepts the OSRTP from the SDP and happily continues to negotiate DTLS-SRTP, which completes successfully on the side facing Asterisk:

Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [srtp] Processing incoming DTLS packet
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [crypto] DTLS handshake successful
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: INFO: [tR76yoVZjD port 16512]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [srtp] SRTP keys, incoming:
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [srtp] --- AES_CM_128_HMAC_SHA1_80 key 2lOaxn3nl7dHLmr4IH8NQg== salt /KcaC0Kz7tXi1POosZA=
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [srtp] SRTP keys, outgoing:
Mar 19 18:53:30 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD port 16512]: [srtp] --- AES_CM_128_HMAC_SHA1_80 key yThv2Wd52QZvcz2FR6njqQ== salt c/WquotqBPwQY1Yg0qU=

Which is bizarre because Asterisk has no way to verify the DTLS certificate used by rtpengine as no fingerprint has been given to Asterisk, so Asterisk should really reject this DTLS connection. But it doesn't. I guess that's the third thing wrong with Asterisk here. 🤷 But anyway, media is flowing and now you have RTP on the caller side and SRTP on the called (Asterisk) side.

Switching to your SRTP log: On the Asterisk side the same things happen as before, except that here all SDPs involved are proper DTLS-SRTP SDPs. So all good there. (ICE priority numbers are stilled wrong though.)

On the Linphone side also the same thing happens: ICE doesn't complete, even though from the log it looks like it should (using the learned peer-reflexive candidates). Now rtpengine is in charge of establishing the DTLS connection, but because ICE doesn't complete, this is never initiated (DTLS is only started once at least some ICE connectivity has been established). So this explains why there's no media flowing here.

Which version of rtpengine is this?

Cheers

[Raj]

Thanks for your detailed reply. I am going through it and processing it :)

I am using rtpengine Version: 10.0.1.4+0~mr10.0.1.4+omni2297-20+6ca1f5f0d8ac9fe50a864875bb9b08578b5cdb1d1. Installed using repository at ppa:davidlublink/rtpengine-stable. Asterisk is  18.8.0 and Kamailio is kamailio 5.5.4

[Richard Fuchs]

On 21/03/2022 22.58, [EXT] Raj wrote:

Thanks for your detailed reply. I am going through it and processing it :)

I am using rtpengine Version: 
10.0.1.4+0~mr10.0.1.4+omni2297-20+6ca1f5f0d8ac9fe50a864875bb9b08578b5cdb1d1. 
Installed using repository at ppa:davidlublink/rtpengine-stable. Asterisk 
is  18.8.0 and Kamailio is kamailio 5.5.4 

So this seems to be a bit of a chicken-egg problem.

What's happening is this: Linphone talks ICE to rtpengine and rtpengine learns a pair of peer-reflexive candidates from that. These are the only candidates that work. As per the ICE RFC, the foundation for these learned candidates is a generated string:

Mar 19 18:50:22 erx-sbc01 rtpengine[64650]: DEBUG: [VMLl-ytTLs port 16485]: [ice] Created candidate pair Xo7xC5kbNJRmjCEQ:9cd608203258db750:2 between 57.145.197.35 and 145.11.91.85:33869, type prflx
...
Mar 19 18:50:22 erx-sbc01 rtpengine[64650]: DEBUG: [VMLl-ytTLs port 16484]: [ice] Created candidate pair Xo7xC5kbNJRmjCEQ:9cd67fb33258db750:1 between 57.145.197.35 and 145.11.91.85:62430, type prflx

As the foundation string doesn't match between these learned candidates, they're not seen as belonging together. This is why ICE is initially considered as incomplete.

Then later in the working case Linphone correctly sends a re-invite to communicate the correct ICE foundation for these candidates:

Mar 19 18:53:32 erx-sbc01 rtpengine[64650]: a=candidate:3 1 UDP 1862270847 145.11.91.85 59114 typ prflx raddr 192.168.1.221 rport 7078
Mar 19 18:53:32 erx-sbc01 rtpengine[64650]: a=candidate:3 2 UDP 1862270846 145.11.91.85 16767 typ prflx raddr 192.168.1.221 rport 7079

This allows rtpengine to now pair up the learned candidates and see that they belong together:

Mar 19 18:53:32 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD]: [ice] Replacing previously learned prflx ICE candidate with 3:1
Mar 19 18:53:32 erx-sbc01 rtpengine[64650]: DEBUG: [tR76yoVZjD]: [ice] Replacing previously learned prflx ICE candidate with 3:2

With this in place ICE can now fully complete.

However this doesn't happen in the non-working case, presumably because media isn't flowing yet. So ICE cannot complete because media isn't flowing. Media isn't flowing because DTLS isn't established. DTLS isn't established because ICE didn't complete. Derp.

I'll see how this can be improved.

Cheers

[Richard Fuchs]

On 22/03/2022 08.54, [EXT] 'Richard Fuchs' via rtpengine wrote:
> However this doesn't happen in the non-working case, presumably
> because media isn't flowing yet. So ICE cannot complete because media
> isn't flowing. Media isn't flowing because DTLS isn't established.
> DTLS isn't established because ICE didn't complete. Derp.
>
> I'll see how this can be improved.
>

I have a tentative patch for this. It's pushed to a separate git branch
for now (on top of master):
https://github.com/sipwise/rtpengine/tree/rfuchs/ice-prflx

The relevant commits are:

https://github.com/sipwise/rtpengine/commit/24ed84357a96fd3621e455eeb1e4d8b836e88b73
https://github.com/sipwise/rtpengine/commit/e60ef6333eb53ef9ecdb499dea51aa3c3cfd905e

Are you able to build and test from this branch, and/or pick up these
commits on a different branch and test that, to see if this fixes the
issue for you?

Cheers

[Raj]

Thanks for the patch. I have applied it and compiled and looks like its working fine. The current version is 10.4.0.0+0~mr10.4.0.0 git-rfuchs/ice-prflx-ade1a3e1 After enabling DTLS-SRTP calls are working as expected. I have full logs at: https://pastebin.com/jwix6gGz

I have taken liberty to remove repeat some logs of packet handling and timer run time to reduce the log size, hope that do not remove any necessery information. Please let me know if any additional tests needs to be done.

Thanks Again

[Richard Fuchs]

On 24/03/2022 04.16, [EXT] Raj wrote:

Thanks for the patch. I have applied it and compiled and looks like its working fine. The current version is 10.4.0.0+0~mr10.4.0.0 git-rfuchs/ice-prflx-ade1a3e1 After enabling DTLS-SRTP calls are working as expected. I have full logs at: https://pastebin.com/jwix6gGz

I have taken liberty to remove repeat some logs of packet handling and timer run time to reduce the log size, hope that do not remove any necessery information. Please let me know if any additional tests needs to be done.

Great, I'll merge it to master then and backport the crucial commits as I consider this a bugfix.

Cheers

[Xuo Guoto]

Hi,

Thanks for the patch, I will build this patches and test.

X.

Sent with ProtonMail secure email.

------- Original Message -------

> --
>
> You received this message because you are subscribed to the Google Groups "rtpengine" group.
>
> To unsubscribe from this group and stop receiving emails from it, send an email to rtpengine+...@googlegroups.com.
>
> To view this discussion on the web visit https://groups.google.com/d/msgid/rtpengine/5b184a41-1ba0-d0db-19c1-34fda74658dc%40sipwise.com.
>
> For more options, visit https://groups.google.com/d/optout.

[johan]

Richard,


when you do inject dtmf, can it be configured that rtpengine ONLY sends
the event and not the tone ? In the attached pcap you will see that I
inject 12*#3. 

But I wonder if repeating the tone in the stream can be avoided ?

[Richard Fuchs]

I'm not sure I can see in the pcap what you're describing, but either
way: Injection should only ever be either PCM or DTMF event. Never both.
Which version are we talking about?

Cheers

[johan]

9.3.0 Richard.

[Richard Fuchs]

Try a newer version then, at least latest 9.5 or better latest 10.x. 9.3
is not supported any more.

Cheers

[johan]

I confirm that I have and the rtp event and the dtmf repeated in the
stream using latest version.

So the question is, how can I have only the rtp event ? Attached the
pcap (192.168.68.109 is the receiving device). 


wkr,

[Richard Fuchs]

On 13/04/2022 13.25, [EXT] johan wrote:

I confirm that I have and the rtp event and the dtmf repeated in the
stream using latest version.

So the question is, how can I have only the rtp event ? Attached the
pcap (192.168.68.109 is the receiving device). 

You can tell from the noisy audio that this is not DTMF tones generated by rtpengine, but rather tones it received and forwarded from the opposite peer. If I see this right then 192.168.68.115:8000 → 192.168.68.114:30010 SSRC 0x2cf84b29 is the respective ingress stream and if you listen to it you can hear the tones there as well.

Cheers

[johan]

As usual you are totally right.

It's just echo (retested yesterday).

Thanks for having a look.

--

You received this message because you are subscribed to the Google Groups "rtpengine" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rtpengine+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/rtpengine/52cb4e76-ad4c-e47b-4367-9df055d2f2f6%40sipwise.com.

[johan]

Richard,

can I safely ignore below warning ?

Apr 23 06:22:24 debian10opensips31 rtpengine[84199]: INFO: [fpNrMdbFCzjRHbey7wvt9Q..]: [control] Received command 'play DTMF' from 192.168.68.114:34922 Apr 23 06:22:24 debian10opensips31 rtpengine[84199]: DEBUG: [fpNrMdbFCzjRHbey7wvt9Q..]: [control] Dump for 'play DTMF' from 192.168.68.114:34922: { "code": "3", "call-id": "fpNrMdbFCzjRHbey7wvt9Q..", "received-from": [ "IP4", "192.168.68.115" ], "from-tag": "54396b2d", "to-tag": "12cf072e", "command": "play DTMF" } Apr 23 06:22:24 debian10opensips31 rtpengine[84199]: WARNING: [fpNrMdbFCzjRHbey7wvt9Q..]: [core] Unknown dictionary key encountered: 'code'

--

[Richard Fuchs]

On 23/04/2022 06.26, [EXT] johan wrote:
>
> Richard,
>
> can I safely ignore below warning ?
>
> Apr 23 06:22:24 debian10opensips31 rtpengine[84199]: INFO:
> [fpNrMdbFCzjRHbey7wvt9Q..]: [control] Received command 'play DTMF'
> from 192.168.68.114:34922 Apr 23 06:22:24 debian10opensips31
> rtpengine[84199]: DEBUG: [fpNrMdbFCzjRHbey7wvt9Q..]: [control] Dump
> for 'play DTMF' from 192.168.68.114:34922: { "code": "3", "call-id":
> "fpNrMdbFCzjRHbey7wvt9Q..", "received-from": [ "IP4", "192.168.68.115"
> ], "from-tag": "54396b2d", "to-tag": "12cf072e", "command": "play
> DTMF" } Apr 23 06:22:24 debian10opensips31 rtpengine[84199]: WARNING:
> [fpNrMdbFCzjRHbey7wvt9Q..]: [core] Unknown dictionary key encountered:
> 'code'
>
>

Yes, and thanks for reporting.

Cheers