[Freeswitch-users] Unable to transfer calls between 2 locations

26 Sep 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@192.168.30.100:5060 Regex (PASS)
[local_extension] destination_number(110) =~ /(^\d{2,7}$)/ break=on-false

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(dialed_extension=110) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
export(dialed_extension=110) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action limit(hash
${domain_name} 110 ${limit_max} ${limit_destination}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(1 b s
execute_extension::dx XML features) 

Dialplan: sofia/internal/100@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@192.168.30.100:5060 Action bind_meta_app(3 b s
execute_extension::cf XML features) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action bind_meta_app(4 b s
execute_extension::att_xfer XML features) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(ringback=${us-ring}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(transfer_ringback=local_stream://moh) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action set(call_timeout=30)

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(hangup_after_bridge=true) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(continue_on_fail=true) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_numbe
r}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
set(called_party_call_group=${user_data(${dialed_extension}@${domain_name}
var call_group)}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action
bridge(user/${user_data(${destination_number}@${domain_name} attr
id)}@${domain_name}) 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action answer() 

Dialplan: sofia/internal/100@192.168.30.100:5060 Action sleep(1000) 

Dialplan: sofia/internal/100@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@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:473
(sofia/internal/100@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@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@192.168.30.100:5060) State EXECUTE

2013-09-26 15:43:48.517027 [DEBUG] mod_sofia.c:230
sofia/internal/100@192.168.30.100:5060 SOFIA EXECUTE

2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:209
sofia/internal/100@192.168.30.100:5060 Standard EXECUTE

EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_direction=local)

2013-09-26 15:43:48.517027 [DEBUG] mod_dptools.c:1395
sofia/internal/100@192.168.30.100:5060 SET [call_direction]=[local]

EXECUTE sofia/internal/100@192.168.30.100:5060
hash(insert/192.168.30.100-spymap/100/ef19ab2c-f911-4480-8776-a43f91bd7a4f)

EXECUTE sofia/internal/100@192.168.30.100:5060
hash(insert/192.168.30.100-last_dial/100/110)

EXECUTE sofia/internal/100@192.168.30.100:5060
hash(insert/192.168.30.100-last_dial/global/ef19ab2c-f911-4480-8776-a43f91bd
7a4f)

EXECUTE sofia/internal/100@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@192.168.30.100:5060 SET [RFC2822_DATE]=[Thu, 26 Sep 2013
15:43:48 -0300]

EXECUTE sofia/internal/100@192.168.30.100:5060 set(dialed_extension=110)

2013-09-26 15:43:48.517027 [DEBUG] mod_dptools.c:1395
sofia/internal/100@192.168.30.100:5060 SET [dialed_extension]=[110]

EXECUTE sofia/internal/100@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@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@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@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@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@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@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@192.168.30.100:5060 SET [ringback]=[%(2000, 4000, 440.0,
480.0)]

EXECUTE sofia/internal/100@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@192.168.30.100:5060 SET
[transfer_ringback]=[local_stream://moh]

EXECUTE sofia/internal/100@192.168.30.100:5060 set(call_timeout=30)

2013-09-26 15:43:48.537011 [DEBUG] mod_dptools.c:1395
sofia/internal/100@192.168.30.100:5060 SET [call_timeout]=[30]

EXECUTE sofia/internal/100@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@192.168.30.100:5060 SET [hangup_after_bridge]=[true]

EXECUTE sofia/internal/100@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@192.168.30.100:5060 SET [continue_on_fail]=[true]

EXECUTE sofia/internal/100@192.168.30.100:5060
hash(insert/192.168.30.100-call_return/110/100)

EXECUTE sofia/internal/100@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@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@192.168.30.100:5060 SET [called_party_call_group]=[sales,
support, billing]

EXECUTE sofia/internal/100@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@192.168.30.100:5060
bridge(user/110@192.168.30.100)

2013-09-26 15:43:48.537011 [DEBUG] switch_channel.c:1180
sofia/internal/100@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@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@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@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@192.168.30.100]

2013-09-26 15:43:48.537011 [NOTICE] switch_channel.c:1034 New Channel
sofia/internal/sip:110@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:2773
sofia/internal/sip:110@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@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@192.168.30.50:5060) State INIT

2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:87
sofia/internal/sip:110@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:457
(sofia/internal/sip:110@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110@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@192.168.30.50:5060) State ROUTING

2013-09-26 15:43:48.537011 [DEBUG] mod_sofia.c:137
sofia/internal/sip:110@192.168.30.50:5060 SOFIA ROUTING

2013-09-26 15:43:48.537011 [DEBUG] switch_ivr_originate.c:67
(sofia/internal/sip:110@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:48.537011 [DEBUG] switch_core_state_machine.c:473
(sofia/internal/sip:110@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@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@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@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@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:48.597004 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110@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@192.168.30.50:5060!

2013-09-26 15:43:48.597004 [DEBUG] switch_channel.c:3194
(sofia/internal/sip:110@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@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@192.168.30.100:5060!

2013-09-26 15:43:48.597004 [DEBUG] switch_channel.c:3332
(sofia/internal/100@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:48.597004 [DEBUG] switch_ivr_originate.c:1247 Raw Codec
Activation Success L16@8000hz 1 channel 20ms

2013-09-26 15:43:48.597004 [DEBUG] switch_core_codec.c:219
sofia/internal/100@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:48.637046 [DEBUG] sofia.c:5834 Channel
sofia/internal/100@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:52.897038 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:52.897038 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:52.897038 [DEBUG] sofia.c:5834 Channel
sofia/internal/sip:110@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@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@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@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@192.168.30.100:5060 entering state [terminated][487]

2013-09-26 15:43:52.917046 [NOTICE] sofia.c:6642 Hangup
sofia/internal/100@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@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:52.917046 [DEBUG] switch_core_codec.c:244
sofia/internal/100@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@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@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@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@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@192.168.30.50:5060) Callstate Change RINGING ->
ACTIVE

2013-09-26 15:43:52.917046 [DEBUG] sofia.c:6587
sofia/internal/sip:110@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@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@192.168.30.50:5060) State HANGUP

2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:459
sofia/internal/sip:110@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@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@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@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@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@192.168.30.100:5060) State HANGUP

2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:465 Channel
sofia/internal/100@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@192.168.30.50:5060

2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:48
sofia/internal/sip:110@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@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@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@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@192.168.30.50:5060 [BREAK]

2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/sip:110@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@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@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@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@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@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@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@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
(sofia/internal/100@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@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@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@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@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@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@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@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@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@192.168.30.50:5060) State DESTROY

2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:375
sofia/internal/sip:110@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@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@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@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@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@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:52.917046 [DEBUG] switch_core_session.c:1553 Session 138
(sofia/internal/100@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@192.168.30.100:5060) Ended

2013-09-26 15:43:52.917046 [NOTICE] switch_core_session.c:1575 Close Channel
sofia/internal/100@192.168.30.100:5060 [CS_DESTROY]

2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:568
(sofia/internal/100@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@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@192.168.30.100:5060) State DESTROY

2013-09-26 15:43:52.937028 [DEBUG] mod_sofia.c:375
sofia/internal/100@192.168.30.100:5060 SOFIA DESTROY

2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:99
sofia/internal/100@192.168.30.100:5060 Standard DESTROY

2013-09-26 15:43:52.937028 [DEBUG] switch_core_state_machine.c:581
(sofia/internal/100@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.637066 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.657060 [DEBUG] sofia.c:5834 Channel
sofia/internal/100@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@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@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@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@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.937039 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.937039 [DEBUG] switch_core_session.c:1010 Send signal
sofia/internal/100@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel
sofia/internal/100@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@192.168.30.100:5060 [BREAK]

2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel
sofia/internal/100@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.

2013-09-26 15:44:52.197015 [DEBUG] sofia_reg.c:2234 Changing expire time to
600 by request of proxy sip:sip-slb.voicemeup.com

[Freeswitch-users] Unable to transfer calls between 2 locations

Charles Bujold