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

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.org it 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@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@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@199.173.100.16:5060) State HIBERNATE
2009-10-22 17:22:31.741845 [DEBUG] mod_sofia.c:160 sofia/external/+14158867717@199.173.100.16:5060 SOFIA HIBERNATE
2009-10-22 17:22:31.741845 [DEBUG] switch_ivr_bridge.c:650 (sofia/external/+14158867717@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:355 (sofia/external/+14158867717@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@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@199.173.100.16:5060) State RESET
2009-10-22 17:22:31.741845 [DEBUG] mod_sofia.c:145 sofia/external/+14158867717@199.173.100.16:5060 SOFIA RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_ivr_bridge.c:637 sofia/external/+14158867717@199.173.100.16:5060 CUSTOM RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:67 sofia/external/+14158867717@199.173.100.16:5060 Standard RESET
2009-10-22 17:22:31.741845 [DEBUG] switch_core_state_machine.c:336 (sofia/external/+14158867717@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:120 sofia/external/+14158867717@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.748086 [DEBUG] switch_ivr_bridge.c:968 sofia/external/+14158867717@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:31.749553 [DEBUG] switch_core_state_machine.c:306 (sofia/external/+14158867717@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@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@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@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_ivr.c:1365 sofia/external/+14158867717@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [NOTICE] switch_ivr.c:1367 Transfer sofia/external/+14158867717@199.173.100.16:5060 to xml[1998@default]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:343 (sofia/external/+14158867717@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@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@199.173.100.16:5060) State ROUTING
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:130 sofia/external/+14158867717@199.173.100.16:5060 SOFIA ROUTING
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:78 sofia/external/+14158867717@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@199.173.100.16:5060 parsing [default->tod_example] continue=true
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (PASS) [tod_example] ${strftime(%w)}(4) =~ /^([1-5])$/ break=on-false
Dialplan: sofia/external/+14158867717@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@199.173.100.16:5060 Action set(open=true)
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->ivr_demo] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [ivr_demo] destination_number(1998) =~ /^5000$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1975] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1975] destination_number(1998) =~ /^1975$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1971] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1971] destination_number(1998) =~ /^1971$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1972] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1972] destination_number(1998) =~ /^1972$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1920] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1920] destination_number(1998) =~ /^1920$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1981] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1981] destination_number(1998) =~ /^1981$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1982] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1982] destination_number(1998) =~ /^1982$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1481] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1481] destination_number(1998) =~ /^1481$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1989] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1989] destination_number(1998) =~ /^1989$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1990] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1990] destination_number(1998) =~ /^1990$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1991] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1991] destination_number(1998) =~ /^1991$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1992] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1992] destination_number(1998) =~ /^1992$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1993] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1993] destination_number(1998) =~ /^1993$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1994] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1994] destination_number(1998) =~ /^1994$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1995] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1995] destination_number(1998) =~ /^1995$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1996] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1996] destination_number(1998) =~ /^1996$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1997] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (FAIL) [1997] destination_number(1998) =~ /^1997$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 parsing [default->1998] continue=false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Regex (PASS) [1998] destination_number(1998) =~ /^1998$/ break=on-false
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Action set(transfer_after_bridge=1998)
Dialplan: sofia/external/+14158867717@199.173.100.16:5060 Action park()
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:114 (sofia/external/+14158867717@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:333 (sofia/external/+14158867717@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@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@199.173.100.16:5060) State EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] mod_sofia.c:173 sofia/external/+14158867717@199.173.100.16:5060 SOFIA EXECUTE
2009-10-22 17:22:40.639760 [DEBUG] switch_core_state_machine.c:151 sofia/external/+14158867717@199.173.100.16:5060 Standard EXECUTE
EXECUTE sofia/external/+14158867717@199.173.100.16:5060 set(open=true)
2009-10-22 17:22:40.639760 [DEBUG] mod_dptools.c:752 sofia/external/+14158867717@199.173.100.16:5060 SET [open]=[true]
EXECUTE sofia/external/+14158867717@199.173.100.16:5060 set(transfer_after_bridge=1998)
2009-10-22 17:22:40.639760 [DEBUG] mod_dptools.c:752 sofia/external/+14158867717@199.173.100.16:5060 SET [transfer_after_bridge]=[1998]
EXECUTE sofia/external/+14158867717@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@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.com hc: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@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@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@199.173.100.16:5060) State HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:160 sofia/external/+14158867717@199.173.100.16:5060 SOFIA HIBERNATE
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:650 (sofia/external/+14158867717@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:355 (sofia/external/+14158867717@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@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@199.173.100.16:5060) State RESET
2009-10-22 17:23:26.721553 [DEBUG] mod_sofia.c:145 sofia/external/+14158867717@199.173.100.16:5060 SOFIA RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:637 sofia/external/+14158867717@199.173.100.16:5060 CUSTOM RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:67 sofia/external/+14158867717@199.173.100.16:5060 Standard RESET
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:336 (sofia/external/+14158867717@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:120 sofia/external/+14158867717@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_ivr_bridge.c:968 sofia/external/+14158867717@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:26.721553 [DEBUG] switch_core_state_machine.c:306 (sofia/external/+14158867717@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@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.882153 [DEBUG] switch_ivr_bridge.c:495 sofia/external/+14158867717@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@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@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@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@199.173.100.16:5060 [KILL]
2009-10-22 17:23:31.882153 [DEBUG] switch_core_session.c:932 Send signal sofia/external/+14158867717@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.882153 [DEBUG] switch_core_state_machine.c:464 (sofia/external/+14158867717@199.173.100.16:5060) State HANGUP
2009-10-22 17:23:31.882153 [DEBUG] mod_sofia.c:344 Channel sofia/external/+14158867717@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@199.173.100.16:5060
2009-10-22 17:23:31.882153 [DEBUG] switch_core_state_machine.c:46 sofia/external/+14158867717@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@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.com hc: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@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.902676 [DEBUG] switch_core_state_machine.c:306 (sofia/external/+14158867717@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@199.173.100.16:5060) State REPORTING
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:53 sofia/external/+14158867717@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@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@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@199.173.100.16:5060 [BREAK]
2009-10-22 17:23:31.903742 [DEBUG] switch_core_session.c:1069 Session 4 (sofia/external/+14158867717@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@199.173.100.16:5060) Ended
2009-10-22 17:23:31.903742 [NOTICE] switch_core_session.c:1089 Close Channel sofia/external/+14158867717@199.173.100.16:5060 [CS_DESTROY]
2009-10-22 17:23:31.903742 [DEBUG] switch_core_state_machine.c:401 (sofia/external/+14158867717@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@199.173.100.16:5060) State DESTROY
2009-10-22 17:23:31.904799 [DEBUG] mod_sofia.c:261 sofia/external/+14158867717@199.173.100.16:5060 SOFIA DESTROY
2009-10-22 17:23:31.904799 [DEBUG] switch_core_state_machine.c:60 sofia/external/+14158867717@199.173.100.16:5060 Standard DESTROY
2009-10-22 17:23:31.904799 [DEBUG] switch_core_state_machine.c:412 (sofia/external/+14158867717@199.173.100.16:5060) State DESTROY going to sleep



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


On Sun, Oct 18, 2009 at 9:48 PM, Matthew Fong <mattdfong@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@lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org