[Freeswitch-users] EXCHANGE_ROUTING_ERROR -- how to diagnose?

Matthew Fong mattdfong at gmail.com
Thu Oct 22 10:42:29 PDT 2009 

I figured out how to turn debug mode on. For some reason F8 didn't work, so
I just set the default debug mode to DEBUG in switch.conf.xml

http://pastebin.freeswitch.org/10805
<http://pastebin.freeswitch.org/10805>So my program does more or less the
same sequence for an Agent every time when connected to another party. They
uuid_kill the bridged parties uuid, and then are transfered to an extension
that park's the agent (using the transfer_after_bridge variable -- in my
dialplan extn 1998). In some instances the agent is then transfered to
another extension, played a wav file, and then park'ed again

Sometimes, FreeSWITCH unexpectidly hangsup the Agent channel citing an
EXCHANGE_ROUTING_ERROR. It seems (to me to happen at random times)...and
it's more prevelent with some did providers than others. With
didforsale.orgit happens about one ever 5 bridges. With
icall.com it only happens about once every 30 bridges. With IPKall it
happens rarely. I can't figure it out, and it's driving me crazy :)


A GOOD UUID_KILL SEQUENCE:
2009-10-22 17:22:31.741845 [DEBUG] switch_ivr_play_say.c:1432 done playing
file
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:340
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXECUTE going to
sleep
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_HIBERNATE
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:355
(sofia/external/+14158867717 at 199.173.100.16:5060) State HIBERNATE
2009-10-22 17:22:31.741845 [DEBUG] mod_sofia.c:160 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA HIBERNATE
2009-10-22 17:22:31.741845 [DEBUG] switch_ivr_bridge.c:650 (sofia/external/+
14158867717 at 199.173.100.16:5060) State Change CS_HIBERNATE -> CS_RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:355
(sofia/external/+14158867717 at 199.173.100.16:5060) State HIBERNATE going to
sleep
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:336
(sofia/external/+14158867717 at 199.173.100.16:5060) State RESET
2009-10-22 17:22:31.741845 [DEBUG] mod_sofia.c:145 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_ivr_bridge.c:637 sofia/external/+
14158867717 at 199.173.100.16:5060 CUSTOM RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:67
sofia/external/+14158867717 at 199.173.100.16:5060 Standard RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:336
(sofia/external/+14158867717 at 199.173.100.16:5060) State RESET going to sleep
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:340
(sofia/external/14159927717) State EXECUTE going to sleep
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_HIBERNATE
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:355
(sofia/external/14159927717) State HIBERNATE
2009-10-22 17:22:31.748086 [DEBUG] mod_sofia.c:160
sofia/external/14159927717 SOFIA HIBERNATE
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:650
(sofia/external/14159927717) State Change CS_HIBERNATE -> CS_RESET
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:355
(sofia/external/14159927717) State HIBERNATE going to sleep
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_RESET
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:336
(sofia/external/14159927717) State RESET
2009-10-22 17:22:31.748086 [DEBUG] mod_sofia.c:145
sofia/external/14159927717 SOFIA RESET
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:637
sofia/external/14159927717 CUSTOM RESET
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:642
(sofia/external/14159927717) State Change CS_RESET -> CS_SOFT_EXECUTE
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:336
(sofia/external/14159927717) State RESET going to sleep
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_SOFT_EXECUTE
2009-10-22 17:22:31.748086 [DEBUG] switch_core_state_machine.c:346
(sofia/external/14159927717) State SOFT_EXECUTE
2009-10-22 17:22:31.748086 [DEBUG] mod_sofia.c:442 SOFIA TRANSMIT
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:660
sofia/external/14159927717 CUSTOM SOFT_EXECUTE
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_originate.c:674
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change CS_RESET ->
CS_SOFT_EXECUTE
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:120 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [DISPLAY]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:120
sofia/external/14159927717 receive message [DISPLAY]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:924 (sofia/external/+
14158867717 at 199.173.100.16:5060) State Change CS_SOFT_EXECUTE ->
CS_CONSUME_MEDIA
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:968 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [BRIDGE]
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:975
sofia/external/14159927717 receive message [BRIDGE]
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:1019
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change
CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2009-10-22 17:22:31.748086 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.749553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_EXCHANGE_MEDIA
2009-10-22 17:22:31.749553 [DEBUG] switch_core_state_machine.c:343
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXCHANGE_MEDIA
2009-10-22 17:22:31.749553 [DEBUG] mod_sofia.c:436 SOFIA LOOPBACK
multipler is being overrided to1
2009-10-22 17:22:34.300662 [INFO] switch_cpp.cpp:1116 BG_AG_GEN_CALLS,
Agents total:1 avail:0 OutChan:0 AR:0 +-Calls:0:Q Call NYNoc
multipler is being overrided to1
2009-10-22 17:22:39.303041 [INFO] switch_cpp.cpp:1116 BG_AG_GEN_CALLS,
Agents total:1 avail:0 OutChan:0 AR:0 +-Calls:0:Q Call NYNoc
2009-10-22 17:22:40.626379 [NOTICE] sofia.c:328 Hangup
sofia/external/14159927717 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2009-10-22 17:22:40.626379 [DEBUG] switch_channel.c:1810 Send signal
sofia/external/14159927717 [KILL]
2009-10-22 17:22:40.626379 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
active_true=1
--contact NOT in playmsg or conference, update AGENT
2009-10-22 17:22:40.626379 [DEBUG] switch_core_state_machine.c:437 thread
mismatch skipping state handler.
2009-10-22 17:22:40.626379 [INFO] switch_cpp.cpp:1116 EVENTC_HANGUP_CONTACT,
Q_CONTACT fired for agent:1/1 for qcall:1 contact:4801442/4
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:440
sofia/external/14159927717 ending bridge by request from write function
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:495 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [UNBRIDGE]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:521 BRIDGE THREAD
DONE [sofia/external/+14158867717 at 199.173.100.16:5060]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:523 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr.c:1361 (sofia/external/+
14158867717 at 199.173.100.16:5060) State Change CS_EXCHANGE_MEDIA ->
CS_ROUTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr.c:1365 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [TRANSFER]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [NOTICE] switch_ivr.c:1367 Transfer
sofia/external/+14158867717 at 199.173.100.16:5060 to xml[1998 at default]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:343
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXCHANGE_MEDIA going
to sleep
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_ROUTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:333
(sofia/external/+14158867717 at 199.173.100.16:5060) State ROUTING
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:130 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA ROUTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:78
sofia/external/+14158867717 at 199.173.100.16:5060 Standard ROUTING
2009-10-22 17:22:40.639760 [INFO] mod_dialplan_xml.c:391 Processing
+14158867717->1998 in context default
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->tod_example] continue=true
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (PASS)
[tod_example] ${strftime(%w)}(4) =~ /^([1-5])$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (PASS)
[tod_example] ${strftime(%H%M)}(1722) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/
break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Action
set(open=true)
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->ivr_demo] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[ivr_demo] destination_number(1998) =~ /^5000$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1975] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1975] destination_number(1998) =~ /^1975$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1971] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1971] destination_number(1998) =~ /^1971$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1972] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1972] destination_number(1998) =~ /^1972$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1920] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1920] destination_number(1998) =~ /^1920$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1981] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1981] destination_number(1998) =~ /^1981$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1982] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1982] destination_number(1998) =~ /^1982$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1481] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1481] destination_number(1998) =~ /^1481$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1989] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1989] destination_number(1998) =~ /^1989$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1990] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1990] destination_number(1998) =~ /^1990$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1991] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1991] destination_number(1998) =~ /^1991$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1992] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1992] destination_number(1998) =~ /^1992$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1993] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1993] destination_number(1998) =~ /^1993$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1994] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1994] destination_number(1998) =~ /^1994$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1995] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1995] destination_number(1998) =~ /^1995$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1996] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1996] destination_number(1998) =~ /^1996$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1997] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (FAIL)
[1997] destination_number(1998) =~ /^1997$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 parsing
[default->1998] continue=false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Regex (PASS)
[1998] destination_number(1998) =~ /^1998$/ break=on-false
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Action
set(transfer_after_bridge=1998)
Dialplan: sofia/external/+14158867717 at 199.173.100.16:5060 Action park()
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:114
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change CS_ROUTING ->
CS_EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:333
(sofia/external/+14158867717 at 199.173.100.16:5060) State ROUTING going to
sleep
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:340
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:173 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:151
sofia/external/+14158867717 at 199.173.100.16:5060 Standard EXECUTE
EXECUTE sofia/external/+14158867717 at 199.173.100.16:5060 set(open=true)
2009-10-22 17:22:40.639760 [DEBUG] mod_dptools.c:752 sofia/external/+
14158867717 at 199.173.100.16:5060 SET [open]=[true]
EXECUTE sofia/external/+14158867717 at 199.173.100.16:5060set(transfer_after_bridge=1998)
2009-10-22 17:22:40.639760 [DEBUG] mod_dptools.c:752 sofia/external/+
14158867717 at 199.173.100.16:5060 SET [transfer_after_bridge]=[1998]
EXECUTE sofia/external/+14158867717 at 199.173.100.16:5060 park()
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:446
sofia/external/14159927717 ending bridge by request from read function
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:521 BRIDGE THREAD
DONE [sofia/external/14159927717]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr_bridge.c:523 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
subtracting 9 seconds for hh_call: 1095422
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:346
(sofia/external/14159927717) State SOFT_EXECUTE going to sleep
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_HANGUP
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:464
(sofia/external/14159927717) State HANGUP
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:344 Channel
sofia/external/14159927717 hanging up, cause: NORMAL_CLEARING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:46
sofia/external/14159927717 Standard HANGUP, cause: NORMAL_CLEARING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:464
(sofia/external/14159927717) State HANGUP going to sleep
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:325
(sofia/external/14159927717) State Change CS_HANGUP -> CS_REPORTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_REPORTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:555
(sofia/external/14159927717) State REPORTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:53
sofia/external/14159927717 Standard REPORTING, cause: NORMAL_CLEARING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:555
(sofia/external/14159927717) State REPORTING going to sleep
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:319
(sofia/external/14159927717) State Change CS_REPORTING -> CS_DESTROY
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_session.c:1069 Session 6
(sofia/external/14159927717) Locked, Waiting on external entities
2009-10-22 17:22:40.639760 [NOTICE] switch_core_session.c:1087 Session 6
(sofia/external/14159927717) Ended
2009-10-22 17:22:40.639760 [NOTICE] switch_core_session.c:1089 Close Channel
sofia/external/14159927717 [CS_DESTROY]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:401
(sofia/external/14159927717) Running State Change CS_DESTROY
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:412
(sofia/external/14159927717) State DESTROY
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:261
sofia/external/14159927717 SOFIA DESTROY
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:60
sofia/external/14159927717 Standard DESTROY
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:412
(sofia/external/14159927717) State DESTROY going to sleep
2009-10-22 17:22:40.639760 [INFO] switch_cpp.cpp:1116 PCHangup
gw:teliax.comhc:NORMAL_CLEARING du:9 cn:sofia/external/14159927717



