Thanks for information.
But I am not able to use any other codec than PCMU/PCMA for some reason. I read related settings and what they mean.
I am using Vitelity for now and they say they do support G722/GSM/G729 on their end.
In sip_profiles, I have
<param name="inbound-codec-negotiation" value="greedy"/>
(tried scrooge but no success)
In vars.xml, I have
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,GSM,PCMU,PCMA"/>
<X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=G722,GSM,PCMU,PCMA"/>
In modules.conf.xml, I have
<load module="mod_spandsp"/>
Debug trace from console:
-----
2012-04-10 18:00:17.430961 [DEBUG] sofia.c:7547 IP IP1 Approved by acl "Malay_ACL[]". Access Granted.
2012-04-10 18:00:17.430961 [NOTICE] switch_channel.c:926 New Channel sofia/sipinterface_1/7607058888@IP2 [45fe1639-ead1-4547-b063-e40f38b5fd04]
2012-04-10 18:00:17.430961 [DEBUG] sofia.c:5561 Channel sofia/sipinterface_1/7607058888@IP2 entering state [received][100]
2012-04-10 18:00:17.430961 [DEBUG] sofia.c:5572 Remote SDP:
v=0
o=root 15681 15681 IN IP4 IP2
s=session
c=IN IP4 IP2
t=0 0
m=audio 12860 RTP/AVP 0 8 3 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_NEW
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMU:0:8000:20:64000]/[LPC:7:8000:90:2400]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMA:8:8000:20:64000]/[LPC:7:8000:90:2400]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [GSM:3:8000:20:13200]/[LPC:7:8000:90:2400]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:380 (sofia/sipinterface_1/7607058888@IP2) State NEW
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[LPC:7:8000:90:2400]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[LPC:7:8000:90:2400]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMU:0:8000:20:64000]/[G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMA:8:8000:20:64000]/[G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [GSM:3:8000:20:13200]/[G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMU:0:8000:20:64000]/[AAL2-G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMA:8:8000:20:64000]/[AAL2-G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [GSM:3:8000:20:13200]/[AAL2-G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [G729:18:8000:20:8000]/[AAL2-G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [telephone-event:101:8000:20:0]/[AAL2-G726-16:124:8000:20:16000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4895 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:4911 Bah HUMBUG! Sticking with PCMA@8000h@20i
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:3006 Set Codec sofia/sipinterface_1/7607058888@IP2 PCMA/8000 20 ms 160 samples 64000 bits
2012-04-10 18:00:17.430961 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/7607058888@IP2 Original read codec set to PCMA:8
2012-04-10 18:00:17.430961 [DEBUG] sofia_glue.c:5016 Set 2833 dtmf send/recv payload to 101
2012-04-10 18:00:17.430961 [DEBUG] sofia.c:5786 (sofia/sipinterface_1/7607058888@IP2) State Change CS_NEW -> CS_INIT
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_INIT
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/7607058888@IP2) State INIT
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:85 sofia/sipinterface_1/7607058888@IP2 SOFIA INIT
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:125 (sofia/sipinterface_1/7607058888@IP2) State Change CS_INIT -> CS_ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/7607058888@IP2) State INIT going to sleep
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_channel.c:1886 (sofia/sipinterface_1/7607058888@IP2) Callstate Change DOWN -> RINGING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/7607058888@IP2) State ROUTING
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:148 sofia/sipinterface_1/7607058888@IP2 SOFIA ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/7607058888@IP2 Standard ROUTING
2012-04-10 18:00:17.430961 [INFO] mod_dialplan_xml.c:485 Processing +17607058888 <7607058888>->DID1 in context inbound
Dialplan: sofia/sipinterface_1/7607058888@IP2 parsing [inbound->vitel-inbound] continue=false
Dialplan: sofia/sipinterface_1/7607058888@IP2 Regex (PASS) [vitel-inbound] destination_number(DID1) =~ // break=on-false
Dialplan: sofia/sipinterface_1/7607058888@IP2 Action transfer(1056 XML default)
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:154 (sofia/sipinterface_1/7607058888@IP2) State Change CS_ROUTING -> CS_EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/7607058888@IP2) State ROUTING going to sleep
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/7607058888@IP2) State EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:241 sofia/sipinterface_1/7607058888@IP2 SOFIA EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:192 sofia/sipinterface_1/7607058888@IP2 Standard EXECUTE
EXECUTE sofia/sipinterface_1/7607058888@IP2 transfer(1056 XML default)
2012-04-10 18:00:17.430961 [DEBUG] switch_ivr.c:1711 (sofia/sipinterface_1/7607058888@IP2) State Change CS_EXECUTE -> CS_ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:731 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [NOTICE] switch_ivr.c:1717 Transfer sofia/sipinterface_1/7607058888@IP2 to XML[1056@default]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/7607058888@IP2) State EXECUTE going to sleep
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/7607058888@IP2) State ROUTING
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:148 sofia/sipinterface_1/7607058888@IP2 SOFIA ROUTING
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/7607058888@IP2 Standard ROUTING
2012-04-10 18:00:17.430961 [INFO] mod_dialplan_xml.c:485 Processing +17607058888 <7607058888>->1056 in context default
Dialplan: sofia/sipinterface_1/7607058888@IP2 parsing [default->CHPhoneAsmtDev] continue=false
Dialplan: sofia/sipinterface_1/7607058888@IP2 Regex (PASS) [CHPhoneAsmtDev] destination_number(1056) =~ /^105\d$/ break=on-false
Dialplan: sofia/sipinterface_1/7607058888@IP2 Action sleep(1000)
Dialplan: sofia/sipinterface_1/7607058888@IP2 Action managed(clsAsmtApp)
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:154 (sofia/sipinterface_1/7607058888@IP2) State Change CS_ROUTING -> CS_EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/7607058888@IP2) State ROUTING going to sleep
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/7607058888@IP2) State EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] mod_sofia.c:241 sofia/sipinterface_1/7607058888@IP2 SOFIA EXECUTE
2012-04-10 18:00:17.430961 [DEBUG] switch_core_state_machine.c:192 sofia/sipinterface_1/7607058888@IP2 Standard EXECUTE
EXECUTE sofia/sipinterface_1/7607058888@IP2 sleep(1000)
EXECUTE sofia/sipinterface_1/7607058888@IP2 managed(clsAsmtApp)
2012-04-10 18:00:18.451403 [DEBUG] switch_cpp.cpp:1227 FreeSWITCH.Managed: attempting to run application 'clsAsmtApp'.
2012-04-10 18:00:18.650609 [DEBUG] switch_cpp.cpp:1172 CoreSession::seHangupHook, hangup_func: 00000000
2012-04-10 18:00:19.491376 [NOTICE] switch_cpp.cpp:1227 Not an outbound call.
2012-04-10 18:00:19.491376 [INFO] switch_cpp.cpp:1227 caller_id_number: 7607058888
2012-04-10 18:00:19.491376 [DEBUG] sofia_glue.c:3258 AUDIO RTP [sofia/sipinterface_1/7607058888@IP2] 10.25.20.202 port 31458 -> IP2 port 12
odec: 8 ms: 20
2012-04-10 18:00:19.491376 [DEBUG] switch_rtp.c:1669 Not using a timer
2012-04-10 18:00:19.510906 [DEBUG] sofia_glue.c:3522 Set 2833 dtmf send payload to 101
2012-04-10 18:00:19.510906 [DEBUG] sofia_glue.c:3528 Set 2833 dtmf receive payload to 101
2012-04-10 18:00:19.510906 [DEBUG] mod_sofia.c:754 Local SDP sofia/sipinterface_1/7607058888@IP2:
v=0
o=FreeSWITCH 1334067361 1334067362 IN IP4 64.22.232.56
s=FreeSWITCH
c=IN IP4 64.22.232.56
t=0 0
m=audio 31458 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2012-04-10 18:00:19.510906 [DEBUG] switch_core_session.c:731 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:19.510906 [DEBUG] switch_channel.c:3244 (sofia/sipinterface_1/7607058888@IP2) Callstate Change RINGING -> ACTIVE
2012-04-10 18:00:19.510906 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:19.510906 [NOTICE] switch_cpp.cpp:599 Channel [sofia/sipinterface_1/7607058888@IP2] has been answered
2012-04-10 18:00:19.510906 [DEBUG] sofia.c:5561 Channel sofia/sipinterface_1/7607058888@IP2 entering state [completed][200]
2012-04-10 18:00:19.550942 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:19.550942 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:19.550942 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:20.331166 [INFO] switch_cpp.cpp:1227 OK. Connected to customer DB.
2012-04-10 18:00:20.331166 [DEBUG] switch_ivr_play_say.c:2462 OPEN TTS flite
2012-04-10 18:00:20.331166 [DEBUG] switch_ivr_play_say.c:2471 Raw Codec Activated
2012-04-10 18:00:20.390732 [DEBUG] switch_ivr_play_say.c:2160 Speaking text: <break strength='medium'/>Hello.<break strength='medium'/>Welcome.
2012-04-10 18:00:20.411239 [DEBUG] sofia.c:5561 Channel sofia/sipinterface_1/7607058888@IP2 entering state [ready][200]
2012-04-10 18:00:20.611421 [DEBUG] switch_rtp.c:3224 Correct ip/port confirmed.
2012-04-10 18:00:26.071033 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:26.071033 [DEBUG] switch_channel.c:2848 (sofia/sipinterface_1/7607058888@IP2) Callstate Change ACTIVE -> HANGUP
2012-04-10 18:00:26.071033 [NOTICE] sofia.c:636 Hangup sofia/sipinterface_1/7607058888@IP2 [CS_EXECUTE] [NORMAL_CLEARING]
2012-04-10 18:00:26.071033 [DEBUG] switch_channel.c:2871 Send signal sofia/sipinterface_1/7607058888@IP2 [KILL]
2012-04-10 18:00:26.071033 [DEBUG] switch_cpp.cpp:1227 AppFunction is in hangupCallback.
2012-04-10 18:00:26.071033 [NOTICE] switch_cpp.cpp:1227 45fe1639-ead1-4547-b063-e40f38b5fd04-clsAsmtApp hanging up, UUID: 45fe1639-ead1-4547-b063-e40f38b5f
2012-04-10 18:00:26.071033 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:26.071033 [DEBUG] switch_ivr_play_say.c:2354 done speaking text
2012-04-10 18:00:26.071033 [NOTICE] switch_cpp.cpp:1227 45fe1639-ead1-4547-b063-e40f38b5fd04-Inside clsAsmtApp.Run (args ''); HookState is CS_HANGUP.
2012-04-10 18:00:26.091539 [DEBUG] switch_cpp.cpp:635 CoreSession::hangup
2012-04-10 18:00:26.231179 [INFO] switch_cpp.cpp:1227 Entered 6 SpeakDelayReport in ThCustomerDb database.
2012-04-10 18:00:26.231179 [INFO] switch_cpp.cpp:1227 Entered 2 PathDelayReport in ThCustomerDb database.
2012-04-10 18:00:26.250709 [INFO] switch_cpp.cpp:1227 Entered 4 IVRAsmtStatusRecord in ThCustomerDb database.
2012-04-10 18:00:26.250709 [DEBUG] switch_cpp.cpp:1007 sofia/sipinterface_1/7607058888@IP2 destroy/unlink session from object
2012-04-10 18:00:26.250709 [DEBUG] switch_core_session.c:2287 sofia/sipinterface_1/7607058888@IP2 skip receive message [APPLICATION_EXEC_COMPLETE]
nel is hungup already)
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/7607058888@IP2) State EXECUTE going to sleep
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_HANGUP
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/7607058888@IP2) State HANGUP
2012-04-10 18:00:26.250709 [DEBUG] mod_sofia.c:469 Channel sofia/sipinterface_1/7607058888@IP2 hanging up, cause: NORMAL_CLEARING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:47 sofia/sipinterface_1/7607058888@IP2 Standard HANGUP, cause: NORMAL_CLEARING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/7607058888@IP2) State HANGUP going to sleep
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:393 (sofia/sipinterface_1/7607058888@IP2) State Change CS_HANGUP -> CS_REPORTING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_REPORTING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/7607058888@IP2) State REPORTING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:79 sofia/sipinterface_1/7607058888@IP2 Standard REPORTING, cause: NORMAL_CLEARING
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/7607058888@IP2) State REPORTING going to sleep
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:387 (sofia/sipinterface_1/7607058888@IP2) State Change CS_REPORTING -> CS_DESTROY
2012-04-10 18:00:26.250709 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/7607058888@IP2 [BREAK]
2012-04-10 18:00:26.250709 [DEBUG] switch_core_session.c:1382 Session 1 (sofia/sipinterface_1/7607058888@IP2) Locked, Waiting on external entities
2012-04-10 18:00:26.250709 [NOTICE] switch_core_session.c:1400 Session 1 (sofia/sipinterface_1/7607058888@IP2) Ended
2012-04-10 18:00:26.250709 [NOTICE] switch_core_session.c:1402 Close Channel sofia/sipinterface_1/7607058888@IP2 [CS_DESTROY]
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/7607058888@IP2) Callstate Change HANGUP -> DOWN
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:494 (sofia/sipinterface_1/7607058888@IP2) Running State Change CS_DESTROY
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/7607058888@IP2) State DESTROY
2012-04-10 18:00:26.250709 [DEBUG] mod_sofia.c:374 sofia/sipinterface_1/7607058888@IP2 SOFIA DESTROY
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:86 sofia/sipinterface_1/7607058888@IP2 Standard DESTROY
2012-04-10 18:00:26.250709 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/7607058888@IP2) State DESTROY going to sleep
-----
Thanks for help. Am I doing something wrong here?
Malay