called with g722-->


2011-01-06 15:30:43.040722 [NOTICE] switch_channel.c:808 New Channel sofia/internal/7001@192.168.2.190 [a97449df-688e-4bf9-9724-3d63338907fb]
2011-01-06 15:30:43.041645 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_NEW
2011-01-06 15:30:43.041645 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/7001@192.168.2.190) State NEW
2011-01-06 15:30:43.041645 [DEBUG] sofia.c:4616 Channel sofia/internal/7001@192.168.2.190 entering state [received][100]
2011-01-06 15:30:43.041645 [DEBUG] sofia.c:4627 Remote SDP:
v=0
o=- 25952772 25952780 IN IP4 192.168.2.15
s=eyeBeam
c=IN IP4 192.168.2.15
t=0 0
m=audio 6398 RTP/AVP 110 101
a=rtpmap:110 g7222/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : AC5CC22D 0000007A 192.168.2.15 6398
a=ptime:110 20

2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [g7222:110:16000:110:0]/[G7221:115:32000:20:48000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [g7222:110:16000:110:0]/[G7221:107:16000:20:32000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [g7222:110:16000:110:0]/[PCMU:0:8000:20:64000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [g7222:110:16000:110:0]/[PCMA:8:8000:20:64000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [g7222:110:16000:110:0]/[G729:18:8000:20:8000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [telephone-event:101:8000:110:0]/[G7221:115:32000:20:48000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [telephone-event:101:8000:110:0]/[G7221:107:16000:20:32000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [telephone-event:101:8000:110:0]/[PCMU:0:8000:20:64000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [telephone-event:101:8000:110:0]/[PCMA:8:8000:20:64000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [telephone-event:101:8000:110:0]/[G729:18:8000:20:8000]
2011-01-06 15:30:43.041645 [DEBUG] sofia_glue.c:4507 Set 2833 dtmf send/recv payload to 101
2011-01-06 15:30:43.041645 [DEBUG] switch_channel.c:2535 (sofia/internal/7001@192.168.2.190) Callstate Change DOWN -> HANGUP
2011-01-06 15:30:43.041645 [NOTICE] sofia.c:4838 Hangup sofia/internal/7001@192.168.2.190 [CS_NEW] [INCOMPATIBLE_DESTINATION]
2011-01-06 15:30:43.041645 [DEBUG] switch_channel.c:2551 Send signal sofia/internal/7001@192.168.2.190 [KILL]
2011-01-06 15:30:43.041645 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:30:43.042561 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_HANGUP
2011-01-06 15:30:43.042561 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/7001@192.168.2.190) State HANGUP
2011-01-06 15:30:43.042561 [DEBUG] mod_sofia.c:459 Channel sofia/internal/7001@192.168.2.190 hanging up, cause: INCOMPATIBLE_DESTINATION
2011-01-06 15:30:43.044377 [DEBUG] mod_sofia.c:521 Responding to INVITE with: 488
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:46 sofia/internal/7001@192.168.2.190 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/7001@192.168.2.190) State HANGUP going to sleep
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/7001@192.168.2.190) State Change CS_HANGUP -> CS_REPORTING
2011-01-06 15:30:43.044377 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_REPORTING
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/7001@192.168.2.190) State REPORTING
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:53 sofia/internal/7001@192.168.2.190 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2011-01-06 15:30:43.044377 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/7001@192.168.2.190) State REPORTING going to sleep
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/7001@192.168.2.190) State Change CS_REPORTING -> CS_DESTROY
2011-01-06 15:30:43.045293 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:30:43.045293 [DEBUG] switch_core_session.c:1255 Session 46 (sofia/internal/7001@192.168.2.190) Locked, Waiting on external entities
2011-01-06 15:30:43.045293 [NOTICE] switch_core_session.c:1273 Session 46 (sofia/internal/7001@192.168.2.190) Ended
2011-01-06 15:30:43.045293 [NOTICE] switch_core_session.c:1275 Close Channel sofia/internal/7001@192.168.2.190 [CS_DESTROY]
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/7001@192.168.2.190) Callstate Change HANGUP -> DOWN
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/7001@192.168.2.190) Running State Change CS_DESTROY
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/7001@192.168.2.190) State DESTROY
2011-01-06 15:30:43.045293 [DEBUG] mod_sofia.c:364 sofia/internal/7001@192.168.2.190 SOFIA DESTROY
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7001@192.168.2.190 Standard DESTROY
2011-01-06 15:30:43.045293 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/7001@192.168.2.190) State DESTROY going to sleep