A BAD UUID_KILL SEQUENCE: (where the agent is hungup, unexpectedly)

--bridged in: 0.005821 seconds
2009-10-22 17:23:26.718930 [INFO] switch_cpp.cpp:1116 AG_CBRIDGE, connected
agent:1/1 contact:4801439/22/1/1
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_play_say.c:1432 done playing
file
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:340
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXECUTE going to
sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:355
(sofia/external/+14158867717 at 199.173.100.16:5060) State HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:160 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:650 (sofia/external/+
14158867717 at 199.173.100.16:5060) State Change CS_HIBERNATE -> CS_RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:355
(sofia/external/+14158867717 at 199.173.100.16:5060) State HIBERNATE going to
sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:336
(sofia/external/+14158867717 at 199.173.100.16:5060) State RESET
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:145 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:637 sofia/external/+
14158867717 at 199.173.100.16:5060 CUSTOM RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:67
sofia/external/+14158867717 at 199.173.100.16:5060 Standard RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:336
(sofia/external/+14158867717 at 199.173.100.16:5060) State RESET going to sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:340
(sofia/external/14159927717) State EXECUTE going to sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:355
(sofia/external/14159927717) State HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:160
sofia/external/14159927717 SOFIA HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:650
(sofia/external/14159927717) State Change CS_HIBERNATE -> CS_RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:355
(sofia/external/14159927717) State HIBERNATE going to sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:336
(sofia/external/14159927717) State RESET
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:145
sofia/external/14159927717 SOFIA RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:637
sofia/external/14159927717 CUSTOM RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:642
(sofia/external/14159927717) State Change CS_RESET -> CS_SOFT_EXECUTE
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:336
(sofia/external/14159927717) State RESET going to sleep
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_SOFT_EXECUTE
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:346
(sofia/external/14159927717) State SOFT_EXECUTE
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:442 SOFIA TRANSMIT
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:660
sofia/external/14159927717 CUSTOM SOFT_EXECUTE
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_originate.c:674
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change CS_RESET ->
CS_SOFT_EXECUTE
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:120 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [DISPLAY]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:120
sofia/external/14159927717 receive message [DISPLAY]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:924 (sofia/external/+
14158867717 at 199.173.100.16:5060) State Change CS_SOFT_EXECUTE ->
CS_CONSUME_MEDIA
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:968 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [BRIDGE]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:975
sofia/external/14159927717 receive message [BRIDGE]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:1019
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change
CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2009-10-22 17:23:26.721553 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_EXCHANGE_MEDIA
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:343
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXCHANGE_MEDIA
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:436 SOFIA LOOPBACK
2009-10-22 17:23:26.740065 [DEBUG] switch_core_io.c:234 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [TRANSCODING_NECESSARY]
2009-10-22 17:23:27.319618 [DEBUG] switch_core_media_bug.c:393 Removing BUG
from sofia/external/+14158867717 at 199.173.100.16:5060
multipler is being overrided to1
2009-10-22 17:23:29.406414 [INFO] switch_cpp.cpp:1116 BG_AG_GEN_CALLS,
Agents total:1 avail:0 OutChan:0 AR:0 +-Calls:0:Q Call NYNoc
2009-10-22 17:23:31.873352 [NOTICE] mod_commands.c:1523 Hangup
sofia/external/14159927717 [CS_SOFT_EXECUTE] [NORMAL_CLEARING]
2009-10-22 17:23:31.874411 [INFO] switch_cpp.cpp:1116 EVENTC_HANGUP_CONTACT,
Q_CONTACT fired for agent:1/1 for qcall:1 contact:4801439/1
active_true=1
--contact NOT in playmsg or conference, update AGENT
2009-10-22 17:23:31.875475 [DEBUG] switch_channel.c:1810 Send signal
sofia/external/14159927717 [KILL]
2009-10-22 17:23:31.875475 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:31.875475 [DEBUG] switch_core_state_machine.c:437 thread
mismatch skipping state handler.
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:446
sofia/external/14159927717 ending bridge by request from read function
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:521 BRIDGE THREAD
DONE [sofia/external/14159927717]
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:523 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:495 sofia/external/+
14158867717 at 199.173.100.16:5060 receive message [UNBRIDGE]
2009-10-22 17:23:31.882153 [DEBUG] switch_core_session.c:630 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:521 BRIDGE THREAD
DONE [sofia/external/+14158867717 at 199.173.100.16:5060]
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:523 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:31.882153 [NOTICE] switch_ivr.c:1268 Hangup
sofia/external/+14158867717 at 199.173.100.16:5060 [CS_EXCHANGE_MEDIA]
[EXCHANGE_ROUTING_ERROR]
2009-10-22 17:23:31.882153 [DEBUG] switch_channel.c:1810 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [KILL]
2009-10-22 17:23:31.882153 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.882153 [DEBUG] switch_core_state_machine.c:464
(sofia/external/+14158867717 at 199.173.100.16:5060) State HANGUP
2009-10-22 17:23:31.882153 [DEBUG] mod_sofia.c:344 Channel sofia/external/+
14158867717 at 199.173.100.16:5060 hanging up, cause: EXCHANGE_ROUTING_ERROR
2009-10-22 17:23:31.882153 [DEBUG] mod_sofia.c:382 Sending BYE to
sofia/external/+14158867717 at 199.173.100.16:5060
2009-10-22 17:23:31.882153 [DEBUG] switch_core_state_machine.c:46
sofia/external/+14158867717 at 199.173.100.16:5060 Standard HANGUP, cause:
EXCHANGE_ROUTING_ERROR
2009-10-22 17:23:31.882153 [DEBUG] switch_core_state_machine.c:464
(sofia/external/+14158867717 at 199.173.100.16:5060) State HANGUP going to
sleep
2009-10-22 17:23:31.884357 [INFO] switch_cpp.cpp:1116 HH_HANGUP, agent:1/1
uuid: f8604694-4e44-4c4c-9805-722b3e9d6b68
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:346
(sofia/external/14159927717) State SOFT_EXECUTE going to sleep
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_HANGUP
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:464
(sofia/external/14159927717) State HANGUP
2009-10-22 17:23:31.885412 [DEBUG] mod_sofia.c:344 Channel
sofia/external/14159927717 hanging up, cause: NORMAL_CLEARING
2009-10-22 17:23:31.885412 [DEBUG] mod_sofia.c:382 Sending BYE to
sofia/external/14159927717
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:46
sofia/external/14159927717 Standard HANGUP, cause: NORMAL_CLEARING
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:464
(sofia/external/14159927717) State HANGUP going to sleep
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:325
(sofia/external/14159927717) State Change CS_HANGUP -> CS_REPORTING
2009-10-22 17:23:31.885412 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
subtracting 5 seconds for hh_call: 1095423
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:306
(sofia/external/14159927717) Running State Change CS_REPORTING
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:555
(sofia/external/14159927717) State REPORTING
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:53
sofia/external/14159927717 Standard REPORTING, cause: NORMAL_CLEARING
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:555
(sofia/external/14159927717) State REPORTING going to sleep
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:319
(sofia/external/14159927717) State Change CS_REPORTING -> CS_DESTROY
2009-10-22 17:23:31.885412 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/14159927717 [BREAK]
2009-10-22 17:23:31.885412 [DEBUG] switch_core_session.c:1069 Session 7
(sofia/external/14159927717) Locked, Waiting on external entities
2009-10-22 17:23:31.885412 [NOTICE] switch_core_session.c:1087 Session 7
(sofia/external/14159927717) Ended
2009-10-22 17:23:31.885412 [NOTICE] switch_core_session.c:1089 Close Channel
sofia/external/14159927717 [CS_DESTROY]
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:401
(sofia/external/14159927717) Running State Change CS_DESTROY
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:412
(sofia/external/14159927717) State DESTROY
2009-10-22 17:23:31.885412 [DEBUG] mod_sofia.c:261
sofia/external/14159927717 SOFIA DESTROY
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:60
sofia/external/14159927717 Standard DESTROY
2009-10-22 17:23:31.885412 [DEBUG] switch_core_state_machine.c:412
(sofia/external/14159927717) State DESTROY going to sleep
2009-10-22 17:23:31.885412 [INFO] switch_cpp.cpp:1116 PCHangup
gw:teliax.comhc:NORMAL_CLEARING du:5 cn:sofia/external/14159927717
2009-10-22 17:23:31.885412 [INFO] switch_cpp.cpp:1116 EVENTC_BILLING_CEIL,
subtracting 5 for hh_call:1095423
2009-10-22 17:23:31.901620 [DEBUG] switch_core_state_machine.c:494 Hangup
Command luarun(hh_hangup.lua f8604694-4e44-4c4c-9805-722b3e9d6b68 1 1):
+OK

