2012-03-18 23:59:34.622132 [NOTICE] switch_channel.c:926 New Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com [e246464e-7134-11e1-838a-f77ccb01f5b9]
2012-03-18 23:59:34.622132 [DEBUG] sofia.c:5532 Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com entering state [received][100]
2012-03-18 23:59:34.622132 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 3541089576 3541089576 IN IP4 192.168.5.37
s=pjmedia
c=IN IP4 192.168.5.37
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 9 107 106 105 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:107 speex/32000
a=rtpmap:106 speex/16000
a=rtpmap:105 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4001 IN IP4 192.168.5.37

2012-03-18 23:59:34.622132 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2012-03-18 23:59:34.622132 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2012-03-18 23:59:34.622132 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-18 23:59:34.622132 [DEBUG] sofia_glue.c:2996 Set Codec sofia/sipinterface_1/2916@freeswitch.voipqso.com G722/8000 20 ms 160 samples 64000 bits
2012-03-18 23:59:34.622132 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/2916@freeswitch.voipqso.com Original read codec set to G722:9
2012-03-18 23:59:34.622132 [DEBUG] sofia_glue.c:5000 Set 2833 dtmf send/recv payload to 101
2012-03-18 23:59:34.622132 [DEBUG] sofia.c:5757 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_NEW -> CS_INIT
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_INIT
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State INIT
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:85 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA INIT
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:125 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_INIT -> CS_ROUTING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State INIT going to sleep
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_ROUTING
2012-03-18 23:59:34.622132 [DEBUG] switch_channel.c:1886 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change DOWN -> RINGING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State ROUTING
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:148 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA ROUTING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard ROUTING
2012-03-18 23:59:34.622132 [INFO] mod_dialplan_xml.c:485 Processing 2916 <2916>->9888 in context context_1
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (PASS) [conditioning_callerid] ${internal_caller_id_number}(2916) =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(effective_caller_id_name=${internal_caller_id_name}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(effective_caller_id_number=${internal_caller_id_number}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Absolute Condition [postroute_global]
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->main_number_7] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (FAIL) [main_number_7] destination_number(9888) =~ /^2916$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->main_number_8] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (FAIL) [main_number_8] destination_number(9888) =~ /^\*9001$/ break=on-false
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:154 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_ROUTING -> CS_EXECUTE
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State ROUTING going to sleep
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_EXECUTE
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State EXECUTE
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:241 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA EXECUTE
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:192 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(effective_caller_id_name=n3glv csip)
2012-03-18 23:59:34.622132 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [effective_caller_id_name]=[n3glv csip]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(effective_caller_id_number=2916)
2012-03-18 23:59:34.622132 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [effective_caller_id_number]=[2916]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-spymap/2916/e246464e-7134-11e1-838a-f77ccb01f5b9)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-last_dial/2916/9888)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-last_dial/global/e246464e-7134-11e1-838a-f77ccb01f5b9)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(RFC2822_DATE=Sun, 18 Mar 2012 23:59:34 +0400)
2012-03-18 23:59:34.622132 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [RFC2822_DATE]=[Sun, 18 Mar 2012 23:59:34 +0400]
2012-03-18 23:59:34.622132 [NOTICE] switch_core_state_machine.c:226 sofia/sipinterface_1/2916@freeswitch.voipqso.com has executed the last dialplan instruction, hanging up.
2012-03-18 23:59:34.622132 [DEBUG] switch_channel.c:2848 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change RINGING -> HANGUP
2012-03-18 23:59:34.622132 [NOTICE] switch_core_state_machine.c:228 Hangup sofia/sipinterface_1/2916@freeswitch.voipqso.com [CS_EXECUTE] [NORMAL_CLEARING]
2012-03-18 23:59:34.622132 [DEBUG] switch_channel.c:2871 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [KILL]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State EXECUTE going to sleep
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_HANGUP
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State HANGUP
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:469 Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com hanging up, cause: NORMAL_CLEARING
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:534 Responding to INVITE with: 480
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:47 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard HANGUP, cause: NORMAL_CLEARING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State HANGUP going to sleep
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:393 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_HANGUP -> CS_REPORTING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_REPORTING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State REPORTING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:79 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard REPORTING, cause: NORMAL_CLEARING
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State REPORTING going to sleep
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:387 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_REPORTING -> CS_DESTROY
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_session.c:1382 Session 6 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Locked, Waiting on external entities
2012-03-18 23:59:34.622132 [NOTICE] switch_core_session.c:1400 Session 6 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Ended
2012-03-18 23:59:34.622132 [NOTICE] switch_core_session.c:1402 Close Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com [CS_DESTROY]
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change HANGUP -> DOWN
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:494 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_DESTROY
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State DESTROY
2012-03-18 23:59:34.622132 [DEBUG] mod_sofia.c:374 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA DESTROY
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:86 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard DESTROY
2012-03-18 23:59:34.622132 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State DESTROY going to sleep
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:449 Adding tone_descriptor: 1
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 1, tone: CED_TONE(0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: CED_TONE(0), element (2100, 0, 500, 0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 1, tone: SIT(1)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: SIT(1), element (950, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: SIT(1), element (1400, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: SIT(1), element (1800, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 1, tone: REORDER_TONE(2)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: REORDER_TONE(2), element (480, 620, 224, 272)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: REORDER_TONE(2), element (0, 0, 224, 272)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 1, tone: BUSY_TONE(3)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: BUSY_TONE(3), element (480, 620, 464, 516)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 1, tone: BUSY_TONE(3), element (0, 0, 464, 516)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:449 Adding tone_descriptor: 44
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 44, tone: CED_TONE(0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: CED_TONE(0), element (2100, 0, 500, 0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 44, tone: SIT(1)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: SIT(1), element (950, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: SIT(1), element (1400, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: SIT(1), element (1800, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 44, tone: REORDER_TONE(2)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: REORDER_TONE(2), element (400, 0, 368, 416)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: REORDER_TONE(2), element (0, 0, 336, 368)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: REORDER_TONE(2), element (400, 0, 256, 288)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: REORDER_TONE(2), element (0, 0, 512, 544)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 44, tone: BUSY_TONE(3)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: BUSY_TONE(3), element (400, 0, 352, 384)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: BUSY_TONE(3), element (0, 0, 352, 384)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: BUSY_TONE(3), element (400, 0, 352, 384)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 44, tone: BUSY_TONE(3), element (0, 0, 352, 384)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:449 Adding tone_descriptor: 49
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 49, tone: CED_TONE(0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: CED_TONE(0), element (2100, 0, 500, 0)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 49, tone: SIT(1)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: SIT(1), element (900, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: SIT(1), element (1400, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: SIT(1), element (1800, 0, 256, 400)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 49, tone: REORDER_TONE(2)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: REORDER_TONE(2), element (425, 0, 224, 272)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: REORDER_TONE(2), element (0, 0, 224, 272)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:470 Adding tone_descriptor: 49, tone: BUSY_TONE(3)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: BUSY_TONE(3), element (425, 0, 464, 516)
2012-03-19 00:01:40.202197 [DEBUG] mod_spandsp.c:505 Adding tone_descriptor: 49, tone: BUSY_TONE(3), element (0, 0, 464, 516)
2012-03-19 00:01:40.202197 [INFO] mod_enum.c:812 ENUM Reloaded
2012-03-19 00:01:40.202197 [INFO] switch_time.c:1128 Timezone reloaded 530 definitions
2012-03-19 00:01:52.161127 [NOTICE] switch_channel.c:926 New Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com [344135f8-7135-11e1-8390-f77ccb01f5b9]
2012-03-19 00:01:52.161127 [DEBUG] sofia.c:5532 Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com entering state [received][100]
2012-03-19 00:01:52.161127 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 3541089714 3541089714 IN IP4 192.168.5.37
s=pjmedia
c=IN IP4 192.168.5.37
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 9 107 106 105 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:107 speex/32000
a=rtpmap:106 speex/16000
a=rtpmap:105 speex/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4001 IN IP4 192.168.5.37

2012-03-19 00:01:52.161127 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:115:32000:20:48000]
2012-03-19 00:01:52.161127 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G7221:107:16000:20:32000]
2012-03-19 00:01:52.161127 [DEBUG] sofia_glue.c:4879 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-19 00:01:52.161127 [DEBUG] sofia_glue.c:2996 Set Codec sofia/sipinterface_1/2916@freeswitch.voipqso.com G722/8000 20 ms 160 samples 64000 bits
2012-03-19 00:01:52.161127 [DEBUG] switch_core_codec.c:111 sofia/sipinterface_1/2916@freeswitch.voipqso.com Original read codec set to G722:9
2012-03-19 00:01:52.161127 [DEBUG] sofia_glue.c:5000 Set 2833 dtmf send/recv payload to 101
2012-03-19 00:01:52.161127 [DEBUG] sofia.c:5757 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_NEW -> CS_INIT
2012-03-19 00:01:52.161127 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_INIT
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State INIT
2012-03-19 00:01:52.161127 [DEBUG] mod_sofia.c:85 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA INIT
2012-03-19 00:01:52.161127 [DEBUG] mod_sofia.c:125 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_INIT -> CS_ROUTING
2012-03-19 00:01:52.161127 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State INIT going to sleep
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_ROUTING
2012-03-19 00:01:52.161127 [DEBUG] switch_channel.c:1886 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change DOWN -> RINGING
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State ROUTING
2012-03-19 00:01:52.161127 [DEBUG] mod_sofia.c:148 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA ROUTING
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:104 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard ROUTING
2012-03-19 00:01:52.161127 [INFO] mod_dialplan_xml.c:485 Processing 2916 <2916>->9888 in context context_1
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->conditioning_callerid] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (PASS) [conditioning_callerid] ${internal_caller_id_number}(2916) =~ /^.+$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(effective_caller_id_name=${internal_caller_id_name}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(effective_caller_id_number=${internal_caller_id_number}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->postroute_global] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Absolute Condition [postroute_global]
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->main_number_7] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (FAIL) [main_number_7] destination_number(9888) =~ /^2916$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->main_number_8] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (FAIL) [main_number_8] destination_number(9888) =~ /^\*9001$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com parsing [context_1->main_number_9] continue=true
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Regex (PASS) [main_number_9] destination_number(9888) =~ /^9888$/ break=on-false
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(call_timeout=30) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(ringback=${us-ring}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action set(transfer_ringback=${us-ring}) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action export(sip_callee_id_name=9888) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action export(sip_callee_id_number=9888) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action bridge({ignore_early_media=true}sofia/sipinterface_3/888@voipqso.com:5060) 
Dialplan: sofia/sipinterface_1/2916@freeswitch.voipqso.com Action hangup() 
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:154 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_ROUTING -> CS_EXECUTE
2012-03-19 00:01:52.161127 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State ROUTING going to sleep
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_EXECUTE
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State EXECUTE
2012-03-19 00:01:52.161127 [DEBUG] mod_sofia.c:241 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA EXECUTE
2012-03-19 00:01:52.161127 [DEBUG] switch_core_state_machine.c:192 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard EXECUTE
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(effective_caller_id_name=n3glv csip)
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [effective_caller_id_name]=[n3glv csip]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(effective_caller_id_number=2916)
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [effective_caller_id_number]=[2916]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-spymap/2916/344135f8-7135-11e1-8390-f77ccb01f5b9)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-last_dial/2916/9888)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com hash(insert/freeswitch.voipqso.com-last_dial/global/344135f8-7135-11e1-8390-f77ccb01f5b9)
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(RFC2822_DATE=Mon, 19 Mar 2012 00:01:52 +0400)
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [RFC2822_DATE]=[Mon, 19 Mar 2012 00:01:52 +0400]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(call_timeout=30)
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [call_timeout]=[30]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(ringback=%(2000,4000,440,480))
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com set(transfer_ringback=%(2000,4000,440,480))
2012-03-19 00:01:52.161127 [DEBUG] mod_dptools.c:1281 sofia/sipinterface_1/2916@freeswitch.voipqso.com SET [transfer_ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com export(sip_callee_id_name=9888)
2012-03-19 00:01:52.161127 [DEBUG] switch_channel.c:1093 EXPORT (export_vars) [sip_callee_id_name]=[9888]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com export(sip_callee_id_number=9888)
2012-03-19 00:01:52.161127 [DEBUG] switch_channel.c:1093 EXPORT (export_vars) [sip_callee_id_number]=[9888]
EXECUTE sofia/sipinterface_1/2916@freeswitch.voipqso.com bridge({ignore_early_media=true}sofia/sipinterface_3/888@voipqso.com:5060)
2012-03-19 00:01:52.241300 [DEBUG] switch_channel.c:1047 sofia/sipinterface_1/2916@freeswitch.voipqso.com EXPORTING[export_vars] [sip_callee_id_name]=[9888] to event
2012-03-19 00:01:52.241300 [DEBUG] switch_channel.c:1047 sofia/sipinterface_1/2916@freeswitch.voipqso.com EXPORTING[export_vars] [sip_callee_id_number]=[9888] to event
2012-03-19 00:01:52.241300 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-03-19 00:01:52.241300 [DEBUG] switch_event.c:1522 Parsing variable [ignore_early_media]=[true]
2012-03-19 00:01:52.241300 [NOTICE] switch_channel.c:926 New Channel sofia/sipinterface_3/888@voipqso.com:5060 [344db896-7135-11e1-8395-f77ccb01f5b9]
2012-03-19 00:01:52.241300 [DEBUG] mod_sofia.c:4691 (sofia/sipinterface_3/888@voipqso.com:5060) State Change CS_NEW -> CS_INIT
2012-03-19 00:01:52.241300 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_INIT
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_3/888@voipqso.com:5060) State INIT
2012-03-19 00:01:52.281133 [DEBUG] mod_sofia.c:85 sofia/sipinterface_3/888@voipqso.com:5060 SOFIA INIT
2012-03-19 00:01:52.281133 [DEBUG] mod_sofia.c:125 (sofia/sipinterface_3/888@voipqso.com:5060) State Change CS_INIT -> CS_ROUTING
2012-03-19 00:01:52.281133 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:401 (sofia/sipinterface_3/888@voipqso.com:5060) State INIT going to sleep
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_ROUTING
2012-03-19 00:01:52.281133 [DEBUG] switch_channel.c:1886 (sofia/sipinterface_3/888@voipqso.com:5060) Callstate Change DOWN -> RINGING
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_3/888@voipqso.com:5060) State ROUTING
2012-03-19 00:01:52.281133 [DEBUG] mod_sofia.c:148 sofia/sipinterface_3/888@voipqso.com:5060 SOFIA ROUTING
2012-03-19 00:01:52.281133 [DEBUG] switch_ivr_originate.c:66 (sofia/sipinterface_3/888@voipqso.com:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-03-19 00:01:52.281133 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:410 (sofia/sipinterface_3/888@voipqso.com:5060) State ROUTING going to sleep
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_CONSUME_MEDIA
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:429 (sofia/sipinterface_3/888@voipqso.com:5060) State CONSUME_MEDIA
2012-03-19 00:01:52.281133 [DEBUG] switch_core_state_machine.c:429 (sofia/sipinterface_3/888@voipqso.com:5060) State CONSUME_MEDIA going to sleep
2012-03-19 00:01:52.281133 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.281133 [DEBUG] sofia.c:5532 Channel sofia/sipinterface_3/888@voipqso.com:5060 entering state [calling][0]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:877 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.441068 [ERR] sofia_reg.c:2104 Cannot locate any authentication credentials to complete an authentication request for realm '"asterisk"'
2012-03-19 00:01:52.441068 [DEBUG] switch_channel.c:2848 (sofia/sipinterface_3/888@voipqso.com:5060) Callstate Change RINGING -> HANGUP
2012-03-19 00:01:52.441068 [NOTICE] sofia_reg.c:2124 Hangup sofia/sipinterface_3/888@voipqso.com:5060 [CS_CONSUME_MEDIA] [MANDATORY_IE_MISSING]
2012-03-19 00:01:52.441068 [DEBUG] switch_channel.c:2871 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [KILL]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_HANGUP
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_3/888@voipqso.com:5060) State HANGUP
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:469 Channel sofia/sipinterface_3/888@voipqso.com:5060 hanging up, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/sipinterface_3/888@voipqso.com:5060
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:47 sofia/sipinterface_3/888@voipqso.com:5060 Standard HANGUP, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_3/888@voipqso.com:5060) State HANGUP going to sleep
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:393 (sofia/sipinterface_3/888@voipqso.com:5060) State Change CS_HANGUP -> CS_REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_3/888@voipqso.com:5060) State REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:79 sofia/sipinterface_3/888@voipqso.com:5060 Standard REPORTING, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_3/888@voipqso.com:5060) State REPORTING going to sleep
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:387 (sofia/sipinterface_3/888@voipqso.com:5060) State Change CS_REPORTING -> CS_DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_3/888@voipqso.com:5060 [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1382 Session 8 (sofia/sipinterface_3/888@voipqso.com:5060) Locked, Waiting on external entities
2012-03-19 00:01:52.441068 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 96 [MANDATORY_IE_MISSING]
2012-03-19 00:01:52.441068 [INFO] mod_dptools.c:2922 Originate Failed.  Cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] switch_channel.c:2848 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change RINGING -> HANGUP
2012-03-19 00:01:52.441068 [NOTICE] mod_dptools.c:3041 Hangup sofia/sipinterface_1/2916@freeswitch.voipqso.com [CS_EXECUTE] [MANDATORY_IE_MISSING]
2012-03-19 00:01:52.441068 [DEBUG] switch_channel.c:2871 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [KILL]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:2287 sofia/sipinterface_1/2916@freeswitch.voipqso.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:417 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State EXECUTE going to sleep
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_HANGUP
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State HANGUP
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:469 Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com hanging up, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:534 Responding to INVITE with: 480
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:47 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard HANGUP, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:602 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State HANGUP going to sleep
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:393 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_HANGUP -> CS_REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:362 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State REPORTING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:79 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard REPORTING, cause: MANDATORY_IE_MISSING
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:662 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State REPORTING going to sleep
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:387 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State Change CS_REPORTING -> CS_DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1182 Send signal sofia/sipinterface_1/2916@freeswitch.voipqso.com [BREAK]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_session.c:1382 Session 7 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Locked, Waiting on external entities
2012-03-19 00:01:52.441068 [NOTICE] switch_core_session.c:1400 Session 7 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Ended
2012-03-19 00:01:52.441068 [NOTICE] switch_core_session.c:1402 Close Channel sofia/sipinterface_1/2916@freeswitch.voipqso.com [CS_DESTROY]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Callstate Change HANGUP -> DOWN
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:494 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) Running State Change CS_DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State DESTROY
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:374 sofia/sipinterface_1/2916@freeswitch.voipqso.com SOFIA DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:86 sofia/sipinterface_1/2916@freeswitch.voipqso.com Standard DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_1/2916@freeswitch.voipqso.com) State DESTROY going to sleep
2012-03-19 00:01:52.441068 [NOTICE] switch_core_session.c:1400 Session 8 (sofia/sipinterface_3/888@voipqso.com:5060) Ended
2012-03-19 00:01:52.441068 [NOTICE] switch_core_session.c:1402 Close Channel sofia/sipinterface_3/888@voipqso.com:5060 [CS_DESTROY]
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:491 (sofia/sipinterface_3/888@voipqso.com:5060) Callstate Change HANGUP -> DOWN
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:494 (sofia/sipinterface_3/888@voipqso.com:5060) Running State Change CS_DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_3/888@voipqso.com:5060) State DESTROY
2012-03-19 00:01:52.441068 [DEBUG] mod_sofia.c:374 sofia/sipinterface_3/888@voipqso.com:5060 SOFIA DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:86 sofia/sipinterface_3/888@voipqso.com:5060 Standard DESTROY
2012-03-19 00:01:52.441068 [DEBUG] switch_core_state_machine.c:504 (sofia/sipinterface_3/888@voipqso.com:5060) State DESTROY going to sleep