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)}/${strftime(%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_number})
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-a43f91bd7a4f)
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/ef19ab2c-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/ef19ab2c-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-a43f91bd7a4f)
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