Unable to transfer calls between 2 locations
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
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@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@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:5060hash(insert/192.168.30.100-spymap/100/ef19ab2c-f911-4480-8776-a43f91bd7a4f) ****
EXECUTE sofia/internal/100@192.168.30.100:5060hash(insert/192.168.30.100-last_dial/100/110) ****
EXECUTE sofia/internal/100@192.168.30.100:5060hash(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: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@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:5060set(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:5060set(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:5060hash(insert/192.168.30.100-call_return/110/100) ****
EXECUTE sofia/internal/100@192.168.30.100:5060hash(insert/192.168.30.100-last_dial_ext/110/ef19ab2c-f911-4480-8776-a43f91bd7a4f) ****
EXECUTE sofia/internal/100@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@192.168.30.100:5060 SET [called_party_call_group]=[sales, support, billing]****
EXECUTE sofia/internal/100@192.168.30.100:5060hash(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****
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
participants (2)
-
Cal Leeming [Simplicity Media Ltd]
-
Charles Bujold