[Freeswitch-users] Packet-time negotiation problem

Fri Apr 20 04:36:17 MSD 2012

Hello,

	I have installed freeSwitch 1.1beta from the git repository (FreeSWITCH-mod_sofia/1.1.beta1-git-d2edcad 2012-03-31 23-42-27 +0000). I have enabled iLBC at 30i codec by setting global vars:

	<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G7221 at 32000h,G7221 at 16000h,G722,PCMU,PCMA,GSM,iLBC at 30i,SILK,G729"/>
	<X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM,iLBC at 30i,SILK,G729"/>

	I try to call from Bria for iPhone to x-Lite 4.1.  Bria offers iLBC at 30i:

2012-04-20 00:24:03.740477 [NOTICE] switch_channel.c:926 New Channel sofia/internal/1001 at sukmad.dyndns-home.com [624007f0-d580-4500-834f-76c2ba578df0]
2012-04-20 00:24:03.740477 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/1001 at sukmad.dyndns-home.com) Running State Change CS_NEW
2012-04-20 00:24:03.740477 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/1001 at sukmad.dyndns-home.com) State NEW
2012-04-20 00:24:03.740477 [DEBUG] sofia.c:5561 Channel sofia/internal/1001 at sukmad.dyndns-home.com entering state [received][100]
2012-04-20 00:24:03.740477 [DEBUG] sofia.c:5572 Remote SDP:
v=0
o=- 3543863125 3543863125 IN IP4 88.9.239.104
s=cpc_med
c=IN IP4 88.9.239.104
t=0 0
m=audio 17002 RTP/AVP 112 18 105 101
c=IN IP4 88.9.239.104
a=rtpmap:112 SILK/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:105 iLBC/8000
a=fmtp:105 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

	But FS set the codec to iLBC 98 (according to vars.xml,  it corresponds to iLBC at 20i):

2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[G7221:115:32000:20:48000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[G7221:115:32000:20:48000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[G7221:115:32000:20:48000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[G7221:115:32000:20:48000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[G7221:107:16000:20:32000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[G7221:107:16000:20:32000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[G7221:107:16000:20:32000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[G7221:107:16000:20:32000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[G722:9:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[G722:9:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[G722:9:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[G722:9:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[PCMU:0:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[PCMU:0:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[PCMU:0:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[PCMU:0:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[PCMA:8:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[PCMA:8:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[PCMA:8:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[PCMA:8:8000:20:64000]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[GSM:3:8000:20:13200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[GSM:3:8000:20:13200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[GSM:3:8000:20:13200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[GSM:3:8000:20:13200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [SILK:112:8000:20:0]/[iLBC:98:8000:20:15200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[iLBC:98:8000:20:15200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [iLBC:105:8000:30:0]/[iLBC:98:8000:20:15200]
2012-04-20 00:24:03.740477 [DEBUG] sofia_glue.c:3006 Set Codec sofia/internal/1001 at sukmad.dyndns-home.com iLBC/8000 20 ms 160 samples 15200 bits
2012-04-20 00:24:03.740477 [DEBUG] switch_core_codec.c:111 sofia/internal/1001 at sukmad.dyndns-home.com Original read codec set to iLBC:98

	I'm trying to fix the codec in the dialplan by setting absolute_codec_string channel variable:

Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action bridge({absolute_codec_string='iLBC at 30i,G729'}user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1001 at sukmad.dyndns-home.com Action answer() 

	When FS rings in the B-leg,  I think it sends an incorrect codec (mode=20)

2012-04-20 00:24:04.170478 [DEBUG] mod_sofia.c:2582 Ring SDP:
v=0
o=FreeSWITCH 1334863010 1334863011 IN IP4 88.9.239.104
s=FreeSWITCH
c=IN IP4 88.9.239.104
t=0 0
m=audio 11234 RTP/AVP 105 101
a=rtpmap:105 iLBC/8000
a=fmtp:105 mode=20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

	When I try to answer in B-leg (x-Lite softphone) it offers iLBC 98 (30 ms):

2012-04-20 00:24:13.750480 [DEBUG] switch_core_session.c:877 Send signal sofia/internal/sip:1002 at 192.168.0.2:3348 [BREAK]
2012-04-20 00:24:13.750480 [DEBUG] switch_core_session.c:877 Send signal sofia/internal/sip:1002 at 192.168.0.2:3348 [BREAK]
2012-04-20 00:24:13.750480 [DEBUG] sofia.c:5561 Channel sofia/internal/sip:1002 at 192.168.0.2:3348 entering state [completing][200]
2012-04-20 00:24:13.750480 [DEBUG] sofia.c:5572 Remote SDP:
v=0
o=- 1334874336856091 1 IN IP4 192.168.1.2
s=CounterPath X-Lite 4.1
c=IN IP4 192.168.1.2
t=0 0
m=audio 54624 RTP/AVP 98 101
a=rtpmap:98 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

	and the call ends with the following error:

2012-04-20 00:24:13.800478 [DEBUG] switch_core_session.c:793 Send signal sofia/internal/1001 at sukmad.dyndns-home.com [BREAK]
2012-04-20 00:24:13.810479 [DEBUG] switch_core_io.c:1095 Engaging Write Buffer at 320 bytes to accommodate 480->320
2012-04-20 00:24:13.980477 [WARNING] mod_sofia.c:1158 Asynchronous PTIME not supported, changing our end from 20 to 30
2012-04-20 00:24:13.980477 [DEBUG] sofia_glue.c:2924 Changing Codec from iLBC at 20ms@8000hz to iLBC at 30ms@8000hz
2012-04-20 00:24:14.020479 [WARNING] switch_core_codec.c:691 Codec iLBC Exists but not at the desired implementation. 8000hz 30ms
2012-04-20 00:24:14.020479 [ERR] sofia_glue.c:2954 Can't load codec?
2012-04-20 00:24:14.020479 [DEBUG] switch_channel.c:2848 (sofia/internal/1001 at sukmad.dyndns-home.com) Callstate Change ACTIVE -> HANGUP
2012-04-20 00:24:14.020479 [NOTICE] sofia_glue.c:2955 Hangup sofia/internal/1001 at sukmad.dyndns-home.com [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]

	Is it possible to re-packetize iLBC streams from iLBC at 20i to iLBC at 30i?.  Why FS choose an incorrect packet time?. 
	I have read about this problem in Internet and I try to uncomment the following line:

	<param name="rtp-autofix-timing" value="false"/>

	But when I try to make the call I don't hear nothing (except a big noise)...  There are any solution?.  I attach all the dump from fs_cli.

Thanks in advance.

Regards.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120420/ce99d1c6/attachment-0002.html 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: error_bria.log
Type: application/octet-stream
Size: 43529 bytes
Desc: not available
Url : http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120420/ce99d1c6/attachment-0001.obj 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20120420/ce99d1c6/attachment-0003.html 