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>