2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:343
(sofia/external/+14158867717 at 199.173.100.16:5060) State EXCHANGE_MEDIA going
to sleep
2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_HANGUP
2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:442 handler
already called, skipping state handler.
2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:325
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change CS_HANGUP ->
CS_REPORTING
2009-10-22 17:23:31.902676 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:306
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_REPORTING
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:555
(sofia/external/+14158867717 at 199.173.100.16:5060) State REPORTING
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:53
sofia/external/+14158867717 at 199.173.100.16:5060 Standard REPORTING, cause:
EXCHANGE_ROUTING_ERROR
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:555
(sofia/external/+14158867717 at 199.173.100.16:5060) State REPORTING going to
sleep
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:319
(sofia/external/+14158867717 at 199.173.100.16:5060) State Change CS_REPORTING
-> CS_DESTROY
2009-10-22 17:23:31.903742 [DEBUG] switch_core_session.c:932 Send signal
sofia/external/+14158867717 at 199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.903742 [DEBUG] switch_core_session.c:1069 Session 4
(sofia/external/+14158867717 at 199.173.100.16:5060) Locked, Waiting on
external entities
2009-10-22 17:23:31.903742 [NOTICE] switch_core_session.c:1087 Session 4
(sofia/external/+14158867717 at 199.173.100.16:5060) Ended
2009-10-22 17:23:31.903742 [NOTICE] switch_core_session.c:1089 Close Channel
sofia/external/+14158867717 at 199.173.100.16:5060 [CS_DESTROY]
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:401
(sofia/external/+14158867717 at 199.173.100.16:5060) Running State Change
CS_DESTROY
2009-10-22 17:23:31.904799 [DEBUG] switch_core_state_machine.c:412
(sofia/external/+14158867717 at 199.173.100.16:5060) State DESTROY
2009-10-22 17:23:31.904799 [DEBUG] mod_sofia.c:261 sofia/external/+
14158867717 at 199.173.100.16:5060 SOFIA DESTROY
2009-10-22 17:23:31.904799 [DEBUG] switch_core_state_machine.c:60
sofia/external/+14158867717 at 199.173.100.16:5060 Standard DESTROY
2009-10-22 17:23:31.904799 [DEBUG] switch_core_state_machine.c:412
(sofia/external/+14158867717 at 199.173.100.16:5060) State DESTROY going to
sleep



On Tue, Oct 20, 2009 at 1:44 AM, Michael Collins <msc at freeswitch.org> wrote:

>
>
> On Sun, Oct 18, 2009 at 9:48 PM, Matthew Fong <mattdfong at gmail.com> wrote:
>
>> The debug level logs to the console, right? The pastebin, had log level
>> debug, sofia trace on for external and default, and sofia loglevel all 9. Is
>> there another log enable command I'm missing? It seems loglevel all 9
>> outputs enter and exit functions, but at least to my novice eye, it's not
>> too obvious why freeswitch is sending a BYE to my DID provider.
>>
>> Evidently the console loglevel debug did not take because there isn't a
> single DEBUG level line of output. Please try again. Just remember that
> debug level log messages will have A LOT of information so be patient while
> sifting through it. Of course, feel free to pastebin the output and add a
> link to it in this email thread.
>
> -MC
>
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20091023/13ebf8dc/attachment-0002.html

More information about the FreeSWITCH-users mailing list