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

Mon Sep 30 11:51:00 MSD 2013

Hi Charles,

Sorry for the delayed response, looks like the ML was fairly quiet over the
weekend.

Your email mentioned that you didn't know where/why this was being sent to
voicemail - have you taken a look at your dialplan first? According to your
logs, it attempts to bridge first, then goes to email upon failure. Can you
tell us a few things;

* Does the callee (the phone being called) ring?
* Does the caller (the phone making the call) hear a ringback tone?
* How long does the phone ring before going to voicemail?
* Have you been able to find a fix for this so far?

Generally speaking, if the bridge fails then the callee was unable to take
the call thus it proceeds to the next step in the dialplan. Sometimes NAT
problems can cause this to happen too.

Once you've ascertained the above, you can attempt to fix the problem. For
example, if the phone is not ringing then this would suggest a registration
problem, if the phone is registered fine then this could be a NAT issue. If
the phone is ringing, what happens when you pick up? Etc etc.

Also - in future please paste any logs directly into pastebin and provide a
URL, large chunks of debug become malformed and make reading a struggle.

Cal

On Thu, Sep 26, 2013 at 8:11 PM, Charles Bujold <cjbujold at accra.ca> wrote:

> 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 Regex (PASS)
> [local_extension] destination_number(110) =~ /(^\d{2,7}$)/ break=on-false*
> ***
>
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action
> set(dialed_extension=110) ****
>
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action
> export(dialed_extension=110) ****
>
> Dialplan: 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 Action bind_meta_app(1 b
> s execute_extension::dx XML features) ****
>
> Dialplan: 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)}/${strftime(%b)}/${strftime(%d)}/${uuid}.wav)
> ****
>
> Dialplan: 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 Action bind_meta_app(4 b
> s execute_extension::att_xfer XML features) ****
>
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action
> set(ringback=${us-ring}) ****
>
> Dialplan: 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 Action
> set(call_timeout=30) ****
>
> Dialplan: 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 Action
> set(continue_on_fail=true) ****
>
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action
> hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
> ****
>
> Dialplan: 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 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 Action
> hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid}) *
> ***
>
> Dialplan: 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 Action answer() ****
>
> Dialplan: sofia/internal/100 at 192.168.30.100:5060 Action sleep(1000) ****
>
> Dialplan: 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) 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 [BREAK]****
>
> 2013-09-26 15:43:48.517027 [DEBUG] switch_core_state_machine.c:473
> (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) 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) State EXECUTE****
>
> 2013-09-26 15:43:48.517027 [DEBUG] mod_sofia.c:230 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 Standard EXECUTE****
>
> EXECUTE 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 SET [call_direction]=[local]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(insert/192.168.30.100-spymap/100/ef19ab2c-f911-4480-8776-a43f91bd7a4f)
> ****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(insert/192.168.30.100-last_dial/100/110)
> ****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(insert/192.168.30.100-last_dial/global/ef19ab2c-f911-4480-8776-a43f91bd7a4f)
> ****
>
> EXECUTE 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 SET [RFC2822_DATE]=[Thu, 26 Sep 2013 15:43:48
> -0300]****
>
> EXECUTE 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 SET [dialed_extension]=[110]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060export(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 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 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 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 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 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 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 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060set(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 SET [transfer_ringback]=[local_stream://moh]****
>
> EXECUTE 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 SET [call_timeout]=[30]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060set(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 SET [hangup_after_bridge]=[true]****
>
> EXECUTE 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 SET [continue_on_fail]=[true]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(insert/192.168.30.100-call_return/110/100)
> ****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(insert/192.168.30.100-last_dial_ext/110/ef19ab2c-f911-4480-8776-a43f91bd7a4f)
> ****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060set(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 SET [called_party_call_group]=[sales, support,
> billing]****
>
> EXECUTE sofia/internal/100 at 192.168.30.100:5060hash(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 bridge(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 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 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 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 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!****
>
> 2013-09-26 15:43:48.597004 [DEBUG] switch_channel.c:3332 (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 [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 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 [BREAK]****
>
> 2013-09-26 15:43:48.637046 [DEBUG] sofia.c:5834 Channel 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 [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 [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 [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 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 [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 [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 [BREAK]****
>
> 2013-09-26 15:43:52.917046 [DEBUG] switch_core_codec.c:244 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 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) 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) 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) State HANGUP****
>
> 2013-09-26 15:43:52.917046 [DEBUG] mod_sofia.c:465 Channel 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 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) 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) 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) 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 [BREAK]****
>
> 2013-09-26 15:43:52.917046 [DEBUG] switch_core_state_machine.c:418
> (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) 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 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) 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) 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 [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) 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) 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 [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) 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) 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) State DESTROY****
>
> 2013-09-26 15:43:52.937028 [DEBUG] mod_sofia.c:375 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 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) 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 [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 [BREAK]****
>
> 2013-09-26 15:43:59.657060 [DEBUG] sofia.c:5834 Channel 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) 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 [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 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 [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 [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 [BREAK]****
>
> 2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel 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 [BREAK]****
>
> 2013-09-26 15:43:59.937039 [DEBUG] sofia.c:5834 Channel 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.****
>
> 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****
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20130930/ccbc721e/attachment-0001.html 