freeswitch@ALOK-WORK> 2013-03-01 18:54:49.931097 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOIN G: format: Supervisory sapi: 000 c/r: 0 ea: 0 tei: 000 ea: 1 n(r): 022 p/f: 1 cmd: RR - receive ready [ 00 01 01 2d ] 2013-03-01 18:54:49.931097 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:49.931097 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Supervisory sapi: 000 c/r: 0 ea: 0 tei: 000 ea: 1 n(r): 013 p/f: 1 cmd: RR - receive ready [ 00 01 01 1b ] 2013-03-01 18:54:51.352945 [NOTICE] switch_channel.c:968 New Channel sofia/external/9995@83.102.149.150 [4c43dd11-c96d-4 4a4-8d7f-d5235cd3e535] 2013-03-01 18:54:51.352945 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.352945 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.352945 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_NEW 2013-03-01 18:54:51.352945 [DEBUG] switch_core_state_machine.c:433 (sofia/external/9995@83.102.149.150) State NEW 2013-03-01 18:54:51.368570 [DEBUG] sofia.c:7678 IP 83.102.149.150 Approved by acl "domains[ThruToAster_83.102.149.150@19 2.168.2.22]". Access Granted. 2013-03-01 18:54:51.368570 [DEBUG] sofia.c:7805 Authenticating user ThruToAster_83.102.149.150@192.168.2.22 2013-03-01 18:54:51.368570 [DEBUG] sofia.c:5578 Channel sofia/external/9995@83.102.149.150 entering state [received][100 ] 2013-03-01 18:54:51.368570 [DEBUG] sofia.c:5589 Remote SDP: v=0 o=root 131770701 131770701 IN IP4 83.102.149.150 s=Asterisk PBX 1.6.0.26-FONCORE-r78 c=IN IP4 83.102.149.150 t=0 0 m=audio 12678 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 2013-03-01 18:54:51.368570 [DEBUG] sofia.c:5802 (sofia/external/9995@83.102.149.150) State Change CS_NEW -> CS_INIT 2013-03-01 18:54:51.368570 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.368570 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_INIT 2013-03-01 18:54:51.368570 [DEBUG] switch_core_state_machine.c:454 (sofia/external/9995@83.102.149.150) State INIT 2013-03-01 18:54:51.368570 [DEBUG] mod_sofia.c:86 sofia/external/9995@83.102.149.150 SOFIA INIT 2013-03-01 18:54:51.368570 [DEBUG] mod_sofia.c:126 (sofia/external/9995@83.102.149.150) State Change CS_INIT -> CS_ROUTI NG 2013-03-01 18:54:51.368570 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.368570 [DEBUG] switch_core_state_machine.c:454 (sofia/external/9995@83.102.149.150) State INIT going to sleep 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_ROUTING 2013-03-01 18:54:51.399819 [DEBUG] switch_channel.c:2003 (sofia/external/9995@83.102.149.150) Callstate Change DOWN -> R INGING 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:470 (sofia/external/9995@83.102.149.150) State ROUTING 2013-03-01 18:54:51.399819 [DEBUG] mod_sofia.c:149 sofia/external/9995@83.102.149.150 SOFIA ROUTING 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:117 sofia/external/9995@83.102.149.150 Standard ROUTING 2013-03-01 18:54:51.399819 [INFO] mod_dialplan_xml.c:557 Processing ALEKSEEV A. <9995>->140 in context public Dialplan: sofia/external/9995@83.102.149.150 parsing [public->unloop] continue=false Dialplan: sofia/external/9995@83.102.149.150 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/external/9995@83.102.149.150 parsing [public->outside_call] continue=true Dialplan: sofia/external/9995@83.102.149.150 Absolute Condition [outside_call] Dialplan: sofia/external/9995@83.102.149.150 Action set(outside_call=true) Dialplan: sofia/external/9995@83.102.149.150 Action export(outside_call=true) Dialplan: sofia/external/9995@83.102.149.150 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/external/9995@83.102.149.150 parsing [public->call_debug] continue=true Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/external/9995@83.102.149.150 parsing [public->public_asterisk_9124] continue=false Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_asterisk_9124] destination_number(140) =~ /^(9124)$/ b reak=on-false Dialplan: sofia/external/9995@83.102.149.150 parsing [public->public_to_default] continue=false Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(0[1-9])$/ ma tch=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(5?810\d{10,1 2}$|^5?\+\d{10,12})$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(5?8\d{10}$|^ 5?\+7\d{10})$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(41\d{2}$|^42 \d{2}$|^437\d{2}$|^438\d{2})$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(46\d{4})$/ m atch=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(7\d{2}$|^91\ d{2})$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(7761\d{2})$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(7[345][0-9]) $/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_to_default] destination_number(140) =~ /^(10[01][0-9]) $/ match=any Dialplan: sofia/external/9995@83.102.149.150 parsing [public->public_local_3xx_intercept_and_testgroup] continue=false Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_local_3xx_intercept_and_testgroup] destination_number( 140) =~ /^(377)$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_local_3xx_intercept_and_testgroup] destination_number( 140) =~ /^(388)$/ match=any Dialplan: sofia/external/9995@83.102.149.150 Regex (FAIL) [public_local_3xx_intercept_and_testgroup] destination_number( 140) =~ /^(399)$/ match=any Dialplan: sofia/external/9995@83.102.149.150 parsing [public->public_out_pbxlg] continue=false Dialplan: sofia/external/9995@83.102.149.150 Regex (PASS) [public_out_pbxlg] destination_number(140) =~ /^([123]\d{2})$/ break=on-false Dialplan: sofia/external/9995@83.102.149.150 Action set(dialed_extension=140) Dialplan: sofia/external/9995@83.102.149.150 Action set(ringback=${ru-ring}) Dialplan: sofia/external/9995@83.102.149.150 Action flush_dtmf() Dialplan: sofia/external/9995@83.102.149.150 Action queue_dtmf(WWW140@250) Dialplan: sofia/external/9995@83.102.149.150 Action bridge(freetdm/wp1/a/140) 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:167 (sofia/external/9995@83.102.149.150) State Change CS_ ROUTING -> CS_EXECUTE 2013-03-01 18:54:51.399819 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:470 (sofia/external/9995@83.102.149.150) State ROUTING go ing to sleep 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_EXECUTE 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:477 (sofia/external/9995@83.102.149.150) State EXECUTE 2013-03-01 18:54:51.399819 [DEBUG] mod_sofia.c:242 sofia/external/9995@83.102.149.150 SOFIA EXECUTE 2013-03-01 18:54:51.399819 [DEBUG] switch_core_state_machine.c:209 sofia/external/9995@83.102.149.150 Standard EXECUTE EXECUTE sofia/external/9995@83.102.149.150 set(outside_call=true) 2013-03-01 18:54:51.399819 [DEBUG] mod_dptools.c:1349 sofia/external/9995@83.102.149.150 SET [outside_call]=[true] EXECUTE sofia/external/9995@83.102.149.150 export(outside_call=true) 2013-03-01 18:54:51.399819 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [outside_call]=[true] EXECUTE sofia/external/9995@83.102.149.150 export(RFC2822_DATE=Fri, 01 Mar 2013 18:54:51 ╠юёъютёъюх тЁхь  (чшьр)) 2013-03-01 18:54:51.399819 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 01 Mar 2013 18:54:51 ╠юёъютёъюх тЁхь  (чшьр)] EXECUTE sofia/external/9995@83.102.149.150 set(dialed_extension=140) 2013-03-01 18:54:51.399819 [DEBUG] mod_dptools.c:1349 sofia/external/9995@83.102.149.150 SET [dialed_extension]=[140] EXECUTE sofia/external/9995@83.102.149.150 set(ringback=%(800,3200,425)) 2013-03-01 18:54:51.399819 [DEBUG] mod_dptools.c:1349 sofia/external/9995@83.102.149.150 SET [ringback]=[%(800,3200,425) ] EXECUTE sofia/external/9995@83.102.149.150 flush_dtmf() EXECUTE sofia/external/9995@83.102.149.150 queue_dtmf(WWW140@250) 2013-03-01 18:54:51.399819 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=W ms=250 samples=2000 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=W ms=250 samples=2000 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=W ms=250 samples=2000 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=1 ms=250 samples=2000 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=4 ms=250 samples=2000 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:504 sofia/external/9995@83.102.149.150 Queue dtmf digit=0 ms=250 samples=2000 EXECUTE sofia/external/9995@83.102.149.150 bridge(freetdm/wp1/a/140) 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:1089 sofia/external/9995@83.102.149.150 EXPORTING[export_vars] [outs ide_call]=[true] to event 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:1089 sofia/external/9995@83.102.149.150 EXPORTING[export_vars] [RFC2 822_DATE]=[Fri, 01 Mar 2013 18:54:51 ╠юёъютёъюх тЁхь  (чшьр)] to event 2013-03-01 18:54:51.415444 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:403 Set codec PCMA 20ms 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:1242 Connect outbound channel FreeTDM/1:1/140 2013-03-01 18:54:51.415444 [NOTICE] switch_channel.c:968 New Channel FreeTDM/1:1/140 [25526cb5-23b9-41e3-bc23-fadc6276c3 3b] 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:1251 (FreeTDM/1:1/140) State Change CS_NEW -> CS_INIT 2013-03-01 18:54:51.415444 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:1270 Attached session 25526cb5-23b9-41e3-bc23-fadc6276c33b to channel 1 :1 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:1758 [s1c1][1:1] Changed state from DOWN to DIALING 2013-03-01 18:54:51.415444 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for DIALING 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to DIALING 2013-03-01 18:54:51.415444 [INFO] ftmod_sangoma_isdn_stack_out.c:62 [s1c1][1:1] Outgoing call: Called No:[140] Calling N o:[9995] 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn_support.c:1164 [s1c1][1:1] Overriding bearer cap to a-law 2013-03-01 18:54:51.415444 [INFO] ftmod_sangoma_isdn_stack_out.c:79 [s1c1][1:1] Sending SETUP (suId:1 suInstId:6 spInstI d:0 dchan:1 ces:0) 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME OUTGOING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Originating side) Type:SETUP (0x5) Sending complete: Bearer Capability:Coding:ITU-T(0) TransferCap:Speech(0) TransferRate:64 Kbit/s(16) L1Prot:G.711 A-Law(3) Channel Id:No:1 Type:B-chans(3) Exclusive/Implicit Calling Party Number:9995(l:4) plan:isdn(1) type:national(2)scr:user, passed(1) pres:allowed(0) Called Party Number:140(l:3) plan:isdn(1) type:national(2) [ 08 02 00 03 05 a1 04 03 80 90 a3 18 03 a9 83 81 6c 06 21 81 39 39 39 35 70 04 a1 31 34 30 ] 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Unnumbered sapi: 013 c/r: 0 ea: 0 tei: 024 ea: 0 p/f: 0 cmd: Unknown [ 34 30 83 81 6c 06 21 81 39 39 39 35 70 04 a1 31 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc ] 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from DOWN to DIALING in 1 ms 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:2657 got clear channel sig [DIALING] 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_INIT 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:454 (FreeTDM/1:1/140) State INIT 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:430 (FreeTDM/1:1/140) State Change CS_INIT -> CS_ROUTING 2013-03-01 18:54:51.415444 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:454 (FreeTDM/1:1/140) State INIT going to sleep 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_ROUTING 2013-03-01 18:54:51.415444 [DEBUG] switch_channel.c:2003 (FreeTDM/1:1/140) Callstate Change DOWN -> RINGING 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:470 (FreeTDM/1:1/140) State ROUTING 2013-03-01 18:54:51.415444 [DEBUG] mod_freetdm.c:453 FreeTDM/1:1/140 CHANNEL ROUTING 2013-03-01 18:54:51.415444 [DEBUG] switch_ivr_originate.c:67 (FreeTDM/1:1/140) State Change CS_ROUTING -> CS_CONSUME_MED IA 2013-03-01 18:54:51.415444 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:470 (FreeTDM/1:1/140) State ROUTING going to sleep 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_CONSUME_MED IA 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:489 (FreeTDM/1:1/140) State CONSUME_MEDIA 2013-03-01 18:54:51.415444 [DEBUG] switch_core_state_machine.c:489 (FreeTDM/1:1/140) State CONSUME_MEDIA going to sleep 2013-03-01 18:54:51.415444 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:51.415444 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Supervisory sapi: 000 c/r: 0 ea: 0 tei: 000 ea: 1 n(r): 014 p/f: 0 cmd: RR - receive ready [ 00 01 01 1c ] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Information sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(s): 022 n(r): 014 p: 0 [ 02 01 2c 1c 08 02 80 03 02 18 03 a9 83 81 ] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 023 p/f: 0 cmd: RR - receive ready [ 02 01 01 2e ] 2013-03-01 18:54:51.477943 [INFO] ftmod_sangoma_isdn_stack_rcv.c:194 [s1c1][1:1] Received PROCEED (suId:1 suInstId:6 spI nstId:6 ces:0) 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME INCOMING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Destination side) Type:PROCEED (0x2) Channel Id:No:1 Type:B-chans(3) Exclusive/Implicit [ 08 02 80 03 02 18 03 a9 83 81 ] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:380 [s1c1][1:1] Processing PROCEED (suId:1 suInstId:6 spInstId:6 ces:0) 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:414 [s1c1][1:1] Early media not available 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:425 [s1c1][1:1] Changed state from DIALING to PROCEED 2013-03-01 18:54:51.477943 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for PROCEED 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to PROCEED 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from DIALING to PROCEED i n 0 ms 2013-03-01 18:54:51.477943 [DEBUG] mod_freetdm.c:2657 got clear channel sig [PROCEED] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Information sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(s): 023 n(r): 014 p: 0 [ 02 01 2e 1c 08 02 80 03 01 18 03 a9 83 81 ] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 024 p/f: 0 cmd: RR - receive ready [ 02 01 01 30 ] 2013-03-01 18:54:51.477943 [INFO] ftmod_sangoma_isdn_stack_rcv.c:194 [s1c1][1:1] Received ALERT (suId:1 suInstId:6 spIns tId:6 ces:0) 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME INCOMING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Destination side) Type:ALERT (0x1) Channel Id:No:1 Type:B-chans(3) Exclusive/Implicit [ 08 02 80 03 01 18 03 a9 83 81 ] 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:380 [s1c1][1:1] Processing ALERT (suId:1 suInstId:6 s pInstId:6 ces:0) 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:414 [s1c1][1:1] Early media not available 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:436 [s1c1][1:1] Changed state from PROCEED to RINGING 2013-03-01 18:54:51.477943 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for RINGING 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to RINGING 2013-03-01 18:54:51.477943 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from PROCEED to RINGING i n 0 ms 2013-03-01 18:54:51.477943 [DEBUG] mod_freetdm.c:2657 got clear channel sig [RINGING] 2013-03-01 18:54:51.477943 [NOTICE] mod_freetdm.c:2720 Ring-Ready FreeTDM/1:1/140! 2013-03-01 18:54:51.493567 [INFO] switch_ivr_originate.c:1185 Sending early media 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:5139 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000] 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:5139 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:3095 Set Codec sofia/external/9995@83.102.149.150 PCMA/8000 20 ms 160 sa mples 64000 bits 2013-03-01 18:54:51.493567 [DEBUG] switch_core_codec.c:111 sofia/external/9995@83.102.149.150 Original read codec set to PCMA:8 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:5268 Set 2833 dtmf send/recv payload to 101 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:3353 AUDIO RTP [sofia/external/9995@83.102.149.150] 192.168.2.22 port 17 502 -> 83.102.149.150 port 12678 codec: 8 ms: 20 2013-03-01 18:54:51.493567 [DEBUG] switch_rtp.c:1974 Starting timer [soft] 160 bytes per 20ms 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:3617 Set 2833 dtmf send payload to 101 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:3623 Set 2833 dtmf receive payload to 101 2013-03-01 18:54:51.493567 [DEBUG] sofia_glue.c:3650 sofia/external/9995@83.102.149.150 Set rtp dtmf delay to 40 2013-03-01 18:54:51.493567 [NOTICE] sofia_glue.c:4261 Pre-Answer sofia/external/9995@83.102.149.150! 2013-03-01 18:54:51.493567 [DEBUG] switch_channel.c:3136 (sofia/external/9995@83.102.149.150) Callstate Change RINGING - > EARLY 2013-03-01 18:54:51.493567 [DEBUG] mod_sofia.c:2810 Ring SDP: v=0 o=FreeSWITCH 1362132189 1362132190 IN IP4 192.168.2.22 s=FreeSWITCH c=IN IP4 192.168.2.22 t=0 0 m=audio 17502 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2013-03-01 18:54:51.493567 [DEBUG] switch_core_session.c:830 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.493567 [DEBUG] switch_ivr_originate.c:1242 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2013-03-01 18:54:51.493567 [DEBUG] switch_core_codec.c:219 sofia/external/9995@83.102.149.150 Push codec L16:70 2013-03-01 18:54:51.493567 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.493567 [DEBUG] switch_ivr_originate.c:1305 Play Ringback Tone [%(800,3200,425)] 2013-03-01 18:54:51.509192 [DEBUG] sofia.c:5578 Channel sofia/external/9995@83.102.149.150 entering state [early][183] 2013-03-01 18:54:51.774812 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Information sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(s): 024 n(r): 014 p: 0 [ 02 01 30 1c 08 02 80 03 07 ] 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 025 p/f: 0 cmd: RR - receive ready [ 02 01 01 32 ] 2013-03-01 18:54:51.774812 [INFO] ftmod_sangoma_isdn_stack_rcv.c:144 [s1c1][1:1] Received CONNECT/CONNECT ACK (suId:1 su InstId:6 spInstId:6 ces:0) 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME INCOMING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Destination side) Type:CONNECT (0x7) [ 08 02 80 03 07 ] 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:285 [s1c1][1:1] Processing CONNECT/CONNECT ACK (suId: 1 suInstId:6 spInstId:6 ces:0) 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:313 [s1c1][1:1] Changed state from RINGING to UP 2013-03-01 18:54:51.774812 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for UP 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to UP 2013-03-01 18:54:51.774812 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from RINGING to UP in 0 m s 2013-03-01 18:54:51.774812 [DEBUG] mod_freetdm.c:2657 got clear channel sig [UP] 2013-03-01 18:54:51.774812 [DEBUG] switch_channel.c:3395 (FreeTDM/1:1/140) Callstate Change RINGING -> ACTIVE 2013-03-01 18:54:51.774812 [DEBUG] switch_channel.c:3407 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.774812 [NOTICE] mod_freetdm.c:2690 Channel [FreeTDM/1:1/140] has been answered 2013-03-01 18:54:51.774812 [DEBUG] ftdm_io.c:3386 [s1c1][1:1] Enabled software DTMF detector 2013-03-01 18:54:51.790437 [DEBUG] switch_core_codec.c:244 sofia/external/9995@83.102.149.150 Restore previous codec PCM A:8. 2013-03-01 18:54:51.790437 [DEBUG] mod_sofia.c:856 Local SDP sofia/external/9995@83.102.149.150: v=0 o=FreeSWITCH 1362132189 1362132191 IN IP4 192.168.2.22 s=FreeSWITCH c=IN IP4 192.168.2.22 t=0 0 m=audio 17502 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2013-03-01 18:54:51.790437 [DEBUG] switch_core_session.c:830 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.790437 [DEBUG] switch_channel.c:3395 (sofia/external/9995@83.102.149.150) Callstate Change EARLY -> ACTIVE 2013-03-01 18:54:51.790437 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.790437 [NOTICE] switch_ivr_originate.c:3378 Channel [sofia/external/9995@83.102.149.150] has been an swered 2013-03-01 18:54:51.790437 [DEBUG] sofia.c:5578 Channel sofia/external/9995@83.102.149.150 entering state [completed][20 0] 2013-03-01 18:54:51.790437 [DEBUG] switch_ivr_originate.c:3435 Originate Resulted in Success: [FreeTDM/1:1/140] 2013-03-01 18:54:51.790437 [DEBUG] switch_core_session.c:830 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:51.790437 [DEBUG] switch_core_session.c:830 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.790437 [DEBUG] switch_ivr_bridge.c:1370 (FreeTDM/1:1/140) State Change CS_CONSUME_MEDIA -> CS_EXCHAN GE_MEDIA 2013-03-01 18:54:51.790437 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_EXCHANGE_ME DIA 2013-03-01 18:54:51.790437 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:51.790437 [DEBUG] switch_core_state_machine.c:480 (FreeTDM/1:1/140) State EXCHANGE_MEDIA 2013-03-01 18:54:51.790437 [DEBUG] mod_freetdm.c:672 CHANNEL EXCHANGE_MEDIA 2013-03-01 18:54:51.790437 [DEBUG] ftmod_wanpipe.c:982 [s1c1][1:1] Rx Queue length exceeded 80% threshold (9/10) 2013-03-01 18:54:51.790437 [DEBUG] ftmod_wanpipe.c:1002 [s1c1][1:1] First packet read stats: Rx queue len: 9, Rx queue s ize: 10 2013-03-01 18:54:51.790437 [DEBUG] ftmod_wanpipe.c:982 [s1c1][1:1] Rx Queue length exceeded 80% threshold (8/10) 2013-03-01 18:54:51.790437 [DEBUG] ftmod_wanpipe.c:986 [s1c1][1:1] Rx Queue length reduced 80% threshold (7/10) 2013-03-01 18:54:51.821686 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.821686 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:51.821686 [DEBUG] switch_core_session.c:975 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:52.790418 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] freeswitch@ALOK-WORK> freeswitch@ALOK-WORK> 2013-03-01 18:54:53.790398 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] freeswitch@ALOK-WORK> freeswitch@ALOK-WORK> 2013-03-01 18:54:54.790379 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:54.790379 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:54.790379 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:54.790379 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:54.790379 [DEBUG] sofia.c:5578 Channel sofia/external/9995@83.102.149.150 entering state [ready][200] 2013-03-01 18:54:54.790379 [DEBUG] ftdm_io.c:3979 [s1c1][1:1] Generating DTMF [140] 2013-03-01 18:54:54.790379 [DEBUG] ftmod_wanpipe.c:938 [s1c1][1:1] First packet write stats: Tx queue len: 1, Tx queue s ize: 5, Tx idle: 340 2013-03-01 18:54:54.821629 [DEBUG] switch_core_session.c:892 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:54.821629 [DEBUG] switch_core_session.c:892 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:54.868503 [DEBUG] switch_rtp.c:3693 Correct ip/port confirmed. 2013-03-01 18:54:55.055999 [DEBUG] switch_rtp.c:3904 RTP RECV DTMF 1:1440 2013-03-01 18:54:55.055999 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.055999 [DEBUG] ftdm_io.c:3979 [s1c1][1:1] Generating DTMF [1] 2013-03-01 18:54:55.399742 [DEBUG] switch_rtp.c:3904 RTP RECV DTMF 4:1280 2013-03-01 18:54:55.399742 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.399742 [DEBUG] ftdm_io.c:3979 [s1c1][1:1] Generating DTMF [4] 2013-03-01 18:54:55.759111 [DEBUG] switch_rtp.c:3904 RTP RECV DTMF 0:1280 2013-03-01 18:54:55.759111 [DEBUG] switch_ivr_bridge.c:402 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.759111 [DEBUG] ftdm_io.c:3979 [s1c1][1:1] Generating DTMF [0] 2013-03-01 18:54:55.774735 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Information sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(s): 025 n(r): 014 p: 0 [ 02 01 32 1c 08 02 80 03 45 08 02 80 e6 ] 2013-03-01 18:54:55.774735 [INFO] ftmod_sangoma_isdn_stack_rcv.c:232 [s1c1][1:1] Received DISCONNECT (suId:1 suInstId:6 spInstId:6) 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 026 p/f: 0 cmd: RR - receive ready [ 02 01 01 34 ] 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME INCOMING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Destination side) Type:DISCONNECT (0x45) Cause:coding:ITU-T(0) location:User(0) val:Recovery on timer expired(102) Timer T [ 08 02 80 03 45 08 02 80 e6 ] 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:543 [s1c1][1:1] Processing DISCONNECT (suId:1 suInstI d:6 spInstId:6) 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:563 [s1c1][1:1] Changed state from UP to TERMINATING 2013-03-01 18:54:55.774735 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for TERMINATING 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to TERMINATING 2013-03-01 18:54:55.774735 [DEBUG] ftdm_io.c:6150 [s1c1][1:1] Scheduling safety hangup timer 2013-03-01 18:54:55.774735 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from UP to TERMINATING in 0 ms 2013-03-01 18:54:55.774735 [DEBUG] mod_freetdm.c:2657 got clear channel sig [STOP] 2013-03-01 18:54:55.774735 [DEBUG] switch_channel.c:2994 (FreeTDM/1:1/140) Callstate Change ACTIVE -> HANGUP 2013-03-01 18:54:55.774735 [NOTICE] mod_freetdm.c:2681 Hangup FreeTDM/1:1/140 [CS_EXCHANGE_MEDIA] [RECOVERY_ON_TIMER_EXP IRE] 2013-03-01 18:54:55.774735 [DEBUG] switch_channel.c:3017 Send signal FreeTDM/1:1/140 [KILL] 2013-03-01 18:54:55.774735 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.774735 [DEBUG] switch_ivr_bridge.c:597 BRIDGE THREAD DONE [FreeTDM/1:1/140] 2013-03-01 18:54:55.774735 [DEBUG] switch_ivr_bridge.c:622 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:55.774735 [DEBUG] switch_core_state_machine.c:480 (FreeTDM/1:1/140) State EXCHANGE_MEDIA going to sleep 2013-03-01 18:54:55.774735 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_HANGUP 2013-03-01 18:54:55.774735 [DEBUG] switch_core_state_machine.c:667 (FreeTDM/1:1/140) State HANGUP 2013-03-01 18:54:55.774735 [DEBUG] mod_freetdm.c:544 [1:1] FreeTDM/1:1/140 CHANNEL HANGUP ENTER 2013-03-01 18:54:55.790360 [DEBUG] mod_freetdm.c:620 [s1c1][1:1] Changed state from TERMINATING to HANGUP 2013-03-01 18:54:55.790360 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for HANGUP 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to HANGUP 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:807 [s1c1][1:1] Acknowledging remote hangup 2013-03-01 18:54:55.790360 [INFO] ftmod_sangoma_isdn_stack_out.c:441 [s1c1][1:1] Sending RELEASE/RELEASE COMPLETE (suId: 1 suInstId:6 spInstId:6) 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME OUTGOING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Originating side) Type:RELEASE (0x4d) Cause:coding:ITU-T(0) location:Private network, local user(1) val:Recovery on timer expired(102) Timer T [ 08 02 00 03 4d 08 02 81 e6 ] 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Information sapi: 000 c/r: 0 ea: 0 tei: 000 ea: 1 n(s): 014 n(r): 026 p: 0 [ 00 01 1c 34 08 02 00 03 4d 08 02 81 e6 ] 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:853 [s1c1][1:1] Completed state change from TERMINATING to HANGU P in 1 ms 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:853 [s1c1][1:1] Changed state from HANGUP to HANGUP_COMPLETE 2013-03-01 18:54:55.790360 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for HANGUP_COMPLETE 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to HANGUP_COMPLETE 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:865 [s1c1][1:1] Waiting for release from stack 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn.c:923 [s1c1][1:1] Completed state change from HANGUP to HANGUP_COM PLETE in 1 ms 2013-03-01 18:54:55.790360 [DEBUG] mod_freetdm.c:640 [1:1] FreeTDM/1:1/140 CHANNEL HANGUP EXIT 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:48 FreeTDM/1:1/140 Standard HANGUP, cause: RECOVERY_ON_TI MER_EXPIRE 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:667 (FreeTDM/1:1/140) State HANGUP going to sleep 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:446 (FreeTDM/1:1/140) State Change CS_HANGUP -> CS_REPORT ING 2013-03-01 18:54:55.790360 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/140) Running State Change CS_REPORTING 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:749 (FreeTDM/1:1/140) State REPORTING 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:92 FreeTDM/1:1/140 Standard REPORTING, cause: RECOVERY_ON _TIMER_EXPIRE 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:749 (FreeTDM/1:1/140) State REPORTING going to sleep 2013-03-01 18:54:55.790360 [DEBUG] switch_core_state_machine.c:440 (FreeTDM/1:1/140) State Change CS_REPORTING -> CS_DES TROY 2013-03-01 18:54:55.790360 [DEBUG] switch_core_session.c:1291 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.790360 [DEBUG] switch_core_session.c:1499 Session 11 (FreeTDM/1:1/140) Locked, Waiting on external e ntities 2013-03-01 18:54:55.790360 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:55.790360 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Supervisory sapi: 000 c/r: 0 ea: 0 tei: 000 ea: 1 n(r): 015 p/f: 0 cmd: RR - receive ready [ 00 01 01 1e ] 2013-03-01 18:54:55.821609 [DEBUG] switch_ivr_bridge.c:597 BRIDGE THREAD DONE [sofia/external/9995@83.102.149.150] 2013-03-01 18:54:55.821609 [DEBUG] switch_ivr_bridge.c:622 Send signal FreeTDM/1:1/140 [BREAK] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_session.c:830 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:55.821609 [NOTICE] switch_core_session.c:1517 Session 11 (FreeTDM/1:1/140) Ended 2013-03-01 18:54:55.821609 [NOTICE] switch_core_state_machine.c:262 sofia/external/9995@83.102.149.150 has executed the last dialplan instruction, hanging up. 2013-03-01 18:54:55.821609 [NOTICE] switch_core_session.c:1521 Close Channel FreeTDM/1:1/140 [CS_DESTROY] 2013-03-01 18:54:55.821609 [DEBUG] switch_channel.c:2994 (sofia/external/9995@83.102.149.150) Callstate Change ACTIVE -> HANGUP 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:556 (FreeTDM/1:1/140) Callstate Change HANGUP -> DOWN 2013-03-01 18:54:55.821609 [NOTICE] switch_core_state_machine.c:264 Hangup sofia/external/9995@83.102.149.150 [CS_EXECUT E] [NORMAL_CLEARING] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:559 (FreeTDM/1:1/140) Running State Change CS_DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_channel.c:3017 Send signal sofia/external/9995@83.102.149.150 [KILL] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:477 (sofia/external/9995@83.102.149.150) State EXECUTE go ing to sleep 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:569 (FreeTDM/1:1/140) State DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_HANGUP 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:99 FreeTDM/1:1/140 Standard DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:569 (FreeTDM/1:1/140) State DESTROY going to sleep 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:667 (sofia/external/9995@83.102.149.150) State HANGUP 2013-03-01 18:54:55.821609 [DEBUG] mod_sofia.c:503 Channel sofia/external/9995@83.102.149.150 hanging up, cause: NORMAL_ CLEARING 2013-03-01 18:54:55.821609 [DEBUG] mod_sofia.c:552 Sending BYE to sofia/external/9995@83.102.149.150 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:48 sofia/external/9995@83.102.149.150 Standard HANGUP, ca use: NORMAL_CLEARING 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:667 (sofia/external/9995@83.102.149.150) State HANGUP goi ng to sleep 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:446 (sofia/external/9995@83.102.149.150) State Change CS_ HANGUP -> CS_REPORTING 2013-03-01 18:54:55.821609 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:415 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_REPORTING 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:749 (sofia/external/9995@83.102.149.150) State REPORTING 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:92 sofia/external/9995@83.102.149.150 Standard REPORTING, cause: NORMAL_CLEARING 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:749 (sofia/external/9995@83.102.149.150) State REPORTING going to sleep 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:440 (sofia/external/9995@83.102.149.150) State Change CS_ REPORTING -> CS_DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_session.c:1291 Send signal sofia/external/9995@83.102.149.150 [BREAK] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_session.c:1499 Session 10 (sofia/external/9995@83.102.149.150) Locked, Wa iting on external entities 2013-03-01 18:54:55.821609 [NOTICE] switch_core_session.c:1517 Session 10 (sofia/external/9995@83.102.149.150) Ended 2013-03-01 18:54:55.821609 [NOTICE] switch_core_session.c:1521 Close Channel sofia/external/9995@83.102.149.150 [CS_DEST ROY] 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:556 (sofia/external/9995@83.102.149.150) Callstate Change HANGUP -> DOWN 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:559 (sofia/external/9995@83.102.149.150) Running State Ch ange CS_DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:569 (sofia/external/9995@83.102.149.150) State DESTROY 2013-03-01 18:54:55.821609 [DEBUG] mod_sofia.c:396 sofia/external/9995@83.102.149.150 SOFIA DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:99 sofia/external/9995@83.102.149.150 Standard DESTROY 2013-03-01 18:54:55.821609 [DEBUG] switch_core_state_machine.c:569 (sofia/external/9995@83.102.149.150) State DESTROY go ing to sleep 2013-03-01 18:54:55.852859 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Information sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(s): 026 n(r): 015 p: 0 [ 02 01 34 1e 08 02 80 03 5a 08 02 81 e6 ] 2013-03-01 18:54:55.852859 [INFO] ftmod_sangoma_isdn_stack_rcv.c:267 [s1c1][1:1] Received RELEASE/RELEASE COMPLETE (suId :1 suInstId:6 spInstId:6) 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 027 p/f: 0 cmd: RR - receive ready [ 02 01 01 36 ] 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_trace.c:224 [SNGISDN Q931] wp1 FRAME INCOMING: Prot Disc:Q.931/I.451 (0x08) Call Ref:0003 (Destination side) Type:RELEASE COMPLETE (0x5a) Cause:coding:ITU-T(0) location:Private network, local user(1) val:Recovery on timer expired(102) Timer T [ 08 02 80 03 5a 08 02 81 e6 ] 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:607 [s1c1][1:1] Processing RELEASE/RELEASE COMPLETE ( suId:1 suInstId:6 spInstId:6) 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_stack_hndl.c:626 [s1c1][1:1] Changed state from HANGUP_COMPLETE to DOWN 2013-03-01 18:54:55.852859 [DEBUG] ftdm_state.c:541 [s1c1][1:1] Executing state processor for DOWN 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn.c:655 [s1c1][1:1] processing state change to DOWN 2013-03-01 18:54:55.852859 [DEBUG] ftmod_sangoma_isdn_support.c:136 [s1c1][1:1] Clearing call data (suId:1 suInstId:6 sp InstId:6) 2013-03-01 18:54:55.852859 [DEBUG] ftdm_io.c:3185 [s1c1][1:1] DTMF debug is already disabled 2013-03-01 18:54:55.852859 [DEBUG] ftdm_io.c:3217 [s1c1][1:1] No need to disable input dump 2013-03-01 18:54:55.852859 [DEBUG] ftdm_io.c:3248 [s1c1][1:1] No need to disable output dump 2013-03-01 18:54:55.852859 [DEBUG] ftdm_io.c:6780 Cleared call with id 6 2013-03-01 18:54:55.852859 [DEBUG] ftdm_io.c:2990 [s1c1][1:1] channel done 2013-03-01 18:54:55.852859 [DEBUG] mod_freetdm.c:2657 got clear channel sig [RELEASED] freeswitch@ALOK-WORK> freeswitch@ALOK-WORK> freeswitch@ALOK-WORK> freeswitch@ALOK-WORK> 2013-03-01 18:55:14.914993 [DEBUG] ftmod_wanpipe.c:1400 [s1c31][1:16] Link status is 1 2013-03-01 18:55:14.914993 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME INCOMING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 015 p/f: 1 cmd: RR - receive ready [ 02 01 01 1f ] 2013-03-01 18:55:14.914993 [DEBUG] ftmod_sangoma_isdn_trace.c:117 [SNGISDN Q921] wp1 FRAME OUTGOING: format: Supervisory sapi: 000 c/r: 1 ea: 0 tei: 000 ea: 1 n(r): 027 p/f: 1 cmd: RR - receive ready [ 02 01 01 37 ] freeswitch@internal> freeswitch@internal>