Project

General

Profile

Actions

Bug #1784

closed

osmo-sip-connector: early media not functional as with LCR

Added by keith over 7 years ago. Updated almost 7 years ago.

Status:
Closed
Priority:
High
Assignee:
Target version:
-
Start date:
07/27/2016
Due date:
% Done:

0%

Resolution:
Spec Reference:

Description

Bug Summary from UX pov: No early media when connecting through voip provider.
No audio feedback of call progress on local GSM-GSM calls with (at least) certain Nokia phones.

This is a diff of two log segment from osmo-nitb.
The call is exactly the same, osc.log was created with osmo-sip-connector and lcr.log with LCR.

I note the extra MNCC sent by by LCR:

$ diff -u osc.log lcr.log     
--- osc.log     2016-07-26 16:17:19.986897563 +0100
+++ lcr.log     2016-07-26 16:17:33.238845393 +0100
@@ -17,6 +17,12 @@
 <0001> gsm_04_08.c:1300 new state NULL -> INITIATED
 <0001> gsm_04_08.c:1935 Subscriber Meteor (68000137793) sends SETUP to 68000135657
 <0001> gsm_04_08.c:1361 (bts 0 trx 0 ts 2 ti 8 sub 68000137793) Sending 'MNCC_SETUP_IND' to MNCC.
+<0006> gsm_04_08.c:3211 receive message MNCC_CALL_PROC_REQ
+<0001> gsm_04_08.c:3415 (bts 0 trx 0 ts 2 ti 08 sub 68000137793) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
+<0001> gsm_04_08.c:1300 new state INITIATED -> MO_CALL_PROC
+<0001> gsm_04_08.c:138 (bts 0 trx 0 ts 2 ti 80) Sending 'CALL_PROC' to MS.
+<0006> gsm_04_08.c:3211 receive message MNCC_FRAME_RECV
+<0001> gsm_04_08.c:1722 queue tch_recv_mncc request (1)
 <0006> gsm_04_08.c:3211 receive message MNCC_RTP_CREATE
 <000a> bsc_api.c:383 Sending ChanModify for speech 1 1
 <0003> gsm_04_08_utils.c:461 -> CHANNEL MODE MODIFY mode=0x01 @@ -25,13 +31,9 @@
 <0004> abis_rsl.c:1866 (bts=0,trx=0,ts=2,ss=0) IPAC_BIND speech_mode=0x10 RTP_PAYLOAD=3
 <0003> osmo_msc.c:72 MSC assign complete (do nothing).
 <0004> abis_rsl.c:1217 (bts=0,trx=0,ts=2,ss=0) CHANNEL MODE MODIFY ACK
-<0004> abis_rsl.c:2030 (bts=0,trx=0,ts=2,ss=0) IPAC_CRCX_ACK LOCAL_IP=172.16.0.11 LOCAL_PORT=14286 CON_ID=0 <0006> gsm_04_08.c:3118 (bts=0,trx=0,ts=2,ss=0) sending pending RTP create ind.
+<0004> abis_rsl.c:2030 (bts=0,trx=0,ts=2,ss=0) IPAC_CRCX_ACK LOCAL_IP=172.16.0.11 LOCAL_PORT=58708 CON_ID=0 <0006> gsm_04_08.c:3118 (bts=0,trx=0,ts=2,ss=0) sending pending RTP create ind.
 <0001> gsm_04_08.c:1369 (bts - trx - ts - ti -- sub -) Sending 'MNCC_RTP_CREATE' to MNCC.

-<0006> gsm_04_08.c:3211 receive message MNCC_CALL_PROC_REQ
-<0001> gsm_04_08.c:3415 (bts 0 trx 0 ts 2 ti 08 sub 68000137793) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
-<0001> gsm_04_08.c:1300 new state INITIATED -> MO_CALL_PROC
-<0001> gsm_04_08.c:138 (bts 0 trx 0 ts 2 ti 80) Sending 'CALL_PROC' to MS.
 <0006> gsm_04_08.c:3211 receive message MNCC_SETUP_REQ
 <000d> db.c:894 Found Subscriber: ID 72, IMSI 214220001782190, NAME 'DigiMovil', TMSI 4294967295, EXTEN '68000135657', LAC 1, AUTH 1
 <0001> transaction.c:71 subscr=0xf578f0, net=0xf11a80 @@ -39,7 +41,7 @@
 <0007> paging.c:291 Start paging of subscriber 72 on bts 0.
 <0007> paging.c:83 Going to send paging commands: imsi: '214220001782190' tmsi: '0xffffffff'
 <0007> paging.c:83 Going to send paging commands: imsi: '214220001782190' tmsi: '0xffffffff'