When sending with g729 -->




2011-01-06 15:36:16.594761 [NOTICE] switch_channel.c:808 New Channel sofia/internal/7001@192.168.2.190 [946f3be9-dc5f-43cc-948d-b090c21b0079]
2011-01-06 15:36:16.595675 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_NEW
2011-01-06 15:36:16.595675 [DEBUG] switch_core_state_machine.c:338 (sofia/internal/7001@192.168.2.190) State NEW
2011-01-06 15:36:16.595675 [DEBUG] sofia.c:4616 Channel sofia/internal/7001@192.168.2.190 entering state [received][100]
2011-01-06 15:36:16.595675 [DEBUG] sofia.c:4627 Remote SDP:
v=0
o=- 26286332 26286340 IN IP4 192.168.2.15
s=eyeBeam
c=IN IP4 192.168.2.15
t=0 0
m=audio 6398 RTP/AVP 18 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : DB678F86 00000016 192.168.2.15 6398

2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [G729:18:8000:0:8000]/[G7221:115:32000:20:48000]
2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [G729:18:8000:0:8000]/[G7221:107:16000:20:32000]
2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [G729:18:8000:0:8000]/[PCMU:0:8000:20:64000]
2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [G729:18:8000:0:8000]/[PCMA:8:8000:20:64000]
2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [G729:18:8000:0:8000]/[G729:18:8000:20:8000]
2011-01-06 15:36:16.595675 [DEBUG] sofia_glue.c:2750 Set Codec sofia/internal/7001@192.168.2.190 G729/8000 20 ms 160 samples 8000 bits
2011-01-06 15:36:16.596685 [DEBUG] sofia_glue.c:4507 Set 2833 dtmf send/recv payload to 101
2011-01-06 15:36:16.596685 [DEBUG] sofia.c:4794 (sofia/internal/7001@192.168.2.190) State Change CS_NEW -> CS_INIT
2011-01-06 15:36:16.596685 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_INIT
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/7001@192.168.2.190) State INIT
2011-01-06 15:36:16.596685 [DEBUG] mod_sofia.c:86 sofia/internal/7001@192.168.2.190 SOFIA INIT
2011-01-06 15:36:16.596685 [DEBUG] mod_sofia.c:126 (sofia/internal/7001@192.168.2.190) State Change CS_INIT -> CS_ROUTING
2011-01-06 15:36:16.596685 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/7001@192.168.2.190) State INIT going to sleep
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_ROUTING
2011-01-06 15:36:16.596685 [DEBUG] switch_channel.c:1657 (sofia/internal/7001@192.168.2.190) Callstate Change DOWN -> RINGING
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/7001@192.168.2.190) State ROUTING
2011-01-06 15:36:16.596685 [DEBUG] mod_sofia.c:149 sofia/internal/7001@192.168.2.190 SOFIA ROUTING
2011-01-06 15:36:16.596685 [DEBUG] switch_core_state_machine.c:77 sofia/internal/7001@192.168.2.190 Standard ROUTING
2011-01-06 15:36:16.596685 [INFO] mod_dialplan_xml.c:331 Processing 7001 <7001>->7013 in context novanet
Dialplan: sofia/internal/7001@192.168.2.190 parsing [novanet->novanet_7011] continue=false
Dialplan: sofia/internal/7001@192.168.2.190 Regex (FAIL) [novanet_7011] destination_number(7013) =~ /^(7011)/ break=on-false
Dialplan: sofia/internal/7001@192.168.2.190 parsing [novanet->novanet_7012] continue=false
Dialplan: sofia/internal/7001@192.168.2.190 Regex (FAIL) [novanet_7012] destination_number(7013) =~ /^(7012)/ break=on-false
Dialplan: sofia/internal/7001@192.168.2.190 parsing [novanet->novanet_7013] continue=false
Dialplan: sofia/internal/7001@192.168.2.190 Regex (PASS) [novanet_7013] destination_number(7013) =~ /^(7013)/ break=on-false
Dialplan: sofia/internal/7001@192.168.2.190 Action set(dialed_extension=7013)
Dialplan: sofia/internal/7001@192.168.2.190 Action export(dialed_extension=7013)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(call_timeout=20)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(export_vars=#,*)
Dialplan: sofia/internal/7001@192.168.2.190 Action export(#=true)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(bind_meta_key=#)
Dialplan: sofia/internal/7001@192.168.2.190 Action bind_meta_app(1 ab s execute_extension::dx XML features)
Dialplan: sofia/internal/7001@192.168.2.190 Action bind_meta_app(2 ab s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/7001@192.168.2.190 Action set(continue_on_fail=true)
Dialplan: sofia/internal/7001@192.168.2.190 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/7001@192.168.2.190 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/7001@192.168.2.190 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/7001@192.168.2.190 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/7001@192.168.2.190 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/7001@192.168.2.190 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/7001@192.168.2.190 Action bridge({sip_invite_domain=192.168.2.190}user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/7001@192.168.2.190 Action set(continue_on_fail=NORMAL_TEMPORARY_FAILURE,USER_BUSY,NO_ANSWER,TIMEOUT,NO_ROUTE_DESTINATION,USER_NOT_REGISTERED)
Dialplan: sofia/internal/7001@192.168.2.190 Action bridge(freetdm/wp1/a/9833658320)
Dialplan: sofia/internal/7001@192.168.2.190 Action answer()
Dialplan: sofia/internal/7001@192.168.2.190 Action sleep(1000)
Dialplan: sofia/internal/7001@192.168.2.190 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2011-01-06 15:36:16.598554 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/7001@192.168.2.190) State Change CS_ROUTING -> CS_EXECUTE
2011-01-06 15:36:16.598554 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:16.598554 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/7001@192.168.2.190) State ROUTING going to sleep
2011-01-06 15:36:16.598554 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_EXECUTE
2011-01-06 15:36:16.598554 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/7001@192.168.2.190) State EXECUTE
2011-01-06 15:36:16.598554 [DEBUG] mod_sofia.c:242 sofia/internal/7001@192.168.2.190 SOFIA EXECUTE
2011-01-06 15:36:16.598554 [DEBUG] switch_core_state_machine.c:157 sofia/internal/7001@192.168.2.190 Standard EXECUTE
EXECUTE sofia/internal/7001@192.168.2.190 set(dialed_extension=7013)
2011-01-06 15:36:16.598554 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [dialed_extension]=[7013]
EXECUTE sofia/internal/7001@192.168.2.190 export(dialed_extension=7013)
2011-01-06 15:36:16.599470 [DEBUG] switch_channel.c:957 EXPORT (export_vars) [dialed_extension]=[7013]
EXECUTE sofia/internal/7001@192.168.2.190 set(transfer_ringback=local_stream://moh)
2011-01-06 15:36:16.599470 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/7001@192.168.2.190 set(call_timeout=20)
2011-01-06 15:36:16.599470 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [call_timeout]=[20]
EXECUTE sofia/internal/7001@192.168.2.190 set(export_vars=#,*)
2011-01-06 15:36:16.600385 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [export_vars]=[#,*]
EXECUTE sofia/internal/7001@192.168.2.190 export(#=true)
2011-01-06 15:36:16.600385 [DEBUG] switch_channel.c:957 EXPORT (export_vars) [#]=[true]
EXECUTE sofia/internal/7001@192.168.2.190 set(bind_meta_key=#)
2011-01-06 15:36:16.600385 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [bind_meta_key]=[#]
EXECUTE sofia/internal/7001@192.168.2.190 bind_meta_app(1 ab s execute_extension::dx XML features)
2011-01-06 15:36:16.601300 [INFO] switch_ivr_async.c:3004 Bound A-Leg: # execute_extension::dx XML features
2011-01-06 15:36:16.601300 [INFO] switch_ivr_async.c:3012 Bound B-Leg: # execute_extension::dx XML features
EXECUTE sofia/internal/7001@192.168.2.190 bind_meta_app(2 ab s execute_extension::att_xfer XML features)
2011-01-06 15:36:16.601300 [INFO] switch_ivr_async.c:3004 Bound A-Leg: # execute_extension::att_xfer XML features
2011-01-06 15:36:16.601300 [INFO] switch_ivr_async.c:3012 Bound B-Leg: # execute_extension::att_xfer XML features
EXECUTE sofia/internal/7001@192.168.2.190 set(hangup_after_bridge=true)
2011-01-06 15:36:16.602215 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/7001@192.168.2.190 set(continue_on_fail=true)
2011-01-06 15:36:16.602215 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/7001@192.168.2.190 hash(insert/192.168.2.190-call_return/7013/7001)
EXECUTE sofia/internal/7001@192.168.2.190 hash(insert/192.168.2.190-last_dial_ext/7013/946f3be9-dc5f-43cc-948d-b090c21b0079)
EXECUTE sofia/internal/7001@192.168.2.190 hash(insert/192.168.2.190-last_dial_ext//946f3be9-dc5f-43cc-948d-b090c21b0079)
EXECUTE sofia/internal/7001@192.168.2.190 hash(insert/192.168.2.190-last_dial_ext/global/946f3be9-dc5f-43cc-948d-b090c21b0079)
EXECUTE sofia/internal/7001@192.168.2.190 set(called_party_callgroup=1)
2011-01-06 15:36:16.603130 [DEBUG] mod_dptools.c:1050 sofia/internal/7001@192.168.2.190 SET [called_party_callgroup]=[1]
EXECUTE sofia/internal/7001@192.168.2.190 hash(insert/192.168.2.190-last_dial/1/946f3be9-dc5f-43cc-948d-b090c21b0079)
EXECUTE sofia/internal/7001@192.168.2.190 bridge({sip_invite_domain=192.168.2.190}user/7013@192.168.2.190)
2011-01-06 15:36:16.603130 [DEBUG] switch_channel.c:914 sofia/internal/7001@192.168.2.190 EXPORTING[export_vars] [#]=[true] to event
2011-01-06 15:36:16.603130 [DEBUG] switch_channel.c:914 sofia/internal/7001@192.168.2.190 EXPORTING[export_vars] [#]=[true] to event
2011-01-06 15:36:16.603130 [DEBUG] switch_ivr_originate.c:1961 variable string 0 = [sip_invite_domain=192.168.2.190]
2011-01-06 15:36:16.605902 [DEBUG] switch_channel.c:914 sofia/internal/7001@192.168.2.190 EXPORTING[export_vars] [#]=[true] to event
2011-01-06 15:36:16.605902 [DEBUG] switch_channel.c:914 sofia/internal/7001@192.168.2.190 EXPORTING[export_vars] [#]=[true] to event
2011-01-06 15:36:16.605902 [DEBUG] switch_ivr_originate.c:1961 variable string 0 = [presence_id=7013@192.168.2.190]
2011-01-06 15:36:16.606823 [NOTICE] switch_channel.c:808 New Channel sofia/internal/sip:7013@192.168.2.42:5060 [94892779-a422-4b43-91d6-8666006edfbf]
2011-01-06 15:36:16.606823 [DEBUG] mod_sofia.c:4101 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_NEW -> CS_INIT
2011-01-06 15:36:16.606823 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:16.606823 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_INIT
2011-01-06 15:36:16.606823 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:7013@192.168.2.42:5060) State INIT
2011-01-06 15:36:16.606823 [DEBUG] mod_sofia.c:86 sofia/internal/sip:7013@192.168.2.42:5060 SOFIA INIT
2011-01-06 15:36:16.606823 [DEBUG] sofia_glue.c:2317 sip:7013@192.168.2.42:5060;transport=udp Setting proxy route to sofia/internal/sip:7013@192.168.2.42:5060
2011-01-06 15:36:16.606823 [DEBUG] mod_sofia.c:126 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_INIT -> CS_ROUTING
2011-01-06 15:36:16.606823 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:16.606823 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:7013@192.168.2.42:5060) State INIT going to sleep
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_ROUTING
2011-01-06 15:36:16.607737 [DEBUG] switch_channel.c:1657 (sofia/internal/sip:7013@192.168.2.42:5060) Callstate Change DOWN -> RINGING
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:7013@192.168.2.42:5060) State ROUTING
2011-01-06 15:36:16.607737 [DEBUG] mod_sofia.c:149 sofia/internal/sip:7013@192.168.2.42:5060 SOFIA ROUTING
2011-01-06 15:36:16.607737 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-01-06 15:36:16.607737 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:7013@192.168.2.42:5060) State ROUTING going to sleep
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_CONSUME_MEDIA
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:7013@192.168.2.42:5060) State CONSUME_MEDIA
2011-01-06 15:36:16.607737 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:7013@192.168.2.42:5060) State CONSUME_MEDIA going to sleep
2011-01-06 15:36:16.607737 [DEBUG] sofia.c:4616 Channel sofia/internal/sip:7013@192.168.2.42:5060 entering state [calling][0]
2011-01-06 15:36:16.871955 [INFO] sofia.c:720 sofia/internal/sip:7013@192.168.2.42:5060 Update Callee ID to "Outbound Call" <7013>
2011-01-06 15:36:16.872867 [DEBUG] sofia.c:4616 Channel sofia/internal/sip:7013@192.168.2.42:5060 entering state [proceeding][180]
2011-01-06 15:36:16.872867 [NOTICE] sofia.c:4694 Ring-Ready sofia/internal/sip:7013@192.168.2.42:5060!
2011-01-06 15:36:16.873779 [NOTICE] mod_sofia.c:2176 Ring-Ready sofia/internal/7001@192.168.2.190!
2011-01-06 15:36:16.873779 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:16.873779 [DEBUG] sofia.c:4616 Channel sofia/internal/7001@192.168.2.190 entering state [early][180]
2011-01-06 15:36:16.873779 [NOTICE] switch_ivr_originate.c:479 Ring Ready sofia/internal/7001@192.168.2.190!
2011-01-06 15:36:17.337685 [WARNING] sofia_reg.c:1216 SIP auth challenge (REGISTER) on sofia profile 'internal' for [7030@192.168.2.190] from ip 192.168.2.52
2011-01-06 15:36:19.913658 [WARNING] sofia_reg.c:1216 SIP auth challenge (REGISTER) on sofia profile 'internal' for [7013@192.168.2.190] from ip 192.168.2.42
2011-01-06 15:36:20.246147 [DEBUG] sofia.c:4616 Channel sofia/internal/sip:7013@192.168.2.42:5060 entering state [completing][200]
2011-01-06 15:36:20.246147 [DEBUG] sofia.c:4627 Remote SDP:
v=0
o=Cisco-SIPUA 22233 0 IN IP4 192.168.2.42
s=SIP Call
t=0 0
m=audio 29494 RTP/AVP 0 101
c=IN IP4 192.168.2.42
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2011-01-06 15:36:20.246147 [DEBUG] sofia.c:4616 Channel sofia/internal/sip:7013@192.168.2.42:5060 entering state [ready][200]
2011-01-06 15:36:20.246147 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [PCMU:0:8000:0:64000]/[G729:18:8000:20:8000]
2011-01-06 15:36:20.246147 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [PCMU:0:8000:0:64000]/[G7221:115:32000:20:48000]
2011-01-06 15:36:20.246147 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [PCMU:0:8000:0:64000]/[G7221:107:16000:20:32000]
2011-01-06 15:36:20.246147 [DEBUG] sofia_glue.c:4403 Audio Codec Compare [PCMU:0:8000:0:64000]/[PCMU:0:8000:20:64000]
2011-01-06 15:36:20.246147 [DEBUG] sofia_glue.c:2750 Set Codec sofia/internal/sip:7013@192.168.2.42:5060 PCMU/8000 20 ms 160 samples 64000 bits
2011-01-06 15:36:20.247179 [DEBUG] sofia_glue.c:4501 Set 2833 dtmf send payload to 101
2011-01-06 15:36:20.247179 [DEBUG] sofia_glue.c:2980 AUDIO RTP [sofia/internal/sip:7013@192.168.2.42:5060] 192.168.2.190 port 29432 -> 192.168.2.42 port 29494 codec: 0 ms: 20
2011-01-06 15:36:20.247179 [DEBUG] switch_rtp.c:1427 Starting timer [soft] 160 bytes per 20ms
2011-01-06 15:36:20.248111 [DEBUG] sofia_glue.c:3221 Set 2833 dtmf send payload to 101
2011-01-06 15:36:20.248111 [DEBUG] sofia_glue.c:3226 Set 2833 dtmf receive payload to 101
2011-01-06 15:36:20.248111 [DEBUG] switch_channel.c:2782 (sofia/internal/sip:7013@192.168.2.42:5060) Callstate Change RINGING -> ACTIVE
2011-01-06 15:36:20.248111 [DEBUG] switch_channel.c:2794 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.248111 [NOTICE] sofia.c:5200 Channel [sofia/internal/sip:7013@192.168.2.42:5060] has been answered
2011-01-06 15:36:20.248111 [DEBUG] sofia_glue.c:2980 AUDIO RTP [sofia/internal/7001@192.168.2.190] 192.168.2.190 port 32534 -> 192.168.2.15 port 6398 codec: 18 ms: 20
2011-01-06 15:36:20.248111 [DEBUG] switch_rtp.c:1427 Starting timer [soft] 160 bytes per 20ms
2011-01-06 15:36:20.249967 [DEBUG] sofia_glue.c:3221 Set 2833 dtmf send payload to 101
2011-01-06 15:36:20.249967 [DEBUG] sofia_glue.c:3226 Set 2833 dtmf receive payload to 101
2011-01-06 15:36:20.249967 [DEBUG] mod_sofia.c:683 Local SDP sofia/internal/7001@192.168.2.190:
v=0
o=FreeSWITCH 1294275846 1294275847 IN IP4 192.168.2.190
s=FreeSWITCH
c=IN IP4 192.168.2.190
t=0 0
m=audio 32534 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2011-01-06 15:36:20.249967 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.249967 [DEBUG] switch_channel.c:2782 (sofia/internal/7001@192.168.2.190) Callstate Change RINGING -> ACTIVE
2011-01-06 15:36:20.250883 [NOTICE] switch_ivr_originate.c:3317 Channel [sofia/internal/7001@192.168.2.190] has been answered
2011-01-06 15:36:20.250883 [DEBUG] switch_ivr_originate.c:3362 Originate Resulted in Success: [sofia/internal/sip:7013@192.168.2.42:5060]
2011-01-06 15:36:20.250883 [DEBUG] sofia.c:4616 Channel sofia/internal/7001@192.168.2.190 entering state [completed][200]
2011-01-06 15:36:20.250883 [DEBUG] switch_ivr_originate.c:3362 Originate Resulted in Success: [sofia/internal/sip:7013@192.168.2.42:5060]
2011-01-06 15:36:20.251763 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.251763 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.251763 [DEBUG] switch_ivr_bridge.c:1234 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2011-01-06 15:36:20.251763 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.251763 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_EXCHANGE_MEDIA
2011-01-06 15:36:20.251763 [DEBUG] switch_core_state_machine.c:369 (sofia/internal/sip:7013@192.168.2.42:5060) State EXCHANGE_MEDIA
2011-01-06 15:36:20.251763 [DEBUG] mod_sofia.c:554 SOFIA EXCHANGE_MEDIA
2011-01-06 15:36:20.252711 [DEBUG] sofia.c:4616 Channel sofia/internal/7001@192.168.2.190 entering state [ready][200]
2011-01-06 15:36:20.252711 [DEBUG] switch_core_session.c:738 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.252711 [DEBUG] switch_core_session.c:738 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.293303 [DEBUG] switch_rtp.c:2681 Correct ip/port confirmed.
2011-01-06 15:36:20.293303 [ERR] mod_g729.c:145 This codec is only usable in passthrough mode!
2011-01-06 15:36:20.293303 [ERR] switch_core_io.c:882 Codec G.729 decoder error!
2011-01-06 15:36:20.293303 [DEBUG] switch_ivr_bridge.c:494 sofia/internal/sip:7013@192.168.2.42:5060 ending bridge by request from write function
2011-01-06 15:36:20.294237 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [sofia/internal/7001@192.168.2.190]
2011-01-06 15:36:20.294237 [DEBUG] switch_ivr_bridge.c:601 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.294237 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [sofia/internal/sip:7013@192.168.2.42:5060]
2011-01-06 15:36:20.294237 [DEBUG] switch_ivr_bridge.c:601 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.294237 [DEBUG] switch_channel.c:2535 (sofia/internal/sip:7013@192.168.2.42:5060) Callstate Change ACTIVE -> HANGUP
2011-01-06 15:36:20.294237 [NOTICE] switch_ivr_bridge.c:653 Hangup sofia/internal/sip:7013@192.168.2.42:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2011-01-06 15:36:20.294237 [DEBUG] switch_channel.c:2551 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [KILL]
2011-01-06 15:36:20.294237 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.294237 [DEBUG] switch_core_state_machine.c:369 (sofia/internal/sip:7013@192.168.2.42:5060) State EXCHANGE_MEDIA going to sleep
2011-01-06 15:36:20.294237 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_HANGUP
2011-01-06 15:36:20.294237 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/sip:7013@192.168.2.42:5060) State HANGUP
2011-01-06 15:36:20.295216 [DEBUG] mod_sofia.c:459 Channel sofia/internal/sip:7013@192.168.2.42:5060 hanging up, cause: NORMAL_CLEARING
2011-01-06 15:36:20.295216 [DEBUG] switch_ivr_bridge.c:1305 sofia/internal/sip:7013@192.168.2.42:5060 skip receive message [UNBRIDGE] (channel is hungup already)
2011-01-06 15:36:20.295216 [DEBUG] switch_core_session.c:676 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.295216 [DEBUG] switch_channel.c:2535 (sofia/internal/7001@192.168.2.190) Callstate Change ACTIVE -> HANGUP
2011-01-06 15:36:20.295216 [NOTICE] switch_ivr_bridge.c:1328 Hangup sofia/internal/7001@192.168.2.190 [CS_EXECUTE] [NORMAL_CLEARING]
2011-01-06 15:36:20.295216 [DEBUG] switch_channel.c:2551 Send signal sofia/internal/7001@192.168.2.190 [KILL]
2011-01-06 15:36:20.295216 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.295216 [DEBUG] switch_core_session.c:2012 sofia/internal/7001@192.168.2.190 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2011-01-06 15:36:20.295216 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/7001@192.168.2.190) State EXECUTE going to sleep
2011-01-06 15:36:20.295216 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_HANGUP
2011-01-06 15:36:20.296200 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/7001@192.168.2.190) State HANGUP
2011-01-06 15:36:20.296200 [DEBUG] mod_sofia.c:459 Channel sofia/internal/7001@192.168.2.190 hanging up, cause: NORMAL_CLEARING
2011-01-06 15:36:20.296200 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/sip:7013@192.168.2.42:5060
2011-01-06 15:36:20.297185 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/internal/7001@192.168.2.190
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:7013@192.168.2.42:5060 Standard HANGUP, cause: NORMAL_CLEARING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/sip:7013@192.168.2.42:5060) State HANGUP going to sleep
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_HANGUP -> CS_REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/sip:7013@192.168.2.42:5060) State REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:7013@192.168.2.42:5060 Standard REPORTING, cause: NORMAL_CLEARING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/sip:7013@192.168.2.42:5060) State REPORTING going to sleep
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/sip:7013@192.168.2.42:5060) State Change CS_REPORTING -> CS_DESTROY
2011-01-06 15:36:20.297185 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/sip:7013@192.168.2.42:5060 [BREAK]
2011-01-06 15:36:20.297185 [DEBUG] switch_core_session.c:1255 Session 55 (sofia/internal/sip:7013@192.168.2.42:5060) Locked, Waiting on external entities
2011-01-06 15:36:20.297185 [NOTICE] switch_core_session.c:1273 Session 55 (sofia/internal/sip:7013@192.168.2.42:5060) Ended
2011-01-06 15:36:20.297185 [NOTICE] switch_core_session.c:1275 Close Channel sofia/internal/sip:7013@192.168.2.42:5060 [CS_DESTROY]
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:46 sofia/internal/7001@192.168.2.190 Standard HANGUP, cause: NORMAL_CLEARING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:557 (sofia/internal/7001@192.168.2.190) State HANGUP going to sleep
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/sip:7013@192.168.2.42:5060) Callstate Change HANGUP -> DOWN
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/7001@192.168.2.190) State Change CS_HANGUP -> CS_REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/7001@192.168.2.190) Running State Change CS_REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:7013@192.168.2.42:5060) Running State Change CS_DESTROY
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/7001@192.168.2.190) State REPORTING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:7013@192.168.2.42:5060) State DESTROY
2011-01-06 15:36:20.297185 [DEBUG] mod_sofia.c:364 sofia/internal/sip:7013@192.168.2.42:5060 SOFIA DESTROY
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:7013@192.168.2.42:5060 Standard DESTROY
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:7013@192.168.2.42:5060) State DESTROY going to sleep
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:53 sofia/internal/7001@192.168.2.190 Standard REPORTING, cause: NORMAL_CLEARING
2011-01-06 15:36:20.297185 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/7001@192.168.2.190) State REPORTING going to sleep
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/7001@192.168.2.190) State Change CS_REPORTING -> CS_DESTROY
2011-01-06 15:36:20.298177 [DEBUG] switch_core_session.c:1083 Send signal sofia/internal/7001@192.168.2.190 [BREAK]
2011-01-06 15:36:20.298177 [DEBUG] switch_core_session.c:1255 Session 54 (sofia/internal/7001@192.168.2.190) Locked, Waiting on external entities
2011-01-06 15:36:20.298177 [NOTICE] switch_core_session.c:1273 Session 54 (sofia/internal/7001@192.168.2.190) Ended
2011-01-06 15:36:20.298177 [NOTICE] switch_core_session.c:1275 Close Channel sofia/internal/7001@192.168.2.190 [CS_DESTROY]
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/7001@192.168.2.190) Callstate Change HANGUP -> DOWN
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/7001@192.168.2.190) Running State Change CS_DESTROY
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/7001@192.168.2.190) State DESTROY
2011-01-06 15:36:20.298177 [DEBUG] mod_sofia.c:364 sofia/internal/7001@192.168.2.190 SOFIA DESTROY
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:60 sofia/internal/7001@192.168.2.190 Standard DESTROY
2011-01-06 15:36:20.298177 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/7001@192.168.2.190) State DESTROY going to sleep