Could you put this into a pastebin entry? Also, for completeness, could you enable sip trace as well? That will probably have all the info you need to figure out what's happening. Be sure to use FreeSWITCH Log for the syntax highlighting so that these old eyes can more easily see what's going on.

Thanks!

-MC

On Tue, Mar 12, 2013 at 12:14 AM, Sayyed Mohammad Emami Razavi <emamirazavi@gmail.com> wrote:
Two extensions 401 and 403 are registered by Twinkle!
401 calls 403 but 403 does not ring and 401 does not listen ring back,
but FS thinks them ringing!
I had not this problem beforehand,
This server has two ethernet cards,
#1 for connecting to trunk
and #2 for connecting to local network.(I have no problem in network routing and I've tested all things)
These two extensions are registered at local network (192.168.54.69)
What is the problem? My freeswitch log is below:

2013-03-12 13:56:51.741964 [NOTICE] switch_channel.c:968 New Channel sofia/sipinterface_6/401@192.168.54.69 [5ab2118c-8aff-11e2-bd72-4f1eb6844087]
2013-03-12 13:56:51.741964 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.741964 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.741964 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_NEW
2013-03-12 13:56:51.741964 [DEBUG] switch_core_state_machine.c:433 (sofia/sipinterface_6/401@192.168.54.69) State NEW
2013-03-12 13:56:51.761967 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.761967 [DEBUG] sofia.c:1719 detaching session 5ab2118c-8aff-11e2-bd72-4f1eb6844087
2013-03-12 13:56:51.761967 [DEBUG] sofia.c:1811 Re-attaching to session 5ab2118c-8aff-11e2-bd72-4f1eb6844087
2013-03-12 13:56:51.761967 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.761967 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.781957 [DEBUG] sofia.c:5574 Channel sofia/sipinterface_6/401@192.168.54.69 entering state [received][100]
2013-03-12 13:56:51.781957 [DEBUG] sofia.c:5585 Remote SDP:
v=0
o=twinkle 799456135 497926540 IN IP4 192.168.1.102
s=-
c=IN IP4 192.168.1.102
t=0 0
m=audio 8000 RTP/AVP 98 97 8 0 3 101
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:98:16000:20:0]/[G722:9:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:98:16000:20:0]/[PCMU:0:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:98:16000:20:0]/[PCMA:8:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:98:16000:20:0]/[GSM:3:8000:20:13200]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:97:8000:20:0]/[G722:9:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:97:8000:20:0]/[PCMU:0:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:97:8000:20:0]/[PCMA:8:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [speex:97:8000:20:0]/[GSM:3:8000:20:13200]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-03-12 13:56:51.781957 [DEBUG] sofia_glue.c:5137 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-03-12 13:56:51.801956 [DEBUG] sofia_glue.c:3093 Set Codec sofia/sipinterface_6/401@192.168.54.69 PCMA/8000 20 ms 160 samples 64000 bits
2013-03-12 13:56:51.801956 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_6/401@192.168.54.69 Original read codec set to PCMA:8
2013-03-12 13:56:51.801956 [DEBUG] sofia_glue.c:5266 Set 2833 dtmf send/recv payload to 101
2013-03-12 13:56:51.801956 [DEBUG] sofia.c:5818 (sofia/sipinterface_6/401@192.168.54.69) State Change CS_NEW -> CS_INIT
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_INIT
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_6/401@192.168.54.69) State INIT
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:86 sofia/sipinterface_6/401@192.168.54.69 SOFIA INIT
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:126 (sofia/sipinterface_6/401@192.168.54.69) State Change CS_INIT -> CS_ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_6/401@192.168.54.69) State INIT going to sleep
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:2003 (sofia/sipinterface_6/401@192.168.54.69) Callstate Change DOWN -> RINGING
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_6/401@192.168.54.69) State ROUTING
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:149 sofia/sipinterface_6/401@192.168.54.69 SOFIA ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:117 sofia/sipinterface_6/401@192.168.54.69 Standard ROUTING
2013-03-12 13:56:51.801956 [INFO] mod_dialplan_xml.c:557 Processing Parsa <401>->403 in context context_1
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (PASS) [conditioning_callerid] ${internal_caller_id_number}(401) =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(effective_caller_id_name=${internal_caller_id_name})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(effective_caller_id_number=${internal_caller_id_number})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->conditioning_callrecord] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Absolute Condition [conditioning_callrecord]
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_TITLE=Recording ${destination_number} ${caller_id_number} ${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_SOFTWARE=blue.box)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_ARTIST=2600hz)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with blue.box)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_DATE=${strftime(%Y-%m-%d %H:%M)})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RECORD_STEREO=true)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->postroute_global] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Absolute Condition [postroute_global]
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->preanswer_callrecord_outbound] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [preanswer_callrecord_outbound] ${callrecord_outbound}() =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_17] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_17] destination_number(403) =~ /^334$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_18] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_18] destination_number(403) =~ /^496$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_23] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_23] destination_number(403) =~ /^4101$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_13] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_13] destination_number(403) =~ /^288|223$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_25] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_25] destination_number(403) =~ /^422$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_27] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_27] destination_number(403) =~ /^0[^0][0-9]{9}$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_28] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_28] destination_number(403) =~ /^401$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_29] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_29] destination_number(403) =~ /^402$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_30] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (PASS) [main_number_30] destination_number(403) =~ /^403$/ break=on-false
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(call_timeout=30)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(ringback=local_stream://moh)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action export(sip_callee_id_name=m.emami)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action export(sip_callee_id_number=403)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action bridge(user/403@192.168.54.69)
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Action hangup()
Dialplan: sofia/sipinterface_6/401@192.168.54.69 parsing [context_1->main_number_31] continue=true
Dialplan: sofia/sipinterface_6/401@192.168.54.69 Regex (FAIL) [main_number_31] destination_number(403) =~ /^497$/ break=on-false
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:167 (sofia/sipinterface_6/401@192.168.54.69) State Change CS_ROUTING -> CS_EXECUTE
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_6/401@192.168.54.69) State ROUTING going to sleep
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_EXECUTE
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:477 (sofia/sipinterface_6/401@192.168.54.69) State EXECUTE
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:242 sofia/sipinterface_6/401@192.168.54.69 SOFIA EXECUTE
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:209 sofia/sipinterface_6/401@192.168.54.69 Standard EXECUTE
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(effective_caller_id_name=Parsa Moshrefi)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [effective_caller_id_name]=[Parsa Moshrefi]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(effective_caller_id_number=401)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [effective_caller_id_number]=[401]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_TITLE=Recording 403 401 2013-03-12 13:56)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_TITLE]=[Recording 403 401 2013-03-12 13:56]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_COPYRIGHT=(c) 2010 VoIP, Inc.)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_COPYRIGHT]=[(c) 2010 VoIP, Inc.]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_SOFTWARE=blue.box)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_SOFTWARE]=[blue.box]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_ARTIST=2600hz)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_ARTIST]=[2600hz]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_COMMENT=Automatically recorded via FreeSWITCH with blue.box)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_COMMENT]=[Automatically recorded via FreeSWITCH with blue.box]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_DATE=2013-03-12 13:56)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_DATE]=[2013-03-12 13:56]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RECORD_STEREO=true)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RECORD_STEREO]=[true]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 hash(insert/192.168.54.69-spymap/401/5ab2118c-8aff-11e2-bd72-4f1eb6844087)
EXECUTE sofia/sipinterface_6/401@192.168.54.69 hash(insert/192.168.54.69-last_dial/401/403)
EXECUTE sofia/sipinterface_6/401@192.168.54.69 hash(insert/192.168.54.69-last_dial/global/5ab2118c-8aff-11e2-bd72-4f1eb6844087)
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(RFC2822_DATE=Tue, 12 Mar 2013 13:56:51 )
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [RFC2822_DATE]=[Tue, 12 Mar 2013 13:56:51 ]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(call_timeout=30)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [call_timeout]=[30]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(ringback=local_stream://moh)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [ringback]=[local_stream://moh]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 set(transfer_ringback=local_stream://moh)
2013-03-12 13:56:51.801956 [DEBUG] mod_dptools.c:1344 sofia/sipinterface_6/401@192.168.54.69 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 export(sip_callee_id_name=m.emami)
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [sip_callee_id_name]=[m.emami]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 export(sip_callee_id_number=403)
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [sip_callee_id_number]=[403]
EXECUTE sofia/sipinterface_6/401@192.168.54.69 bridge(user/403@192.168.54.69)
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1089 sofia/sipinterface_6/401@192.168.54.69 EXPORTING[export_vars] [sip_callee_id_name]=[m.emami] to event
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1089 sofia/sipinterface_6/401@192.168.54.69 EXPORTING[export_vars] [sip_callee_id_number]=[403] to event
2013-03-12 13:56:51.801956 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1089 sofia/sipinterface_6/401@192.168.54.69 EXPORTING[export_vars] [sip_callee_id_name]=[m.emami] to event
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:1089 sofia/sipinterface_6/401@192.168.54.69 EXPORTING[export_vars] [sip_callee_id_number]=[403] to event
2013-03-12 13:56:51.801956 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-03-12 13:56:51.801956 [DEBUG] switch_event.c:1608 Parsing variable [presence_id]=[403@192.168.54.69]
2013-03-12 13:56:51.801956 [NOTICE] switch_channel.c:968 New Channel sofia/sipinterface_6/sip:403@192.168.1.115 [5abc3f36-8aff-11e2-bd8e-4f1eb6844087]
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:4961 (sofia/sipinterface_6/sip:403@192.168.1.115) State Change CS_NEW -> CS_INIT
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_INIT
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_6/sip:403@192.168.1.115) State INIT
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:86 sofia/sipinterface_6/sip:403@192.168.1.115 SOFIA INIT
2013-03-12 13:56:51.801956 [DEBUG] sofia_glue.c:2647 Local SDP:
v=0
o=FreeSWITCH 1363059707 1363059708 IN IP4 192.168.54.69
s=FreeSWITCH
c=IN IP4 192.168.54.69
t=0 0
m=audio 24304 RTP/AVP 8 9 0 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:126 (sofia/sipinterface_6/sip:403@192.168.1.115) State Change CS_INIT -> CS_ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:454 (sofia/sipinterface_6/sip:403@192.168.1.115) State INIT going to sleep
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:975 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_channel.c:2003 (sofia/sipinterface_6/sip:403@192.168.1.115) Callstate Change DOWN -> RINGING
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_6/sip:403@192.168.1.115) State ROUTING
2013-03-12 13:56:51.801956 [DEBUG] mod_sofia.c:149 sofia/sipinterface_6/sip:403@192.168.1.115 SOFIA ROUTING
2013-03-12 13:56:51.801956 [DEBUG] switch_ivr_originate.c:67 (sofia/sipinterface_6/sip:403@192.168.1.115) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-03-12 13:56:51.801956 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:470 (sofia/sipinterface_6/sip:403@192.168.1.115) State ROUTING going to sleep
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_CONSUME_MEDIA
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:489 (sofia/sipinterface_6/sip:403@192.168.1.115) State CONSUME_MEDIA
2013-03-12 13:56:51.801956 [DEBUG] switch_core_state_machine.c:489 (sofia/sipinterface_6/sip:403@192.168.1.115) State CONSUME_MEDIA going to sleep
2013-03-12 13:56:51.801956 [DEBUG] sofia.c:5574 Channel sofia/sipinterface_6/sip:403@192.168.1.115 entering state [calling][0]
2013-03-12 13:57:21.001969 [DEBUG] switch_channel.c:2994 (sofia/sipinterface_6/sip:403@192.168.1.115) Callstate Change RINGING -> HANGUP
2013-03-12 13:57:21.001969 [NOTICE] switch_ivr_originate.c:3351 Hangup sofia/sipinterface_6/sip:403@192.168.1.115 [CS_CONSUME_MEDIA] [NO_ANSWER]
2013-03-12 13:57:21.001969 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_HANGUP
2013-03-12 13:57:21.001969 [DEBUG] switch_channel.c:3017 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [KILL]
2013-03-12 13:57:21.001969 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:57:21.001969 [DEBUG] switch_core_state_machine.c:667 (sofia/sipinterface_6/sip:403@192.168.1.115) State HANGUP
2013-03-12 13:57:21.001969 [DEBUG] mod_sofia.c:503 Channel sofia/sipinterface_6/sip:403@192.168.1.115 hanging up, cause: NO_ANSWER
2013-03-12 13:57:21.001969 [NOTICE] switch_ivr_originate.c:2608 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
2013-03-12 13:57:21.001969 [DEBUG] switch_ivr_originate.c:3533 Originate Resulted in Error Cause: 19 [NO_ANSWER]
2013-03-12 13:57:21.001969 [INFO] mod_dptools.c:3055 Originate Failed.  Cause: NO_ANSWER
EXECUTE sofia/sipinterface_6/401@192.168.54.69 hangup()
2013-03-12 13:57:21.001969 [DEBUG] switch_channel.c:2994 (sofia/sipinterface_6/401@192.168.54.69) Callstate Change RINGING -> HANGUP
2013-03-12 13:57:21.001969 [NOTICE] mod_dptools.c:1150 Hangup sofia/sipinterface_6/401@192.168.54.69 [CS_EXECUTE] [NORMAL_CLEARING]
2013-03-12 13:57:21.001969 [DEBUG] switch_channel.c:3017 Send signal sofia/sipinterface_6/401@192.168.54.69 [KILL]
2013-03-12 13:57:21.001969 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:57:21.001969 [DEBUG] switch_core_session.c:2689 sofia/sipinterface_6/401@192.168.54.69 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-03-12 13:57:21.001969 [DEBUG] switch_core_state_machine.c:477 (sofia/sipinterface_6/401@192.168.54.69) State EXECUTE going to sleep
2013-03-12 13:57:21.001969 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_HANGUP
2013-03-12 13:57:21.001969 [DEBUG] switch_core_state_machine.c:667 (sofia/sipinterface_6/401@192.168.54.69) State HANGUP
2013-03-12 13:57:21.001969 [DEBUG] mod_sofia.c:503 Channel sofia/sipinterface_6/401@192.168.54.69 hanging up, cause: NORMAL_CLEARING
2013-03-12 13:57:21.021986 [DEBUG] mod_sofia.c:562 Sending CANCEL to sofia/sipinterface_6/sip:403@192.168.1.115
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:48 sofia/sipinterface_6/sip:403@192.168.1.115 Standard HANGUP, cause: NO_ANSWER
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:667 (sofia/sipinterface_6/sip:403@192.168.1.115) State HANGUP going to sleep
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:446 (sofia/sipinterface_6/sip:403@192.168.1.115) State Change CS_HANGUP -> CS_REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:749 (sofia/sipinterface_6/sip:403@192.168.1.115) State REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:92 sofia/sipinterface_6/sip:403@192.168.1.115 Standard REPORTING, cause: NO_ANSWER
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:749 (sofia/sipinterface_6/sip:403@192.168.1.115) State REPORTING going to sleep
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:440 (sofia/sipinterface_6/sip:403@192.168.1.115) State Change CS_REPORTING -> CS_DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/sip:403@192.168.1.115 [BREAK]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1499 Session 48 (sofia/sipinterface_6/sip:403@192.168.1.115) Locked, Waiting on external entities
2013-03-12 13:57:21.021986 [NOTICE] switch_core_session.c:1517 Session 48 (sofia/sipinterface_6/sip:403@192.168.1.115) Ended
2013-03-12 13:57:21.021986 [NOTICE] switch_core_session.c:1521 Close Channel sofia/sipinterface_6/sip:403@192.168.1.115 [CS_DESTROY]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:556 (sofia/sipinterface_6/sip:403@192.168.1.115) Callstate Change HANGUP -> DOWN
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:559 (sofia/sipinterface_6/sip:403@192.168.1.115) Running State Change CS_DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_6/sip:403@192.168.1.115) State DESTROY
2013-03-12 13:57:21.021986 [DEBUG] mod_sofia.c:396 sofia/sipinterface_6/sip:403@192.168.1.115 SOFIA DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:99 sofia/sipinterface_6/sip:403@192.168.1.115 Standard DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_6/sip:403@192.168.1.115) State DESTROY going to sleep
2013-03-12 13:57:21.021986 [DEBUG] mod_sofia.c:633 Responding to INVITE with: 480
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:48 sofia/sipinterface_6/401@192.168.54.69 Standard HANGUP, cause: NORMAL_CLEARING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:667 (sofia/sipinterface_6/401@192.168.54.69) State HANGUP going to sleep
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:446 (sofia/sipinterface_6/401@192.168.54.69) State Change CS_HANGUP -> CS_REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:415 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:749 (sofia/sipinterface_6/401@192.168.54.69) State REPORTING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:92 sofia/sipinterface_6/401@192.168.54.69 Standard REPORTING, cause: NORMAL_CLEARING
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:749 (sofia/sipinterface_6/401@192.168.54.69) State REPORTING going to sleep
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:440 (sofia/sipinterface_6/401@192.168.54.69) State Change CS_REPORTING -> CS_DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1291 Send signal sofia/sipinterface_6/401@192.168.54.69 [BREAK]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_session.c:1499 Session 47 (sofia/sipinterface_6/401@192.168.54.69) Locked, Waiting on external entities
2013-03-12 13:57:21.021986 [NOTICE] switch_core_session.c:1517 Session 47 (sofia/sipinterface_6/401@192.168.54.69) Ended
2013-03-12 13:57:21.021986 [NOTICE] switch_core_session.c:1521 Close Channel sofia/sipinterface_6/401@192.168.54.69 [CS_DESTROY]
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:556 (sofia/sipinterface_6/401@192.168.54.69) Callstate Change HANGUP -> DOWN
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:559 (sofia/sipinterface_6/401@192.168.54.69) Running State Change CS_DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_6/401@192.168.54.69) State DESTROY
2013-03-12 13:57:21.021986 [DEBUG] mod_sofia.c:396 sofia/sipinterface_6/401@192.168.54.69 SOFIA DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:99 sofia/sipinterface_6/401@192.168.54.69 Standard DESTROY
2013-03-12 13:57:21.021986 [DEBUG] switch_core_state_machine.c:569 (sofia/sipinterface_6/401@192.168.54.69) State DESTROY going to sleep


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

FreeSWITCH-powered IP PBX: The CudaTel Communication Server
http://www.cudatel.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://wiki.freeswitch.org
http://www.cluecon.com

FreeSWITCH-users mailing list
FreeSWITCH-users@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org




--
Michael S Collins
Twitter: @mercutioviz
http://www.FreeSWITCH.org
http://www.ClueCon.com
http://www.OSTAG.org