-<0004> abis_rsl.c:1464 (bts=0,trx=0,ts=3,ss=0) Activating ARFCN(31) SS(0) lctype TCH/F r=PAGING ra=0x2f ta=0
+<0004> abis_rsl.c:1464 (bts=0,trx=0,ts=3,ss=0) Activating ARFCN(31) SS(0) lctype TCH/F r=PAGING ra=0x2e ta=0
 <0004> abis_rsl.c:1198 (bts=0,trx=0,ts=3,ss=0) CHANNEL ACTIVATE ACK
 <0007> paging.c:83 Going to send paging commands: imsi: '214220001782190' tmsi: '0xffffffff'
 <0000> abis_rsl.c:1652 (bts=0,trx=0,ts=3,ss=0) SAPI=0 ESTABLISH INDICATION @@ -62,7 +64,8 @@
 <0001> gsm_04_08.c:1857 starting timer T310 with 180 seconds
 <0001> gsm_04_08.c:1300 new state CALL_PRESENT -> MO_TERM_CALL_CONF
 <0001> gsm_04_08.c:1361 (bts 0 trx 0 ts 3 ti 0 sub 68000135657) Sending 'MNCC_CALL_CONF_IND' to MNCC.
-<0006> gsm_04_08.c:3211 receive message MNCC_RTP_CREATE
+<0006> gsm_04_08.c:3211 receive message MNCC_LCHAN_MODIFY
+<0001> gsm_04_08.c:3415 (bts 0 trx 0 ts 3 ti 00 sub 68000135657) Received 'MNCC_LCHAN_MODIFY' from MNCC in state 9 (MO_TERM_CALL_CONF)
 <000a> bsc_api.c:383 Sending ChanModify for speech 1 1
 <0003> gsm_04_08_utils.c:461 -> CHANNEL MODE MODIFY mode=0x01
 <0000> abis_rsl.c:1652 (bts=0,trx=0,ts=3,ss=0) SAPI=0 DATA INDICATION @@ -70,8 +73,9 @@
 <0004> abis_rsl.c:1866 (bts=0,trx=0,ts=3,ss=0) IPAC_BIND speech_mode=0x10 RTP_PAYLOAD=3
 <0003> osmo_msc.c:72 MSC assign complete (do nothing).
 <0004> abis_rsl.c:1217 (bts=0,trx=0,ts=3,ss=0) CHANNEL MODE MODIFY ACK
-<0004> abis_rsl.c:2030 (bts=0,trx=0,ts=3,ss=0) IPAC_CRCX_ACK LOCAL_IP=172.16.0.11 LOCAL_PORT=53836 CON_ID=0 <0006> gsm_04_08.c:3118 (bts=0,trx=0,ts=3,ss=0) sending pending RTP create ind.
-<0001> gsm_04_08.c:1369 (bts - trx - ts - ti -- sub -) Sending 'MNCC_RTP_CREATE' to MNCC.
+<0004> abis_rsl.c:2030 (bts=0,trx=0,ts=3,ss=0) IPAC_CRCX_ACK LOCAL_IP=172.16.0.11 LOCAL_PORT=13340 CON_ID=0 <001b> rtp_proxy.c:542 rtp_socket_create(): success
+<001b> rtp_proxy.c:627 rtp_socket_bind(rs=0xf40f00, IP=0.0.0.0): BOUND_IP=0.0.0.0, BOUND_PORT=30000
+<001b> rtp_proxy.c:682 rtp_socket_connect(rs=0xf40f00, ip=172.16.0.11, port=13340)

 <0000> abis_rsl.c:1652 (bts=0,trx=0,ts=3,ss=0) SAPI=0 DATA INDICATION
 <0000> gsm_04_08.c:3584 Dispatching 04.08 message, pdisc=3 @@ -80,6 +84,13 @@
 <0001> gsm_04_08.c:1857 starting timer T301 with 180 seconds
 <0001> gsm_04_08.c:1300 new state MO_TERM_CALL_CONF -> CALL_RECEIVED
 <0001> gsm_04_08.c:1361 (bts 0 trx 0 ts 3 ti 0 sub 68000135657) Sending 'MNCC_ALERT_IND' to MNCC.
