[Freeswitch-users] Unable to transfer calls between 2 locations
Charles Bujold
cjbujold at accra.ca
Fri Sep 27 23:01:21 MSD 2013
In this example we are using 2 phones that are side by side ( same location)
and trying to transfer the call from one to the other.
Here is the log , what I see is that the call (Ext 100) is transferred ( to
110) but when answered it is sent to voicemail. Do not know where or why it
is being sent to voicemail. Any suggestion would be appreciated. It has to
be a configuration error but I do not know where to look to fix it.
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Regex (PASS)
[local_extension] destination_number(110) =~ /(^\d{2,7}$)/ break=on-false
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(dialed_extension=110)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
export(dialed_extension=110)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action limit(hash
${domain_name} 110 ${limit_max} ${limit_destination})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/archive/${strftime(%Y)}/${s
trftime(%b)}/${strftime(%d)}/${uuid}.wav)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action bind_meta_app(4 b s
execute_extension::att_xfer XML features)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(ringback=${us-ring})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action set(call_timeout=30)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(hangup_after_bridge=true)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(continue_on_fail=true)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_numbe
r})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
set(called_party_call_group=${user_data(${dialed_extension}@${domain_name}
var call_group)})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action
bridge(user/${user_data(${destination_number}@${domain_name} attr
id)}@${domain_name})
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action answer()
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action sleep(1000)
Dialplan: sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Action voicemail(default
${domain_name} ${dialed_extension})
2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:167
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State Change CS_ROUTING ->
CS_EXECUTE
2013-09-26 15:43:48.517027 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:473
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State ROUTING going to
sleep
2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Running State Change
CS_EXECUTE
2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:480
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State EXECUTE
2013-09-26 15:43:48.517027 [DEBUG] mod_sofia.c:230
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SOFIA EXECUTE
2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:209
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Standard EXECUTE
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(call_direction=local)
2013-09-26 15:43:48.517027 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[call_direction]=[local]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-spymap/100/ef19ab2c-f911-4480-8776-a43f91bd7a4f)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-last_dial/100/110)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-last_dial/global/ef19ab2c-f911-4480-8776-a43f91bd
7a4f)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(RFC2822_DATE=Thu, 26
Sep 2013 15:43:48 -0300)
2013-09-26 15:43:48.517027 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET [RFC2822_DATE]=[Thu, 26
Sep 2013 15:43:48 -0300]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(dialed_extension=110)
2013-09-26 15:43:48.517027 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[dialed_extension]=[110]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
export(dialed_extension=110)
2013-09-26 15:43:48.517027 [DEBUG] switch_channel.c:1226 EXPORT
(export_vars) [dialed_extension]=[110]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> limit(hash 192.168.30.100
110 5 )
2013-09-26 15:43:48.537011 [INFO] switch_limit.c:126 incr called:
192.168.30.100_110 max:5, interval:0
2013-09-26 15:43:48.537011 [INFO] mod_hash.c:202 Usage for
192.168.30.100_110 is now 1/5
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> bind_meta_app(1 b s
execute_extension::dx XML features)
2013-09-26 15:43:48.537011 [INFO] switch_ivr_async.c:3630 Bound B-Leg: *1
execute_extension::dx XML features
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> bind_meta_app(2 b s
record_session::/usr/local/freeswitch/recordings/archive/2013/Sep/26/ef19ab2
c-f911-4480-8776-a43f91bd7a4f.wav)
2013-09-26 15:43:48.537011 [INFO] switch_ivr_async.c:3630 Bound B-Leg: *2
record_session::/usr/local/freeswitch/recordings/archive/2013/Sep/26/ef19ab2
c-f911-4480-8776-a43f91bd7a4f.wav
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> bind_meta_app(3 b s
execute_extension::cf XML features)
2013-09-26 15:43:48.537011 [INFO] switch_ivr_async.c:3630 Bound B-Leg: *3
execute_extension::cf XML features
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> bind_meta_app(4 b s
execute_extension::att_xfer XML features)
2013-09-26 15:43:48.537011 [INFO] switch_ivr_async.c:3630 Bound B-Leg: *4
execute_extension::att_xfer XML features
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(ringback=%(2000, 4000,
440.0, 480.0))
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET [ringback]=[%(2000,
4000, 440.0, 480.0)]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
set(transfer_ringback=local_stream://moh)
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(call_timeout=30)
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET [call_timeout]=[30]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
set(hangup_after_bridge=true)
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[hangup_after_bridge]=[true]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> set(continue_on_fail=true)
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[continue_on_fail]=[true]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-call_return/110/100)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-last_dial_ext/110/ef19ab2c-f911-4480-8776-a43f91b
d7a4f)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
set(called_party_call_group=sales, support, billing)
2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SET
[called_party_call_group]=[sales, support, billing]
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
hash(insert/192.168.30.100-last_dial/sales, support,
billing/ef19ab2c-f911-4480-8776-a43f91bd7a4f)
EXECUTE sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060>
bridge(user/110 at 192.168.30.100 <mailto:user/110 at 192.168.30.100> )
2013-09-26 15:43:48.537011 [DEBUG] switch_channel.c:1180
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> EXPORTING[export_vars]
[domain_name]=[192.168.30.100] to event
2013-09-26 15:43:48.537011 [DEBUG] switch_channel.c:1180
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> EXPORTING[export_vars]
[dialed_extension]=[110] to event
2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:2060 Parsing
global variables
2013-09-26 15:43:48.537011 [DEBUG] switch_channel.c:1180
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> EXPORTING[export_vars]
[domain_name]=[192.168.30.100] to event
2013-09-26 15:43:48.537011 [DEBUG] switch_channel.c:1180
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> EXPORTING[export_vars]
[dialed_extension]=[110] to event
2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:2060 Parsing
global variables
2013-09-26 15:43:48.537011 [DEBUG] switch_event.c:1652 Parsing variable
[sip_invite_domain]=[192.168.30.100]
2013-09-26 15:43:48.537011 [DEBUG] switch_event.c:1652 Parsing variable
[leg_timeout]=[30]
2013-09-26 15:43:48.537011 [DEBUG] switch_event.c:1652 Parsing variable
[presence_id]=[110 at 192.168.30.100]
2013-09-26 15:43:48.537011 [NOTICE] switch_channel.c:1034 New Channel
sofia/internal/sip:110 at 192.168.30.50:5060
[4dc18443-2a92-44ba-b215-5c5dca4b67eb]
2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:4480
(sofia/internal/sip:110 at 192.168.30.50:5060) State Change CS_NEW -> CS_INIT
2013-09-26 15:43:48.537011 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:2773
sofia/internal/sip:110 at 192.168.30.50:5060 Setting leg timeout to 30
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change CS_INIT
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:457
(sofia/internal/sip:110 at 192.168.30.50:5060) State INIT
2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:87
sofia/internal/sip:110 at 192.168.30.50:5060 SOFIA INIT
2013-09-26 15:43:48.537011 [DEBUG] sofia_glue.c:1225 Local SDP:
v=0
o=FreeSWITCH 1380202374 1380202375 IN IP4 192.168.30.100
s=FreeSWITCH
c=IN IP4 192.168.30.100
t=0 0
m=audio 18654 RTP/AVP 0 9 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:114
(sofia/internal/sip:110 at 192.168.30.50:5060) State Change CS_INIT ->
CS_ROUTING
2013-09-26 15:43:48.537011 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:457
(sofia/internal/sip:110 at 192.168.30.50:5060) State INIT going to sleep
2013-09-26 15:43:48.537011 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change CS_ROUTING
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:473
(sofia/internal/sip:110 at 192.168.30.50:5060) State ROUTING
2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:137
sofia/internal/sip:110 at 192.168.30.50:5060 SOFIA ROUTING
2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/sip:110 at 192.168.30.50:5060) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2013-09-26 15:43:48.537011 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:473
(sofia/internal/sip:110 at 192.168.30.50:5060) State ROUTING going to sleep
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change
CS_CONSUME_MEDIA
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:492
(sofia/internal/sip:110 at 192.168.30.50:5060) State CONSUME_MEDIA
2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:492
(sofia/internal/sip:110 at 192.168.30.50:5060) State CONSUME_MEDIA going to
sleep
2013-09-26 15:43:48.537011 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110 at 192.168.30.50:5060 entering state [calling][0]
2013-09-26 15:43:48.597004 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.597004 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:48.597004 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110 at 192.168.30.50:5060 entering state [proceeding][180]
2013-09-26 15:43:48.597004 [NOTICE] sofia.c:5924 Ring-Ready
sofia/internal/sip:110 at 192.168.30.50:5060!
2013-09-26 15:43:48.597004 [DEBUG] switch_channel.c:3194
(sofia/internal/sip:110 at 192.168.30.50:5060) Callstate Change DOWN -> RINGING
2013-09-26 15:43:48.597004 [INFO] switch_ivr_originate.c:1190 Sending early
media
2013-09-26 15:43:48.597004 [DEBUG] switch_core_media.c:4098 AUDIO RTP
[sofia/internal/100 at 192.168.30.100:5060] 192.168.30.100 port 23272 ->
192.168.30.50 port 16476 codec: 0 ms: 20
2013-09-26 15:43:48.597004 [DEBUG] switch_rtp.c:2881 Starting timer [soft]
160 bytes per 20ms
2013-09-26 15:43:48.597004 [DEBUG] switch_core_media.c:4440 Set 2833 dtmf
send payload to 101
2013-09-26 15:43:48.597004 [DEBUG] switch_core_media.c:4446 Set 2833 dtmf
receive payload to 101
2013-09-26 15:43:48.597004 [DEBUG] mod_sofia.c:2143 Ring SDP:
v=0
o=FreeSWITCH 1380197756 1380197757 IN IP4 192.168.30.100
s=FreeSWITCH
c=IN IP4 192.168.30.100
t=0 0
m=audio 23272 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2013-09-26 15:43:48.597004 [NOTICE] mod_sofia.c:2146 Pre-Answer
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> !
2013-09-26 15:43:48.597004 [DEBUG] switch_channel.c:3332
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Callstate Change RINGING
-> EARLY
2013-09-26 15:43:48.597004 [DEBUG] switch_core_session.c:865 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:48.597004 [DEBUG] switch_ivr_originate.c:1247 Raw Codec
Activation Success L16 at 8000hz 1 channel 20ms
2013-09-26 15:43:48.597004 [DEBUG] switch_core_codec.c:219
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Push codec L16:70
2013-09-26 15:43:48.616991 [DEBUG] switch_ivr_originate.c:1315 Play Ringback
Tone [%(2000, 4000, 440.0, 480.0)]
2013-09-26 15:43:48.616991 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:48.637046 [DEBUG] sofia.c:5834 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> entering state [early][183]
2013-09-26 15:43:48.677046 [DEBUG] switch_rtp.c:4934 Correct ip/port
confirmed.
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110 at 192.168.30.50:5060 entering state [completing][200]
2013-09-26 15:43:52.897038 [DEBUG] sofia.c:5844 Remote SDP:
v=0
o=- 8118578 8118578 IN IP4 192.168.30.50
s=-
c=IN IP4 192.168.30.50
t=0 0
m=audio 16478 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.897038 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110 at 192.168.30.50:5060 entering state [ready][200]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_media.c:2880 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-09-26 15:43:52.897038 [DEBUG] switch_core_media.c:1913 Set Codec
sofia/internal/sip:110 at 192.168.30.50:5060 PCMU/8000 20 ms 160 samples 64000
bits
2013-09-26 15:43:52.897038 [DEBUG] switch_core_codec.c:111
sofia/internal/sip:110 at 192.168.30.50:5060 Original read codec set to PCMU:0
2013-09-26 15:43:52.897038 [DEBUG] switch_core_media.c:3042 Set 2833 dtmf
send payload to 101
2013-09-26 15:43:52.897038 [DEBUG] switch_core_media.c:4098 AUDIO RTP
[sofia/internal/sip:110 at 192.168.30.50:5060] 192.168.30.100 port 18654 ->
192.168.30.50 port 16478 codec: 0 ms: 20
2013-09-26 15:43:52.897038 [DEBUG] switch_rtp.c:2881 Starting timer [soft]
160 bytes per 20ms
2013-09-26 15:43:52.917046 [DEBUG] sofia.c:5834 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> entering state
[terminated][487]
2013-09-26 15:43:52.917046 [NOTICE] sofia.c:6642 Hangup
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [CS_EXECUTE]
[ORIGINATOR_CANCEL]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_media.c:4440 Set 2833 dtmf
send payload to 101
2013-09-26 15:43:52.917046 [DEBUG] switch_core_media.c:4446 Set 2833 dtmf
receive payload to 101
2013-09-26 15:43:52.917046 [DEBUG] switch_channel.c:3139 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [KILL]
2013-09-26 15:43:52.917046 [INFO] mod_hash.c:304 Usage for
192.168.30.100_110 is now 0
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_codec.c:244
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Restore previous codec
PCMU:0.
2013-09-26 15:43:52.917046 [NOTICE] sofia.c:6587 Channel
[sofia/internal/sip:110 at 192.168.30.50:5060] has been answered
2013-09-26 15:43:52.917046 [NOTICE] switch_ivr_originate.c:3410 Hangup
sofia/internal/sip:110 at 192.168.30.50:5060 [CS_CONSUME_MEDIA]
[ORIGINATOR_CANCEL]
2013-09-26 15:43:52.917046 [DEBUG] switch_channel.c:3139 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [KILL]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_ivr_originate.c:3626 Originate
Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL]
2013-09-26 15:43:52.917046 [NOTICE] switch_ivr_originate.c:2661 Cannot
create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2013-09-26 15:43:52.917046 [DEBUG] switch_ivr_originate.c:3632 Originate
Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2013-09-26 15:43:52.917046 [DEBUG] switch_channel.c:3613
(sofia/internal/sip:110 at 192.168.30.50:5060) Callstate Change RINGING ->
ACTIVE
2013-09-26 15:43:52.917046 [DEBUG] sofia.c:6587
sofia/internal/sip:110 at 192.168.30.50:5060 skip receive message
[ANSWER_EVENT] (channel is hungup already)
2013-09-26 15:43:52.917046 [DEBUG] sofia.c:1087 Channel is already hungup.
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change CS_HANGUP
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:681
(sofia/internal/sip:110 at 192.168.30.50:5060) State HANGUP
2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:459
sofia/internal/sip:110 at 192.168.30.50:5060 Overriding SIP cause 487 with 487
from the other leg
2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:465 Channel
sofia/internal/sip:110 at 192.168.30.50:5060 hanging up, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [INFO] mod_dptools.c:3194 Originate Failed.
Cause: ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:2767
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:480
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State EXECUTE going to
sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Running State Change
CS_HANGUP
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:681
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State HANGUP
2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:465 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> hanging up, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:517 Sending BYE to
sofia/internal/sip:110 at 192.168.30.50:5060
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:48
sofia/internal/sip:110 at 192.168.30.50:5060 Standard HANGUP, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:681
(sofia/internal/sip:110 at 192.168.30.50:5060) State HANGUP going to sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:694
(sofia/internal/sip:110 at 192.168.30.50:5060) Callstate Change ACTIVE ->
HANGUP
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:449
(sofia/internal/sip:110 at 192.168.30.50:5060) State Change CS_HANGUP ->
CS_REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change
CS_REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:48
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Standard HANGUP, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:681
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State HANGUP going to
sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:694
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Callstate Change EARLY ->
HANGUP
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:766
(sofia/internal/sip:110 at 192.168.30.50:5060) State REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:92
sofia/internal/sip:110 at 192.168.30.50:5060 Standard REPORTING, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:449
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State Change CS_HANGUP ->
CS_REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:766
(sofia/internal/sip:110 at 192.168.30.50:5060) State REPORTING going to sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Running State Change
CS_REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:766
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State REPORTING
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:443
(sofia/internal/sip:110 at 192.168.30.50:5060) State Change CS_REPORTING ->
CS_DESTROY
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/sip:110 at 192.168.30.50:5060 [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1553 Session 139
(sofia/internal/sip:110 at 192.168.30.50:5060) Locked, Waiting on external
entities
2013-09-26 15:43:52.917046 [NOTICE] switch_core_session.c:1571 Session 139
(sofia/internal/sip:110 at 192.168.30.50:5060) Ended
2013-09-26 15:43:52.917046 [NOTICE] switch_core_session.c:1575 Close Channel
sofia/internal/sip:110 at 192.168.30.50:5060 [CS_DESTROY]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/sip:110 at 192.168.30.50:5060) Callstate Change HANGUP -> DOWN
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:571
(sofia/internal/sip:110 at 192.168.30.50:5060) Running State Change CS_DESTROY
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:581
(sofia/internal/sip:110 at 192.168.30.50:5060) State DESTROY
2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:375
sofia/internal/sip:110 at 192.168.30.50:5060 SOFIA DESTROY
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:99
sofia/internal/sip:110 at 192.168.30.50:5060 Standard DESTROY
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:581
(sofia/internal/sip:110 at 192.168.30.50:5060) State DESTROY going to sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:92
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Standard REPORTING, cause:
ORIGINATOR_CANCEL
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:766
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State REPORTING going to
sleep
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:443
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State Change CS_REPORTING
-> CS_DESTROY
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1345 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1553 Session 138
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Locked, Waiting on
external entities
2013-09-26 15:43:52.917046 [NOTICE] switch_core_session.c:1571 Session 138
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Ended
2013-09-26 15:43:52.917046 [NOTICE] switch_core_session.c:1575 Close Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [CS_DESTROY]
2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Callstate Change HANGUP ->
DOWN
2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:571
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Running State Change
CS_DESTROY
2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:581
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State DESTROY
2013-09-26 15:43:52.937028 [DEBUG] mod_sofia.c:375
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> SOFIA DESTROY
2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:99
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> Standard DESTROY
2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:581
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) State DESTROY going to
sleep
2013-09-26 15:43:59.637066 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.637066 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.657060 [DEBUG] sofia.c:5834 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> entering state
[received][100]
2013-09-26 15:43:59.657060 [DEBUG] sofia.c:5844 Remote SDP:
v=0
o=- 8119682 8119682 IN IP4 192.168.30.50
s=-
c=IN IP4 192.168.30.50
t=0 0
m=audio 16466 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
2013-09-26 15:43:59.917060 [DEBUG] switch_ivr_play_say.c:1723 done playing
file local_stream://moh
2013-09-26 15:43:59.917060 [DEBUG] switch_channel.c:1909
(sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> ) Callstate Change HELD ->
UNHOLD
2013-09-26 15:43:59.917060 [DEBUG] switch_core_session.c:865 Send signal
sofia/external/15068580441 [BREAK]
2013-09-26 15:43:59.917060 [DEBUG] switch_ivr_bridge.c:388 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:2880 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:1841 Already using
PCMU
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:3051 Set 2833 dtmf
send/recv payload to 101
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:4087 Audio params
changed for sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> from 0.0.0.0:16466 to
192.168.30.50:16466
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:4098 AUDIO RTP
[sofia/internal/100 at 192.168.30.100:5060] 192.168.30.100 port 29654 ->
192.168.30.50 port 16466 codec: 0 ms: 20
2013-09-26 15:43:59.917060 [DEBUG] switch_core_media.c:4139 AUDIO RTP
CHANGING DEST TO: [192.168.30.50:16466]
2013-09-26 15:43:59.917060 [DEBUG] sofia.c:6375 Processing updated SDP
2013-09-26 15:43:59.917060 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.937039 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.937039 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> entering state
[completed][200]
2013-09-26 15:43:59.937039 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> [BREAK]
2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel
sofia/internal/100 at 192.168.30.100:5060
<mailto:sofia/internal/100 at 192.168.30.100:5060> entering state [ready][200]
2013-09-26 15:44:00.097064 [DEBUG] switch_rtp.c:4934 Correct ip/port
confirmed.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20130927/aa757fa9/attachment-0001.html
Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-users
mailing list