+<0006> gsm_04_08.c:3211 receive message MNCC_LCHAN_MODIFY
+<0001> gsm_04_08.c:3415 (bts 0 trx 0 ts 2 ti 08 sub 68000137793) Received 'MNCC_LCHAN_MODIFY' from MNCC in state 3 (MO_CALL_PROC)
+<0006> gsm_04_08.c:3211 receive message MNCC_RTP_CONNECT
+<0004> abis_rsl.c:1905 (bts=0,trx=0,ts=2,ss=0) IPAC_MDCX IP=172.16.0.1 PORT=16396 RTP_PAYLOAD=3 RTP_PAYLOAD2=0 CONN_ID=0 speech_mode=0x00
+<0004> abis_rsl.c:2040 (bts=0,trx=0,ts=2,ss=0) IPAC_MDCX_ACK LOCAL_IP=172.16.0.11 LOCAL_PORT=58708 CON_ID=0 <0006> gsm_04_08.c:3131 (bts=0,trx=0,ts=2,ss=0) sending pending RTP connect ind.
+<0001> gsm_04_08.c:1369 (bts - trx - ts - ti -- sub -) Sending 'MNCC_RTP_CONNECT' to MNCC.
+<0000> abis_rsl.c:1652 (bts=0,trx=0,ts=2,ss=0) SAPI=0 DATA INDICATION
 <0000> gsm_04_08.c:3584 Dispatching 04.08 message, pdisc=3
 <0001> gsm_04_08.c:3508 (bts 0 trx 0 ts 2 ti 8 sub 68000137793) Received 'DISCONNECT' from MS in state 3 (MO_CALL_PROC) @@ -116,10 +127,10 @@
 <0004> abis_rsl.c:615 (bts=0,trx=0,ts=2,ss=0) DEACTivate SACCH CMD
 <0000> abis_rsl.c:1652 (bts=0,trx=0,ts=3,ss=0) SAPI=0 RELEASE INDICATION
 <0004> abis_rsl.c:661 (bts=0,trx=0,ts=3,ss=0) RF Channel Release CMD due error 0
-<0004> abis_rsl.c:2049 (bts=0,trx=0,ts=3,ss=0) IPAC_DLCX_IND CAUSE=0x0f(Normal event, unspecified)
+<0004> abis_rsl.c:2049 (bts=0,trx=0,ts=3,ss=0) IPAC_DLCX_IND CAUSE=0x0f(Normal event, unspecified) <001b> rtp_proxy.c:743 rtp_socket_free(rs=0xf40f00)
+<0004> abis_rsl.c:717 (bts=0,trx=0,ts=3,ss=0) RF CHANNEL RELEASE ACK
 <0000> abis_rsl.c:1652 (bts=0,trx=0,ts=2,ss=0) SAPI=0 RELEASE INDICATION
 <0004> abis_rsl.c:661 (bts=0,trx=0,ts=2,ss=0) RF Channel Release CMD due error 0
 <0004> abis_rsl.c:2049 (bts=0,trx=0,ts=2,ss=0) IPAC_DLCX_IND CAUSE=0x0f(Normal event, unspecified)
 <0004> abis_rsl.c:717 (bts=0,trx=0,ts=2,ss=0) RF CHANNEL RELEASE ACK
-

Files

osipc-nokia-huawei-local.cap osipc-nokia-huawei-local.cap 8.93 KB keith, 07/27/2016 12:01 PM
lcr-nokia-huawei-local.cap lcr-nokia-huawei-local.cap 8.88 KB keith, 07/27/2016 12:01 PM
lcr-nokia-calls-lac0.cap lcr-nokia-calls-lac0.cap 6.32 KB keith, 07/27/2016 12:52 PM
nitb-log.diff nitb-log.diff 5.99 KB keith, 07/27/2016 12:52 PM
osipc-nokia-calls-lac0.cap osipc-nokia-calls-lac0.cap 5.65 KB keith, 07/27/2016 12:52 PM
Actions #1

Updated by zecke over 7 years ago

  • Description updated (diff)
Actions #2

Updated by zecke over 7 years ago

Could you please attach a PCAP of the SIP as well? E.g. I wonder if 180 trying was received. I don't remember if I checked/listened to ringing on the phone.

Actions #3

Updated by keith over 7 years ago

The descriptive text to accompany these SIP traces reads something like:

LCR: On the Nokia 6070, I dial, press send, immediately here some click,
crsshh noise.. then I hear audible remote ringing tone, then I pick up
on the other handset, call continues as normal. I hang up.

O-sip-C: On the Nokia 6070, I dial, press send, I hear nothing, absolute
silence, I look at the phone, the display shows "Calling...." then I
pick up on the other handset, audio kicks in call continues as normal. I
hang up.

Actions #4

Updated by zecke over 7 years ago

I am at an airport with bad wifi.. if you have time for a quick try please try:

diff --git a/src/sip.c b/src/sip.c
index 139c620..afff393 100644
--- a/src/sip.c
+++ b/src/sip.c
@@ -156,7 +156,7 @@ void nua_callback(nua_event_t event, int status, char const *phrase, nua_t *nua,
                if (leg->state == SIP_CC_INITIAL)
                        leg->state = SIP_CC_DLG_CNFD;

-               if (status == 180)
+               if (status == 180 || status == 183)
                        call_progress(leg, sip);
                else if (status == 200)
                        call_connect(leg, sip);

otherwise friday is most likely the next work day for me (depending on jetlag)

Actions #5

Updated by keith over 7 years ago

No hurry...

Quick feedback from a behaviour point of view:
The Nokia, if I call an unconnected subscriber, appears to connect, sounds the locally (phone) generated ringing sound once or sometimes twice then shows "Error in connection" with that annoying 3 ascending tones error sound.

The Huawei activates audio and plays back the USER_BUSY audio from freeswitch, sure enough, osmo-sip-connector seems to be returning USER_BUSY instead of DESTINATION_OUT_OF_ORDER

Actions #6

Updated by zecke over 7 years ago

Okay but that is for a case the call does not connect? It is unrelated to the early audio?

Actions #7

Updated by keith over 7 years ago

The way it is working currently with LCR is that I play audio files based on the variable originate_disposition in the freeswitch dialplan. This works correctly.

LCR would appear to be returning 502 to freeswitch with a Q.850 cause code 27
osmo-sip-connector is just returning 486.

But OK, so that is not partiularly related to the early audio.. Sorry, let's not confuse the issue, mixed up responses may be another ticket?

So.. from what I make of the nitb log, when using LCR I'm still seeing this MNCC_LCHAN_MODIFY and RTP setup stuff that doesn't happen with osmo-sip-connector.

I understand that there are two approaches to this kind of signalling about call progress, right? You either open an "early media" or I've seen it referred to as "pre-audio" channel, or you send other control messages (I don't know what they are called) that the handset responds to by generating it's own audio or visual feedback.

I think ultimately we need to support both options.

Although we may prefer to not have to use an audio channel to communicate "user busy", there are many cases in calling out over VOIP where you have to have audio, for example, the one I mentioned before in email, where I power off my commercial mobile phone and call it, In this case, the remote provider does not "Answer" so no billing takes place, but there is an early media message: "The person you are calling is not available... blah blah..."

Currently the Nokia is giving me the locally generated ringing sound until the remote provider hangs up, then I get "Error in Connection".

The Huawei gives me remote ringing sound, but still no audio message from the provider.
This also happens with some out of service land line numbers numbers that I know of and sometimes use to test this kind of thing. They give "We're sorry.. the number you have called.. blah blah" type messages, but no call connect/billing.

This is something that has never been quite right in any implementation, so I am very keen to work with osmo-sip-connector to get it all right this time!

I am leaving this issue for today. If I get a chance I will take a look at the code and see if I can track some things down.

Gute Reise! ;)

Actions #8

Updated by laforge over 7 years ago

Actions #9

Updated by laforge about 7 years ago

  • Priority changed from Normal to High
Actions #10

Updated by zecke about 7 years ago

  • Status changed from New to In Progress

Okay, finally getting around to work on it (from next week).

Actions #11

Updated by zecke about 7 years ago

I think the only thing that might be missing is to include the MNCC_F_PROGRESS flag and mention in-progress. Will test my change after lunch

Actions #12

Updated by zecke about 7 years ago

Not fully sure (as I play the ringtone only once) but with the nanoBTS I hear the sound. It might be that before a MDCX, recvonly is broken. But this would apply to LCR too. It is my topic for today.

Actions #13

Updated by zecke about 7 years ago

Okay. Replaced nanoBTS with sysmoBTS and I don't hear a ringtone. I am going to look at the BTS TCH handling now. I suspect we don't read from the TCP socket early enough. I can cheat and send the MDCX earlier (as soon as we have the session progress). But our MNCC protocol doesn't allow to indicate send/recv... :(

Actions #14

Updated by zecke about 7 years ago

laforge/@neels:

        /* Special rule: If connect_ip == 0.0.0.0, use RSL IP
         * address */
        if (connect_ip == 0) {
                struct e1inp_sign_link *sign_link =
                                        lchan->ts->trx->rsl_link;

                ia.s_addr = htonl(get_signlink_remote_ip(sign_link));
        } else
                ia.s_addr = connect_ip;
        rc = osmo_rtp_socket_connect(lchan->abis_ip.rtp_socket,
                                     inet_ntoa(ia), ntohs(connect_port));

With a CRCX we do not specify the remote IP/port and connect to the RSL address and port 0. Now this doesn't work for early media and is different to how the nanoBTS works. The mitigation is to issue one or more MDCX. Now the question is why not connect to 0.0.0.0 or omit the connect?

Actions #15

Updated by laforge about 7 years ago

Hi Holger,

On Fri, Mar 10, 2017 at 02:37:41PM +0000, zecke [REDMINE] wrote:

>         /* Special rule: If connect_ip == 0.0.0.0, use RSL IP
>          * address */
>         if (connect_ip == 0) {
>                 struct e1inp_sign_link *sign_link =
>                                         lchan->ts->trx->rsl_link;
> 
>                 ia.s_addr = htonl(get_signlink_remote_ip(sign_link));
>         } else
>                 ia.s_addr = connect_ip;
>         rc = osmo_rtp_socket_connect(lchan->abis_ip.rtp_socket,
>                                      inet_ntoa(ia), ntohs(connect_port));
> 

With a CRCX we do not specify the remote IP/port and connect to the
RSL address and port 0.

Well, only if the CRCX doesn't contain an destination IP nor port
number. Is this valid/expected? I mean, what is a CRCX for, if not to
connect the socket to the remote end? The MDCX is (typically) for
modifying the locel end?

I guess I'm missing more context.

Now this doesn't work for early media and is different to how the
nanoBTS works.

What does it do differently?

Actions #16

Updated by zecke about 7 years ago

On 10 Mar 2017, at 17:15, laforge [REDMINE] <> wrote:

Issue #1784 has been updated by laforge.

With a CRCX we do not specify the remote IP/port and connect to the
RSL address and port 0.

Well, only if the CRCX doesn't contain an destination IP nor port
number. Is this valid/expected? I mean, what is a CRCX for, if not to
connect the socket to the remote end? The MDCX is (typically) for
modifying the locel end?

I guess I'm missing more context.

For a MO-Call, IPA CRCX will be called before we know any remote IP
address/port. Once the call starts ringing the PBX will start sending
to the IP:port returned by IPA CRCX ACK. Now with binding to rsl_peer:0
it will not receive the RTP stream of the PBX. This kind of defeats the
concept of "recvonly".

Now this doesn't work for early media and is different to how the
nanoBTS works.

What does it do differently?

IPA CRCX without remote port/ip will make the nanoBTS accept audio
from any IP/port. In the sysmoBTS case it is ignored.

My workaround is to send IPA MDCX earlier. But I would like to send
it with "recvonly" too.

Actions #17

Updated by laforge about 7 years ago

  • Project changed from OpenBSC to osmo-sip-connector
Actions #18

Updated by zecke about 7 years ago

  • Status changed from In Progress to Closed

I have merged the code with the downside of setting a call sendrecv even if it is only alerting.

Actions #19

Updated by keith almost 7 years ago

Great! The user experience (as I described it) is now as expected, (as I described it) :)
At least, with all the phones I have here to test and with osmo-trx/osmo-trx-bts/USRP

Except that is, for #1682

Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)